595785 - Getting a download's nsIChannel appears unreliable

Status: RESOLVED FIXED

(Toolkit :: Downloads API, defect)

Description

[Matthew Turnbull [Bluefang]]

User-Agent:       Mozilla/5.0 (X11; Linux x86_64; rv:2.0b6pre) Gecko/20100912 Firefox/4.0b6pre
Build Identifier: 

This is somewhat of a continuation of Bug 593553.

I'm using an nsIDownloadProgressListener's onStateChange to obtain the modification time from the request, and onDownloadStateChange to update the downloaded file.

However, sometimes onStateChange is passed null instead of an nsIChannel. For example, as far as my testing goes:

http://b.fanfiction.net/static/ficons/feed.png
This has a valid nsIChannel for both STATE_START and STATE_STOP

ftp://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/latest-mozilla-central/firefox-4.0b6pre.en-US.linux-x86_64.tar.bz2
Only has a valid nsIChannel on STATE_START

ftp://ftp.mozilla.org/pub/mozilla.org/ls-lR.gz
Gets no valid nsIChannel

I also added a debug message for onProgressChange as well, and it also appears to be unreliable.

I would think that the nsDownload, or what ever is generating these events, would be able to hang onto the nsIChannel long enough to dispatch and process these events.

Reproducible: Always

Comment 1

[Shawn Wilsher :sdwilsh]

All we do is pass whatever we are given:
http://mxr.mozilla.org/mozilla-central/source/toolkit/components/downloads/src/nsDownloadManager.cpp#2534

Maybe it has to do with the content type?  It's not clear to me when we are supposed to be able to QI the nsIWebProgress to an nsIChannel

Comment 2

[Boris Zbarsky [:bzbarsky]]

You mean QI the nsIRequest, right?  Should generally work.

