Re: subprocess & redirect

On Mar 21, 2006, at 4:45 PM, Jonathan Ellis wrote:

> Strange.  My first guess would be that the child process is somehow
> interacting with stdout (which Spyce redirects to an internal file
> handle) which screws things up here.  But even when I specify
> subprocess.PIPE for the subprocess stdin/out/err I get the same  
> results.
>  So I don't know.  Let me know if you figure it out. :)

Jonathan, I will need your help for this one, I'm afraid. I've done  
some more digging this afternoon and here's what I learned.

First of all, I realized that the redirect isn't part of the problem,  
so I dropped it. Here's what my code looks like now:
[[\
     import subprocess
     import time

     TheLongRunningProcess = "/usr/local/MyStuff/src/foo.py"

     subprocess.Popen(["python", TheLongRunningProcess])

     response.write("<p>Spawn complete at %s</p>\n" %  
time.strftime("%M:%S", time.gmtime()))

     # This doesn't make a difference except to truncate output.
     #raise spyceDone

]]

With this code, it is easier to see what's happening. The page displays  
in my browser (Firefox) immediately, but FF behaves as if the page  
isn't completely loaded yet. If I cancel the page load at this point by  
clicking the big red X in FF's toolbar and then view source, all of the  
HTML source is there, so why does FF think the page isn't loaded? If I  
don't cancel the page load, Firefox decides the page is completely  
loaded only when my "long running" process foo.py completes sleeping  
for 10 seconds. (Opera and Safari don't display anything until foo.py  
is done.)

I fired up Ethereal and it told me what FF is seeing that I'm not. The  
HTTP response is broken up over two messages. The first contains a  
Transfer-Encoding: chunked header and the page data, ending with  
</html> 0a 0d 0a. This is what the browser receives immediately. Then,  
ten seconds later (once foo.py completes), I get a second HTTP message  
just five bytes long:
30 0d 0a 0d 0a

This is the 0 and double newline that indicates the close of a  
chunked-content response. So FF isn't receiving any displayable data,  
but it is correct in considering the chunked response incomplete until  
it sees these five bytes.

I grepped through the Spyce code and didn't find any references to  
"chunked" or "transfer-encoding", so I guess it isn't Spyce that  
manages the data chunking. I don't really know where to look next  
because I don't understand how Spyce interacts with Apache. At this  
point, I'm in over my head. Actually, I was in over my head when I  
started looking at TCP packets with Ethereal, but I'm a quick learner.  
=)

Suggestions? COmments?


Thanks
Philip



