Зависание плагина MegaD

intrapro

Alex_Jet, правда, удивительно… Спасибо за подробное описание.

Будем рыть глубже

Пожалуйста, обновите систему, добавлено логирование событий сокета.

Упс...Логирование пока убрали, там ошибка. Последний релиз v17.01.06.01 с обычным логированием.

Alex_Jet

Да, обновил и ничего нового не увидел:). Буду ждать когда добавите.

Alex_Jet

С Рождеством весь Ваш коллектив!!!

Сегодня выловил еще вот такой момент:

07.01.2017 16:22:53 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=31&cmd=list
07.01.2017 16:22:53 localhost <= 192.168.12.20:80 HTTP busy
07.01.2017 16:22:53 MG2?
07.01.2017 16:23:53 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=30&cmd=get
07.01.2017 16:23:53 localhost <= 192.168.12.20:80 HTTP temp:26.20/hum:15.30
07.01.2017 16:23:53 MG2?30_1=26.2&30_2=15.3&
07.01.2017 16:23:53 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=31&cmd=list
07.01.2017 16:23:53 localhost <= 192.168.12.20:80 HTTP busy
07.01.2017 16:23:53 MG2?
07.01.2017 16:24:53 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=30&cmd=get
07.01.2017 16:24:53 localhost <= 192.168.12.20:80 HTTP temp:26.20/hum:15.30
07.01.2017 16:24:53 MG2?30_1=26.2&30_2=15.3&
07.01.2017 16:24:53 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=31&cmd=list
07.01.2017 16:24:53 localhost <= 192.168.12.20:80 HTTP busy
07.01.2017 16:24:53 MG2?
07.01.2017 16:25:53 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=30&cmd=get
07.01.2017 16:25:53 localhost <= 192.168.12.20:80 HTTP temp:26.30/hum:15.50
07.01.2017 16:25:53 MG2?30_1=26.3&30_2=15.5&
07.01.2017 16:25:53 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=31&cmd=list
07.01.2017 16:25:53 localhost <= 192.168.12.20:80 HTTP busy
07.01.2017 16:25:53 MG2?

Порт 31 сконфигурирован как 1-wire bus, на нем сейчас висит 3 датчика DS18B20. Период конвертации данных в MegaD - 30 секунд. Когда запрос попадает на момент конвертации, то MegaD выдает "busy". Однако это "busy" в логах плагина длилось порядка 1 часа, пока я не перезагрузил плагин. Как Вы понимаете, 60 раз попадать на момент конвертации данных просто невозможно! Такое ощущение, что это где-то закэшировалось…

intrapro

Alex_Jet, спасибо, и Вас с Рождеством!!! Готово рождественское обновление

1. В плагине MegaD - добавлено логирование событий сокета. Также сокет принудительно закрывается после каждого запроса.

2. Добавлен флаг Debug - сохранение флагов трассировки, suspend и log для плагинов при перезагрузке.

Alex_Jet

Спасибо, обновлюсь.

Тут уже методом перебора пытаюсь выявить из-за чего плагин зависает, поэтому отключаю по одному из датчиков. Отключил датчик СО2, показания по которому обрабатываются скриптом, убрав период опроса в Request, однако при старте плагина скрипт загружается, идет первый опрос и на этом заканчивается. По моему это не правильно. По идее если убрали период опроса, то и скрипт не должен загружаться? Ну или как-то так - Вы сами определите как должно быть правильно.

08.01.2017 20:25:59 MegaD plugin has started.
08.01.2017 20:25:59 Listening localhost:8020
08.01.2017 20:25:59 Address 36 (IA36). Loading script
08.01.2017 20:25:59 Polling   192.168.12.20:80/sec/?cmd=all, interval 0 sek
08.01.2017 20:25:59 Polling   192.168.12.20:80/sec/?pt=30&cmd=get, interval 60 sek
08.01.2017 20:25:59 Polling   192.168.12.20:80/sec/?pt=31&cmd=list, interval 60 sek
08.01.2017 20:25:59 localhost => 192.168.12.20:80 HTTP GET /sec/?cmd=all
08.01.2017 20:25:59 localhost <= 192.168.12.20:80 HTTP OFF/0;OFF/0;OFF/0;OFF/0;OFF/0;OFF/0;OFF/0;OFF;ON;OFF;ON;OFF;OFF;OFF;ON;OFF/0;OFF/0;OFF/0;OFF/0;OFF/0;OFF/0;OFF/0;OFF;OFF;OFF;OFF;ON;OFF;OFF;ON;temp:25.30/hum:14.10;;OFF;OFF;;OFF;160;ON
08.01.2017 20:25:59 Address 36
08.01.2017 20:25:59     run script: val=160 depo={}
08.01.2017 20:25:59  script return:{ reqsek: 5 } depo={ res: [ 160 ] }
08.01.2017 20:25:59 MG2?0=0&1=0&2=0&3=0&4=0&5=0&6=0&7=0&8=1&9=0&10=1&11=0&12=0&13=0&14=1&15=0&16=0&17=0&18=0&19=0&20=0&21=0&22=0&23=0&24=0&25=0&26=1&27=0&28=0&29=1&30_1=25.3&30_2=14.1&31=0&32=0&33=0&34=0&35=0&37=1&
08.01.2017 20:26:59 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=30&cmd=get
08.01.2017 20:27:00 localhost <= 192.168.12.20:80 HTTP temp:24.80/hum:8.40
08.01.2017 20:27:00 MG2?30_1=24.8&30_2=8.4&

