Re: stream reading inconsistency

mike g Tue, 26 Oct 2004 15:41:57 -0700

Darin Fisher wrote:

mike g wrote:
hi, i've written (using just transports and sockets) a very simple xmlrpc server and client in javascript using xpcom. however, i've noticed the client is unable to recieve server responses sometimes.
any ideas?
tia, mg
_______________________________________________
Mozilla-netlib mailing list
[EMAIL PROTECTED]
http://mail.mozilla.org/listinfo/mozilla-netlib
no, but if you provide log files that might help. set these environment variables to enable logging:
NSPR_LOG_MODULES=nsSocketTransport:5
NSPR_LOG_FILE=c:\log.txt
-darin

Hi, thx for the info.

Set up logging with
NSPR_LOG_MODULES=nsSocketTransport:2,nsHttp:2,nsStreamChannel:2

Captured log results in "worked.txt" and "didNotWork.txt". I have sent these as attachments Each consists of a single request/response interaction between client and server.

A possible significant difference I noticed was that in "worked.txt" nsSocketOutputStream::Write is called twice followed immediately by PR_Write [count=xxx] PR_Write returned [n=xxx]

In "didNotWork.txt", nsSocketOutputStream::Write is called 3 times but "PR_Write returned [n=xxx]" is only displayed once.

tia, mg

