335794 - Download rate is completely screwed since caching proxy added

Status: RESOLVED FIXED

(mozilla.org Graveyard :: Server Operations, task)

Description

[James Ross]

Ever since the caching proxy was added to Addons, the download count updating has been completely hosed.

http://twpol.dyndns.org/mozilla/extensions/stats/?group=2;m=dlsamp;range=0+1

Instead of FlashGot getting 1000 - 1300 downloads/hour, it's barely counting 30/hour. That is not right. Notice that it has killed all the extensions listed, it's a global problem.

Top suspect for me is install.php being cached - it's the page that counts the downloads. If it's being cached (it doesn't seem to set any dont-cache-me headers) it would indeed screw up the download count.

Comment 1

[Michael Morgan [:morgamic]]

This was the result of a hardware test.  The IPs are not variable, thus the rate-limiting is causing most downloads to go unlogged.  My guess is that since it's all the same IP, the only way something can get recorded is if:
a) it's a different useragent
AND
b) it's been > 10 minutes since the last instance of that UA

That has produced some interesting stats, obviously.

The challenge:
a) How do we rate-limit install hits if IP is not available?
b) What other env vars are unique per client that would persist?
c) Do _any_ env vars persist at all?

Comment 2

[James Ross]

Is there any reason HTTP_X_FORWARDED_FOR isn't working? (I guess it's not working because that var is Apache-proxy-specific or something)

What proxy is being used, anyway? (without knowing the setup, no-one can help)

Comment 3

[matthew zeier [:mrz]]

(In reply to comment #0)
> Top suspect for me is install.php being cached - it's the page that counts the
> downloads. If it's being cached (it doesn't seem to set any dont-cache-me
> headers) it would indeed screw up the download count.

That's true - install.php was in the cache.   If I'm reading the cache object correctly, it wasn't seeing any "don't cache me" header. 

I've added a NOCACHE rule for any URI containing "install.php" and flushed that from the cache.  

> show cache object -url /install.php -host addons.mozilla.org -port 443
        Integrated cache object statistics:
        Response size: 297 bytes
        Response header size: 297 bytes
        Response status code: 302
        ETag: KXJIGODOBMVPSNQ
        Last-Modified: NONE
        Cache-control: NONE
        Date: Fri, 28 Apr 2006 11:43:21 GMT
        Contentgroup: DEFAULT
        Complex match: NO
        URL: /install.php
        Host: addons.mozilla.org
        Host port: 443
        Destination IP: 10.251.0.75
        Destination port: 443
        Request time: 21367 secs ago
        Response time: started arriving 21367 secs ago
        Age: 21430 secs
        Expiry: Already expired
        Prefetch: period passed
        Current readers: 0
        Current misses: 0
        Hits: 1
        Misses: 1
        Content is gzip compressed: NO
        Content is deflate compressed: NO
        HTTP version in response: 1.1
        Weak ETag present in response: NO
        Negative marker cell: NO
        Auto poll every time: NO
        NetScaler ETag inserted in response: YES
        Full response present in cache: YES
        Destination IP verified by DNS: NO
        Stored through a cache forward proxy: NO
        Delta basefile: NO
        Waiting for minhits: NO
        Minhit count: 0
        HTTP request method: GET
 Done
> flush cache object -url /install.php -host addons.mozilla.org -port 443
 Done
> show cache object -url /install.php -host addons.mozilla.org -port 443
ERROR: No such resource

Comment 4

[James Ross]

Thanks for trying the cache thing - it may still be needed inconjunction with another fix, but it doesn't appear to have made a difference on its own.

Comment 5

[James Ross]

OK, something fixed it about 6-7 hours ago. What?

Comment 6

[Justin Fitzhugh]

Loadbalancer testing is complete (which was announced in many locations including mozilla.general).

Comment 7

[James Ross]

Your arrogance is astounding. The only remotely possible message is about stuff happening last Tuesday.

Comment 8

