121314 - ftp upload waits until mozilla exit

Status: VERIFIED FIXED

(Core Graveyard :: Networking: FTP, defect)

Description

[Kathleen :Brade]

For some reason, uploading a file via ftp waits until mozilla exits to actually
write the data.  The file does seem to get zeroed immediately but the data can't
be retrieved on another computer until the uploading mozilla app has exited. 
Changing the pref for network.ftp.idleConnectionTimeout to 10 didn't help.

At this time, I don't have a patch which can be applied to mozilla to recreate
this but the majority of the patch is in bug 120659.

I will attach a log in a moment.

Comment 1

[Kathleen :Brade]

Attachment: log file

note: this is what I did to generate this log
 * launch mozilla
 * open web location for new Composer window with ftp url
 * type some text to enable publish menu item
 * choose File > Publish
 * in browser, load ftp url for parent directory
 * quit

Comment 2

[Bradley Baetz (:bbaetz)]

According to the log you loaded ftp://bubblegum.mcom.com/cmanske/sss.html, then
stored to it. Is that correct?

I don't see "load ftp url for parent directory" in there, although that is
cached, so it may not me. Theres a macsockopt assertion - is that normal? Can I
get a packet log?

Comment 3

[Kathleen :Brade]

update:  ftp upload worked fine (immediately) on a Solaris box within my local
network.  The ftp server I was testing with earlier was an IIS server.

At this time, I'm not able to get a packet log because I am using SERA to
connect behind the firewall.

regarding the log and what you see there:
  Composer first loads the ftp url so you can edit it
  Composer then tries to publish it (STOR)
so yes, that is correct.

The assertion is something I have been seeing for quite some time; I see it when
I view ftp urls in the browser and load them in Composer.  I don't think I see
this assertion when I push up the file.

Comment 4

[Bradley Baetz (:bbaetz)]

Just to summarise what I said to brade on IRC, its possible that this is a
server problem, where mozilla does something different to ns4.

benc is on sabbatical, I believe - Tom, can you a log of ns4 uploading to
bubblegum via ftp, and attach it?

Comment 5

[Bradley Baetz (:bbaetz)]

Any update on this? Tom?

Comment 6

[Kathleen :Brade]

Attachment: 4.x publishing behavior

This attachment is what 4.x does; it correctly publishes the file to bubblegum

Comment 7

[Kathleen :Brade]

Attachment: 6.x publishing behavior (wrong)

This attachment is what 6.x did (as of last week).
You'll notice that the STOR command is issued after the data is sent.
I re-logged several times and it was always the same.  
I put breakpoints in *_Stor and the data was sent before that breakpoint was
hit.

Comment 8

[Bradley Baetz (:bbaetz)]

Is there an ms ftp server I can get access to?

Comment 9

[Syd Logan]

only nsbeta1+ bugs can have milestones, resetting to ---

Comment 10

[Kathleen :Brade]

We have to have this for publishing--nsbeta1+/1.0
Charley hasn't seen problems on Windows so maybe it's a mac-specific problem?

Comment 11

[Mike Lee]

I see it on Windows, the STOR holds the ftp open.

Comment 12

[Bradley Baetz (:bbaetz)]

Attachment: possible patch

OK, try this. this should fix the problem of sending data before we get the
STOR response. Can you please let me know if this fixes that problem, even if
it doesn't fix the actual bug?

Comment 13

[Bradley Baetz (:bbaetz)]

brade: Did the patch help?

Comment 14

[Kathleen :Brade]

I tried publishing with that patch but it doesn't publish at all (even after
quitting mozilla).  Unfortunately, I can't easily get an ftp log right now to
see where the failure is occurring.

Comment 15

[Charles Manske]

