drawing a blank.. clean install on test system "unexpected response code.. Authentication required."

[ghost]

I would highly appreciate input on whats gone wrong here: Please double check my simple install steps on a totaly fresh debian server The system : debian-6.0.7-amd64

varnished magento test machine steps

freash install deb6 add new repo http://www.dotdeb.org/instructions/

• ( php 5.4 )

apt-get install nginx php5-fpm php5-common php5-cli php5 php5-curl php5-dev php5-gd php5-imagick php5-memcache php5-mysql php-pear

apt-get install mysql-server phpmyadmin subversion varnish

svn checkout http://svn.magentocommerce.com/source/branches/1.7 ( Checked out revision 165117.)

config nginx to /site/www/public_html & use php5 socket..

make db and user for magento.. follow magento install steps magento connecte get turpentine from http://connect20.magentocommerce.com/community/Nexcessnet_Turpentine

flushed all caches , double checked compiler was still disabled.

so the basic shop is up and running, extension installed. got the secrete key from /etc/varnish/secret , pasted into config saved config , msg returned is

Failed to apply the VCL to 127.0.0.1:6082: Got unexpected response code from Varnish: 107 vbdtnodrdhkgvcqmmlsvkpiorupsegaz Authentication required.

The VCL file has been saved.
The configuration has been saved.

what can i take from this ? it saved the settings to the magento site root /var/default.vcl but failed to update the varnish admin interface ?

now if we go to cache management , enable the new caches.. looks fine. clicked 'Save the configuration to a VCL file.' , is 'ok'

click 'apply config file' repsonce is Failed to apply the VCL to 127.0.0.1:6082: Got unexpected response code from Varnish: 107 {random string} Authentication required.

go back to system>config>Varnish Options , enable all logging.

cat /dev/null > system.log

generate some traffic with ab, ab -n 400 -c 10 http://dev.server.url

check the log:

root@debian:/site/www/public_html/var/log# tail system.log
2013-03-22T06:54:57+00:00 INFO (6): TURPENTINE: Checking ESI block candidate: wishlist_sidebar
2013-03-22T06:54:57+00:00 INFO (6): TURPENTINE: Checking ESI block candidate: right.reports.product.viewed
2013-03-22T06:54:57+00:00 INFO (6): TURPENTINE: Checking ESI block candidate: right.reports.product.compared
2013-03-22T06:54:57+00:00 INFO (6): TURPENTINE: Checking ESI block candidate: right.permanent.callout
2013-03-22T06:54:57+00:00 INFO (6): TURPENTINE: Checking ESI block candidate: right.poll
2013-03-22T06:54:57+00:00 INFO (6): TURPENTINE: Checking ESI block candidate: paypal.partner.right.logo
2013-03-22T06:54:57+00:00 INFO (6): TURPENTINE: Checking ESI block candidate: sale.reorder.sidebar
2013-03-22T06:54:57+00:00 INFO (6): TURPENTINE: Checking ESI block candidate: footer
2013-03-22T06:54:57+00:00 INFO (6): TURPENTINE: Checking ESI block candidate: before_body_end
2013-03-22T06:54:57+00:00 INFO (6): TURPENTINE: Checking ESI block candidate: core_profiler
root@debian:/site/www/public_html/var/log#

also worth posting some related log from syslog

root@debian:/var/log# tail syslog
Mar 22 07:12:46 debian varnishd[14492]: CLI telnet 127.0.0.1 39357 127.0.0.1 6082 Rd "auth" "945c63a68506d7b5411c5ad6fb4bc741cf0bcdc084a2f780b3ee610a8356ce7b"
Mar 22 07:12:46 debian varnishd[14492]: CLI telnet 127.0.0.1 39357 127.0.0.1 6082 Wr 107 wfymdpqgyrqrwughgbhtqwzilubsfwpd#012#012Authentication required.

so, its doing 'something', but its not actually affecting anything on the front end, ab testing shows no change at all in reqs/sec, there is nothing in http responce headers to suggest anything from varnish. since before we varnished magento

bottom line.. do i need to be concerned about these "unexpected response code.. Authentication required." messages ? It seems to be a factor at every step, what can be changed ?

Since i get these results on my dev site, and the identical results on a totally fresh server to replicate the problem i'm hoping its just a bug that we can work out.

Alistair LiveSite: http://iluvscotland.co.uk DevSite: not public Server to replicate results: VBox 8core/32GB Ram/64GB SSD/ installed debian-6.0.7-amd64-DVD1.iso