16386[8ac52d8]: nsSocketTransportService::Run
16386[8ac52d8]:   calling PR_Poll [active=0 idle=0]
16384[8994558]: nsSocketTransportService::PostEvent [event=9014c40]
16386[8ac52d8]:   calling PR_Poll [active=0 idle=0]
16384[8994558]: nsSocketTransportService::PostEvent [event=8fcaae8]
16386[8ac52d8]:   calling PR_Poll [active=0 idle=0]
16384[8994558]: nsSocketTransportService::PostEvent [event=9262028]
16386[8ac52d8]: nsSocketTransportService::AttachSocket [handler=9261a08]
16386[8ac52d8]: nsSocketTransportService::AddToIdleList [handler=9261a08]
16386[8ac52d8]:   active=0 idle=1
16386[8ac52d8]:   idle [0] { handler=9261a08 condition=0 pollflags=5 }
16386[8ac52d8]: nsSocketTransportService::AddToPollList [handler=9261a08]
16386[8ac52d8]:   active=1 idle=1
16386[8ac52d8]: nsSocketTransportService::RemoveFromIdleList [handler=9261a08]
16386[8ac52d8]:   active=1 idle=0
16386[8ac52d8]:   calling PR_Poll [active=1 idle=0]
16384[8994558]: nsSocketTransportService::PostEvent [event=90a5ce8]
16386[8ac52d8]:   active [0] { handler=9261a08 condition=0 pollflags=5 }
16386[8ac52d8]:   calling PR_Poll [active=1 idle=0]
16384[8994558]: nsSocketTransportService::PostEvent [event=8a32f08]
16386[8ac52d8]:   active [0] { handler=9261a08 condition=0 pollflags=5 }
16386[8ac52d8]:   calling PR_Poll [active=1 idle=0]
16384[8994558]: nsSocketTransportService::PostEvent [event=8a32f08]
16386[8ac52d8]:   active [0] { handler=9261a08 condition=0 pollflags=5 }
16386[8ac52d8]:   calling PR_Poll [active=1 idle=0]
16384[8994558]: nsSocketTransportService::PostEvent [event=8a32f08]
16386[8ac52d8]:   active [0] { handler=9261a08 condition=0 pollflags=5 }
16386[8ac52d8]:   calling PR_Poll [active=1 idle=0]
16384[8994558]: creating nsSocketTransport @8fc75b8
16384[8994558]: nsSocketTransport::Init [this=8fc75b8 host=localhost:6768 proxy=:0]
16384[8994558]: nsSocketTransport::OpenInputStream [this=8fc75b8 flags=0]
16384[8994558]: nsSocketTransportService::PostEvent [event=9225d48]
16384[8994558]: nsSocketTransport::PostEvent [this=8fc75b8 type=0 status=0 param=0]
16384[8994558]: nsSocketTransportService::PostEvent [event=9225d78]
16384[8994558]: nsSocketTransport::OpenOutputStream [this=8fc75b8 flags=0]
16384[8994558]: nsSocketTransportService::PostEvent [event=90a6330]
16384[8994558]: nsSocketTransport::PostEvent [this=8fc75b8 type=0 status=0 param=0]
16384[8994558]: nsSocketTransportService::PostEvent [event=8b65980]
16386[8ac52d8]: nsSocketInputStream::Read [this=8fc7698 count=4096]
16386[8ac52d8]: nsSocketInputStream::AsyncWait [this=8fc7698]
16386[8ac52d8]: nsSocketTransport::OnSocketEvent [this=8fc75b8 type=0 status=0 param=0]
16386[8ac52d8]:   MSG_ENSURE_CONNECT
16386[8ac52d8]: nsSocketTransport::ResolveHost [this=8fc75b8]
16386[8ac52d8]:   advancing to STATE_RESOLVING
16386[8ac52d8]: nsSocketTransport::SendStatus [this=8fc75b8 status=804b0003]
16386[8ac52d8]: nsSocketOutputStream::Write [this=8fc76b4 count=220]
16386[8ac52d8]: nsSocketOutputStream::AsyncWait [this=8fc76b4]
16386[8ac52d8]: nsSocketTransport::OnSocketEvent [this=8fc75b8 type=0 status=0 param=0]
16386[8ac52d8]:   MSG_ENSURE_CONNECT
16386[8ac52d8]:   ignoring redundant event
16386[8ac52d8]:   active [0] { handler=9261a08 condition=0 pollflags=5 }
16386[8ac52d8]:   calling PR_Poll [active=1 idle=0]
16386[8ac52d8]:   active [0] { handler=9261a08 condition=0 pollflags=5 }
16386[8ac52d8]:   calling PR_Poll [active=1 idle=0]
81926[8fdbb10]: nsSocketTransport::PostEvent [this=8fc75b8 type=1 status=0 
param=900c268]
81926[8fdbb10]: nsSocketTransportService::PostEvent [event=9244870]
16386[8ac52d8]: nsSocketTransport::OnSocketEvent [this=8fc75b8 type=1 status=0 
param=900c268]
16386[8ac52d8]:   MSG_DNS_LOOKUP_COMPLETE
16386[8ac52d8]: nsSocketTransport::InitiateSocket [this=8fc75b8]
16386[8ac52d8]: nsSocketTransport::BuildSocket [this=8fc75b8]
16386[8ac52d8]: nsSocketTransportService::AttachSocket [handler=8fc75b8]
16386[8ac52d8]: nsSocketTransportService::AddToIdleList [handler=8fc75b8]
16386[8ac52d8]:   active=1 idle=1
16386[8ac52d8]:   advancing to STATE_CONNECTING
16386[8ac52d8]: nsSocketTransport::SendStatus [this=8fc75b8 status=804b0007]
16386[8ac52d8]:   trying address: 127.0.0.1
16386[8ac52d8]:   active [0] { handler=9261a08 condition=0 pollflags=5 }
16386[8ac52d8]:   idle [0] { handler=8fc75b8 condition=0 pollflags=6 }
16386[8ac52d8]: nsSocketTransportService::AddToPollList [handler=8fc75b8]
16386[8ac52d8]:   active=2 idle=1
16386[8ac52d8]: nsSocketTransportService::RemoveFromIdleList [handler=8fc75b8]
16386[8ac52d8]:   active=2 idle=0
16386[8ac52d8]:   calling PR_Poll [active=2 idle=0]
16386[8ac52d8]: creating nsSocketTransport @9223638
16386[8ac52d8]: nsSocketTransport::InitWithConnectedSocket [this=9223638 
addr=127.0.0.1:34066]
16386[8ac52d8]: nsSocketTransport::PostEvent [this=9223638 type=2 status=0 param=0]
16386[8ac52d8]: nsSocketTransportService::PostEvent [event=9244870]
16386[8ac52d8]: nsSocketTransport::OnSocketReady [this=8fc75b8 outFlags=2]
16386[8ac52d8]:   advancing to STATE_TRANSFERRING
16386[8ac52d8]: nsSocketTransport::SendStatus [this=8fc75b8 status=804b0004]
16386[8ac52d8]:   active [1] { handler=8fc75b8 condition=0 pollflags=7 }
16386[8ac52d8]:   active [0] { handler=9261a08 condition=0 pollflags=5 }
16386[8ac52d8]:   calling PR_Poll [active=2 idle=0]
16386[8ac52d8]: nsSocketTransport::OnSocketReady [this=8fc75b8 outFlags=2]
16386[8ac52d8]: nsSocketOutputStream::OnSocketReady [this=8fc76b4 cond=0]
16386[8ac52d8]: nsSocketTransportService::PostEvent [event=9223820]
16386[8ac52d8]: nsSocketTransport::OnSocketEvent [this=9223638 type=2 status=0 param=0]
16386[8ac52d8]: nsSocketTransport::InitiateSocket [this=9223638]
16386[8ac52d8]: nsSocketTransportService::AttachSocket [handler=9223638]
16386[8ac52d8]: nsSocketTransportService::AddToIdleList [handler=9223638]
16386[8ac52d8]:   active=2 idle=1
16386[8ac52d8]: nsSocketOutputStream::Write [this=8fc76b4 count=220]
16386[8ac52d8]:   calling PR_Write [count=220]
16386[8ac52d8]:   PR_Write returned [n=220]
16386[8ac52d8]: nsSocketTransport::SendStatus [this=8fc75b8 status=804b0005]
16386[8ac52d8]: nsSocketOutputStream::AsyncWait [this=8fc76b4]
16386[8ac52d8]:   active [1] { handler=8fc75b8 condition=0 pollflags=7 }
16386[8ac52d8]:   active [0] { handler=9261a08 condition=0 pollflags=5 }
16386[8ac52d8]:   idle [0] { handler=9223638 condition=0 pollflags=7 }
16386[8ac52d8]: nsSocketTransportService::AddToPollList [handler=9223638]
16386[8ac52d8]:   active=3 idle=1
16386[8ac52d8]: nsSocketTransportService::RemoveFromIdleList [handler=9223638]
16386[8ac52d8]:   active=3 idle=0
16386[8ac52d8]:   calling PR_Poll [active=3 idle=0]
16386[8ac52d8]: nsSocketTransport::OnSocketReady [this=8fc75b8 outFlags=2]
16386[8ac52d8]: nsSocketOutputStream::OnSocketReady [this=8fc76b4 cond=0]
16386[8ac52d8]: nsSocketTransport::OnSocketReady [this=9223638 outFlags=3]
16386[8ac52d8]: nsSocketOutputStream::OnSocketReady [this=9223734 cond=0]
16386[8ac52d8]: nsSocketInputStream::OnSocketReady [this=9223718 cond=0]
16386[8ac52d8]:   active [2] { handler=9223638 condition=0 pollflags=0 }
16386[8ac52d8]: nsSocketTransportService::AddToIdleList [handler=9223638]
16386[8ac52d8]:   active=3 idle=1
16386[8ac52d8]: nsSocketTransportService::RemoveFromPollList [handler=9223638]
16386[8ac52d8]:   index=2 mActiveCount=3
16386[8ac52d8]:   active=2 idle=1
16386[8ac52d8]:   active [1] { handler=8fc75b8 condition=0 pollflags=5 }
16386[8ac52d8]:   active [0] { handler=9261a08 condition=0 pollflags=5 }
16386[8ac52d8]:   calling PR_Poll [active=2 idle=1]
16384[8994558]: nsSocketTransport::OpenInputStream [this=9223638 flags=0]
16384[8994558]: nsSocketTransportService::PostEvent [event=90af448]
16384[8994558]: nsSocketTransport::PostEvent [this=9223638 type=0 status=0 param=0]
16384[8994558]: nsSocketTransportService::PostEvent [event=91d17e8]
16384[8994558]: nsSocketTransport::OpenOutputStream [this=9223638 flags=0]
16384[8994558]: nsSocketTransportService::PostEvent [event=91e1700]
16384[8994558]: nsSocketTransport::PostEvent [this=9223638 type=0 status=0 param=0]
16384[8994558]: nsSocketTransportService::PostEvent [event=91e1730]
16386[8ac52d8]: nsSocketInputStream::Read [this=9223718 count=4096]
16386[8ac52d8]:   calling PR_Read [count=4096]
16386[8ac52d8]:   PR_Read returned [n=220]
16386[8ac52d8]: nsSocketTransport::SendStatus [this=9223638 status=804b0006]
16386[8ac52d8]: nsSocketInputStream::Read [this=9223718 count=3876]
16386[8ac52d8]:   calling PR_Read [count=3876]
16386[8ac52d8]:   PR_Read returned [n=-1]
16386[8ac52d8]: nsSocketInputStream::AsyncWait [this=9223718]
16386[8ac52d8]: nsSocketTransport::OnSocketEvent [this=9223638 type=0 status=0 param=0]
16386[8ac52d8]:   MSG_ENSURE_CONNECT
16386[8ac52d8]:   ignoring redundant event
16386[8ac52d8]: nsSocketOutputStream::AsyncWait [this=9223734]
16386[8ac52d8]: nsSocketTransport::OnSocketEvent [this=9223638 type=0 status=0 param=0]
16386[8ac52d8]:   MSG_ENSURE_CONNECT
16386[8ac52d8]:   ignoring redundant event
16386[8ac52d8]:   active [1] { handler=8fc75b8 condition=0 pollflags=5 }
16386[8ac52d8]:   active [0] { handler=9261a08 condition=0 pollflags=5 }
16386[8ac52d8]:   idle [0] { handler=9223638 condition=0 pollflags=7 }
16386[8ac52d8]: nsSocketTransportService::AddToPollList [handler=9223638]
16386[8ac52d8]:   active=3 idle=1
16386[8ac52d8]: nsSocketTransportService::RemoveFromIdleList [handler=9223638]
16386[8ac52d8]:   active=3 idle=0
16386[8ac52d8]:   calling PR_Poll [active=3 idle=0]
16386[8ac52d8]: nsSocketTransport::OnSocketReady [this=9223638 outFlags=2]
16386[8ac52d8]: nsSocketOutputStream::OnSocketReady [this=9223734 cond=0]
16386[8ac52d8]:   active [2] { handler=9223638 condition=0 pollflags=5 }
16386[8ac52d8]:   active [1] { handler=8fc75b8 condition=0 pollflags=5 }
16386[8ac52d8]:   active [0] { handler=9261a08 condition=0 pollflags=5 }
16386[8ac52d8]:   calling PR_Poll [active=3 idle=0]
16384[8994558]: nsSocketTransportService::PostEvent [event=90af448]
16384[8994558]: nsSocketTransportService::PostEvent [event=91d7f98]
16384[8994558]: nsSocketInputStream::CloseWithStatus [this=9223718 reason=80470002]
16384[8994558]: nsSocketTransport::PostEvent [this=9223638 type=3 status=80470002 
param=0]
16384[8994558]: nsSocketTransportService::PostEvent [event=91e1730]
16384[8994558]: nsSocketOutputStream::CloseWithStatus [this=9223734 reason=80470002]
16384[8994558]: nsSocketTransport::PostEvent [this=9223638 type=5 status=80470002 
param=0]
16384[8994558]: nsSocketTransportService::PostEvent [event=91d17e8]
16386[8ac52d8]: nsSocketOutputStream::Write [this=9223734 count=221]
16386[8ac52d8]: nsSocketOutputStream::CloseWithStatus [this=9223734 reason=0]
16386[8ac52d8]: nsSocketOutputStream::CloseWithStatus [this=9223734 reason=80470002]
16386[8ac52d8]: nsSocketInputStream::CloseWithStatus [this=9223718 reason=80470002]
16386[8ac52d8]: nsSocketInputStream::CloseWithStatus [this=9223718 reason=80470002]
16386[8ac52d8]: nsSocketTransport::OnSocketEvent [this=9223638 type=3 status=80470002 
param=0]
16386[8ac52d8]:   MSG_INPUT_CLOSED
16386[8ac52d8]: nsSocketTransport::OnMsgInputClosed [this=9223638 reason=80470002]
16386[8ac52d8]: nsSocketInputStream::OnSocketReady [this=9223718 cond=80470002]
16386[8ac52d8]: nsSocketTransportService::PostEvent [event=91d7f98]
16386[8ac52d8]: nsSocketTransport::OnSocketEvent [this=9223638 type=5 status=80470002 
param=0]
16386[8ac52d8]:   MSG_OUTPUT_CLOSED
16386[8ac52d8]: nsSocketTransport::OnMsgOutputClosed [this=9223638 reason=80470002]
16386[8ac52d8]:   after event [this=9223638 cond=80470002]
16386[8ac52d8]:   active [2] { handler=9223638 condition=80470002 pollflags=0 }
16386[8ac52d8]: nsSocketTransportService::DetachSocket [handler=9223638]
16386[8ac52d8]: nsSocketTransport::OnSocketDetached [this=9223638 cond=80470002]
16386[8ac52d8]: nsSocketTransport::RecoverFromError [this=9223638 state=4 
cond=80470002]
16386[8ac52d8]: nsSocketInputStream::OnSocketReady [this=9223718 cond=80470002]
16386[8ac52d8]: nsSocketOutputStream::OnSocketReady [this=9223734 cond=80470002]
16386[8ac52d8]: nsSocketTransportService::PostEvent [event=90af448]
16386[8ac52d8]: nsSocketTransport: calling PR_Close [this=9223638]
16386[8ac52d8]: nsSocketTransportService::RemoveFromPollList [handler=0]
16386[8ac52d8]:   index=2 mActiveCount=3
16386[8ac52d8]:   active=2 idle=0
16386[8ac52d8]:   active [1] { handler=8fc75b8 condition=0 pollflags=5 }
16386[8ac52d8]:   active [0] { handler=9261a08 condition=0 pollflags=5 }
16386[8ac52d8]:   calling PR_Poll [active=2 idle=0]
16386[8ac52d8]: nsSocketTransport::OnSocketReady [this=8fc75b8 outFlags=1]
16386[8ac52d8]: nsSocketInputStream::OnSocketReady [this=8fc7698 cond=0]
16386[8ac52d8]: nsSocketTransportService::PostEvent [event=8c0bc80]
16386[8ac52d8]: nsSocketInputStream::Read [this=8fc7698 count=4096]
16386[8ac52d8]:   calling PR_Read [count=4096]
16386[8ac52d8]:   PR_Read returned [n=0]
16386[8ac52d8]: nsSocketInputStream::CloseWithStatus [this=8fc7698 reason=0]
16386[8ac52d8]: nsSocketInputStream::CloseWithStatus [this=8fc7698 reason=80470002]
16386[8ac52d8]: nsSocketTransport::OnMsgInputClosed [this=8fc75b8 reason=80470002]
16386[8ac52d8]: nsSocketInputStream::OnSocketReady [this=8fc7698 cond=80470002]
16386[8ac52d8]: nsSocketTransportService::PostEvent [event=90af448]
16386[8ac52d8]:   active [1] { handler=8fc75b8 condition=0 pollflags=0 }
16386[8ac52d8]: nsSocketTransportService::AddToIdleList [handler=8fc75b8]
16386[8ac52d8]:   active=2 idle=1
16386[8ac52d8]: nsSocketTransportService::RemoveFromPollList [handler=8fc75b8]
16386[8ac52d8]:   index=1 mActiveCount=2
16386[8ac52d8]:   active=1 idle=1
16386[8ac52d8]:   active [0] { handler=9261a08 condition=0 pollflags=5 }
16386[8ac52d8]:   calling PR_Poll [active=1 idle=1]
16386[8ac52d8]:   active [0] { handler=9261a08 condition=0 pollflags=5 }
16386[8ac52d8]:   idle [0] { handler=8fc75b8 condition=0 pollflags=0 }
16386[8ac52d8]:   calling PR_Poll [active=1 idle=1]
16384[8994558]: nsSocketTransportService::PostEvent [event=8c99248]
16386[8ac52d8]: nsSocketOutputStream::CloseWithStatus [this=8fc76b4 reason=0]
16386[8ac52d8]: nsSocketOutputStream::CloseWithStatus [this=8fc76b4 reason=80470002]
16386[8ac52d8]: nsSocketTransport::OnMsgOutputClosed [this=8fc75b8 reason=80470002]
16386[8ac52d8]:   active [0] { handler=9261a08 condition=0 pollflags=5 }
16386[8ac52d8]:   idle [0] { handler=8fc75b8 condition=80470002 pollflags=0 }
16386[8ac52d8]: nsSocketTransportService::DetachSocket [handler=8fc75b8]
16386[8ac52d8]: nsSocketTransport::OnSocketDetached [this=8fc75b8 cond=80470002]
16386[8ac52d8]: nsSocketTransport::RecoverFromError [this=8fc75b8 state=4 
cond=80470002]
16386[8ac52d8]: nsSocketInputStream::OnSocketReady [this=8fc7698 cond=80470002]
16386[8ac52d8]: nsSocketOutputStream::OnSocketReady [this=8fc76b4 cond=80470002]
16386[8ac52d8]: nsSocketTransportService::PostEvent [event=8c99248]
16386[8ac52d8]: nsSocketTransport: calling PR_Close [this=8fc75b8]
16386[8ac52d8]: nsSocketTransportService::RemoveFromIdleList [handler=0]
16386[8ac52d8]:   active=1 idle=0
16386[8ac52d8]:   calling PR_Poll [active=1 idle=0]
16386[8ac52d8]:   active [0] { handler=9261a08 condition=0 pollflags=5 }
16386[8ac52d8]:   calling PR_Poll [active=1 idle=0]
16384[8994558]: destroying nsSocketTransport @9223638
16384[8994558]: destroying nsSocketTransport @8fc75b8

