Varnish - Error on PURGE request

[lilmuckers]

When i clear the cache in the backend (or from saving a product or any of the other means that trigger a varnish PURGE) the purge command comes into varnishlog as "PURGE%00"

Looking at the code, within Zend\Http\Client\Adapter\Socket::write() it's setting a null path to the request.
This appears to be because the Zend\Uri\Uri object doesn't have a path specified, and is returning a null for the path as well.

When I hardcode the request to have a path of / it works just fine and the PURGE commands execute flawlessly.

I'd be inclined to say this is more a Zend bug than a Magento bug, but I'm not 100% sure on this. When I modified Magento\PageCache\Model\Cache\Server::getUris() to have a not-null path (instead I hardcoded a path of /) it did not resolve the issue, Only when I modified the call to Socket::write() to use the method PURGE / (which is terrible and hurt me to my core)

[erikhansen]

@lilmuckers I believe this issue has been fixed by #3339. That PR has been merged into develop and should be included in next release of Magento. If you agree, you can close this issue.

[lilmuckers]

Agreed. that resolves the issue

[keithbentrup]

@erikhansen @lilmuckers I cherrypicked @davidalger's #3339 in 2.0.5. While bin/magento cache:flush now works as expected, the admin "Flush Magento Cache" option does not generate a PURGE reguest, and all I see in varnishlog is HttpGarbage "PURGE%00". Can anyone else confirm?

[erikhansen]

@keithbentrup I have a Magento Enterprise site running 2.0.5 and clicking the "Flush Magento Cache" button results in this output from varnishlog (we're using Varnish 4):

*   << Request  >> 196790    
-   Begin          req 196789 rxreq
-   Timestamp      Start: 1462483223.207177 0.000000 0.000000
-   Timestamp      Req: 1462483223.207177 0.000000 0.000000
-   ReqStart       127.0.0.1 52469
-   ReqMethod      PURGE
-   ReqURL         HTTP/1.1
-   ReqProtocol    
-   ReqHeader      X-Magento-Tags-Pattern: .*
-   ReqHeader      X-Forwarded-For: 127.0.0.1
-   VCL_call       RECV
-   VCL_acl        MATCH purge "localhost"
-   Debug          "VCL_error(200, Purged)"
-   VCL_return     synth
-   VCL_call       HASH
-   VCL_return     lookup
-   Timestamp      Process: 1462483223.207226 0.000049 0.000049
-   RespHeader     Date: Thu, 05 May 2016 21:20:23 GMT
-   RespHeader     Server: Varnish
-   RespHeader     X-Varnish: 196790
-   RespProtocol   HTTP/1.1
-   RespStatus     200
-   RespReason     OK
-   RespReason     Purged
-   VCL_call       SYNTH
-   RespHeader     Content-Type: text/html; charset=utf-8
-   RespHeader     Retry-After: 5
-   VCL_return     deliver
-   RespHeader     Content-Length: 241
-   Debug          "RES_MODE 2"
-   RespHeader     Connection: close
-   Timestamp      Resp: 1462483223.207277 0.000100 0.000051
-   ReqAcct        47 0 47 192 241 433
-   End            

Make sure you've configured Varnish properly. Here are the Magerun 2 commands we use to configure Varnish in our standard environment:

# Enable varnish in magento config
mr setup:config:set --no-interaction --http-cache-hosts=127.0.0.1:6081
mr config:set system/full_page_cache/caching_application 2
mr config:set system/full_page_cache/ttl 604800
mr config:set system/full_page_cache/varnish/access_list localhost
mr config:set system/full_page_cache/varnish/backend_host localhost
mr config:set system/full_page_cache/varnish/backend_port 8080

You'll also want to make sure you have the latest VCL from 2.0.5.

[keithbentrup]

I believe the config settings are just populating core_config_data and used to generate the sample VCL file. The settings are actually read from app/etc/env.php on the app server, and of course, the active VCL conf loaded on the varnish server.

Regardless, the app server and the cache server are communicating (otherwise, I wouldn't be seeing any responses or the output in varnishlog). bin/magento cache:flush produces the output you pasted in varnishlog. However, clicking "Flush Magento Cache" produces:

*   << Request  >> 41        
-   Begin          req 40 rxreq
-   Timestamp      Start: 1462481744.409979 0.000000 0.000000
-   Timestamp      Req: 1462481744.409979 0.000000 0.000000
-   HttpGarbage    "PURGE%00"
-   ReqAcct        47 0 47 28 0 28
-   End      

To further diagnose, I watched the output with tcpflow.

Here's the output from bin/magento cache:flush:

tcpflow -i eth0 -ac host 10.0.1.5
tcpflow: listening on eth0
010.000.001.003.59700-010.000.001.005.00080: PURGE / HTTP/1.1
X-Magento-Tags-Pattern: .*


write error to stdout

010.000.001.005.00080-010.000.001.003.59700: HTTP/1.1 200 Purged
Date: Thu, 05 May 2016 22:06:38 GMT
Server: Varnish
X-Varnish: 229426
Content-Type: text/html; charset=utf-8
Retry-After: 5
Content-Length: 241
Accept-Ranges: bytes
Connection: keep-alive

<!DOCTYPE html>
<html>
  <head>
    <title>200 Purged</title>
  </head>
  <body>
    <h1>Error 200 Purged</h1>
    <p>Purged</p>
    <h3>Guru Meditation:</h3>
    <p>XID: 229426</p>
    <hr>
    <p>Varnish cache server</p>
  </body>
</html>

and from "Flush Magento Cache"

010.000.001.003.59716-010.000.001.005.00080: PURGE  HTTP/1.1
X-Magento-Tags-Pattern: .*


write error to stdout

010.000.001.005.00080-010.000.001.003.59716: HTTP/1.1 400 Bad Request


write error to stdout

Note PURGE is missing the "/" after and varnish is returning a 400.

[keithbentrup]

I revisited this issue with xdebug which required a server restart. I could no longer reproduce and verified the path was set to "/". It was probably opcache related. Doh!