[aheadley]

got the secrete key from /etc/varnish/secret , pasted into config Failed to apply the VCL to 127.0.0.1:6082: Got unexpected response code from Varnish: 107 vbdtnodrdhkgvcqmmlsvkpiorupsegaz Authentication required.

You probably didn't add the trailing newline to the secret key, try adding \n to the end of it.

[ghost]

Alex, your 100% correct, i had misread the instruction.. i had previously confirmed that the secret file had a /n but i did not consider the text box for secret in magento config would also require a /n.

Now that the config error is out the way , i still have no indication that varnish is doing much of anything.

Saved Config, Applied Config ( now without any errors ) ( even did a /etc/init.d/varnish restart , to see if that helped ) Installed LiveHeaders App in FireFox.

This is what it shows. ( Vbox Machine with hosts config changed, if you test the live site you wont get the same results )

http://iluvscotland.co.uk/index.php/

GET /index.php/ HTTP/1.1
Host: iluvscotland.co.uk
User-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:19.0) Gecko/20100101 Firefox/19.0
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
Accept-Language: en-US,en;q=0.5
Accept-Encoding: gzip, deflate
Referer: http://iluvscotland.co.uk/
Cookie: frontend=t6mgj8bcgeka76ab9oroqk2jv1
Connection: keep-alive

HTTP/1.1 200 OK
Server: nginx/1.2.7
Date: Tue, 26 Mar 2013 16:48:42 GMT
Content-Type: text/html; charset=UTF-8
Transfer-Encoding: chunked
Connection: keep-alive
X-Powered-By: PHP/5.4.13-1~dotdeb.1
Expires: Thu, 19 Nov 1981 08:52:00 GMT
Cache-Control: no-store, no-cache, must-revalidate, post-check=0, pre-check=0
Pragma: no-cache
Set-Cookie: frontend=t6mgj8bcgeka76ab9oroqk2jv1; expires=Tue, 26-Mar-2013 17:48:42 GMT; path=/; domain=iluvscotland.co.uk; httponly
Content-Encoding: gzip

The server log for the same time shows

Mar 26 16:36:18 debian varnishd[2700]: CLI telnet 127.0.0.1 55679 127.0.0.1 6082 Wr 200 VCL compiled.
Mar 26 16:36:19 debian varnishd[2700]: CLI telnet 127.0.0.1 55679 127.0.0.1 6082 Rd "vcl.use" "c8009ee28722145011617986abdc1246bfcd1418ffbc0cb93c4e203c52cc8850"
Mar 26 16:36:19 debian varnishd[2700]: CLI telnet 127.0.0.1 55679 127.0.0.1 6082 Wr 200

Enable Debug Info = Enabled Enable Block Logging = Disabled Enable AJAX Flash Messages = Enabled Enable AJAX Flash Messages = Enabled Enable Crawler Debug = Disabled

Apache Utils AB Test shows.

Server Software: nginx/1.2.7 Server Hostname: iluvscotland.co.uk Server Port: 80

Document Path: /index.php/privacy-policy-cookie-restriction-mode Document Length: 17309 bytes

Concurrency Level: 40 Time taken for tests: 118.936 seconds Complete requests: 4000 Failed requests: 0 Write errors: 0 Total transferred: 70992000 bytes HTML transferred: 69236000 bytes Requests per second: 33.63 #/sec Time per request: 1189.358 ms Time per request: 29.734 [ms](mean, across all concurrent requests) Transfer rate: 582.90 [Kbytes/sec] received

Connection Times (ms) min mean[+/-sd] median max Connect: 0 0 0.3 0 4 Processing: 513 1187 82.8 1186 1724 Waiting: 457 1123 80.2 1122 1675 Total: 516 1187 82.8 1186 1727

Percentage of the requests served within a certain time (ms) 50% 1186 66% 1212 75% 1231 80% 1243 90% 1274 95% 1302 98% 1352 99% 1426 100% 1727 (longest request) root@debian:~#

System Htop and Atop suggest Varnish is idle while the system is being punished through AB test.

any suggestions on what to look for / check next ?

[aheadley]

From the response headers, it looks like the request isn't going through Varnish at all. If it was, then with debugging enabled there would be a X-Varnish header and with debugging disabled there wouldn't be a Server header.

Can you post the output of netstat -lnp | grep varnish?

[ghost]