Сам скрипт, который Владимир на ab-log выкладывал:

function (val, depo)
{   var result;

   if (!depo.res) depo.res = [];   
   depo.res.push(val);  

   if (depo.res.length < 5)    return { reqsek:5 }; // Нужны еще измерения, значение не возвращаем
   depo.res.sort();   

   result = ((Math.round((depo.res[1] + depo.res[2] + depo.res[3]) / 3) - 100 ) * 10 + 350);

   depo.res = []; // Перед следующими измерениями сбрасываем массив
   return { val:result, reqsek:300 }; // Восстанавливаем период 5 мин
}

Alex_Jet

@intrapro:

Alex_Jet, спасибо, и Вас с Рождеством!!! Готово рождественское обновление

1. В плагине MegaD - добавлено логирование событий сокета. Также сокет принудительно закрывается после каждого запроса.

2. Добавлен флаг Debug - сохранение флагов трассировки, suspend и log для плагинов при перезагрузке.

1. В логе плагина ничего не увидел нового… где смотреть? UPD: все увидел! Просто логи плагинов после обновления выключились....

2. Где это найти?

Нельзя ли в каналы плагинов вывести столбец "Период опроса"? Правда вероятно для маленьких разрешений экрана надо будет горизонтальный скролбар добавить... иначе, например, у меня при 1280х720 содержание столбца "Устройства в системе" уже обрезано.

Вот такой вредный busy на канале с 1-wire bus! Так понимаю, что на протяжении примерно 30 минут запрос попадает на конвертацию температуры:

08.01.2017 22:53:26 
08.01.2017 22:53:26 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=31&cmd=list
08.01.2017 22:53:26 localhost <=>192.168.12.20:80 socket handle=17\. Header: GET /sec/?pt=31&cmd=list HTTP/1.1
Host: 192.168.12.20
Connection: close

08.01.2017 22:53:26 localhost <= 192.168.12.20:80 response: statusCode=200 contentType = text/html
08.01.2017 22:53:26 localhost <= 192.168.12.20:80 HTTP busy
08.01.2017 22:53:26 MG2?
08.01.2017 22:53:26 localhost <=>192.168.12.20:80 socket closed

intrapro

@Alex_Jet:

Отключил датчик СО2, показания по которому обрабатываются скриптом, убрав период опроса в Request, однако при старте плагина скрипт загружается, идет первый опрос и на этом заканчивается. По моему это не правильно. По идее если убрали период опроса, то и скрипт не должен загружаться?

Сейчас скрипт грузится, если для канала стоит галка: "Запускать скрипт обработки данных" (колонка Скрипт).

Если галку убрать, скрипт не пропадет, будет доступен для редактирования, просто не будет загружаться.

Связи с периодом опроса канала нет, т.к. значение может читаться при общем опросе. Или как для двойных датчиков или 1-Wire - период м.б. ноль, но данные можно обработать скриптом.

@Alex_Jet:

Нельзя ли в каналы плагинов вывести столбец "Период опроса"? Правда вероятно для маленьких разрешений экрана надо будет горизонтальный скролбар добавить… иначе, например, у меня при 1280х720 содержание столбца "Устройства в системе" уже обрезано.

Горизонтальный скролбар убирали из эстетических соображений :). В планах у нас включена задача: настраивать интерактивно ширину и состав столбцов таблиц в PM.

@Alex_Jet:

Просто логи плагинов после обновления выключились….

Да, в новом релизе добавлен флаг Debug: "Запустить в режиме отладки".

Устанавливается PM: Система - Системные настройки - Параметры запуска сервера.

