nginx proxy MISS

[Maxim Dounin]

Hello!

On Mon, Aug 10, 2020 at 07:33:22PM +0300, Slawa Olhovchenkov wrote:

> On Mon, Aug 10, 2020 at 07:13:22PM +0300, Maxim Dounin wrote:
> 
> > > > Я бы ещё внимательно посмотрел на тайминги.  Непонятно, что за 
> > > > времена приведены в логах, но $request_time там точно нет, а если 
> > > 
> > > $request_time $connection $upstream_cache_status $upstream_connect_time $upstream_response_time $upstream_bytes_received
> > > 
> > > > запросы общаются с бэкендом одновременно и proxy_cache_lock не 
> > > 
> > > да не вопрос.
> > > 
> > > > используется - то и MISS'ов может быть одновременно много, при 
> > > > этом завершаться запросы могут в заметно разное время.
> > > 
> > > не понимаю. вот есть первый запрос, окончился в 21:01:48, начался ну пусть в 21:01:47. апстрим отдался почти мгновенно.
> > > теперь на 5 дней должен быть хит независимо от. а в логе то хит то мисс.
> > 
> > Дальше имеет смысл смотреть на:
> > 
> > 1. Откуда вообще логи, с одной ли машины?  Такой разброс времени 
> > при логгировании можно, конечно, получить при буферизированном 
> > логгировании, но выглядит подозрительно.
> 
> с одной, буферезированно
> 
> > 2. Что на самом деле в заголовках ответов бэкенда?  Скажем, 
> > наличие какого-нибудь Vary легко объясняет наблюдаемый эффект.  
> 
> я поищу объект в кеше на диске.
> бакэнд -- ceph radosgw, он довстаточно тупой, кмк и ничего такого
> выдавать не должен.
> у типичного объекта заголовки выглядят так:
> 
> KEY:
> http://rgw/xxx....xxx/720p_00480.ts
> HTTP/1.1 200 OK
> Content-Length: 925524
> Accept-Ranges: bytes
> Last-Modified: Tue, 28 Jul 2020 11:24:38 GMT
> x-rgw-object-type: Normal
> ETag: "872d2e58236625d418f4c5b5b95938a6"
> x-amz-request-id: tx000000000000004e0151a-005f316581-a67b17a-default
> Access-Control-Allow-Origin: https://some.site
> Vary: Origin
> Access-Control-Allow-Methods: GET
> Access-Control-Expose-Headers: Content-Length,Content-Type
> Content-Type: video/MP2T
> Date: Mon, 10 Aug 2020 15:19:29 GMT
> Connection: close
> 
> это что, Vary: Origin гадит? фильтрануть его с бэкенда, что ли?

Это выглядит как наиболее вероятная причина.

При наличии "Vary: Origin" запросы с разными значениями заголовка 
Origin - это запросы, на которые могут быть разные ответы, и 
соответственно каждое новое значение - это очередной MISS в логах.

Для лечения есть ручка "proxy_ignore_headers Vary;" 
(http://nginx.org/r/proxy_ignore_headers).

> > Особенно в этом плане характерны запросы от одного клиента:
> > 
> > > 85.249.93.174 :61175 [01/Aug/2020:21:02:42 +0300]   "GET /720p_02815.ts HTTP/1.1" 200 616316 0.033 177157 MISS 0.000 0.005 616032
> > > 85.249.93.174 :61175 [01/Aug/2020:21:04:11 +0300]   "GET /720p_02815.ts HTTP/1.1" 200 616316 0.074 177157 HIT - - -
> > 
> > 3. Ну и проверить, что вообще в ключе кэширования, не добавлено ли 
> > там чего-либо клиентоспецифичного случайно.
> 
> вообще не модифицировалось

По умолчанию там конструкция, близкая к 
$scheme$proxy_host$request_uri, и, скажем $proxy_host может 
зависить от клиента, если в proxy_pass написать что-нибудь с 
переменными.

> > Если не поможет - смотреть debug log'и, там всё должно быть 
> > плюс-минус очевидно.
> 
> это продакшен, с дебаг логами боюсь все станет раком (а так бы я прямо
> с них и начал бы).

Just in case, дебаг можно включать не для всех, а только для части 
клиентов (http://nginx.org/r/debug_connection), это можно 
относительно безопасно делать в том числе и в продакшне.  Следя, 
естественно, чтобы не включить слишком много, и чтобы место под 
логи не кончалось.

-- 
Maxim Dounin
http://mdounin.ru/