Nginx FastCGI returns a "spoiled" image, with a different Content-Length. Why?

P

pavelole2018-01-04 14:47:37

Drupal

pavelole, 2018-01-04 14:47:37

The site is running on Nginx + PHP-FPM (on CMS Drupal 7).
In the browser console, most images get the net::ERR_CONTENT_LENGTH_MISMATCH error.
nginx config:

server {
    #сайт запущен на 8080 порту, перед ним стоит varnish на 80, картинка, отдаваемая друпалом "портится" уже на этапе PHP-FPM
    listen 212.***.***.***:8080;
    server_name mysite.ru;

    proxy_buffering off;

    client_max_body_size 10m;
    client_body_buffer_size 1024k;
    index index.php;
    charset UTF-8;
    disable_symlinks if_not_owner from=$root_path;
    include /etc/nginx/vhosts-includes/*.conf;
    include /etc/nginx/vhosts-resources/mysite.ru/*.conf;
    access_log /var/www/httpd-logs/mysite.ru.access.log ;
    error_log /var/www/httpd-logs/mysite.ru.error.log debug;
    ssi on;
    set $root_path /var/www/mysite/data/www/mysite.ru;
    root $root_path;

    location ~ \..*/.*\.php$ {
        return 403;
    }

    location / {
    try_files $uri /index.php?$query_string;
        expires 30d;
    }

    location @rewrite {
        rewrite ^/(.*)$ /index.php?q=$1;
    }

    location ~ '\.php$|^/update.php' {
        fastcgi_split_path_info ^(.+?\.php)(|/.*)$;
        include fastcgi_params;
        fastcgi_param HTTP_PROXY "";
        fastcgi_param SCRIPT_FILENAME $document_root$fastcgi_script_name;
        fastcgi_param PATH_INFO $fastcgi_path_info;
        fastcgi_param QUERY_STRING $query_string;
        fastcgi_intercept_errors on;
        fastcgi_param PHP_ADMIN_VALUE "sendmail_path = /usr/sbin/sendmail -t -i -f [email protected]";
        try_files $uri =404;
        fastcgi_pass unix:/var/www/php-fpm/mysite.sock;
    }

    location ~* \.(js|css|png|jpg|jpeg|gif|ico|svg)$ {
        try_files $uri @rewrite;
        expires 30d;
    }

    gzip on;
    gzip_comp_level 5;
    gzip_disable "msie6";
    gzip_types text/plain text/css application/json application/x-javascript text/xml application/xml application/xml+rss text/javascript application/javascript;
}

There are no errors in the nginx logs, and if you enable log debag, then when you try to load a picture, the following error.log logs are written (when you request a picture, you get a lot of logs, so I shortened them, I hope I didn’t hurt anything useful):

nginx debag logs