При установленном Debug после перезагрузки:

сохраняются флаги suspend и log для плагинов,
сохраняются системные флаги логирования (Трассировка).

Если флаг сброшен, при перезагрузке все это сбрасывается (рабочий режим).

intrapro

@Alex_Jet:

Порт 31 сконфигурирован как 1-wire bus, на нем сейчас висит 3 датчика DS18B20. Период конвертации данных в MegaD - 30 секунд. Когда запрос попадает на момент конвертации, то MegaD выдает "busy". Однако это "busy" в логах плагина длилось порядка 1 часа, пока я не перезагрузил плагин.

….

Вот такой вредный busy на канале с 1-wire bus! Так понимаю, что на протяжении примерно 30 минут запрос попадает на конвертацию температуры

А сколько времени MegaD находится в состоянии busy? Если речь идет о 1-2 сек, то попав в зону busy, можно там и остаться, если период опроса кратен 30 сек ( в данном случае 60 сек). Вариант решения - сделать период не кратным 30 сек - 67 сек, например.

Alex_Jet

Как ответил разработчик MegaD - период конвертации для любого количества датчиков равен 750 мС. Конечно можно разносить период опроса вручную, но вероятно лучше программно обрабатывать тот же "busy" - если ответ такой, то повторяем запрос через 1 секунду, иначе следующий интервал опроса тот что в request.

Кстати, в настройках железа устройств есть "Специальное значение, означающее ошибку датчика" как это работает? То есть впишу я туда "busy" и что сделает система когда датчик ответит ей "busy"? Надо бы это осветить!

Пока больше зависаний плагина не могу зафиксировать. Спустя примерно 5 часов виснет сама MegaD! Сегодня поменяю железку на новую - тут виновата либо железо, либо система…

intrapro

@Alex_Jet:

Как ответил разработчик MegaD - период конвертации для любого количества датчиков равен 750 мС. Конечно можно разносить период опроса вручную, но вероятно лучше программно обрабатывать тот же "busy" - если ответ такой, то повторяем запрос через 1 секунду, иначе следующий интервал опроса тот что в request..

Да, программно обрабатывать можно, просто не хотелось привязываться к деталям реализации…

И жестко программировать повтор запросов, устройство довольно нежное

Поскольку у нас нет возможности проверить (у нас есть только MegaD 238), проверьте пожалуйста, если цикл сдвинуть - ответ после busy все же придет?

@Alex_Jet:

Кстати, в настройках железа устройств есть "Специальное значение, означающее ошибку датчика" как это работает? То есть впишу я туда "busy" и что сделает система когда датчик ответит ей "busy"? Надо бы это осветить!

Эту настройку плагин Mega пока не использует. Стандартное использование - если с канала читается что-то не то, то просто выставляется флаг ошибки датчика, будет алерт и соотв. индикация.

@Alex_Jet:

Пока больше зависаний плагина не могу зафиксировать. Спустя примерно 5 часов виснет сама MegaD! Сегодня поменяю железку на новую - тут виновата либо железо, либо система…

Как в этом случае отрабатывает плагин? Ошибка индицируется? Что в логах?

В последней версии плагина кроме логирования событий сокета делается принудительное закрытие сокета после каждого запроса.

Alex_Jet

@intrapro:

Поскольку у нас нет возможности проверить (у нас есть только MegaD 238), проверьте пожалуйста, если цикл сдвинуть - ответ после busy все же придет?

Да вот как это проверить? Например, запускается плагин и некоторое время все хорошо, а спустя 1-5 часов период опроса попадает на busy. И может час попадать на момент конвертации. Ждать больше не получалось пока (зависает MegaD или перезапускал плаги вручную).
@intrapro:

Эту настройку плагин Mega пока не использует. Стандартное использование - если с канала читается что-то не то, то просто выставляется флаг ошибки датчика, будет алерт и соотв. индикация.

То есть на данный момент бесполезно там что-то писать?
@intrapro:

Как в этом случае отрабатывает плагин? Ошибка индицируется? Что в логах?

В последней версии плагина кроме логирования событий сокета делается принудительное закрытие сокета после каждого запроса.

Закрытие сокета вижу. MegaD уходит в зависание насовсем (ping нет, сам контроллер свои сценарии не отрабатывает), соответственно intrahouse говорит о том что "Контроллер MegaD. Ошибка!" и в лог такой:

11.01.2017 01:30:16 MegaD plugin has started.
11.01.2017 01:30:16 Listening localhost:8020
11.01.2017 01:30:16 Address 36 (IA36). Loading script
11.01.2017 01:30:16 Polling   192.168.12.20:80/sec/?cmd=all, interval 0 sek
11.01.2017 01:30:16 Polling   192.168.12.20:80/sec/?pt=30&cmd=get, interval 60 sek
11.01.2017 01:30:16 Polling   192.168.12.20:80/sec/?pt=36&cmd=get, interval 300 sek
11.01.2017 01:30:16 Polling   192.168.12.20:80/sec/?pt=31&cmd=list, interval 60 sek
11.01.2017 01:30:16 Polling   192.168.12.20:80/sec/?pt=34&scl=35&i2c_dev=htu21d&i2c_par=1, interval 60 sek
11.01.2017 01:30:16 Polling   192.168.12.20:80/sec/?pt=34&scl=35&i2c_dev=htu21d, interval 60 sek
11.01.2017 01:30:16 
11.01.2017 01:30:16 localhost => 192.168.12.20:80 HTTP GET /sec/?cmd=all
11.01.2017 01:30:16 localhost <=>192.168.12.20:80 socket handle=16\. Header: GET /sec/?cmd=all HTTP/1.1
Host: 192.168.12.20
Connection: close

11.01.2017 01:30:20 localhost <= 192.168.12.20:80 Error EHOSTUNREACH.  Stopped.

intrapro

@Alex_Jet:

То есть на данный момент бесполезно там что-то писать?

Да
@Alex_Jet:

Пока больше зависаний плагина не могу зафиксировать. Спустя примерно 5 часов виснет сама MegaD! Сегодня поменяю железку на новую - тут виновата либо железо, либо система…

Удалось ли восстановить работоспособность MegaD? Не хочется добавлять новый функционал, пока не разобрались с зависанием.

Alex_Jet

@intrapro:

Удалось ли восстановить работоспособность MegaD? Не хочется добавлять новый функционал, пока не разобрались с зависанием.

Проблема примерно локализована - необходимо время для проведения еще нескольких тестов.

С тех пор как добавили закрытие сокетов в плагине он ни разу не зависал. Последний uptime-работы плагина - 18 часов, однако убран опрос I2C датчика HTU21D. Большая вероятность что именно из-за его обработки виснит MegaD.

Alex_Jet

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

По зависанию MegaD. Конечно этого не должно быть в принципе, но пока складывается ощущение, что контроллер вешается только в том случае если с помощью intrahouse начинаю опрашивать HTU21D с помощью команды /%pwd%/?pt=34&scl=35&i2c_dev=htu21d&i2c_par=1. То есть как только ввожу в действие опрос этого датчика, то MegaD спустя 4-9 часов зависает. Замечено, что если опрашиваю сразу по обоим параметрам (температура и влажность), причем интервал опроса один и то же для обоих каналов - 60 секунд, то контроллер вешается быстрее - от 2 до 3-х часов.

Мое мнение такое - intrahouse cлишком быстр, в отличие от php и в какой-то момент запросы по каждому каналу начинают сыпаться один за другим с минимальным промежутком, в итоге MegaD виснет от ddos-атаки.

У разработчика MegaD моя конфигурация на php уже работает несколько суток без каких-либо сбоев (опрос датчиков каждые 8 секунд). Сейчас провожу повторный тест - опрашиваю все каналы, которые были, кроме HTU21D (в прошлый раз на протяжении 34 часов контроллер работал без сбоев, потом я начал делать другой тест). Следующий тест - разнос опроса каналов по времени и включение опроса всех каналов (в том числе HTU21D).

intrapro

@Alex_Jet:

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

контроллер MegaD обратил внимание что плагин рестартовал несколько раз:

Коды ошибок плагинов, которые приводят к завершению работы:

code 1 - плагин запустился, но сразу закончил работу.

Для MegaD - не задан IP контроллера или порт для прослушивания занят.

code 2, 3 Ошибка связи или ошибка чтения

Для MegaD - это ошибка во время выполнения запроса GET (м.б. EHOSTUNREACH, ECONNREFUSED, ESOCKETTIMEDOUT,..) В логе плагина для всех этих ошибок есть расшифровка ошибки со словом Stopped

16.01.2017 12:32:20 localhost <= 192.168.0.14:80 Error EHOSTUNREACH.  Stopped.

code 143 - плагин получил сигнал на остановку от сервера, но какие-то операции не завершены.

Собственно, это не ошибка, уберем.

@Alex_Jet:

..в какой-то момент запросы по каждому каналу начинают сыпаться один за другим с минимальным промежутком, в итоге MegaD виснет от ddos-атаки….Следующий тест - разнос опроса каналов по времени и включение опроса всех каналов (в том числе HTU21D).

Предлагаю прямо в коде плагина принудительно разнести запросы.

Сейчас следующий запрос уходит не раньше чем через 200 мС.

Сделаем 2-3-5 сек в коде плагина /opt/intrahouse/server/ihlib/equip/megad.js, стр.71

		// Http клиент. Сформировать массив запросов reqarr и массив таймеров
		prepareOutReqAndTimers();
		setInterval( runOutReq, 2000);  // 200 -> 2000  
	} catch (e) {	
		traceMsg( e.message+' Stopped.');
		process.exit(1);
	}

После редактирования файла плагин нужно перезапустить. Сервер перезагружать не требуется.

Другой вариант - заменить асинхронный механизм отправки запросов на синхронный однопоточный, как, видимо, это происходит в php. Т.е. не отправлять следующий запрос, пока не получен ответ на предыдущий. Можно сделать и так.

Еще версия - опрос HTU21D имеет специфические требования? Контроллер ждет еще чего-то от сервера, а плагин переходит к следующему запросу..

Alex_Jet

@intrapro:

После редактирования файла плагин нужно перезапустить. Сервер перезагружать не требуется.

Все понятно! Спасибо за описание.
@intrapro:

Другой вариант - заменить асинхронный механизм отправки запросов на синхронный однопоточный, как, видимо, это происходит в php. Т.е. не отправлять следующий запрос, пока не получен ответ на предыдущий. Можно сделать и так.

Мне кажется, что это будет как раз правильным решением. Поскольку контроллер, построенный на AVR с Ethernet-контроллером ENC28J60, не может обрабатывать много потоков. Зная, немного прошивку, - там этого просто нет.
@intrapro:

Еще версия - опрос HTU21D имеет специфические требования? Контроллер ждет еще чего-то от сервера, а плагин переходит к следующему запросу..

Нет - это все такой же обычный датчик. Если дать команду через веб, то контроллер сразу выводит значение и ему больше ничего не надо.

Alex_Jet

Разнес запросы по датчикам (см.ниже), однако спустя 4 часа 21 минуту MegaD завис. Разработчик MegaD проверяет версию по поводу ddos-атаки. Попробую внести изменения в работу плагина.

17.01.2017 10:05:51 MegaD plugin has started.
17.01.2017 10:05:51 Listening localhost:8020
17.01.2017 10:05:51 Address 36 (IA36). Loading script
17.01.2017 10:05:51 Polling   192.168.12.20:80/sec/?cmd=all, interval 0 sek
17.01.2017 10:05:51 Polling   192.168.12.20:80/sec/?pt=30&cmd=get, interval 61 sek
17.01.2017 10:05:51 Polling   192.168.12.20:80/sec/?pt=36&cmd=get, interval 300 sek
17.01.2017 10:05:51 Polling   192.168.12.20:80/sec/?pt=31&cmd=list, interval 63 sek
17.01.2017 10:05:51 Polling   192.168.12.20:80/sec/?pt=34&scl=35&i2c_dev=htu21d&i2c_par=1, interval 65 sek
17.01.2017 10:05:51 Polling   192.168.12.20:80/sec/?pt=34&scl=35&i2c_dev=htu21d, interval 67 sek

Alex_Jet

@intrapro:

Предлагаю прямо в коде плагина принудительно разнести запросы.

Сейчас следующий запрос уходит не раньше чем через 200 мС.

Сделаем 2-3-5 сек в коде плагина /opt/intrahouse/server/ihlib/equip/megad.js, стр.71

Вчера обновился, отредактировал megad.js (у меня была стр.53) и запустил плагин (в 22:20). До сих пор (~15 часов) полет нормальный, все работает.

intrapro

Значит 200 мС период все же был короткий. Нужно конечно по крайней мере 24 часа uptime.

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

Alex_Jet

Само собой тест будет так долго сколько получится! Единственное - смущают периодические ошибки по всем датчикам. Лог журнала из веба не копируется! А из консоли где его можно посмотреть?

Приведу пример, помогите разобраться - по журналу в 18.01.2017 13:51:30 Ошибка датчика температуры и влажности (DHT22), который висит на 30-м порте. Лог плагина в промежутке с 18.01.2017 13:50:29 по 18.01.2017 13:52:49 прилагаю. Периодичность опроса датчиков как в предыдущем посте.

