Page MenuHomePhabricator
Create Task
Maniphest T230772

Piwik JS isn't cached
Closed, ResolvedPublic2 Estimated Story Points
Actions

Description

I noticed piwik was being served on the foundation website, from its own domain, at https://piwik.wikimedia.org/piwik.js

Looking at the HTTP headers of this request, it doesn't have caching set up properly.

It's not cached on the server-side, meaning that Varnish doesn't serve it:

x-cache: cp1083 pass, cp3032 pass, cp3040 pass
x-cache-status: pass

This is problematic in case of high traffic spikes, since this is served to every client on this site (and I'm guessing on other sites as well).

And even more importantly, this HTTP request doesn't serve any caching header, meaning that the browser won't ever cache it, downloading it for every page load. A cache-control header would be highly desirable here. Since the URL is unversioned, of course this means that updates of the JS reaching clients that already have a previous version cached would be delayed by that duration. But at the very least the browser should cache this for minutes or hours, so that users can benefit from piwiki being cached for the duration of their browsing session.

Details

SubjectRepoBranchLines +/-
varnish: reload service upon -common separate VCL changesoperations/puppetproduction+4 -1
Adding caching headers for piwik javascriptoperations/puppetproduction+13 -0
cache: allow caching piwikoperations/puppetproduction+0 -5
Customize query in gerrit

Related Objects
Search...

StatusSubtypeAssignedTask
 ResolvedPeterT230708 Performance review of new foundation website design
 Resolved• NuriaT230772 Piwik JS isn't cached

Event Timeline

• Gilles created this task.Aug 20 2019, 8:06 AM
Restricted Application added a project: Analytics. · View Herald TranscriptAug 20 2019, 8:06 AM
Restricted Application added a subscriber: Aklapper. · View Herald Transcript
• Gilles added a parent task: T230708: Performance review of new foundation website design.Aug 20 2019, 8:06 AM
elukey subscribed.EditedAug 20 2019, 8:59 AM

Nice catch, even if I was convinced that the static contents were cached by Varnish 24h if not Cache-Control (or similar) headers were found.. Maybe we have a specific pass policy for piwik? Anyway, I agree that having a cache-control header is sane, going to send a patch.

piwik.wikimedia.org:
  director: 'matomo1001'
  caching: 'pass'
elukey added a subscriber: • ema.Aug 20 2019, 9:01 AM

@ema hi :) Are response headers like Cache-Control used by Varnish in case caching: 'pass' is configured?

• ema added a comment.Aug 22 2019, 1:51 PM
In T230772#5423807, @elukey wrote:

@ema hi :) Are response headers like Cache-Control used by Varnish in case caching: 'pass' is configured?

They are not. The meaning of caching: pass is: whatever the origin server says, do not cache the response. If we want matomo to be cached, we need to remove caching: pass and ensure that all responses include caching headers indicating cacheability.

• ema triaged this task as Medium priority.Aug 22 2019, 1:52 PM
• ema added a project: Traffic.
Restricted Application added a project: SRE. · View Herald TranscriptAug 22 2019, 1:52 PM
• ema moved this task from Backlog to Radar/Not for service by Traffic on the Traffic board.Aug 22 2019, 1:52 PM
• fdans reassigned this task from • Nuria to elukey.Aug 22 2019, 5:27 PM
• fdans reassigned this task from elukey to • Nuria.
• fdans added a subscriber: • Nuria.
• fdans moved this task from Incoming to Operational Excellence on the Analytics board.Aug 22 2019, 5:29 PM
• kchapman moved this task from Inbox, needs triage to Radar on the Performance-Team board.Aug 26 2019, 8:23 PM
• kchapman edited projects, added Performance-Team (Radar); removed Performance-Team.
• Nuria added a comment.Sep 3 2019, 7:28 AM

@ema So I understand: caching pass needs to be removed (will do so) and since caching response includes an eTag. Is removing caching: pass sufficient for caching this request since eTag is present?

gerritbot added a comment.Sep 3 2019, 8:20 AM

