SSE. Задержка отображения содержимого вкладок

[san]

При включенном режиме SSE, при попытке обновить страницу некоторые вкладки не отображаются сразу, приходится долго ждать.
После нажатия Ctrl+F5 появляется "шапка" с вкладками, однако вкладки: Платы, TDM, Генератор, Чат остаются пустыми, на длительное время (40+ секунд). Замечу, что если происходит какое-то событие(авария, сообщение в чате) содержимое вкладок сразу отображается.
r1955
Chrome 84.0.4147.105(64 бит)

Думаю, что будет правильно после обновления сразу отображать содержимое вкладок.

[alx]

Можешь приложить сюда дамп обмена по HTTP при загрузке страницы?

[san]

Вот ​дамп.
Браузер 192.168.0.5
SW-01 192.168.1.52

Запись начал перед обновлением страницы. Содержимое вкладки "Платы" отобразилось примерно через минуту, после чего запись закончил.

[alx]

Поведение хоста мне кажется очень странным...

17:42:16.745298 IP 192.168.0.5.54685 > 192.168.1.52.80: Flags [P.], seq 4904:5390, ack 175827, win 61441, length 486: HTTP: GET /events HTTP/1.1
17:42:17.214963 IP 192.168.0.5.54721 > 192.168.1.52.80: Flags [P.], seq 7083:7722, ack 34706, win 16092, length 639: HTTP: POST /api.php HTTP/1.1
17:42:17.236822 IP 192.168.1.52.80 > 192.168.0.5.54721: Flags [P.], seq 34706:35664, ack 7722, win 5279, length 958: HTTP: HTTP/1.1 200 OK
17:42:48.387377 IP 192.168.0.5.54721 > 192.168.1.52.80: Flags [P.], seq 7722:8361, ack 35664, win 16425, length 639: HTTP: POST /api.php HTTP/1.1
17:42:48.410524 IP 192.168.1.52.80 > 192.168.0.5.54721: Flags [P.], seq 35664:36622, ack 8361, win 5279, length 958: HTTP: HTTP/1.1 200 OK
17:43:17.156597 IP 192.168.0.5.54721 > 192.168.1.52.80: Flags [P.], seq 8361:8998, ack 36622, win 16185, length 637: HTTP: POST /api.php HTTP/1.1

Первая строчка - запрос от браузера к серверу. В ответ от сервера на порт 54685 - полная тишина, нет даже TCP ACK, что уже странно, учитывая что сервер живой, и мы видим, как по другим соединениям TCP идет обмен... Но что еще более странно, клиентская сторона, отправив данные и не получив в ответ ACK, не делает никаких повторных посылок...

Точно ли приложенный дамп полный? Какие фильтры использовались? Не было ли в процессе обмена каких-нибудь сообщений ICMP, которые не попали в дамп? Где (на клиенте, на сервере, между ними) был сделан этот дамп?

[alx]

Приходят в голову мысли о каких-то конфликтах адресов...

Попробуй воспроизвести проблему на "Нижнем самурае" (192.168.0.60 или [2a03:1ac0:2e92:d910:ad:c2ff:fe00:e1]).

[alx]

Вот как должно быть:

16:07:50.787019 IP6 (flowlabel 0x9357c, hlim 64, next-header TCP (6) payload length: 559) 2a02:2698:22:24bd::b851.48186 > 2a03:1ac0:2e92:d910:ad:c2ff:fe00:e1.80: Flags [P.], cksum 0x3ef5 (incorrect -> 0x0f72), seq 2134:2661, ack 1080, win 501, options [nop,nop,TS val 1853634997 ecr 278025409], length 527: HTTP, length: 527
	GET /events HTTP/1.1
	Host: [2a03:1ac0:2e92:d910:ad:c2ff:fe00:e1]
	Connection: keep-alive
	Accept: text/event-stream
	Cache-Control: no-cache
	User-Agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/84.0.4147.105 Safari/537.36
	Referer: http://[2a03:1ac0:2e92:d910:ad:c2ff:fe00:e1]/
	Accept-Encoding: gzip, deflate
	Accept-Language: ru-RU,ru;q=0.9,en-US;q=0.8,en;q=0.7
	Cookie: login=admin; time=1596884863; password=****************; nonce=2459fffeb95d8957427718a3cc811dfc
	
16:07:50.828566 IP6 (class 0x04, hlim 61, next-header TCP (6) payload length: 32) 2a03:1ac0:2e92:d910:ad:c2ff:fe00:e1.80 > 2a02:2698:22:24bd::b851.48186: Flags [.], cksum 0xf66f (correct), ack 2661, win 3036, options [nop,nop,TS val 278025869 ecr 1853634997], length 0
16:07:51.006138 IP6 (class 0x04, hlim 61, next-header TCP (6) payload length: 268) 2a03:1ac0:2e92:d910:ad:c2ff:fe00:e1.80 > 2a02:2698:22:24bd::b851.48186: Flags [P.], cksum 0x3c96 (correct), seq 1080:1316, ack 2661, win 3036, options [nop,nop,TS val 278026045 ecr 1853634997], length 236: HTTP, length: 236
	HTTP/1.1 200 OK
	Transfer-Encoding: chunked
	Connection: keep-alive
	Cache-Control: no-cache
	Content-Type: text/event-stream; charset=utf-8
	Date: Sat, 08 Aug 2020 11:07:50 GMT
	
	31
	retry: 5000
	data: {"type":"resync"}
	id: 1104601
	
	