18.01.2017 13:50:29 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d&i2c_par=1
18.01.2017 13:50:29 localhost <=>192.168.12.20:80 socket handle=55\. Header: GET /sec/?pt=34&scl=35&i2c_dev=htu21d&i2c_par=1 HTTP/1.1
Host: 192.168.12.20
Connection: close

18.01.2017 13:50:29 localhost <= 192.168.12.20:80 response: statusCode=200 contentType = text/html
18.01.2017 13:50:29 localhost <= 192.168.12.20:80 HTTP 26.14
18.01.2017 13:50:29 MG2?341=26.14&
18.01.2017 13:50:29 localhost <=>192.168.12.20:80 socket closed
18.01.2017 13:50:31 
18.01.2017 13:50:31 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=31&cmd=list
18.01.2017 13:50:31 localhost <=>192.168.12.20:80 socket handle=55\. Header: GET /sec/?pt=31&cmd=list HTTP/1.1
Host: 192.168.12.20
Connection: close

18.01.2017 13:50:31 localhost <= 192.168.12.20:80 response: statusCode=200 contentType = text/html
18.01.2017 13:50:31 localhost <= 192.168.12.20:80 HTTP ff862a831501:24.06;ff6e2a831501:24.12;ff676b821503:23.68
18.01.2017 13:50:31 MG2?31_ff862a831501=24.06&31_ff6e2a831501=24.12&31_ff676b821503=23.68&
18.01.2017 13:50:31 localhost <=>192.168.12.20:80 socket closed
18.01.2017 13:50:33 
18.01.2017 13:50:33 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=30&cmd=get
18.01.2017 13:50:33 localhost <=>192.168.12.20:80 socket handle=55\. Header: GET /sec/?pt=30&cmd=get HTTP/1.1
Host: 192.168.12.20
Connection: close

18.01.2017 13:51:15 
18.01.2017 13:51:15 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=36&cmd=get
18.01.2017 13:51:15 localhost <=>192.168.12.20:80 socket handle=56\. Header: GET /sec/?pt=36&cmd=get HTTP/1.1
Host: 192.168.12.20
Connection: close

18.01.2017 13:51:15 localhost <= 192.168.12.20:80 response: statusCode=200 contentType = text/html
18.01.2017 13:51:15 localhost <= 192.168.12.20:80 HTTP 158
18.01.2017 13:51:15 Address 36
18.01.2017 13:51:15     run script: val=158 depo={ res: [] }
18.01.2017 13:51:15  script return:{ reqsek: 5 } depo={ res: [ 158 ] }
18.01.2017 13:51:15 Address 36\. Shift request interval: 5 sek.
18.01.2017 13:51:15 MG2?
18.01.2017 13:51:15 localhost <=>192.168.12.20:80 socket closed
18.01.2017 13:51:21 
18.01.2017 13:51:21 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=36&cmd=get
18.01.2017 13:51:21 localhost <=>192.168.12.20:80 socket handle=56\. Header: GET /sec/?pt=36&cmd=get HTTP/1.1
Host: 192.168.12.20
Connection: close

18.01.2017 13:51:21 localhost <= 192.168.12.20:80 response: statusCode=200 contentType = text/html
18.01.2017 13:51:21 localhost <= 192.168.12.20:80 HTTP 160
18.01.2017 13:51:21 Address 36
18.01.2017 13:51:21     run script: val=160 depo={ res: [ 158 ] }
18.01.2017 13:51:21  script return:{ reqsek: 5 } depo={ res: [ 158, 160 ] }
18.01.2017 13:51:21 MG2?
18.01.2017 13:51:21 localhost <=>192.168.12.20:80 socket closed
18.01.2017 13:51:27 
18.01.2017 13:51:27 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=36&cmd=get
18.01.2017 13:51:27 localhost <=>192.168.12.20:80 socket handle=56\. Header: GET /sec/?pt=36&cmd=get HTTP/1.1
Host: 192.168.12.20
Connection: close

18.01.2017 13:51:27 localhost <= 192.168.12.20:80 response: statusCode=200 contentType = text/html
18.01.2017 13:51:27 localhost <= 192.168.12.20:80 HTTP 148
18.01.2017 13:51:27 Address 36
18.01.2017 13:51:27     run script: val=148 depo={ res: [ 158, 160 ] }
18.01.2017 13:51:27  script return:{ reqsek: 5 } depo={ res: [ 158, 160, 148 ] }
18.01.2017 13:51:27 MG2?
18.01.2017 13:51:27 localhost <=>192.168.12.20:80 socket closed
18.01.2017 13:51:33 
18.01.2017 13:51:33 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=36&cmd=get
18.01.2017 13:51:33 localhost <=>192.168.12.20:80 socket handle=56\. Header: GET /sec/?pt=36&cmd=get HTTP/1.1
Host: 192.168.12.20
Connection: close