Change 534034 had a related patch set uploaded (by Ema; owner: Ema):
[operations/puppet@production] cache: allow caching piwik

https://gerrit.wikimedia.org/r/534034

gerritbot added a project: Patch-For-Review.Sep 3 2019, 8:20 AM
• ema added a comment.Sep 3 2019, 8:28 AM
In T230772#5460265, @Nuria wrote:

@ema So I understand: caching pass needs to be removed

Yes, and the equivalent change needs to be done for ATS too. I've prepared a patch addressing both Varnish and ATS: https://gerrit.wikimedia.org/r/534034

Is removing caching: pass sufficient for caching this request since eTag is present?

Cache-Control needs to be set too. See @elukey's patch here as an example: https://gerrit.wikimedia.org/r/#/c/operations/puppet/+/529795/

• Nuria added a project: Analytics-Kanban.Sep 3 2019, 8:31 AM
• Nuria moved this task from Next Up to In Progress on the Analytics-Kanban board.
gerritbot added a comment.Sep 3 2019, 8:55 AM

Change 534114 had a related patch set uploaded (by Nuria; owner: Nuria):
[operations/puppet@production] Adding caching headers for piwik javascript

https://gerrit.wikimedia.org/r/534114

gerritbot added a comment.Sep 3 2019, 9:06 AM

Change 534034 merged by Ema:
[operations/puppet@production] cache: allow caching piwik

https://gerrit.wikimedia.org/r/534034

• Nuria moved this task from In Progress to Ready to Deploy on the Analytics-Kanban board.Sep 3 2019, 9:11 AM
• Nuria set the point value for this task to 2.
• Nuria added a comment.Sep 3 2019, 10:53 AM

I think what is left here is to restart apache for settings to take place

• Nuria added a comment.Sep 3 2019, 10:54 AM

Restarted with : sudo apache2ctl restart

gerritbot added a comment.Sep 3 2019, 1:39 PM

Change 534114 merged by Ottomata:
[operations/puppet@production] Adding caching headers for piwik javascript

https://gerrit.wikimedia.org/r/534114

• Nuria added a comment.Sep 3 2019, 2:07 PM

I can see the cache-control: max-age=604800 , I think @ema needs to change something on his end so varnish /ATS settings apply?

Maintenance_bot removed a project: Patch-For-Review.Sep 3 2019, 2:10 PM
gerritbot added a comment.Sep 4 2019, 9:12 AM

Change 534387 had a related patch set uploaded (by Ema; owner: Ema):
[operations/puppet@production] varnish: reload service upon -common separate VCL changes

https://gerrit.wikimedia.org/r/534387

gerritbot added a project: Patch-For-Review.Sep 4 2019, 9:12 AM
• ema added a comment.Sep 4 2019, 9:13 AM
In T230772#5461321, @Nuria wrote:

I can see the cache-control: max-age=604800 , I think @ema needs to change something on his end so varnish /ATS settings apply?

The problem was that changes to separate common VCL did not trigger a varnish reload. I've reloaded varnish manually and I see caching working as expected.

$ curl  -v https://piwik.wikimedia.org/piwik.js 2>&1 | grep x-cache:
< x-cache: cp1079 pass, cp3040 hit/128, cp3043 hit/272

https://gerrit.wikimedia.org/r/#/c/operations/puppet/+/534387/ should fix the issue in general.

gerritbot added a comment.Sep 4 2019, 9:15 AM

Change 534387 merged by Ema:
[operations/puppet@production] varnish: reload service upon -common separate VCL changes

https://gerrit.wikimedia.org/r/534387

Maintenance_bot removed a project: Patch-For-Review.Sep 4 2019, 10:10 AM
• Nuria added a comment.Sep 4 2019, 12:22 PM

I think things look good now:

[nuriaruiz@nurieta][~/tips]$ curl -v https://piwik.wikimedia.org/piwik.js > piwik

  • Trying 91.198.174.192... % Total % Received % Xferd Average Speed Time Time Time Current Dload Upload Total Spent Left Speed 0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0* Connected to piwik.wikimedia.org (91.198.174.192) port 443 (#0)
  • TLS 1.2 connection using TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384
  • Server certificate: *.wikipedia.org
  • Server certificate: GlobalSign Organization Validation CA - SHA256 - G2
  • Server certificate: GlobalSign

GET /piwik.js HTTP/1.1
Host: piwik.wikimedia.org
User-Agent: curl/7.47.1
Accept: */*

< HTTP/1.1 200 OK
< Date: Wed, 04 Sep 2019 12:21:24 GMT
< Content-Type: application/javascript
< Content-Length: 67245
< Connection: keep-alive
< Server: Apache
< Last-Modified: Thu, 21 Mar 2019 07:50:00 GMT
< Vary: Accept-Encoding
< Backend-Timing: D=296 t=1567543025322864
< Cache-Control: max-age=604800
< ETag: W/"106ad-58495fc36da00"
< X-Varnish: 261194407 407699841, 170003865 48792434, 191497129 1046530572
< Age: 56657
< X-Cache: cp1079 hit/188, cp3040 hit/6, cp3030 hit/64
< X-Cache-Status: hit-front
< Server-Timing: cache;desc="hit-front"
< Strict-Transport-Security: max-age=106384710; includeSubDomains; preload
< Set-Cookie: WMF-Last-Access=04-Sep-2019;Path=/;HttpOnly;secure;Expires=Sun, 06 Oct 2019 12:00:00 GMT
< X-Analytics: https=1;nocookies=1
< X-Client-IP: 82.141.252.179
< Accept-Ranges: bytes

• Gilles added a comment.Sep 4 2019, 1:44 PM

While the caching header is correctly served, when the request is in the context of the foundation website, Varnish is doing a pass:

Capture d'écran 2019-09-04 15.19.22.png (727×672 px, 114 KB)

When requesting the same URL via cURL, I'm seeing the expected hit on cp3042.

Not sure what's going on here? Copying the cURL command with the headers seen in the developer tools also results in a hit:

curl 'https://piwik.wikimedia.org/piwik.js' -H 'Sec-Fetch-Mode: no-cors' -H 'Referer: https://wikimediafoundation.org/' -H 'User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.132 Safari/537.36' --compressed --verbose

< x-cache: cp1079 hit/188, cp3040 hit/7, cp3042 hit/81

I cannot reproduce the issue on Firefox, this is only happening on Chrome (76).

Capturing the Varnishlog frontend entry of my request coming from the browser, I get:

*   << Request  >> 818093875 
-   Begin          req 818093874 rxreq
-   Timestamp      Start: 1567604408.481564 0.000000 0.000000
-   Timestamp      Req: 1567604408.481564 0.000000 0.000000
-   ReqStart       10.20.0.177 45341
-   ReqMethod      GET
-   ReqURL         /piwik.js
-   ReqProtocol    HTTP/1.1
-   ReqHeader      Connection: close
-   ReqHeader      Host: piwik.wikimedia.org
-   ReqHeader      X-Client-IP: 37.171.118.134
-   ReqHeader      X-Forwarded-For: 37.171.118.134
-   ReqHeader      X-Forwarded-Proto: https
-   ReqHeader      X-Connection-Properties: H2=1; SSR=0; SSL=TLSv1.2; C=ECDHE-ECDSA-CHACHA20-POLY1305; EC=X25519;
-   ReqHeader      sec-fetch-mode: no-cors
-   ReqHeader      user-agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_14_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.132 Safari/537.36
-   ReqHeader      accept: */*
-   ReqHeader      sec-fetch-site: cross-site
-   ReqHeader      referer: https://wikimediafoundation.org/
-   ReqHeader      accept-encoding: gzip, deflate, br
-   ReqHeader      accept-language: en-US,en;q=0.9,fr;q=0.8
-   ReqHeader      cookie: GeoIP=FR:IDF:Paris:48.86:2.33:v4; CP=H2; __mmapiwsid=fd28ae37-c711-4420-81b1-f7aae95f1712:2b3a7adf469a761ef6a6b4001a5816bed5694f76; WMF-Last-Access-Global=26-Aug-2019; WMF-Last-Access=04-Sep-2019
-   ReqUnset       X-Forwarded-For: 37.171.118.134
-   ReqHeader      X-Forwarded-For: 37.171.118.134, 10.20.0.177
-   VCL_call       RECV
-   ReqUnset       Host: piwik.wikimedia.org
-   ReqHeader      Host: piwik.wikimedia.org
-   ReqUnset       Host: piwik.wikimedia.org
-   ReqHeader      Host: piwik.wikimedia.org
-   Debug          "Now using wikimedia_misc VCL"
-   VCL_return     vcl
-   VCL_call       RECV
-   ReqUnset       Host: piwik.wikimedia.org
-   ReqHeader      Host: piwik.wikimedia.org
-   ReqUnset       Host: piwik.wikimedia.org
-   ReqHeader      Host: piwik.wikimedia.org
-   VCL_acl        MATCH wikimedia_trust "10.0.0.0"/8
-   VCL_acl        NO_MATCH local_host
-   VCL_acl        MATCH local_tls_terminator "10.20.0.177"
-   ReqUnset       X-Forwarded-For: 37.171.118.134
-   ReqHeader      X-Forwarded-For: 37.171.118.134
-   ReqUnset       X-Forwarded-For: 37.171.118.134
-   ReqHeader      X-Forwarded-For: 37.171.118.134
-   ReqUnset       X-Forwarded-For: 37.171.118.134
-   ReqHeader      X-Forwarded-For: 37.171.118.134
-   ReqHeader      via-nginx: 1
-   ReqHeader      X-Trusted-Proxy: 
-   ReqUnset       X-Trusted-Proxy: 
-   VCL_acl        NO_MATCH blocked_nets
-   ReqHeader      X-WMF-LastStamp: 04-Sep-2019
-   ReqHeader      X-CP-HTTP2: 1
-   ReqHeader      X-CP-TLS-Version: TLSv1.2
-   ReqHeader      X-CP-TLS-Session-Reused: 0
-   ReqHeader      X-CP-Key-Exchange: X25519
-   ReqHeader      X-CP-Full-Cipher: ECDHE-ECDSA-CHACHA20-POLY1305
-   ReqHeader      X-CP-Auth: ECDHE-ECDSA-CHACHA20-POLY1305
-   ReqHeader      X-CP-Cipher: CHACHA20-POLY1305
-   ReqUnset       X-CP-Auth: ECDHE-ECDSA-CHACHA20-POLY1305
-   ReqHeader      X-CP-Auth: ECDSA
-   ReqUnset       X-CP-Cipher: CHACHA20-POLY1305
-   ReqHeader      X-CP-Cipher: CHACHA20-POLY1305-SHA256
-   VCL_Log        CP-HTTP2: 1
-   VCL_Log        CP-TLS-Version: TLSv1.2
-   VCL_Log        CP-TLS-Session-Reused: 0
-   VCL_Log        CP-Key-Exchange: X25519
-   VCL_Log        CP-Auth: ECDSA
-   VCL_Log        CP-Cipher: CHACHA20-POLY1305-SHA256
-   VCL_Log        CP-Full-Cipher: ECDHE-ECDSA-CHACHA20-POLY1305
-   ReqUnset       X-CP-HTTP2: 1
-   ReqUnset       X-CP-TLS-Version: TLSv1.2
-   ReqUnset       X-CP-TLS-Session-Reused: 0
-   ReqUnset       X-CP-Key-Exchange: X25519
-   ReqUnset       X-CP-Auth: ECDSA
-   ReqUnset       X-CP-Cipher: CHACHA20-POLY1305-SHA256
-   ReqUnset       X-CP-Full-Cipher: ECDHE-ECDSA-CHACHA20-POLY1305
-   ReqHeader      NC-Cookie: ; __mmapiwsid=fd28ae37-c711-4420-81b1-f7aae95f1712:2b3a7adf469a761ef6a6b4001a5816bed5694f76
-   ReqUnset       NC-Cookie: ; __mmapiwsid=fd28ae37-c711-4420-81b1-f7aae95f1712:2b3a7adf469a761ef6a6b4001a5816bed5694f76
-   ReqHeader      NC-Cookie: __mmapiwsid=fd28ae37-c711-4420-81b1-f7aae95f1712:2b3a7adf469a761ef6a6b4001a5816bed5694f76
-   ReqUnset       NC-Cookie: __mmapiwsid=fd28ae37-c711-4420-81b1-f7aae95f1712:2b3a7adf469a761ef6a6b4001a5816bed5694f76
-   VCL_return     pass
-   VCL_call       HASH
-   VCL_return     lookup
-   VCL_call       PASS
-   ReqHeader      X-CDIS: pass
-   VCL_return     fetch
-   Link           bereq 818093876 pass
-   Timestamp      Fetch: 1567604408.568663 0.087099 0.087099
-   RespProtocol   HTTP/1.1
-   RespStatus     200
-   RespReason     OK
-   RespHeader     Date: Wed, 04 Sep 2019 13:40:08 GMT
-   RespHeader     Server: Apache
-   RespHeader     Last-Modified: Thu, 21 Mar 2019 07:50:00 GMT
-   RespHeader     Accept-Ranges: bytes
-   RespHeader     Vary: Accept-Encoding
-   RespHeader     Backend-Timing: D=303 t=1567604408523524
-   RespHeader     Cache-Control: max-age=604800
-   RespHeader     Content-Type: application/javascript
-   RespHeader     ETag: W/"106ad-58495fc36da00"
-   RespHeader     Content-Encoding: gzip
-   RespHeader     X-Varnish: 164580664
-   RespHeader     Via: 1.1 varnish (Varnish/5.1)
-   RespHeader     X-Varnish: 643426432
-   RespHeader     Via: 1.1 varnish (Varnish/5.1)
-   RespHeader     X-Cache-Int: cp1087 pass, cp3042 pass
-   RespHeader     X-CDIS: pass
-   RespHeader     X-Varnish: 818093875
-   RespHeader     Age: 0
-   RespHeader     Via: 1.1 varnish (Varnish/5.1)
-   VCL_call       DELIVER
-   ReqUnset       X-CDIS: pass
-   ReqHeader      X-CDIS: pass
-   RespUnset      X-CDIS: pass
-   RespUnset      X-Cache-Int: cp1087 pass, cp3042 pass
-   RespHeader     X-Cache-Int: cp1087 pass, cp3042 pass, cp3042 pass
-   RespHeader     X-Cache: cp1087 pass, cp3042 pass, cp3042 pass
-   RespHeader     X-Cache-Status: pass, pass, pass
-   RespUnset      X-Cache-Int: cp1087 pass, cp3042 pass, cp3042 pass
-   RespUnset      Via: 1.1 varnish (Varnish/5.1)
-   RespUnset      Via: 1.1 varnish (Varnish/5.1)
-   RespUnset      Via: 1.1 varnish (Varnish/5.1)
-   RespUnset      X-Cache-Status: pass, pass, pass
-   RespHeader     X-Cache-Status: pass
-   RespHeader     Server-Timing: cache;desc="pass"
-   RespHeader     Strict-Transport-Security: max-age=106384710; includeSubDomains; preload
-   RespHeader     X-Analytics: 
-   ReqHeader      X-NowDay: 04-Sep-2019
-   RespUnset      X-Analytics: 
-   RespHeader     X-Analytics: ;WMF-Last-Access=04-Sep-2019
-   RespUnset      X-Analytics: ;WMF-Last-Access=04-Sep-2019
-   RespHeader     X-Analytics: ;WMF-Last-Access=04-Sep-2019;https=1
-   RespUnset      X-Analytics: ;WMF-Last-Access=04-Sep-2019;https=1
-   RespHeader     X-Analytics: WMF-Last-Access=04-Sep-2019;https=1
-   RespHeader     X-Client-IP: 37.171.118.134
-   VCL_return     deliver
-   Timestamp      Process: 1567604408.568727 0.087164 0.000065
-   RespHeader     Transfer-Encoding: chunked
-   RespHeader     Connection: close
-   Timestamp      Resp: 1567604408.595786 0.114222 0.027058
-   ReqAcct        783 0 783 685 22679 23364
-   End

I'm guessing it might be coming from the cookies? Which the Chrome developer tools weren't showing. We've had this issue before on the performance site, where being logged into CentralAuth prevented Varnish caching from kicking in, due to a VCL rule somewhere. Meaning that us (staff members) tend to see a different caching situation than most visitors.

I think it's the same here, the Varnish caching for this particular asset should always work, regardless of cookies received. Especially since we're talking about loggedin status on other domains.

• Nuria added a comment.Sep 4 2019, 1:50 PM

Inddeed! I see server-timing: cache;desc="pass" on reg chrome window as well, thanks @Gilles for catching that

• ema added a comment.Sep 4 2019, 1:53 PM
In T230772#5464917, @Gilles wrote:

I'm guessing it might be coming from the cookies? Which the Chrome developer tools weren't showing. We've had this issue before on the performance site, where being logged into CentralAuth prevented Varnish caching from kicking in, due to a VCL rule somewhere. Meaning that us (staff members) tend to see a different caching situation than most visitors.

I think it's the same here, the Varnish caching for this particular asset should always work, regardless of cookies received. Especially since we're talking about loggedin status on other domains.

Yeah, we've got the following in misc_recv_pass:

// Don't cache cookie requests. Cache requests with google analytics cookies and our
// own global WMF-Last-Access, WMF-Last-Access-Global GeoIP, and CP cookies.
set req.http.NC-Cookie = regsuball(req.http.Cookie, "(?i)(^|;\s*)(_ga[-_a-z]*|_utm[-_a-z]*|_pk_(id|ses)\.[^=]*|WMF-Last-Access(-Global)?|GeoIP|CP)=[^;]*", "");
set req.http.NC-Cookie = regsub(req.http.NC-Cookie, "^;?\s*", "");
if (req.http.NC-Cookie != "") {
    unset req.http.NC-Cookie;
    return (pass);
}

The regular expression above needs to be updated to take WMF's website cookies into account.

• Gilles added a comment.Sep 4 2019, 1:55 PM

I think the issue is that misc_recv_pass is applied to every site. You want it to apply to wikis (where people can log in), but not on non-wiki websites we serve.

• Gilles added a comment.Sep 4 2019, 1:56 PM

Or I guess, to be conservative, add Wikimedia wiki login cookies to the filter only if you're in the context of a non-wiki site.

• Gilles added a comment.Sep 4 2019, 1:57 PM

This should probably be its own task, though, it's not specific to piwik.js

• Nuria added a comment.EditedSep 4 2019, 2:04 PM

Right this is an issue for all resources served for https://stats.wikimedia.org/v2 and, I am gusessing, other non wiki domains.

Can we consider blacklisting cookies for which we do not cache some domainsrather than whitelisting (via regex) the ones for which we do?

• Nuria added a comment.Sep 9 2019, 7:53 PM

ping @ema now that ahem, things are a bit more quiet

• ema closed this task as Resolved.Sep 10 2019, 10:34 AM
• ema mentioned this in T232453: Cookies and misc services caching.
In T230772#5464981, @Gilles wrote:

This should probably be its own task, though, it's not specific to piwik.js

Agreed, I've opened T232453 to track the general issue.

Content licensed under Creative Commons Attribution-ShareAlike (CC BY-SA) 4.0 unless otherwise noted; code licensed under GNU General Public License (GPL) 2.0 or later and other open source licenses. By using this site, you agree to the Terms of Use, Privacy Policy, and Code of Conduct. · Wikimedia Foundation · Privacy Policy · Code of Conduct · Terms of Use · Disclaimer · CC-BY-SA · GPL