Случилось тут у нас странное: заметили, что жалюзи и шторы стали жить своей жизнью. В основном жалюзи, но иногда и шторы занимали какое-то рандомное положение, чаще всего утром.

У нас есть несколько сценариев управления жалюзями, например они закрываются сами утром, если прогноз на сегодня больше 28 °C. Шторы закрываются сами с вечера и и открываются утром. Ну и тому подобные несложные сценарии.

Проблема оказалась в залипающем веб-интерфейсе в Firefox на десктопе, который некорректно стартовал при восстановлении запиненой вкладки.

… но это стало известно уже сильно потом, сначала пришлось разбираться.

Для начала, конфигурация. Всё управление жалюзями и шторами разбито на три группы (файл items/curtains.items):

Group blinds_curtains_cmd "Blinds+Curtains command []" <rollershutter>

Group blinds_cmd "Blinds command []" <rollershutter> (blinds_curtains_cmd)
Group:Dimmer:AVG blinds_pos "Blinds pos [%d %%]" <rollershutter> (g_all)

Group curtains_cmd "Curtains command []" <curtains> (blinds_curtains_cmd)
Group:Dimmer:AVG curtains_pos "Curtains pos [%d %%]" <curtains> (g_all)

Имеется: команда всем (и шторы и жалюзи), команда открыть/закрыть/стоп только жалюзи (blinds) или шторам (curtains), так же установка положения в % для того же набора. Так же имеется аналогичные группы по комнатам, но они тут не играют роли. Мета-группа g_all нужна для управления OpenHAB через Алису. Обратите внимание, что группа управляет несколькими объектами и принимает среднее значение. То есть если одна штора открыта, а две закрыты, то будет 33%.

Изучил логи, там нашлись записи вида:

23:40:05.933 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'ku_blinds_pos' received command 100
07:58:51.880 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'blinds_pos' received command 30
08:01:34.136 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'blinds_pos' received command 36
09:45:40.444 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'sz_blinds_pos' received command 0
14:11:35.509 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'blinds_pos' received command 36
19:26:08.414 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'blinds_pos' received command 27
10:35:41.262 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'blinds_pos' received command 27

То есть, группа blinds_pos получает команду на закрытие в процентах: 30, 36, 27… Что за черт?

Первая мысль была — у нас подключен сервис управления через myopenhab.org, что бы родное приложение на iOS и Android показывали нативные пуши и не требовали VPN для управления и где-то спалил ключи и кто-то балуется.

Алиса — исключаем, так как в логе нет сообщений о приёме команд от прокси (а оно логирует всегда).

Но для начала, решил всё-таки воспроизвести баг (или подождать пока снова наступит). Для отладки включил все логи в уровень DEBUG. Это можно сделать через консоль, но гораздо удобнее отредактировать файл /userdata/etc/log4j2.xml , где выставить нужные уровни. Заодно увеличиваем максимальные размер лога и ротацию, так как логов намного больше.

Включаем логи, рестартим и ждём пока не глюкнет снова. Но когда это будет? Может сегодня, а может через месяц. Кстати, зная суть бага можно уже сказать что могло и никогда не глюкнуть, так как для этого нужны были совпадения условий.

Поскольку ждать было влом, решил посмотреть логи Nginx, за которым у меня собственно находится контейнер с OpenHAB. И там с немалым удивлением обнаружил, что команда поступила через Веб-интерфейс от меня самого! Там был IP-Адрес моего компьютера.

10.1.2.3 - - [23/Sep/2024:07:59:19 +0200] "POST /rest/items/blinds_pos HTTP/2.0" 400 0 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:130.0) Gecko/20100101 Firefox/130.0"
10.1.2.3 - - [23/Sep/2024:07:59:21 +0200] "POST /rest/items/blinds_pos HTTP/2.0" 400 0 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:130.0) Gecko/20100101 Firefox/130.0"
10.1.2.3 - - [23/Sep/2024:08:01:34 +0200] "POST /rest/items/blinds_pos HTTP/2.0" 200 0 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:130.0) Gecko/20100101 Firefox/130.0"
10.1.2.3 - - [23/Sep/2024:08:01:36 +0200] "POST /rest/items/blinds_pos HTTP/2.0" 400 0 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:130.0) Gecko/20100101 Firefox/130.0"
10.1.2.3 - - [23/Sep/2024:08:01:37 +0200] "POST /rest/items/blinds_pos HTTP/2.0" 400 0 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:130.0) Gecko/20100101 Firefox/130.0"
10.1.2.3 - - [23/Sep/2024:08:01:38 +0200] "POST /rest/items/blinds_pos HTTP/2.0" 400 0 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:130.0) Gecko/20100101 Firefox/130.0"

В логе выше один из случаев, когда в 08:01 жалюзи получили команду установки 36%. И команда пришла с моего десктопа, судя по адресу. У меня как раз в примерно восемь был онлайн-урок по немецкому.

На комьютере для управления умным домом у меня есть только одно — интерфейс BasicUI в виде запиненой вкладке в браузере Firefox. И в этом интерфейсе есть два слайдера, которые как раз командуют данными группами:

Следовательно, при открытии браузера он восстанавливал прошлые вкладки и интерфейс отправлял последние сохраненные значения как обновление слайдеров. Таким образом, что бы баг проявился, необходимо следующее:

• Пользоваться веб-интерфейсом на десктопе каким-либо образом
• Выключить компьютер (закрыть браузер)
• В то время пока компьютер выключен — шторы или жалюзи должны поменять своё значение на какое-то другое
• При включении компьютера все шторы и жалюзи получают команду на среднее значение того что было при выключении: то есть если одна была закрыта, а две открыты, то все они встанут в среднее положение — то есть будут закрыты на треть

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

Судя по всему, бага на такое поведение в Firefox описана тут: [BasicUI] Live update is fully unstable with OH 4.1.1 and Firefox 121.0.1.

Решить можно двумя способами:

• В Firefox надо включить опцию browser.sessionstore.restore_pinned_tabs_on_demand в значение false. Что не будет подгружать старое содержимое во вкладки при восстановлении и они будут грузиться сначала при первом открытии. Подробное описание здесь.
• Просто убрать слайдеры с главной страницы интерфейса. Все остальные контролы не имеют этого бага.

Я применил оба способа — всё равно удобнее, что вкладки обновляют содержимое на старте, а слайдеры на главной заменил на простое отображение состояния — всё равно ими никто не пользовался особо.

Такой вот странный баг — чего только не бывает в умном доме!