root@debian:~# netstat -lnp | grep varnish
tcp        0      0 0.0.0.0:6081            0.0.0.0:*               LISTEN      2701/varnishd
tcp        0      0 127.0.0.1:6082          0.0.0.0:*               LISTEN      2700/varnishd
tcp6       0      0 :::6081                 :::*                    LISTEN      2701/varnishd
root@debian:~#

[aheadley]

Ok, it looks like Varnish's default listening port wasn't changed. Varnish is a proxy, so it needs to sit "in front" of your webserver (Nginx). You can fix this by changing the listening port in Varnish's config (probably /etc/sysconfig/varnish) to listen on port 80 (instead of 6081), and make Nginx listen on a different port, common choices are 81 and 8080 but it doesn't really matter so long as nothing else is already using that port. Note that you will want to change the backend port to the new Nginx port in Varnish Options > General Options > Server List before you change the Nginx and Varnish ports.

Alternatively, you can just test your site through Varnish on port 6081 if you open that port in your firewall. Note that if you do this the links that Magento generates will take you back to the non-Varnish site on port 80 so you can only test individual pages, as soon as you click a link you will be bypassing Varnish.

[ghost]

I did wonder about the use of port 6081, and considered hitting it up in a web browser however the output was unexpected

Error 503 Service Unavailable Service Unavailable Guru Meditation: XID: 2133189223 Varnish cache server

as for setting varnishes listening ports the file /etc/sysconfig/varnish doesn't exist on a stock debian install a file is provided by the default install of varnish here /etc/default/varnish

and it contains a stock/example daemon config of "... DAEMON_OPTS="-a :6081 \ -T localhost:6082 \ -f /etc/varnish/default.vcl \ -S /etc/varnish/secret \ -s malloc,256m" ..."

So changes made thus far changed nginx listen port to 8080 ( because this is the port given in turpentines config file saved to /etc/varnish/default.vcl ) changed varnish listen port to 80

restarted all services.. root@debian:~# /etc/init.d/nginx restart Restarting nginx: nginx. root@debian:~# netstat -lnp | grep nginx tcp 0 0 0.0.0.0:8080 0.0.0.0:* LISTEN 15684/nginx tcp 0 0 0.0.0.0:81 0.0.0.0:* LISTEN 15684/nginx root@debian:~# /etc/init.d/varnish restart Stopping HTTP accelerator: varnishd. Starting HTTP accelerator: varnishd. root@debian:~# netstat -lnp | grep varnish tcp 0 0 0.0.0.0:80 0.0.0.0:* LISTEN 15722/varnishd tcp 0 0 127.0.0.1:6082 0.0.0.0:* LISTEN 15721/varnishd tcp6 0 0 :::80 :::* LISTEN 15722/varnishd

and bingo, everything is running exactly as it should be. Now to see the differences

Server Software: nginx/1.2.7 Server Hostname: iluvscotland.co.uk Server Port: 80

Document Path: /index.php/privacy-policy-cookie-restriction-mode Document Length: 20789 bytes

Concurrency Level: 40 Time taken for tests: 0.718 seconds Complete requests: 4000 Failed requests: 0 Write errors: 0 Total transferred: 84860000 bytes HTML transferred: 83156000 bytes Requests per second: 5567.19 #/sec Time per request: 7.185 ms Time per request: 0.180 [ms](mean, across all concurrent requests) Transfer rate: 115339.83 [Kbytes/sec] received

Connection Times (ms) min mean[+/-sd] median max Connect: 1 2 5.5 2 125 Processing: 1 5 11.3 4 135 Waiting: 1 3 10.0 2 134 Total: 2 7 12.8 6 141

Percentage of the requests served within a certain time (ms) 50% 6 66% 6 75% 6 80% 6 90% 7 95% 7 98% 8 99% 128 100% 141 (longest request) root@debian:~#

wholly smokes batman ...

I knew taking on this turpentine project would be worth while. Alex, you have been invaluable.

I am going to roll this out on my dev server, first for final testing but i'll be sure to take some detailed notes for installation on magento with debian6 + nginx + php-fpm and forward them over to you. It may be helpful for others.

thanks again,

Alistair

[aheadley]

wholly smokes batman ... I knew taking on this turpentine project would be worth while. Alex, you have been invaluable.

Glad you got it working, if you could add a review on Magento Connect I'd appreciate it.

I am going to roll this out on my dev server, first for final testing but i'll be sure to take some detailed notes for installation on magento with debian6 + nginx + php-fpm and forward them over to you. It may be helpful for others.

Great, more documentation is always welcome.