18.01.2017 13:51:33 localhost <= 192.168.12.20:80 response: statusCode=200 contentType = text/html
18.01.2017 13:51:33 localhost <= 192.168.12.20:80 HTTP 151
18.01.2017 13:51:33 Address 36
18.01.2017 13:51:33     run script: val=151 depo={ res: [ 158, 160, 148 ] }
18.01.2017 13:51:33  script return:{ reqsek: 5 } depo={ res: [ 158, 160, 148, 151 ] }
18.01.2017 13:51:33 MG2?
18.01.2017 13:51:33 localhost <=>192.168.12.20:80 socket closed
18.01.2017 13:51:35 
18.01.2017 13:51:35 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d
18.01.2017 13:51:35 localhost <=>192.168.12.20:80 socket handle=56\. Header: GET /sec/?pt=34&scl=35&i2c_dev=htu21d HTTP/1.1
Host: 192.168.12.20
Connection: close

18.01.2017 13:51:35 localhost <= 192.168.12.20:80 response: statusCode=200 contentType = text/html
18.01.2017 13:51:35 localhost <= 192.168.12.20:80 HTTP 12.60
18.01.2017 13:51:35 MG2?342=12.6&
18.01.2017 13:51:35 localhost <=>192.168.12.20:80 socket closed
18.01.2017 13:51:37 
18.01.2017 13:51:37 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d&i2c_par=1
18.01.2017 13:51:37 localhost <=>192.168.12.20:80 socket handle=56\. Header: GET /sec/?pt=34&scl=35&i2c_dev=htu21d&i2c_par=1 HTTP/1.1
Host: 192.168.12.20
Connection: close

18.01.2017 13:51:39 
18.01.2017 13:51:39 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=31&cmd=list
18.01.2017 13:51:39 localhost <=>192.168.12.20:80 socket handle=57\. Header: GET /sec/?pt=31&cmd=list HTTP/1.1
Host: 192.168.12.20
Connection: close

18.01.2017 13:51:39 localhost <= 192.168.12.20:80 response: statusCode=200 contentType = text/html
18.01.2017 13:51:39 localhost <= 192.168.12.20:80 HTTP ff862a831501:24.00;ff6e2a831501:24.06;ff676b821503:23.62
18.01.2017 13:51:39 MG2?31_ff862a831501=24.00&31_ff6e2a831501=24.06&31_ff676b821503=23.62&
18.01.2017 13:51:39 localhost <=>192.168.12.20:80 socket closed
18.01.2017 13:51:41 
18.01.2017 13:51:41 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=30&cmd=get
18.01.2017 13:51:41 localhost <=>192.168.12.20:80 socket handle=57\. Header: GET /sec/?pt=30&cmd=get HTTP/1.1
Host: 192.168.12.20
Connection: close

18.01.2017 13:51:41 localhost <= 192.168.12.20:80 response: statusCode=200 contentType = text/html
18.01.2017 13:51:41 localhost <= 192.168.12.20:80 HTTP temp:24.60/hum:10.20
18.01.2017 13:51:41 MG2?30_1=24.6&30_2=10.2&
18.01.2017 13:51:41 localhost <=>192.168.12.20:80 socket closed
18.01.2017 13:51:43 
18.01.2017 13:51:43 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=36&cmd=get
18.01.2017 13:51:43 localhost <=>192.168.12.20:80 socket handle=57\. Header: GET /sec/?pt=36&cmd=get HTTP/1.1
Host: 192.168.12.20
Connection: close

18.01.2017 13:51:43 localhost <= 192.168.12.20:80 response: statusCode=200 contentType = text/html
18.01.2017 13:51:43 localhost <= 192.168.12.20:80 HTTP 151
18.01.2017 13:51:43 Address 36
18.01.2017 13:51:43     run script: val=151 depo={ res: [ 158, 160, 148, 151 ] }
18.01.2017 13:51:43  script return:{ val: 880, reqsek: 300 } depo={ res: [] }
18.01.2017 13:51:43 Address 36\. Shift request interval: 300 sek.
18.01.2017 13:51:43 MG2?36=880&
18.01.2017 13:51:43 localhost <=>192.168.12.20:80 socket closed
18.01.2017 13:52:43 
18.01.2017 13:52:43 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d
18.01.2017 13:52:43 localhost <=>192.168.12.20:80 socket handle=57\. Header: GET /sec/?pt=34&scl=35&i2c_dev=htu21d HTTP/1.1
Host: 192.168.12.20
Connection: close