16386[8ac52d8]: nsSocketTransportService::Run
16386[8ac52d8]:   calling PR_Poll [active=0 idle=0]
16384[8994558]: nsSocketTransportService::PostEvent [event=91131a8]
16386[8ac52d8]: nsSocketTransportService::AttachSocket [handler=912d2b0]
16386[8ac52d8]: nsSocketTransportService::AddToIdleList [handler=912d2b0]
16386[8ac52d8]:   active=0 idle=1
16386[8ac52d8]:   idle [0] { handler=912d2b0 condition=0 pollflags=5 }
16386[8ac52d8]: nsSocketTransportService::AddToPollList [handler=912d2b0]
16386[8ac52d8]:   active=1 idle=1
16386[8ac52d8]: nsSocketTransportService::RemoveFromIdleList [handler=912d2b0]
16386[8ac52d8]:   active=1 idle=0
16386[8ac52d8]:   calling PR_Poll [active=1 idle=0]
16384[8994558]: creating nsSocketTransport @9250b28
16384[8994558]: nsSocketTransport::Init [this=9250b28 host=localhost:6768 proxy=:0]
16384[8994558]: nsSocketTransport::OpenInputStream [this=9250b28 flags=0]
16384[8994558]: nsSocketTransportService::PostEvent [event=9251570]
16386[8ac52d8]: nsSocketInputStream::Read [this=9250c08 count=4096]
16386[8ac52d8]: nsSocketInputStream::AsyncWait [this=9250c08]
16386[8ac52d8]:   active [0] { handler=912d2b0 condition=0 pollflags=5 }
16386[8ac52d8]:   calling PR_Poll [active=1 idle=0]
16384[8994558]: nsSocketTransport::PostEvent [this=9250b28 type=0 status=0 param=0]
16384[8994558]: nsSocketTransportService::PostEvent [event=9251628]
16386[8ac52d8]: nsSocketTransport::OnSocketEvent [this=9250b28 type=0 status=0 param=0]
16386[8ac52d8]:   MSG_ENSURE_CONNECT
16386[8ac52d8]: nsSocketTransport::ResolveHost [this=9250b28]
16386[8ac52d8]:   advancing to STATE_RESOLVING
16386[8ac52d8]: nsSocketTransport::SendStatus [this=9250b28 status=804b0003]
16386[8ac52d8]:   active [0] { handler=912d2b0 condition=0 pollflags=5 }
16386[8ac52d8]:   calling PR_Poll [active=1 idle=0]
114696[92516d8]: nsSocketTransport::PostEvent [this=9250b28 type=1 status=0 
param=9251628]
114696[92516d8]: nsSocketTransportService::PostEvent [event=9247908]
16386[8ac52d8]: nsSocketTransport::OnSocketEvent [this=9250b28 type=1 status=0 
param=9251628]
16386[8ac52d8]:   MSG_DNS_LOOKUP_COMPLETE
16386[8ac52d8]: nsSocketTransport::InitiateSocket [this=9250b28]
16386[8ac52d8]: nsSocketTransport::BuildSocket [this=9250b28]
16386[8ac52d8]: nsSocketTransportService::AttachSocket [handler=9250b28]
16386[8ac52d8]: nsSocketTransportService::AddToIdleList [handler=9250b28]
16386[8ac52d8]:   active=1 idle=1
16386[8ac52d8]:   advancing to STATE_CONNECTING
16386[8ac52d8]: nsSocketTransport::SendStatus [this=9250b28 status=804b0007]
16386[8ac52d8]:   trying address: 127.0.0.1
16386[8ac52d8]:   active [0] { handler=912d2b0 condition=0 pollflags=5 }
16386[8ac52d8]:   idle [0] { handler=9250b28 condition=0 pollflags=6 }
16386[8ac52d8]: nsSocketTransportService::AddToPollList [handler=9250b28]
16386[8ac52d8]:   active=2 idle=1
16386[8ac52d8]: nsSocketTransportService::RemoveFromIdleList [handler=9250b28]
16386[8ac52d8]:   active=2 idle=0
16386[8ac52d8]:   calling PR_Poll [active=2 idle=0]
16386[8ac52d8]: creating nsSocketTransport @9251c50
16386[8ac52d8]: nsSocketTransport::InitWithConnectedSocket [this=9251c50 
addr=127.0.0.1:34155]
16386[8ac52d8]: nsSocketTransport::PostEvent [this=9251c50 type=2 status=0 param=0]
16386[8ac52d8]: nsSocketTransportService::PostEvent [event=9247908]
16386[8ac52d8]: nsSocketTransport::OnSocketReady [this=9250b28 outFlags=2]
16386[8ac52d8]:   advancing to STATE_TRANSFERRING
16386[8ac52d8]: nsSocketTransport::SendStatus [this=9250b28 status=804b0004]
16386[8ac52d8]:   active [1] { handler=9250b28 condition=0 pollflags=7 }
16386[8ac52d8]:   active [0] { handler=912d2b0 condition=0 pollflags=5 }
16386[8ac52d8]:   calling PR_Poll [active=2 idle=0]
16386[8ac52d8]: nsSocketTransport::OnSocketReady [this=9250b28 outFlags=2]
16386[8ac52d8]: nsSocketOutputStream::OnSocketReady [this=9250c24 cond=0]
16386[8ac52d8]: nsSocketTransport::OnSocketEvent [this=9251c50 type=2 status=0 param=0]
16386[8ac52d8]: nsSocketTransport::InitiateSocket [this=9251c50]
16386[8ac52d8]: nsSocketTransportService::AttachSocket [handler=9251c50]
16386[8ac52d8]: nsSocketTransportService::AddToIdleList [handler=9251c50]
16386[8ac52d8]:   active=2 idle=1
16386[8ac52d8]:   active [1] { handler=9250b28 condition=0 pollflags=5 }
16386[8ac52d8]:   active [0] { handler=912d2b0 condition=0 pollflags=5 }
16386[8ac52d8]:   idle [0] { handler=9251c50 condition=0 pollflags=7 }
16386[8ac52d8]: nsSocketTransportService::AddToPollList [handler=9251c50]
16386[8ac52d8]:   active=3 idle=1
16386[8ac52d8]: nsSocketTransportService::RemoveFromIdleList [handler=9251c50]
16386[8ac52d8]:   active=3 idle=0
16386[8ac52d8]:   calling PR_Poll [active=3 idle=0]
16386[8ac52d8]: nsSocketTransport::OnSocketReady [this=9251c50 outFlags=2]
16386[8ac52d8]: nsSocketOutputStream::OnSocketReady [this=9251d4c cond=0]
16386[8ac52d8]:   active [2] { handler=9251c50 condition=0 pollflags=5 }
16386[8ac52d8]:   active [1] { handler=9250b28 condition=0 pollflags=5 }
16386[8ac52d8]:   active [0] { handler=912d2b0 condition=0 pollflags=5 }
16386[8ac52d8]:   calling PR_Poll [active=3 idle=0]
16384[8994558]: nsSocketTransport::OpenOutputStream [this=9250b28 flags=0]
16384[8994558]: nsSocketTransportService::PostEvent [event=9254c98]
16386[8ac52d8]: nsSocketOutputStream::AsyncWait [this=9250c24]
16386[8ac52d8]:   active [2] { handler=9251c50 condition=0 pollflags=5 }
16386[8ac52d8]:   active [1] { handler=9250b28 condition=0 pollflags=7 }
16386[8ac52d8]:   active [0] { handler=912d2b0 condition=0 pollflags=5 }
16386[8ac52d8]:   calling PR_Poll [active=3 idle=0]
16386[8ac52d8]: nsSocketTransport::OnSocketReady [this=9250b28 outFlags=2]
16386[8ac52d8]: nsSocketOutputStream::OnSocketReady [this=9250c24 cond=0]
16386[8ac52d8]:   active [2] { handler=9251c50 condition=0 pollflags=5 }
16386[8ac52d8]:   active [1] { handler=9250b28 condition=0 pollflags=5 }
16386[8ac52d8]:   active [0] { handler=912d2b0 condition=0 pollflags=5 }
16386[8ac52d8]:   calling PR_Poll [active=3 idle=0]
16384[8994558]: nsSocketTransport::PostEvent [this=9250b28 type=0 status=0 param=0]
16384[8994558]: nsSocketTransportService::PostEvent [event=9254cc8]
16386[8ac52d8]: nsSocketTransport::OnSocketEvent [this=9250b28 type=0 status=0 param=0]
16386[8ac52d8]:   MSG_ENSURE_CONNECT
16386[8ac52d8]:   ignoring redundant event
16386[8ac52d8]:   active [2] { handler=9251c50 condition=0 pollflags=5 }
16386[8ac52d8]:   active [1] { handler=9250b28 condition=0 pollflags=5 }
16386[8ac52d8]:   active [0] { handler=912d2b0 condition=0 pollflags=5 }
16386[8ac52d8]:   calling PR_Poll [active=3 idle=0]
16384[8994558]: nsSocketTransportService::PostEvent [event=92551a8]
16386[8ac52d8]: nsSocketOutputStream::Write [this=9250c24 count=220]
16386[8ac52d8]:   calling PR_Write [count=220]
16386[8ac52d8]:   PR_Write returned [n=220]
16386[8ac52d8]: nsSocketTransport::SendStatus [this=9250b28 status=804b0005]
16386[8ac52d8]: nsSocketOutputStream::AsyncWait [this=9250c24]
16386[8ac52d8]:   active [2] { handler=9251c50 condition=0 pollflags=5 }
16386[8ac52d8]:   active [1] { handler=9250b28 condition=0 pollflags=7 }
16386[8ac52d8]:   active [0] { handler=912d2b0 condition=0 pollflags=5 }
16386[8ac52d8]:   calling PR_Poll [active=3 idle=0]
16386[8ac52d8]: nsSocketTransport::OnSocketReady [this=9250b28 outFlags=2]
16386[8ac52d8]: nsSocketOutputStream::OnSocketReady [this=9250c24 cond=0]
16386[8ac52d8]: nsSocketTransport::OnSocketReady [this=9251c50 outFlags=1]
16386[8ac52d8]: nsSocketInputStream::OnSocketReady [this=9251d30 cond=0]
16386[8ac52d8]:   active [2] { handler=9251c50 condition=0 pollflags=0 }
16386[8ac52d8]: nsSocketTransportService::AddToIdleList [handler=9251c50]
16386[8ac52d8]:   active=3 idle=1
16386[8ac52d8]: nsSocketTransportService::RemoveFromPollList [handler=9251c50]
16386[8ac52d8]:   index=2 mActiveCount=3
16386[8ac52d8]:   active=2 idle=1
16386[8ac52d8]:   active [1] { handler=9250b28 condition=0 pollflags=5 }
16386[8ac52d8]:   active [0] { handler=912d2b0 condition=0 pollflags=5 }
16386[8ac52d8]:   calling PR_Poll [active=2 idle=1]
16384[8994558]: nsSocketTransport::OpenInputStream [this=9251c50 flags=0]
16384[8994558]: nsSocketTransportService::PostEvent [event=924d160]
16386[8ac52d8]: nsSocketInputStream::Read [this=9251d30 count=4096]
16386[8ac52d8]:   calling PR_Read [count=4096]
16386[8ac52d8]:   PR_Read returned [n=220]
16386[8ac52d8]: nsSocketTransport::SendStatus [this=9251c50 status=804b0006]
16386[8ac52d8]: nsSocketInputStream::Read [this=9251d30 count=3876]
16386[8ac52d8]:   calling PR_Read [count=3876]
16386[8ac52d8]:   PR_Read returned [n=-1]
16386[8ac52d8]: nsSocketInputStream::AsyncWait [this=9251d30]
16386[8ac52d8]:   active [1] { handler=9250b28 condition=0 pollflags=5 }
16386[8ac52d8]:   active [0] { handler=912d2b0 condition=0 pollflags=5 }
16386[8ac52d8]:   idle [0] { handler=9251c50 condition=0 pollflags=5 }
16386[8ac52d8]: nsSocketTransportService::AddToPollList [handler=9251c50]
16386[8ac52d8]:   active=3 idle=1
16386[8ac52d8]: nsSocketTransportService::RemoveFromIdleList [handler=9251c50]
16386[8ac52d8]:   active=3 idle=0
16386[8ac52d8]:   calling PR_Poll [active=3 idle=0]
16384[8994558]: nsSocketTransport::PostEvent [this=9251c50 type=0 status=0 param=0]
16384[8994558]: nsSocketTransportService::PostEvent [event=91e64f0]
16386[8ac52d8]: nsSocketTransport::OnSocketEvent [this=9251c50 type=0 status=0 param=0]
16386[8ac52d8]:   MSG_ENSURE_CONNECT
16386[8ac52d8]:   ignoring redundant event
16386[8ac52d8]:   active [2] { handler=9251c50 condition=0 pollflags=5 }
16386[8ac52d8]:   active [1] { handler=9250b28 condition=0 pollflags=5 }
16386[8ac52d8]:   active [0] { handler=912d2b0 condition=0 pollflags=5 }
16386[8ac52d8]:   calling PR_Poll [active=3 idle=0]
16384[8994558]: nsSocketTransport::OpenOutputStream [this=9251c50 flags=0]
16384[8994558]: nsSocketTransportService::PostEvent [event=91ebbd0]
16386[8ac52d8]: nsSocketOutputStream::AsyncWait [this=9251d4c]
16386[8ac52d8]:   active [2] { handler=9251c50 condition=0 pollflags=7 }
16386[8ac52d8]:   active [1] { handler=9250b28 condition=0 pollflags=5 }
16386[8ac52d8]:   active [0] { handler=912d2b0 condition=0 pollflags=5 }
16386[8ac52d8]:   calling PR_Poll [active=3 idle=0]
16386[8ac52d8]: nsSocketTransport::OnSocketReady [this=9251c50 outFlags=2]
16386[8ac52d8]: nsSocketOutputStream::OnSocketReady [this=9251d4c cond=0]
16386[8ac52d8]:   active [2] { handler=9251c50 condition=0 pollflags=5 }
16386[8ac52d8]:   active [1] { handler=9250b28 condition=0 pollflags=5 }
16386[8ac52d8]:   active [0] { handler=912d2b0 condition=0 pollflags=5 }
16386[8ac52d8]:   calling PR_Poll [active=3 idle=0]
16384[8994558]: nsSocketTransport::PostEvent [this=9251c50 type=0 status=0 param=0]
16384[8994558]: nsSocketTransportService::PostEvent [event=91ebc00]
16386[8ac52d8]: nsSocketTransport::OnSocketEvent [this=9251c50 type=0 status=0 param=0]
16386[8ac52d8]:   MSG_ENSURE_CONNECT
16386[8ac52d8]:   ignoring redundant event
16386[8ac52d8]:   active [2] { handler=9251c50 condition=0 pollflags=5 }
16386[8ac52d8]:   active [1] { handler=9250b28 condition=0 pollflags=5 }
16386[8ac52d8]:   active [0] { handler=912d2b0 condition=0 pollflags=5 }
16386[8ac52d8]:   calling PR_Poll [active=3 idle=0]
16384[8994558]: nsSocketTransportService::PostEvent [event=91f5f60]
16386[8ac52d8]: nsSocketOutputStream::Write [this=9251d4c count=221]
16386[8ac52d8]:   calling PR_Write [count=221]
16386[8ac52d8]:   PR_Write returned [n=221]
16386[8ac52d8]: nsSocketTransport::SendStatus [this=9251c50 status=804b0005]
16386[8ac52d8]: nsSocketOutputStream::AsyncWait [this=9251d4c]
16386[8ac52d8]:   active [2] { handler=9251c50 condition=0 pollflags=7 }
16386[8ac52d8]:   active [1] { handler=9250b28 condition=0 pollflags=5 }
16386[8ac52d8]:   active [0] { handler=912d2b0 condition=0 pollflags=5 }
16386[8ac52d8]:   calling PR_Poll [active=3 idle=0]
16386[8ac52d8]: nsSocketTransport::OnSocketReady [this=9250b28 outFlags=1]
16386[8ac52d8]: nsSocketInputStream::OnSocketReady [this=9250c08 cond=0]
16386[8ac52d8]: nsSocketTransportService::PostEvent [event=91f5f60]
16386[8ac52d8]: nsSocketTransport::OnSocketReady [this=9251c50 outFlags=2]
16386[8ac52d8]: nsSocketOutputStream::OnSocketReady [this=9251d4c cond=0]
16386[8ac52d8]:   active [2] { handler=9251c50 condition=0 pollflags=5 }
16386[8ac52d8]:   active [1] { handler=9250b28 condition=0 pollflags=0 }
16386[8ac52d8]: nsSocketTransportService::AddToIdleList [handler=9250b28]
16386[8ac52d8]:   active=3 idle=1
16386[8ac52d8]: nsSocketTransportService::RemoveFromPollList [handler=9250b28]
16386[8ac52d8]:   index=1 mActiveCount=3
16386[8ac52d8]:   active=2 idle=1
16386[8ac52d8]:   active [0] { handler=912d2b0 condition=0 pollflags=5 }
16386[8ac52d8]:   calling PR_Poll [active=2 idle=1]
16386[8ac52d8]: nsSocketInputStream::Read [this=9250c08 count=4096]
16386[8ac52d8]:   calling PR_Read [count=4096]
16386[8ac52d8]:   PR_Read returned [n=221]
16386[8ac52d8]: nsSocketTransport::SendStatus [this=9250b28 status=804b0006]
16386[8ac52d8]: nsSocketInputStream::Read [this=9250c08 count=3875]
16386[8ac52d8]:   calling PR_Read [count=3875]
16386[8ac52d8]:   PR_Read returned [n=-1]
16386[8ac52d8]: nsSocketInputStream::AsyncWait [this=9250c08]
16386[8ac52d8]:   active [1] { handler=9251c50 condition=0 pollflags=5 }
16386[8ac52d8]:   active [0] { handler=912d2b0 condition=0 pollflags=5 }
16386[8ac52d8]:   idle [0] { handler=9250b28 condition=0 pollflags=5 }
16386[8ac52d8]: nsSocketTransportService::AddToPollList [handler=9250b28]
16386[8ac52d8]:   active=3 idle=1
16386[8ac52d8]: nsSocketTransportService::RemoveFromIdleList [handler=9250b28]
16386[8ac52d8]:   active=3 idle=0
16386[8ac52d8]:   calling PR_Poll [active=3 idle=0]
16384[8994558]: nsSocketTransportService::PostEvent [event=91f5f60]
16386[8ac52d8]: nsSocketOutputStream::CloseWithStatus [this=9251d4c reason=0]
16386[8ac52d8]: nsSocketOutputStream::CloseWithStatus [this=9251d4c reason=80470002]
16386[8ac52d8]: nsSocketTransport::OnMsgOutputClosed [this=9251c50 reason=80470002]
16386[8ac52d8]: nsSocketOutputStream::OnSocketReady [this=9251d4c cond=80470002]
16386[8ac52d8]: nsSocketTransportService::PostEvent [event=91f60b8]
16386[8ac52d8]:   active [2] { handler=9250b28 condition=0 pollflags=5 }
16386[8ac52d8]:   active [1] { handler=9251c50 condition=0 pollflags=5 }
16386[8ac52d8]:   active [0] { handler=912d2b0 condition=0 pollflags=5 }
16386[8ac52d8]:   calling PR_Poll [active=3 idle=0]
16386[8ac52d8]:   active [2] { handler=9250b28 condition=0 pollflags=5 }
16386[8ac52d8]:   active [1] { handler=9251c50 condition=0 pollflags=5 }
16386[8ac52d8]:   active [0] { handler=912d2b0 condition=0 pollflags=5 }
16386[8ac52d8]:   calling PR_Poll [active=3 idle=0]
16384[8994558]: nsSocketTransportService::PostEvent [event=91f60b8]
16386[8ac52d8]: nsSocketInputStream::CloseWithStatus [this=9251d30 reason=80470002]
16386[8ac52d8]: nsSocketTransport::OnMsgInputClosed [this=9251c50 reason=80470002]
16386[8ac52d8]: nsSocketInputStream::CloseWithStatus [this=9251d30 reason=80470002]
16386[8ac52d8]:   active [2] { handler=9250b28 condition=0 pollflags=5 }
16386[8ac52d8]:   active [1] { handler=9251c50 condition=80470002 pollflags=5 }
16386[8ac52d8]: nsSocketTransportService::DetachSocket [handler=9251c50]
16386[8ac52d8]: nsSocketTransport::OnSocketDetached [this=9251c50 cond=80470002]
16386[8ac52d8]: nsSocketTransport::RecoverFromError [this=9251c50 state=4 
cond=80470002]
16386[8ac52d8]: nsSocketInputStream::OnSocketReady [this=9251d30 cond=80470002]
16386[8ac52d8]: nsSocketTransportService::PostEvent [event=91f60b8]
16386[8ac52d8]: nsSocketOutputStream::OnSocketReady [this=9251d4c cond=80470002]
16386[8ac52d8]: nsSocketTransport: calling PR_Close [this=9251c50]
16386[8ac52d8]: nsSocketTransportService::RemoveFromPollList [handler=0]
16386[8ac52d8]:   index=1 mActiveCount=3
16386[8ac52d8]:   active=2 idle=0
16386[8ac52d8]:   active [0] { handler=912d2b0 condition=0 pollflags=5 }
16386[8ac52d8]:   calling PR_Poll [active=2 idle=0]
16386[8ac52d8]: nsSocketTransport::OnSocketReady [this=9250b28 outFlags=1]
16386[8ac52d8]: nsSocketInputStream::OnSocketReady [this=9250c08 cond=0]
16386[8ac52d8]: nsSocketTransportService::PostEvent [event=91f5f60]
16386[8ac52d8]: nsSocketInputStream::Read [this=9250c08 count=3875]
16386[8ac52d8]:   calling PR_Read [count=3875]
16386[8ac52d8]:   PR_Read returned [n=0]
16386[8ac52d8]: nsSocketInputStream::CloseWithStatus [this=9250c08 reason=0]
16386[8ac52d8]: nsSocketInputStream::CloseWithStatus [this=9250c08 reason=80470002]
16386[8ac52d8]: nsSocketTransport::OnMsgInputClosed [this=9250b28 reason=80470002]
16386[8ac52d8]: nsSocketInputStream::OnSocketReady [this=9250c08 cond=80470002]
16386[8ac52d8]: nsSocketTransportService::PostEvent [event=91f60b8]
16386[8ac52d8]:   active [1] { handler=9250b28 condition=0 pollflags=0 }
16386[8ac52d8]: nsSocketTransportService::AddToIdleList [handler=9250b28]
16386[8ac52d8]:   active=2 idle=1
16386[8ac52d8]: nsSocketTransportService::RemoveFromPollList [handler=9250b28]
16386[8ac52d8]:   index=1 mActiveCount=2
16386[8ac52d8]:   active=1 idle=1
16386[8ac52d8]:   active [0] { handler=912d2b0 condition=0 pollflags=5 }
16386[8ac52d8]:   calling PR_Poll [active=1 idle=1]
16386[8ac52d8]:   active [0] { handler=912d2b0 condition=0 pollflags=5 }
16386[8ac52d8]:   idle [0] { handler=9250b28 condition=0 pollflags=0 }
16386[8ac52d8]:   calling PR_Poll [active=1 idle=1]
16384[8994558]: nsSocketInputStream::CloseWithStatus [this=9251d30 reason=80470002]
16384[8994558]: nsSocketOutputStream::CloseWithStatus [this=9251d4c reason=80470002]
16384[8994558]: nsSocketTransportService::PostEvent [event=91e9550]
16386[8ac52d8]: nsSocketOutputStream::CloseWithStatus [this=9250c24 reason=0]
16386[8ac52d8]: nsSocketOutputStream::CloseWithStatus [this=9250c24 reason=80470002]
16386[8ac52d8]: nsSocketTransport::OnMsgOutputClosed [this=9250b28 reason=80470002]
16386[8ac52d8]:   active [0] { handler=912d2b0 condition=0 pollflags=5 }
16386[8ac52d8]:   idle [0] { handler=9250b28 condition=80470002 pollflags=0 }
16386[8ac52d8]: nsSocketTransportService::DetachSocket [handler=9250b28]
16386[8ac52d8]: nsSocketTransport::OnSocketDetached [this=9250b28 cond=80470002]
16386[8ac52d8]: nsSocketTransport::RecoverFromError [this=9250b28 state=4 
cond=80470002]
16386[8ac52d8]: nsSocketInputStream::OnSocketReady [this=9250c08 cond=80470002]
16386[8ac52d8]: nsSocketOutputStream::OnSocketReady [this=9250c24 cond=80470002]
16386[8ac52d8]: nsSocketTransportService::PostEvent [event=91e9550]
16386[8ac52d8]: nsSocketTransport: calling PR_Close [this=9250b28]
16386[8ac52d8]: nsSocketTransportService::RemoveFromIdleList [handler=0]
16386[8ac52d8]:   active=1 idle=0
16386[8ac52d8]:   calling PR_Poll [active=1 idle=0]
16386[8ac52d8]:   active [0] { handler=912d2b0 condition=0 pollflags=5 }
16386[8ac52d8]:   calling PR_Poll [active=1 idle=0]
16384[8994558]: destroying nsSocketTransport @9251c50
16384[8994558]: destroying nsSocketTransport @9250b28
16384[8994558]: nsSocketTransportService::PostEvent [event=91e1d20]
16386[8ac52d8]:   active [0] { handler=912d2b0 condition=0 pollflags=5 }
16386[8ac52d8]:   calling PR_Poll [active=1 idle=0]

Re: stream reading inconsistency

Reply via email to