16:07:51.006224 IP6 (flowlabel 0x9357c, hlim 64, next-header TCP (6) payload length: 32) 2a02:2698:22:24bd::b851.48186 > 2a03:1ac0:2e92:d910:ad:c2ff:fe00:e1.80: Flags [.], cksum 0x3ce6 (incorrect -> 0xfddf), ack 1316, win 501, options [nop,nop,TS val 1853635216 ecr 278026045], length 0

Получив событие типа "resync" браузер запрашивает текущее состояние блока - список плат, список аварий и т.п. В твоем эксперименте этого события почему-то не приходит, поэтому и список плат не запрашивается.

[alx]

Replying to alx:

Где (на клиенте, на сервере, между ними) был сделан этот дамп?

Судя по некорректным контрольным суммам IP в запросах, дамп был сделан на стороне клиента. Было бы интересно посмотреть, что видно на стороне сервера. А еще лучше - одновременно и там, и там...

[san]

Точно ли приложенный дамп полный?

Точно не полный, какие фильтры я не вспомню уже, но ​вот нефильтрованный дамп.

Попробуй воспроизвести проблему на "Нижнем самурае"

Визуально воспроизводится аналогично.

[alx]

Replying to san:

Точно не полный, какие фильтры я не вспомню уже, но ​вот нефильтрованный дамп.

Вот, совсем другое дело. Видно, что ответ браузер получил. Следовательно, проблема на его стороне.

А в консоли браузера ошибок нет?

[alx]

Попробуй сейчас открыть "Нижний самурай". Я заметил, что события сервера парсились функцией parseJSON(), тогда как во всех остальных местах использовалась собственная обертка evalJSON(). Заменил первую на вторую чтобы было "как везде". Хотя скорее всего никакой разницы не будет, так как обе функции - обертки нативной функции JSON.parse()... Мой Хром работает одинаково с обоими вариантами, но вдруг твоему что-то не понравилось...

[san]

Открыл Самурай, разницы не заметил, ошибок в консоли нет.

[alx]

Подобавлял вывод контрольных точек в консоль. Обнови, пожалуйста, страничку в "Нижнем самурае" и скажи, что напишет в консоль.

[san]

Все 4 надписи появились только спустя длительное время, во время отображения содержимого вкладки

[alx]

Я здаюсь. Все контрольный точки пройдены. "checkpoint 4" - самая последняя. В следующей за ней строке отправляется запрос "board", которого твой браузер, судя по дампу, почему-то не отправляет... Необъяснимо...

[san]

Так они пройдены только ПОСЛЕ длительного ожидания...

[san]

Ещё заметил, что при установке в консоли уровня вывода "Verbose", после обновления страницы постепенно накапливаются какие-то сообщения:

[alx]

Replying to san:

Все 4 надписи появились только спустя длительное время, во время отображения содержимого вкладки

А-а-а... Сообщение "checkpoint 1" выводится немедленно после получения любого сообщения. Как мы видим по дампу, сообщение {"type":"resync"} передается немедленно после подключения браузера, и браузер его принимает. Но обработчик события вызывает, как ты пишешь, спустя длительное время. Следовательно, проблема сидит где-то внутри барузера. Странно только, что тот же самый браузер у меня работает нормально... Возможно, проблема связана не с кодом самого (или не только с кодом самого) браузера, а какой-то используемой библиотекой, которая в наших системах отличается...

Что с этим делать - непонятно... Путь пока тикет повисит, вдруг появятся какие-нибудь идеи...

[alx]

Я только что заметил, что браузер начинает обрабатывать сообщение после того как через минуту бездействия сервер передает в соединение пустой комментарий ":\n" (keep-alive для предотвращения разъединения). Возникла мысль попробовать передавать это сразу после первого сообщения.

Попробуй еще раз открыть "Нижний самурай".

[san]

Также, пустая вкладка висит минуту...

Ещё браузер "просыпается" и отображает содержимое вкладки если происходит какой-нибудь ивент, например авария.

[alx]

В порядке шаманства: вычитал где-то о том, что надо послать в самом начале 2 килобайта мусора (закомментаренного), почему-то было написано, что это надо для IE (вообще-то IE не поддерживает SSE). Сделал это в "Нижнем самурае". Попробуй, не будет ли каких-либо улучшений?

И правильно ли я понимаю, что после запроса и отрисовки списка плат задержек с реакцией на события уже не наблюдается?

[san]

Попробовал, улучшение не вижу.
Да, никаких задержек событий не наблюдается, проблема только с задержкой первого вывода содержимого вкладки.

[san]

В r1975 ничего похожего не замечаю.
После нажатия Ctrl+F5 сразу отображается всё содержимое.
Chrome 86.0.4240.193(64 бит)

Толи в хроме пофиксили что-то, толи у нас что-то изменилось.
Вообщем сейчас всё хорошо.