18.01.2017 13:52:43 localhost <= 192.168.12.20:80 response: statusCode=200 contentType = text/html
18.01.2017 13:52:43 localhost <= 192.168.12.20:80 HTTP 12.67
18.01.2017 13:52:43 MG2?342=12.67&
18.01.2017 13:52:43 localhost <=>192.168.12.20:80 socket closed
18.01.2017 13:52:45 
18.01.2017 13:52:45 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d&i2c_par=1
18.01.2017 13:52:45 localhost <=>192.168.12.20:80 socket handle=57\. Header: GET /sec/?pt=34&scl=35&i2c_dev=htu21d&i2c_par=1 HTTP/1.1
Host: 192.168.12.20
Connection: close

18.01.2017 13:52:45 localhost <= 192.168.12.20:80 response: statusCode=200 contentType = text/html
18.01.2017 13:52:45 localhost <= 192.168.12.20:80 HTTP 26.05
18.01.2017 13:52:45 MG2?341=26.05&
18.01.2017 13:52:45 localhost <=>192.168.12.20:80 socket closed
18.01.2017 13:52:47 
18.01.2017 13:52:47 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=31&cmd=list
18.01.2017 13:52:47 localhost <=>192.168.12.20:80 socket handle=57\. Header: GET /sec/?pt=31&cmd=list HTTP/1.1
Host: 192.168.12.20
Connection: close

18.01.2017 13:52:47 localhost <= 192.168.12.20:80 response: statusCode=200 contentType = text/html
18.01.2017 13:52:47 localhost <= 192.168.12.20:80 HTTP ff862a831501:23.75;ff6e2a831501:23.81;ff676b821503:23.37
18.01.2017 13:52:47 MG2?31_ff862a831501=23.75&31_ff6e2a831501=23.81&31_ff676b821503=23.37&
18.01.2017 13:52:47 localhost <=>192.168.12.20:80 socket closed
18.01.2017 13:52:49 
18.01.2017 13:52:49 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=30&cmd=get
18.01.2017 13:52:49 localhost <=>192.168.12.20:80 socket handle=57\. Header: GET /sec/?pt=30&cmd=get HTTP/1.1
Host: 192.168.12.20
Connection: close

18.01.2017 13:52:49 localhost <= 192.168.12.20:80 response: statusCode=200 contentType = text/html
18.01.2017 13:52:49 localhost <= 192.168.12.20:80 HTTP temp:25.10/hum:10.30
18.01.2017 13:52:49 MG2?30_1=25.1&30_2=10.3&
18.01.2017 13:52:49 localhost <=>192.168.12.20:80 socket closed

Мое предположение: на запрос 18.01.2017 13:50:33 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=30&cmd=get от контроллера просто нет ответа! Почему время по журналу 18.01.2017 13:51:30??? В устройстве время не ответа стоит 120 секунд - на что это влияет?

При детальном анализе лога плагина нашел, что частенько "множественный" опрос канала (с помощью скрипта) прерывается следующим образом:

1. В 18.01.2017 13:51:15 идет запрос по каналу 36 (localhost => 192.168.12.20:80 HTTP GET /sec/?pt=36&cmd=get), начинает работать скрипт - проходит 4 измерения

2. Однако после 4-го следуют запросы по расписанию на порты шины I2C и 31,30:

18.01.2017 13:51:35 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d

18.01.2017 13:51:37 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d&i2c_par=1

18.01.2017 13:51:39 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=31&cmd=list

18.01.2017 13:51:41 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=30&cmd=get

3. Только потом очередь доходит до 5-го запроса по 36-му каналу, на основании которого делается расчет среднего значения:

18.01.2017 13:51:43 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=36&cmd=get

После этого идет в штатном порядке.

Ладно, пусть данные по этому датчику формируются не за 25 секунд (5 измерений через 5 секунд), а за 28-40 секунд. Это не так плохо, однако отслеживая графики (выложу позже), я вижу проблемы по датчикам, в частности для СО2 (о котором веду речь) в 01:03, 05:36, 10:13, 14:51 (обратите внимание на промежутки времени между этими точками - 4:33, 4:37, 4:38) были нулевые показания! Не могу сейчас посмотреть логи из консоли что было в это время, однако проблема есть.

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

UPD: разработчик MegaD просит привести пример HTTP пакета, который генерирует ваш плагин. Сам только вечером wireshark-ом могу глянуть.