> But, it will definitely work if you use a thread instead of a process  
> to
> do your computation...  Cleaner, too, if it's just more python code you
> want to run.
> On Tue, 21 Mar 2006 15:59:12 -0500, "Philip Semanchuk"
> <[email protected]> said:
>>
>> On Mar 20, 2006, at 7:12 PM, Philip Semanchuk wrote:
>>
>>>
>>> On Mar 20, 2006, at 7:03 PM, Jonathan Ellis wrote:
>>>
>>>> Did you try using the native spyce server?  It should work fine  
>>>> there.
>>>> I wouldn't be surprised if mod_python or something else is screwing
>>>> with
>>>> you.
>>>
>>> If by "native spyce server" you mean Spyce proxied behind Apache,  
>>> then
>>> yes, that's how I have it set up. I'm running Apache 2.1.9  under
>>> FreeBSD 6.0, FYI.
>>
>> More clues. First, I used the LiveHTTPHeaders extension for Firefox to
>> see what's happening when I hit RedirectTest.spy. Here's the
>> conversation that it reports:
>>
>> ----------------------------------------------------------
>> http://whiskey/RedirectTest.spy
>>
>> GET /RedirectTest.spy HTTP/1.1
>> Host: whiskey
>> User-Agent: Mozilla/5.0 (Macintosh; U; PPC Mac OS X Mach-O; en-US;
>> rv:1.8.0.1) Gecko/20060111 Firefox/1.5.0.1
>> Accept:
>> text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/
>> plain;q=0.8,image/png,*/*;q=0.5
>> Accept-Language: en-us,en;q=0.7,sv;q=0.3
>> Accept-Encoding: gzip,deflate
>> Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
>> Keep-Alive: 300
>> Connection: keep-alive
>>
>> HTTP/1.x 302 MOVED TEMPORARILY
>> Date: Tue, 21 Mar 2006 20:27:19 GMT
>> Status: 302 "MOVED TEMPORARILY"
>> Content-Type: text/html
>> X-Spyce: Spyce/www_2.0.3 Python/2.4
>> Location: http://google.com
>> Via: 1.1 192.168.0.103
>> Transfer-Encoding: chunked
>> ----------------------------------------------------------
>>
>>
>> The interesting thing to note is that the date header on Spyce's
>> response is at 27:19 after the hour. The spyce log says that the
>> request was received at 27:19 and took 0.0684680938721 seconds to
>> process.
>>
>> Second clue comes from adding a line that writes to a file immediately
>> after spawning the subprocess:
>>      file("/tmp/SpawnComplete.txt",  
>> "w").write(time.strftime("%H:%M:%S",
>> time.gmtime()))
>>
>> That happens at the same time (27:19) as the Spyce log says the  
>> request
>> was received, so Spyce is definitely not getting hung up on the
>> spawning of the subprocess.
>>
>> Based on these clues I'm tempted to conclude that Spyce is generating
>> the redirect response immediately but it is not getting returned to  
>> the
>> browser (for some reason) until the subprocess completes. Any idea why
>> this might happen?
>>
>>
>> Relevant spyce.log section follows.
>>
>>
>> handler for spy is <unbound method myHTTPhandler.handler_spyce>
>> localhost.my.domain - - [21/Mar/2006 15:27:19] "GET /RedirectTest.spy
>> HTTP/1.1" - -
>> elapsed to get spycecode: 0.00439715385437
>> request.load
>> cache hit (1115213323) for request in
>> /usr/local/share/spyce-2.0.3/modules/request.py
>> request.start
>> GET variables: {}
>> POST variables: {}
>> response.load
>> cache hit (1113103628) for response in
>> /usr/local/share/spyce-2.0.3/modules/response.py
>> response.start
>> stdout.load
>> cache hit (1112993912) for stdout in
>> /usr/local/share/spyce-2.0.3/modules/stdout.py
>> stdout.start
>> error.load
>> cache hit (1113883773) for error in
>> /usr/local/share/spyce-2.0.3/modules/error.py
>> error.start
>> redirect.load
>> cache hit (1114403437) for redirect in
>> /usr/local/share/spyce-2.0.3/modules/redirect.py
>> redirect.start
>> elapsed to init wrapper: 0.013818025589
>> external redirect to http://google.com at the behest of
>> /usr/local/www/data-dist/RedirectTest.spy
>> elapsed to process: 0.0558350086212
>> redirect.finish
>> error.finish
>> stdout.finish
>> response.finish
>> request.finish
>> finished destroy for /usr/local/www/data-dist/RedirectTest.spy
>> elapsed to finish: 0.0641510486603
>> total for /RedirectTest.spy was 0.0684680938721
>> foo: done
>>
>>
>>
>> -------------------------------------------------------
>> This SF.Net email is sponsored by xPML, a groundbreaking scripting
>> language
>> that extends applications into web and mobile media. Attend the live
>> webcast
>> and join the prime developer group breaking into this new coding
>> territory!
>> http://sel.as-us.falkag.net/sel? 
>> cmd=lnk&kid=110944&bid=241720&dat=121642
>> _______________________________________________
>> Spyce-users mailing list
>> [email protected]
>> https://lists.sourceforge.net/lists/listinfo/spyce-users
> -- 
> C++ is history repeated as tragedy. Java is history repeated as farce.  
>  --Scott McKay
>
>
>



-------------------------------------------------------
This SF.Net email is sponsored by xPML, a groundbreaking scripting language
that extends applications into web and mobile media. Attend the live webcast
and join the prime developer group breaking into this new coding territory!
http://sel.as-us.falkag.net/sel?cmd=lnk&kid=110944&bid=241720&dat=121642