[Michael Morgan [:morgamic]]

James, we will take a closer look at using the hardware cache properly w/ install.php -- the stuff we saw last week was due to testing of the hardware load balancer, and the info was sent out in the IT blog:
http://weblogs.mozillazine.org/it/

On a side note, Justin is a cool guy, unless he's button mashing in Dead or Alive 4 and beating you repeatedly.  I'm sure he didn't mean to upset you with his comment.

The IP issue still remains, even if the script is not cached -- if I'm not mistaken.  So, there might need to be some additional work on trying to uniquely identify different download clicks... :\

Any ideas?

Comment 9

[James Ross]

(In reply to comment #8)
> http://weblogs.mozillazine.org/it/

That's still not helpful - it's the same as the newsgroup post, which didn't tally with anything going on in this bug, much less provide any useful information.

> Any ideas?

As I mentioned before, the Apache proxy provides the original IP specially. I'm kinda hoping your proxy isn't about to be out-done by the comes-as-standard Apache one... (note that you've still failed to answer *both* my questions in comment 2)

Comment 10

[Michael Morgan [:morgamic]]

Matt, is it possible to get the hardware load balancer forward the original IP in some way (like Apache)?

Comment 11

[matthew zeier [:mrz]]

(In reply to comment #10)
> Matt, is it possible to get the hardware load balancer forward the original IP
> in some way (like Apache)?

Probably - I'll have to research.  We're no longer  using the load balancer so you shouldn't have this problem now.  If/when we deploy for production I'll ping you for testing.

Comment 12

[alanjstr]

What hardware are we thinking of using?  

We're tracking by IP to prevent someone from artificially bumping up download counts, right?  

Comment 13

[Rob Marshall [tH]]

This is happening again with the new caching setup.

Comment 14

[Michael Morgan [:morgamic]]

We've verified that the http_x_forwarded_for env var is being set properly -- the next thing we've tried is a patch for install.php to deliver a Cache-control: no-cache header.

If the values still do not update, I believe it might be a scheduling problem for the maintenance script that is responsible for updating the lookup values in the main table.  I will ask infra to double check that these scripts are running properly.

Comment 15

[matthew zeier [:mrz]]

(In reply to comment #14)
> We've verified that the http_x_forwarded_for env var is being set properly --
> the next thing we've tried is a patch for install.php to deliver a
> Cache-control: no-cache header.

What's the full URI?  I assumed /install.php or install.php.  Neither currently shows in the cache:

> sh cache object -url install.php -host addons.mozilla.org
ERROR: No such resource
> sh cache object -url /install.php -host addons.mozilla.org
ERROR: No such resource

Comment 16

[Michael Morgan [:morgamic]]

Justing and I verified that the script isn't in the cache -- we are looking into another problem with the SHADOW config for the read-only slave.  The problem might be more fundamental.

Comment 17

[Michael Morgan [:morgamic]]

Alright, the problem was with how the NS was caching the 302 returned by instal.php (the passthru to the file's URI on releases.mozilla.org), combined with the capitalization (possibly) of the "Cache-Control" header -- used to be "Cache-control".

After modifying these values, we were able to stabilize the weekly count, and the total count is incrementing at a normal rate.

We should see the weekly count hover for a few days around the same value, but once the low-count days get outside the 7-day window, the counts will increase to their previous values.

Comment 18

[Giorgio Maone [:ma1]]

Back and selective now: some items are cached (e.g. FlashGot, AdBlock, IETab - apparently getting about 10 downloads per hour), other are not.
What LiveHTTPHeaders can see when clicking on the "Install Now" link:

FlashGot, CACHED
========================================================================
https://addons.mozilla.org/install.php?uri=http://releases.mozilla.org/pub/mozilla.org/extensions/flashgot/flashgot-0.5.9.995-fx+fl+mz+ns+zm+tb.xpi

GET /install.php?uri=http://releases.mozilla.org/pub/mozilla.org/extensions/flashgot/flashgot-0.5.9.995-fx+fl+mz+ns+zm+tb.xpi HTTP/1.1
Host: addons.mozilla.org
User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8.0.6) Gecko/20060728 FireFox Firefox/1.5.0.6
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.5
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 Found
Age: 368
Date: Mon, 21 Aug 2006 18:21:44 GMT
Cache-Control: no-cache
Connection: Keep-Alive
Via: NS-CACHE-6.0:   4
Etag: "KXNMGICECJXNMTMQX"
Server: Apache/2.0.52 (Red Hat)
X-Powered-By: PHP/4.3.9
Location: http://releases.mozilla.org/pub/mozilla.org/extensions/flashgot/flashgot-0.5.9.995-fx+fl+mz+ns+zm+tb.xpi
Content-Length: 0
Content-Type: text/html; charset=UTF-8
========================================================================


NoScript, NOT cached
========================================================================
https://addons.mozilla.org/install.php?uri=http://releases.mozilla.org/pub/mozilla.org/extensions/noscript/noscript-1.1.4.1-fx+fl+mz+zm.xpi

GET /install.php?uri=http://releases.mozilla.org/pub/mozilla.org/extensions/noscript/noscript-1.1.4.1-fx+fl+mz+zm.xpi HTTP/1.1
Host: addons.mozilla.org
User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8.0.6) Gecko/20060728 FireFox Firefox/1.5.0.6
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.5
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 Found
Date: Mon, 21 Aug 2006 18:27:35 GMT
Server: Apache/2.0.52 (Red Hat)
X-Powered-By: PHP/4.3.9
Cache-Control: no-cache
Location: http://releases.mozilla.org/pub/mozilla.org/extensions/noscript/noscript-1.1.4.1-fx+fl+mz+zm.xpi
Content-Length: 0
Connection: close
Content-Type: text/html; charset=UTF-8
========================================================================

Comment 19

[Giorgio Maone [:ma1]]

It's been OK for about a week, but now it's back affecting all top ten *except* FlashGot, Fasterfox and ForecastFox.
Exactly the same issue, with the 3 addons above served directly and the other ones apparently cached

Via: NS-CACHE-6.0:   4

Comment 20

[Dave Miller [:justdave]]

Netscaler issue -> server ops

Comment 21

[Jeremy Orem [:oremj]]

This is still being cached.  That would probably be the problem. 
wget -S -O - https://addons.mozilla.org/install.php?uri=http://releases.mozilla.org/pub/mozilla.org/extensions/flashgot/flashgot-0.5.96.06
--10:41:22--  https://addons.mozilla.org/install.php?uri=http://releases.mozilla.org/pub/mozilla.org/extensions/flashgot/flashgot-0.5.96.06
           => `-'
Resolving addons.mozilla.org... 63.245.209.31
Connecting to addons.mozilla.org|63.245.209.31|:443... connected.
HTTP request sent, awaiting response... 
  HTTP/1.1 200 OK
  Age: 348       
  Date: Wed, 13 Sep 2006 17:37:23 GMT
  Connection: Keep-Alive
  Via: NS-CACHE-6.0:   4
  ETag: "KXNMGICECJWZRKZLQ"
  Server: Apache/2.0.52 (Red Hat)
  X-Powered-By: PHP/4.3.9
  Content-Length: 0
  Content-Type: text/html; charset=UTF-8

Comment 22

[Jeremy Orem [:oremj]]

This looks like pretty much the same thing as giorgio, but I don't receive the no cache header.

Comment 23

[Mike Shaver (:shaver emeritus)]

We believe that the problem is that while the rule went in correctly as described in comment 3, the cache wasn't flushed of existing objects.  And then the rule was disabled when the app grew the cache-control headers, but things that were already in the cache were of course not purged by that either.  We've done the full purge now, and don't see flashgot being cached any more.

(Tragically, the interface of the caching appliance doesn't let us look at the URLs that are in the cache by pattern, only exact match, which doesn't help investigating these at all!)

Thanks to oremj and mrz for tracking this down with me.  We can see what's involved in extracting "lost" downloads from the cache's logs if it's deeply needed, but I'd prefer not to.

Comment 24

[Mike Shaver (:shaver emeritus)]

I misunderstood mrz via IRC: he _did_ flush the whole cache after adding the policy, and the policy was only disabled after install.php started sending the right headers, so we still don't know what happened here.

Comment 25

[Jeremy Orem [:oremj]]

This is still working.  Closing for now please reopen if this happens again.

nslb01> show cache object -url /install.php?uri=http://releases.mozilla.org/pub/mozilla.org/extensions/flashgot/flashgot-0.5.96.06 -host addons.mozilla.org -port 443
ERROR: No such resource

Comment 26

[Cameron]

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

Comment 27

[Giorgio Maone [:ma1]]

Bad news: it's worse than ever, involving all the add-ons together (at least the 20 or so I checked with Live HTTP Headers).

Good news: very simple and ultimate fix with no side effects coming in minutes as an install.js patch.

Comment 28

[Giorgio Maone [:ma1]]

Attachment: Changes the AJAX method from "GET" to "POST".

Semantically more correct, since it triggers one or more database writes, and it should never be cached.

Comment 29

[Jeremy Orem [:oremj]]

It is seeing the no-cache no-store, but still caching... 

nslb01> show cache object -url /install.php?uri=http://releases.mozilla.org/pub/mozilla.org/extensions/flashgot/flashgot-0.5.97.01-fx+fl+mz+ns+zm+tb.xpi -host addons.mozilla.org -port 443
	Integrated cache object statistics:
	Response size: 496 bytes
	Response header size: 496 bytes
	Response status code: 302
	ETag: KXNMGICECJNKMLORZX
	Last-Modified: NONE
	Cache-control: no-cache,no-store
	Date: Sun, 05 Nov 2006 21:39:32 GMT
	Contentgroup: ADDONS
	Complex match: NO
	URL: /install.php?uri=http://releases.mozilla.org/pub/mozilla.org/extensions/flashgot/flashgot-0.5.97.01-fx+fl+mz+ns+zm+tb.xpi
	Host: addons.mozilla.org
	Host port: 443
	Destination IP: 63.245.209.31
	Destination port: 443
	Request time: 457 secs ago
	Response time: started arriving 457 secs ago
	Age: 464 secs
	Expiry: 136 secs left to expiry
	Prefetch: 98 secs left to prefetch
	Current readers: 0
	Current misses: 0
	Hits: 131048
	Misses: 651
	Content is gzip compressed: NO
	Content is deflate compressed: NO
	HTTP version in response: 1.1
	Weak ETag present in response: NO
	Negative marker cell: NO
	Auto poll every time: NO
	NetScaler ETag inserted in response: YES
	Full response present in cache: YES
	Destination IP verified by DNS: NO
	Stored through a cache forward proxy: NO
	Delta basefile: NO
	Waiting for minhits: NO
	Minhit count: 0
	HTTP request method: GET

Comment 30

[Jeremy Orem [:oremj]]

Found the problem.  The NetScaler was ignoring cache-control headers.

Comment 31

[Jeremy Orem [:oremj]]

For future reference.  The netscaler content groups must be configured to allow cache-control headers.  Also, any policies that select a content group have to be MAY_CACHE not CACHE.

Comment 32

[Wladimir Palant]

It is broken again, for all extensions - see http://twpol.dyndns.org/mozilla/extensions/stats/image.pl?id=220,26,722,1865,684,1419,10;m=dlsamp;average=12;range=0+7;w=1000;h=507

Reopening bug.

Comment 33

[Giorgio Maone [:ma1]]

Thanks Wladimir for noticing the symptom, but it's a different bug: I've just opened bug 362060 for this.