2017/12/28 14:02:02 [notice] 3222#3222: *18 rewritten data: "/index.php", args: "q=sites/default/files/styles/large/public/inline/images/29/sochi_galechnyi_plyazh_25.jpg", client: 31.202.5.148, server: mysite.ru, request: "GET /sites/default/files/styles/large/public/inline/images/29/sochi_galechnyi_plyazh_25.jpg HTTP/1.1", host: "212.***.***.***:8080", referrer: "http://212.***.***.***:8080/pogoda-v-sochi-v-noyabre-2018-goda?amp"
......
2017/12/28 14:02:02 [debug] 3222#3222: *18 test location: ~ "\.php$|^/update.php"
2017/12/28 14:02:02 [debug] 3222#3222: *18 using configuration "\.php$|^/update.php"
......
2017/12/28 14:02:02 [debug] 3222#3222: *18 http fastcgi header: "Content-Length: 60023"
2017/12/28 14:02:02 [debug] 3222#3222: *18 http fastcgi parser: 1
2017/12/28 14:02:02 [debug] 3222#3222: *18 http fastcgi header done
2017/12/28 14:02:02 [debug] 3222#3222: *18 HTTP/1.1 200 OK
Server: nginx/1.12.2
Date: Thu, 28 Dec 2017 11:02:02 GMT
Content-Type: image/jpeg
Content-Length: 60023
Connection: keep-alive
Expires: Sun, 19 Nov 1978 05:00:00 GMT
Cache-Control: no-cache, must-revalidate
X-Content-Type-Options: nosniff
2017/12/28 14:02:02 [debug] 3222#3222: *18 write new buf t:1 f:0 000055D5E4BF8F18, pos 000055D5E4BF8F18, size: 266 file: 0, size: 0
2017/12/28 14:02:02 [debug] 3222#3222: *18 http write filter: l:0 f:0 s:266
......
2017/12/28 14:02:02 [debug] 3222#3222: *18 http write filter 0000000000000000
2017/12/28 14:02:02 [debug] 3222#3222: *18 http copy filter: 0 "/index.php?q=sites/default/files/styles/large/public/inline/images/29/sochi_galechnyi_plyazh_25.jpg"
2017/12/28 14:02:02 [debug] 3222#3222: *18 pipe write downstream done
2017/12/28 14:02:02 [debug] 3222#3222: *18 event timer: 26, old: 1514458982606, new: 1514458982750
2017/12/28 14:02:02 [debug] 3222#3222: *18 http upstream exit: 0000000000000000
2017/12/28 14:02:02 [debug] 3222#3222: *18 finalize http upstream request: 0
2017/12/28 14:02:02 [debug] 3222#3222: *18 finalize http fastcgi request
2017/12/28 14:02:02 [debug] 3222#3222: *18 free rr peer 1 0
2017/12/28 14:02:02 [debug] 3222#3222: *18 close http upstream connection: 26
2017/12/28 14:02:02 [debug] 3222#3222: *18 free: 000055D5E4B26080, unused: 48
2017/12/28 14:02:02 [debug] 3222#3222: *18 event timer del: 26: 1514458982606
2017/12/28 14:02:02 [debug] 3222#3222: *18 reusable connection: 0
2017/12/28 14:02:02 [debug] 3222#3222: *18 http upstream temp fd: -1
2017/12/28 14:02:02 [debug] 3222#3222: *18 http output filter "/index.php?q=sites/default/files/styles/large/public/inline/images/29/sochi_galechnyi_plyazh_25.jpg"
2017/12/28 14:02:02 [debug] 3222#3222: *18 http copy filter: "/index.php?q=sites/default/files/styles/large/public/inline/images/29/sochi_galechnyi_plyazh_25.jpg"
2017/12/28 14:02:02 [debug] 3222#3222: *18 http postpone filter "/index.php?q=sites/default/files/styles/large/public/inline/images/29/sochi_galechnyi_plyazh_25.jpg" 00007FFE07D7C1D0
2017/12/28 14:02:02 [debug] 3222#3222: *18 write new buf t:0 f:0 0000000000000000, pos 0000000000000000, size: 0 file: 0, size: 0
2017/12/28 14:02:02 [debug] 3222#3222: *18 http write filter: l:1 f:0 s:0
2017/12/28 14:02:02 [debug] 3222#3222: *18 http copy filter: 0 "/index.php?q=sites/default/files/styles/large/public/inline/images/29/sochi_galechnyi_plyazh_25.jpg"
2017/12/28 14:02:02 [debug] 3222#3222: *18 http finalize request: 0, "/index.php?q=sites/default/files/styles/large/public/inline/images/29/sochi_galechnyi_plyazh_25.jpg" a:1, c:1
2017/12/28 14:02:02 [debug] 3222#3222: *18 set http keepalive handler
2017/12/28 14:02:02 [debug] 3222#3222: *18 http close request
2017/12/28 14:02:02 [debug] 3222#3222: *18 http log handler
2017/12/28 14:02:02 [debug] 3222#3222: *18 free: 0000000000000000
2017/12/28 14:02:02 [debug] 3222#3222: *18 free: 0000000000000000
2017/12/28 14:02:02 [debug] 3222#3222: *18 free: 000055D5E4BF9810
2017/12/28 14:02:02 [debug] 3222#3222: *18 free: 000055D5E4B37590, unused: 3
2017/12/28 14:02:02 [debug] 3222#3222: *18 free: 000055D5E4BF77F0, unused: 6
2017/12/28 14:02:02 [debug] 3222#3222: *18 free: 000055D5E4BF8800, unused: 649
2017/12/28 14:02:02 [debug] 3222#3222: *18 free: 000055D5E4BF30E0
2017/12/28 14:02:02 [debug] 3222#3222: *18 hc free: 0000000000000000
2017/12/28 14:02:02 [debug] 3222#3222: *18 hc busy: 0000000000000000 0
2017/12/28 14:02:02 [debug] 3222#3222: *18 tcp_nodelay
2017/12/28 14:02:02 [debug] 3222#3222: *18 reusable connection: 1
2017/12/28 14:02:02 [debug] 3222#3222: *18 event timer add: 25: 65000:1514458987750

As you can see, Drupal returns a header with Content-Length: 60023.
And the access.log log looks like this:

31.202.5.148 - - [28/Dec/2017:14:02:02 +0300] "GET /sites/default/files/styles/large/public/inline/images/29/sochi_galechnyi_plyazh_25.jpg HTTP/1.1" 200 60021 "http://212.***.***.***:8080/pogoda-v-sochi-v-noyabre-2018-goda" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_2) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/63.0.3239.84 Safari/537.36"

Here, for some reason, the file size is 60021.
In the Chrome console in the Header, the file size is 60023 (apparently, the real size of the picture is 60021, this is the mismatch):

Cache-Control:no-cache, must-revalidate
Connection:keep-alive
Content-Length:60023
Content-Type:image/jpeg
Date:Thu, 28 Dec 2017 11:02:02 GMT
Expires:Sun, 19 Nov 1978 05:00:00 GMT
Server:nginx/1.12.2
X-Content-Type-Options:nosniff

As a result, the picture at first seems to be loading, but is slightly corrupted at the bottom, then the picture disappears and the net::ERR_CONTENT_LENGTH_MISMATCH error appears. The picture looks like this (note that the bottom bar is underloaded):

picture

Error in Chrome console:

GET http://212.***.***.***:8080/sites/default/files/styles/large/public/inline/images/29/sochi_galechnyi_plyazh_25.jpg net::ERR_CONTENT_LENGTH_MISMATCH
http://212.***.***.***:8080/sites/default/files/styles/large/public/inline/images/29/sochi_galechnyi_plyazh_25.jpg

As you can see, the picture actually has Content-Length: 60023, but then for some reason nginx spoils it, and the size becomes 60021. Tell me, why is this happening?