Whoever can reproduce this problem (given that comment 0 doesn't actually have useful STR), can you just set a breakpoint in your code and examine what the stack looks like, who calls you, and how they decide what to pass for the nsIRequest?

Comment 3

[Matthew Turnbull [Bluefang]]

Steps to Reproduce:
1. Install the extension
2. In extension preferences, change logging verbosity to Debug
3. Open the error console
4. Clear the error console
5. Download http://b.fanfiction.net/static/ficons/feed.png
6. Download ftp://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/latest-mozilla-central/firefox-4.0b6pre.en-US.linux-x86_64.tar.bz2
7. Download ftp://ftp.mozilla.org/pub/mozilla.org/ls-lR.gz

The log events you're interested in looking at are:

PDMTS: Network status changed - 0x50001 (ERR: 0)

and

PDMTS: Network status changed - 0x50010 (ERR: 0)

Some downloads have both, some only have the first, and some have neither.

Comment 4

[Matthew Turnbull [Bluefang]]

Here are my results



PDMTS: Download status changed - 5
	/tmp/feed.png
 ----------
PDMTS: Network status changed - 0x50001 (ERR: 0)
	http://b.fanfiction.net/static/ficons/feed.png
 ----------
PDMTS: File downloading via HTTP://
	/tmp/feed.png
 ----------
PDMTS: Download status changed - 0
	/tmp/feed.png
 ----------
PDMTS: Download status changed - 1
	/tmp/feed.png
 ----------
PDMTS: Download finished, updating timestamp
	/tmp/feed.png
 ----------
PDMTS: Last modified time now Wed, 17 Mar 2010 22:37:00 GMT
	/tmp/feed.png
 ----------
PDMTS: Network status changed - 0x50010 (ERR: 0)
	http://b.fanfiction.net/static/ficons/feed.png



PDMTS: Download status changed - 5
	/tmp/firefox-4.0b6pre.en-US.linux-x86_64.tar.bz2
 ----------
PDMTS: Network status changed - 0x50001 (ERR: 0)
	ftp://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/latest-mozilla-central/firefox-4.0b6pre.en-US.linux-x86_64.tar.bz2
 ----------
PDMTS: File downloading via FTP://
	/tmp/firefox-4.0b6pre.en-US.linux-x86_64.tar.bz2
 ----------
PDMTS: Download status changed - 0
	/tmp/firefox-4.0b6pre.en-US.linux-x86_64.tar.bz2
 ----------
PDMTS: Download status changed - 1
	/tmp/firefox-4.0b6pre.en-US.linux-x86_64.tar.bz2
 ----------
PDMTS: Download finished, updating timestamp
	/tmp/firefox-4.0b6pre.en-US.linux-x86_64.tar.bz2
 ----------
PDMTS: Last modified time now Mon, 13 Sep 2010 08:26:53 GMT
	/tmp/firefox-4.0b6pre.en-US.linux-x86_64.tar.bz2



PDMTS: Download status changed - 5
	/tmp/ls-lR.gz
 ----------
PDMTS: Download status changed - 0
	/tmp/ls-lR.gz
 ----------
PDMTS: Download status changed - 1
	/tmp/ls-lR.gz
 ----------
PDMTS: Download finished, updating timestamp
	/tmp/ls-lR.gz
 ----------
PDMTS: Last modified time unavailable
	/tmp/ls-lR.gz

Comment 5

[Matthew Turnbull [Bluefang]]

Here's the relevant listener, so you don't need to look in the extension. In testing, I put a debug statement in before the first return and I did verify that "req" is null.

onStateChange: function(prog, req, flags, status, dl)
{
  // We only want to look at the URI we know about
  // Basically, ignore "Web page, complete" downloads
  // Also handle case where req is null
  if(!(req instanceof CI.nsIChannel)
  || !(dl.source.equals(req.URI) || dl.source.equals(req.originalURI)))
  {
	return;
  }

  this.log(LOG_DEBUG, "net.stat", [flags.toString(16), status], req.URI.spec);

  // Only rely on STATE_START and STATE_STOP... and STATE_STOP might come
  // after DOWNLOAD_FINISHED. So wait for STATE_START.
  if(!(flags & CI.nsIWebProgressListener.STATE_START))
  {
	return;
  }

  ...
}

Comment 6

[Boris Zbarsky [:bzbarsky]]

Ok.  What are you adding that listener in comment 5 to?

Comment 7

[Matthew Turnbull [Bluefang]]

It's an nsIDownloadProgressListener registered with @mozilla.org/download-manager;1 (via addListener).

Comment 8

[Boris Zbarsky [:bzbarsky]]

OK.

Shawn, what's nsDownloadManager registering with to get its web progress notifications?

Comment 9

[Boris Zbarsky [:bzbarsky]]

And seriously, someone should do what I suggest in comment 2.  I can try to get to it, but it might not happen this week.... and it really can be done by anyone with a debug build.

Comment 10

[Shawn Wilsher :sdwilsh]

(In reply to comment #8)
> Shawn, what's nsDownloadManager registering with to get its web progress
> notifications?
Assuming we are going through nsExternalHelperAppService, we do so here:
http://mxr.mozilla.org/mozilla-central/source/uriloader/exthandler/nsExternalHelperAppService.cpp#1288

Comment 11

[Boris Zbarsky [:bzbarsky]]

Oh, I see.  The external helper app service definitely sends state notifications with a null request.  See the end of ExecuteDesiredAction.  By that point, mRequest is null.  I suppose we could try rejiggering that code to hold on to it until then, instead....

Comment 12

[Matthew Turnbull [Bluefang]]

That's interesting. I hadn't realized there were [at least] 2 separate download paths. I've done a bit more poking around, and so far I've found:


* Downloads that go through internalSave (saveURL, saveImageURL, saveDocument) in chrome://global/content/contentAreaUtils.js use an nsIWebBrowserPersist. The user picks the target location, it's added to the download manager, and then the download is started.

These downloads appear to reliably get a valid nsIChannel on STATE_START. However, getting an nsIChannel on STATE_STOP is unreliable.


* Downloads that go through nsExternalHelperAppService look to be in-progress as soon as they're clicked on. They are added to the download manager once the user chooses the desired action and/or download directory.

If the download completes before it's added to the download manager, the nsIChannel will be null on STATE_START. And from the implementation, it looks like it's always null on STATE_STOP.


So, at the very least, it looks like the nsExternalHelperAppService needs to be a bit more intelligent about how long it hangs onto an nsIChannel.

Comment 13

[Andrey Ivanov]

(In reply to comment #12)

Is this bug still actual? I found that nsExternalHelperAppService has been updated to hold nsIChannel. I tried to save all three URLs from comment #3 and add-in updated timestamps correctly for each file. Checked with Firefox 4 only.

Comment 14

[Matthew Turnbull [Bluefang]]

I still see problems when the download finishes before it's added to the download manager. The nsiIRequest for STATE_START is still null.

Comment 15

[Grigory Mozhaev]

Confirmed. The problem still exists. I'm looking for solution.

Comment 16

[Grigory Mozhaev]

Here the explanation of the problem. We have 2 ways to download a file. 
1. Use "Save as.."
2. Click on file and wait for helper dialog to appear.

1 one works perfectly, 2 has a problem with nsiIRequest = null. This is related to dialog modality. Let's review the functions call chain for both cases:

1. "Save as..." case:

***** OnStartRequest()
SaveToDisk
PromptForSaveToFile
(Here we have "Save as.." dialog and choose file destination)
CreateProgressListener()
InitializeDownload
PDMTS: Download status changed - 5
        /tmp/index.html.en
CreateProgressListener()
PDMTS: Network status changed - 0x50001 (ERR: 0)
        http://localhost/index.html.en
PDMTS: File downloading via HTTP://
        /tmp/index.html.en
***** OnStartRequest() end
PDMTS: Download status changed - 0
        /tmp/index.html.en
***** OnStopRequest() (Note! AFTER THIS CALL nsiRequest is NULL, but we don't need it since dowload process has been  started)
ExecuteDesiredAction
PDMTS: Download status changed - 1
        /tmp/index.html.en
PDMTS: Download finished, updating timestamp
        /tmp/index.html.en
PDMTS: Last modified time now Sun, 31 Dec 2006 11:42:37 GMT
        /tmp/index.html.en
***** OnStopRequest() end

2. "Click on file and wait for helper dialog to appear" case:
***** OnStartRequest()
***** OnStartRequest() end
***** OnStopRequest()
ExecuteDesiredAction
***** OnStopRequest() end (Note! AFTER THIS CALL nsiRequest is NULL, but we STILL NEED it since download process wasn't started)
ExecuteDesiredAction
Heights: 323, 293
(Here we have helper dialog and choose 'to save' file or to 'open it with')
SaveToDisk
PromptForSaveToFile
CreateProgressListener()
InitializeDownload
PDMTS: Download status changed - 5
        /misc/archive/downloads/unsorted/index.html(1).de
CreateProgressListener()
ExecuteDesiredAction
PDMTS: Download status changed - 0
        /misc/archive/downloads/unsorted/index.html(1).de
PDMTS: Download status changed - 1
        /misc/archive/downloads/unsorted/index.html(1).de
PDMTS: Download finished, updating timestamp
        /misc/archive/downloads/unsorted/index.html(1).de
PDMTS: Last modified time unavailable
        /misc/archive/downloads/unsorted/index.html(1).de

Why second case doesn't work like first one? Because helper dialog isn't in modal mode and I believe it can't be turned into modal mode. Thus the possible solution I see to keep nsiRequest alive after OnStopRequest (or store it in other class member variable) in case if helper dialog is created.

Comment 17

[Grigory Mozhaev]

Attachment: Fixes nsiRequest null for STATE_START

Here is the patch that makes it work as expected. 

Don't know to who ask to review (supereview) it, please let me know if you know.

Regards,
Grigory

Comment 18

[Shawn Wilsher :sdwilsh]

Comment on attachment 517251 [details] [diff] [review]
Fixes nsiRequest null for STATE_START

Probably me.  Likely be about a week before I can get to it, however.

Comment 19

[Shawn Wilsher :sdwilsh]

This patch doesn't cover all the cases mentioned in comment 12 thought, right?  It only deals with the second case.

Also, this patch has very little context, which makes it difficult to review.  Could you create it as per the instructions here please: https://developer.mozilla.org/en/Creating_a_patch

Comment 20

[Grigory Mozhaev]

> This patch doesn't cover all the cases mentioned in comment 12 thought, right? 

It's because comment 12 is about nsiChannel (which is fixed, according to comment 13), but this patch fixes a different problem related to nsiRequest.

> Also, this patch has very little context, which makes it difficult to review. 
Could you create it as per the instructions here please:

I have created this patch for 'default' branch of repository with 'hg diff' command in 'mozilla-central' directory.

What does mean 'little context'? What should I change to make right context patch?

Anyway, if you review the patch content you will see - here is only about 5 lines of changes in 2 files, so it can be easy doable manually or let me know how to produce right patch.

Comment 21

[Shawn Wilsher :sdwilsh]

(In reply to comment #20)
> I have created this patch for 'default' branch of repository with 'hg diff'
> command in 'mozilla-central' directory.
The wiki page I linked to says to run 'hg diff -U 8 -p'.  -U 8 means there are 8 lines of context for each diff section, and -p says to include function headers.  Line numbers aren't usually terribly reliable.

Comment 22

[Grigory Mozhaev]

Thank you for explanations. I will make a new patch in few minutes.

Comment 23

[Grigory Mozhaev]

Attachment: This patch fixes nsiRequest = null problem for STATE_START

Here is the patch.

Comment 24

[Shawn Wilsher :sdwilsh]

(In reply to comment #20)
> It's because comment 12 is about nsiChannel (which is fixed, according to
> comment 13), but this patch fixes a different problem related to nsiRequest.
So this is dealing with the issue mentioned in comment 14 now, correct?

Comment 25

[Grigory Mozhaev]

That's right!

Comment 26

[Shawn Wilsher :sdwilsh]

Comment on attachment 517774 [details] [diff] [review]
This patch fixes nsiRequest = null problem for STATE_START

>+++ b/uriloader/exthandler/nsExternalHelperAppService.cpp	Tue Mar 08 20:28:22 2011 +0300
> NS_IMETHODIMP nsExternalAppHandler::OnStopRequest(nsIRequest *request, nsISupports *aCtxt, 
>                                                   nsresult aStatus)
> {
>   mStopRequestIssued = PR_TRUE;
>-  mRequest = nsnull;
>+
>+  if (mKeepRequestAlive)
>+    mKeepRequestAlive = PR_FALSE;
No reason to flip this here; just null out mRequest if mKeepRequestAlive is false.

r=sdwilsh with that change.  bz should probably look at this too since I'm a bit rusty with this code.

Comment 27

[Boris Zbarsky [:bzbarsky]]

Comment on attachment 517774 [details] [diff] [review]
This patch fixes nsiRequest = null problem for STATE_START

r=me.  Thanks for the patch!

Shawn, are you going to push this when the tree reopens, or should I?

Comment 28

[Grigory Mozhaev]

(In reply to comment #26)
> Comment on attachment 517774 [details] [diff] [review]
> This patch fixes nsiRequest = null problem for STATE_START
> 
> >+++ b/uriloader/exthandler/nsExternalHelperAppService.cpp	Tue Mar 08 20:28:22 2011 +0300
> > NS_IMETHODIMP nsExternalAppHandler::OnStopRequest(nsIRequest *request, nsISupports *aCtxt, 
> >                                                   nsresult aStatus)
> > {
> >   mStopRequestIssued = PR_TRUE;
> >-  mRequest = nsnull;
> >+
> >+  if (mKeepRequestAlive)
> >+    mKeepRequestAlive = PR_FALSE;
> No reason to flip this here; just null out mRequest if mKeepRequestAlive is
> false.
> 
> r=sdwilsh with that change.  bz should probably look at this too since I'm a
> bit rusty with this code.
You are right. I recheck this code, this part can be reduced. Will provide patch without it right now.

Comment 29

[Grigory Mozhaev]

Attachment: This patch fixes nsiRequest = null problem for STATE_START

This is the same patch, but the part:

+  if (mKeepRequestAlive)
+    mKeepRequestAlive = PR_FALSE;
+  else
+    mRequest = nsnull;

reduced to:

+  if (!mKeepRequestAlive)
+    mRequest = nsnull;

Comment 30

[Boris Zbarsky [:bzbarsky]]

Comment on attachment 518270 [details] [diff] [review]
This patch fixes nsiRequest = null problem for STATE_START

r=me again (though note that the places where we null out mRequest we don't need to null-check it.  If it's already null and we set it to null again that's ok!

Comment 31

[Grigory Mozhaev]

Attachment: This patch fixes nsiRequest = null problem for STATE_START

That's right! How did I missed it? It's just a habit to check :-) Last patch is for your review.

Comment 32

[Shawn Wilsher :sdwilsh]

Comment on attachment 518492 [details] [diff] [review]
This patch fixes nsiRequest = null problem for STATE_START

r=sdwilsh

Comment 33

[Shawn Wilsher :sdwilsh]

(In reply to comment #27)
> Shawn, are you going to push this when the tree reopens, or should I?
I don't yet have a good way to track bugs to do that, so if you do, please, by all means, land it.

Comment 34

[Boris Zbarsky [:bzbarsky]]

OK.  Taking bug temporarily so I can track it.  Will reassign when I land the patch.

Comment 35

[Boris Zbarsky [:bzbarsky]]

Pushed http://hg.mozilla.org/mozilla-central/rev/1ceb81527a08

Comment 36

[Grigory Mozhaev]

Thanks!

Comment 37

[Boris Zbarsky [:bzbarsky]]

Thank you for writing the patch!