I tried this patch as well (Windows 2K), and unfortunately it breaks uploading 
totally for me too :( 
As brade said, FTP upload has been working for me, sort of:
The file does upload completely, but I do not see the final 
nsIWebProgressListener::onStateChange notification with 
(STATE_STOP | STATE_IS_NETWORK), which I assume is how we are supposed to tell if
upload is completed. 
I'll attached logs soon.

Comment 16

[Charles Manske]

Attachment: FTP log with the patch applied (upload failed)

Comment 17

[Charles Manske]

Attachment: FTP-log: Windows, file uploaded, but no STATE_STOP feedback

This is with trunk tree on 2/20/02, no patch applied

Comment 18

[Bradley Baetz (:bbaetz)]

Thats not this bug... Let me look into why the patch breaks stuff, though. It
definately worked for me.

Comment 19

[Bradley Baetz (:bbaetz)]

Actually, this is the same bug. We never close the data pipe after we've
finished with it, so teh server thinks that we're still going, and never sends
the completion response, so we think its still going, and never send the stop
notification.

Comment 20

[Bradley Baetz (:bbaetz)]

OK, the problem is that nsStorageStream::ReadSegments doesn't check for eof. 

<darin> i think some code in nsStorageStream needs to change to recognize
nsIOutputStream::Close()
<darin> and translate that to cause nsiInputStream::Read to return NS_OK w/ zero
bytes read when at the end of the buffer
<darin> the calling code should close/release its nsIOutpuStream that it got
from nsIStorageStream::NewOutpuTStream
<darin> *before* it gives out an upload stream
<darin> i think this is brade's bug

Because of this, we don't get teh onstop, so we don't tell anyone about it. That
is cmanske's problem.

I'm not sure if this is sufficient to fix the original issue - I may need to
cancel the request (and set the transport to not be reused?) from onstop. I
can't test that until I actually get the onstop, though.

->brade, -qawanted

Comment 21

[Darin Fisher]

brade: this definitely has two parts to it.

1) nsStorageStream is designed to allow one guy to write while to another guy is
reading.  if the reader catches up to the writer, then the reader sees a
NS_BASE_STREAM_WOULD_BLOCK error.  however, if there is no writer, then when the
reader reaches the end of the stream, we can return NS_OK to indicate EOF.

2) in order for this to work correctly, the owner of the storage stream's output
stream has to release it (or close it).

let me know if you need any help w/ the storage stream changes.

Comment 22

[Kathleen :Brade]

*** Bug 126261 has been marked as a duplicate of this bug. ***

Comment 23

[Kathleen :Brade]

I will work on these stream issues but what about the original reason I filed
this bug:
  STOR command is sent *AFTER* data is sent?

Comment 24

[Kathleen :Brade]

Attachment: my understanding of desired fixes

Comment 25

[Bradley Baetz (:bbaetz)]

I don't think that that is the issue - the connection is already open, so tcp
will handle buffering until the server reads from it. I think that your fix will
fix it. I'll test it in a bit. 

Comment 26

[Darin Fisher]

brade: your changes look good to me, except shouldn't StartUpload take a
nsIStorageStream parameter instead of a nsIOutputStream?  it seems to QI to
nsIStorageStream immediately, and it also seems odd to close a stream and then
pass the same stream to StartUpload.  how about doing the QI outside of the call
to StartUpload?

Comment 27

[Kathleen :Brade]

Attachment: patch with changes suggested by Darin

Comment 28

[Adam Lock]

Comment on attachment 70942 [details] [diff] [review]
patch with changes suggested by Darin

r=adamlock

Comment 29

[Charles Manske]

Tested by me with Composer publishing, and we now get the correct "end of file
transfer" messages. Hurray!

Comment 30

[Darin Fisher]

Comment on attachment 70942 [details] [diff] [review]
patch with changes suggested by Darin

sr=darin (nice job fixing this one!)

Comment 31

[Mike Shaver (:shaver emeritus)]

Comment on attachment 70942 [details] [diff] [review]
patch with changes suggested by Darin

a=shaver for 0.9.9, nice work all around!

Comment 32

[Kathleen :Brade]

fix checked in

Comment 33

[benc]

Since this is a transport problem I should be able to see, I'm keeping this for
verification.

Comment 34

[benc]

VERIFIED:
I've been running some functional tests (which involve using a lot of netstat
output) and publishing while using composer at the same time, and I don't see this.

I'll talk to sujay about adding some checks in his composer functional tests
because I don't test composer on a regular basis.

Comment 35

[Legacy TBPL/Treeherder Robot]

submit_timestamp: 2014-10-15T12:28:57
log: https://treeherder.allizom.org/ui/logviewer.html#?repo=try&job_id=1991120
repository: try
who: cdawson[at]mozilla[dot]com
machine: t-xp32-ix-050
buildname: Windows XP 32-bit try opt test mochitest-1
revision: 5b4636011be6

Return code: 1