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



  • Socket IN FETCH. - сокет находится в процессе получения данных. Т.е. связь установлена, запрос ушел, но нет ответа.

    Если это так быстро сейчас ловится - можно параллельно запустить tcpdump и записать в файл (-w ..)

    Потом этот файл можно смотреть с помощью wireshark или тем же tcpdump -r megadump.pcap

    Пришлите файл нам, пожалуйста



  • Ок, записал файл. К слову оказалось, что у меня wireshark был под виндой еще… Пояснения будут в письме.

    Socket IN FETCH проявляется спустя 4-6 минут. При этом управлять выходами контроллера из веба можно:)



  • В дампе видно, что контроллер не ответил на последний запрос. Можно продолжить эксперименты:

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

    В новом обновлении в megad2 изменили таймаут сокета на 2 сек.

    Т.е. через 2 сек опрос продолжится. Плюс попробовать переключить актуатор. Сделать дамп для этого случая

    2. Переключить плагин на megad основной и тоже сделать дамп.

    Если сделаете, пришлите нам



  • Поменял датчик HTU21D на SI7021. Ситуация такая же - при работе плагина megad через некоторое время контроллер зависает насовсем.

    Скинул часть лога плагина (в момент зависания) и дамп на почту.

    Начал тестировать обновленный плагин megad2. Сразу вопросы - при включении/выключении актюаторов плагин ругается (см. лог), при этом актюаторы срабатывают нормально. А еще в лог при срабатывании актюаторов в запросе выводится %pwd%, а не пароль (sec), в реальности в запросе скорее есть sec (посмотрю дамп после записи), поскольку актюаторы срабатывают. Иначе бы не срабатывали а контроллер выдавал бы Unauthorized.

    23.01 01:00:05.959 
    23.01 01:00:05.959 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d
    23.01 01:00:05.961 localhost <=>192.168.12.20:80 socket handle=18\. Header: GET /sec/?pt=34&scl=35&i2c_dev=htu21d HTTP/1.1
    Host: 192.168.12.20
    Connection: close
    
    23.01 01:00:05.984 localhost <= 192.168.12.20:80 response: statusCode=200 contentType = text/html
    23.01 01:00:05.986 localhost <= 192.168.12.20:80 HTTP 46.53
    23.01 01:00:05.986 MG2?342=46.53&
    23.01 01:00:05.987 localhost <=>192.168.12.20:80 socket closed
    23.01 01:01:05.630 localhost => 192.168.12.20:80 HTTP GET /%pwd%/?cmd=7:1
    23.01 01:01:05.638 localhost <= 192.168.12.20:80 response: statusCode=200 contentType = text/html
    23.01 01:01:05.642 ERR (uncaughtException): [ReferenceError: data is not defined]
    23.01 01:01:05.859 
    23.01 01:01:05.860 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d&i2c_par=1
    23.01 01:01:05.862 localhost <=>192.168.12.20:80 socket handle=18\. Header: GET /sec/?pt=34&scl=35&i2c_dev=htu21d&i2c_par=1 HTTP/1.1
    Host: 192.168.12.20
    Connection: close
    
    23.01 01:01:05.915 localhost <= 192.168.12.20:80 response: statusCode=200 contentType = text/html
    23.01 01:01:05.917 localhost <= 192.168.12.20:80 HTTP 27.00
    23.01 01:01:05.917 MG2?341=27&
    23.01 01:01:05.918 localhost <=>192.168.12.20:80 socket closed
    23.01 01:01:06.60 
    23.01 01:01:06.60 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d
    23.01 01:01:06.62 localhost <=>192.168.12.20:80 socket handle=18\. Header: GET /sec/?pt=34&scl=35&i2c_dev=htu21d HTTP/1.1
    Host: 192.168.12.20
    Connection: close
    
    23.01 01:01:06.84 localhost <= 192.168.12.20:80 response: statusCode=200 contentType = text/html
    23.01 01:01:06.86 localhost <= 192.168.12.20:80 HTTP 46.53
    23.01 01:01:06.86 MG2?342=46.53&
    23.01 01:01:06.87 localhost <=>192.168.12.20:80 socket closed
    23.01 01:01:10.425 localhost => 192.168.12.20:80 HTTP GET /%pwd%/?cmd=7:0
    23.01 01:01:10.433 localhost <= 192.168.12.20:80 response: statusCode=200 contentType = text/html
    23.01 01:01:10.437 ERR (uncaughtException): [ReferenceError: data is not defined]
    23.01 01:02:05.957 
    23.01 01:02:05.957 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d&i2c_par=1
    23.01 01:02:05.959 localhost <=>192.168.12.20:80 socket handle=18\. Header: GET /sec/?pt=34&scl=35&i2c_dev=htu21d&i2c_par=1 HTTP/1.1
    Host: 192.168.12.20
    Connection: close
    
    23.01 01:02:06.12 localhost <= 192.168.12.20:80 response: statusCode=200 contentType = text/html
    23.01 01:02:06.19 localhost <= 192.168.12.20:80 HTTP 27.00
    23.01 01:02:06.20 MG2?341=27&
    23.01 01:02:06.22 localhost <=>192.168.12.20:80 socket closed
    23.01 01:02:06.157 
    23.01 01:02:06.158 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d
    23.01 01:02:06.163 localhost <=>192.168.12.20:80 socket handle=18\. Header: GET /sec/?pt=34&scl=35&i2c_dev=htu21d HTTP/1.1
    Host: 192.168.12.20
    Connection: close
    
    23.01 01:02:06.185 localhost <= 192.168.12.20:80 response: statusCode=200 contentType = text/html
    23.01 01:02:06.187 localhost <= 192.168.12.20:80 HTTP 46.53
    23.01 01:02:06.188 MG2?342=46.53&
    23.01 01:02:06.189 localhost <=>192.168.12.20:80 socket closed
    
    

    Кстати, только сейчас обратил внимание, что в принципе контроллер подтверждает выполнение команды! В браузере при наборе, например, команды "sec/?cmd=7:2", контроллер отдает "Done".



  • @Alex_Jet:

    Поменял датчик HTU21D на SI7021. Ситуация такая же - при работе плагина megad через некоторое время контроллер зависает насовсем. Скинул часть лога плагина (в момент зависания) и дамп на почту.

    Начал тестировать обновленный плагин megad2. Сразу вопросы - при включении/выключении актюаторов плагин ругается (см. лог), при этом актюаторы срабатывают нормально. А еще в лог при срабатывании актюаторов в запросе выводится %pwd%, а не пароль (sec), в реальности в запросе скорее есть sec (посмотрю дамп после записи), поскольку актюаторы срабатывают.

    Да, почту 2 транша получили. В megad2 косяк при логировании, на переключения не влияет. Меняли в спешке, поправим 🙂

    @Alex_Jet:

    Кстати, только сейчас обратил внимание, что в принципе контроллер подтверждает выполнение команды! В браузере при наборе, например, команды "sec/?cmd=7:2", контроллер отдает "Done".

    Когда мы контроллер получили, тоже это увидели. В принципе, можно сделать обработку Done в плагине



  • Подскажите, плагин в некоторые моменты работы выдает ошибки. Что это за ошибки?

    31.01 08:42:42.0272 localhost => 192.168.12.21:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d&i2c_par=1
    31.01 08:43:12.0279 localhost <=>192.168.12.21:80 Socket timed out - abort!
    31.01 08:43:12.0283 localhost <= 192.168.12.21:80 Error ECONNRESET.  Stopped.
    31.01 08:43:18.0033 
    31.01 08:43:18.0040 MegaD plugin has started.
    31.01 08:43:18.0092 Listening localhost:10021
    31.01 08:43:18.0104 Address 36 (IA36). Loading script
    31.01 08:43:18.0106 Polling   192.168.12.21:80/sec/?cmd=all, interval 0 sek
    31.01 08:43:18.0107 Polling   192.168.12.21:80/sec/?pt=36&cmd=get, interval 300 sek
    31.01 08:43:18.0107 Polling   192.168.12.21:80/sec/?pt=31&cmd=list, interval 60 sek
    31.01 08:43:18.0107 Polling   192.168.12.21:80/sec/?pt=34&scl=35&i2c_dev=htu21d&i2c_par=1, interval 60 sek
    31.01 08:43:18.0107 Polling   192.168.12.21:80/sec/?pt=34&scl=35&i2c_dev=htu21d, interval 60 sek
    31.01 08:43:18.0114 localhost => 192.168.12.21:80 HTTP GET /sec/?cmd=all
    
    

    С зависанием контроллера так и не разобрались, однако можете прокомментировать почему так получается - в 31.01 09:17:34.0278 идет запрос температуры, контроллер вешается и перезагружается встроенным watchdog-ом. В 31.01 09:17:44.0289 видим, что он перезагрузился, однако в 31.01 09:17:46.0964 прилетает значение температуры, которое не запрашивалось у контроллера после его перезагрузки! Как такое может быть?

    31.01 09:17:34.0278 localhost => 192.168.12.21:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d&i2c_par=1
    31.01 09:17:44.0289 192.168.12.21 => localhost:10021 HTTP GET /mod_megad.php?st=1
    31.01 09:17:44.0294 192.168.12.21 <= localhost:10021 
    31.01 09:17:44.0307 Redirect to MG3
    31.01 09:17:44.0309 localhost => 192.168.12.21:80 HTTP GET /sec/?cmd=22:1
    31.01 09:17:44.0312 MG3?22=1&
    31.01 09:17:44.0332 localhost <= 192.168.12.21:80 HTTP Done
    31.01 09:17:46.0964 localhost <= 192.168.12.21:80 HTTP 25.89
    31.01 09:17:46.0965 MG3?341=25.89&
    31.01 09:17:47.0119 localhost => 192.168.12.21:80 HTTP GET /sec/?cmd=all
    31.01 09:17:47.0243 localhost <= 192.168.12.21:80 HTTP OFF/0;OFF/0;OFF/0;OFF/0;OFF/0;OFF/0;OFF/0;OFF;OFF;OFF;OFF;OFF;OFF;OFF;ON;OFF/0;OFF/0;OFF/0;OFF/0;OFF/0;OFF/0;OFF/0;ON;OFF;OFF;OFF;OFF;OFF;OFF;ON;temp:0.00/hum:0.00;;OFF;OFF;;OFF;230;ON
    
    


  • @Alex_Jet:

    Подскажите, плагин в некоторые моменты работы выдает ошибки. Что это за ошибки?

    > 31.01 08:42:42.0272 localhost => 192.168.12.21:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d&i2c_par=1
    > 31.01 08:43:12.0279 localhost <=>192.168.12.21:80 Socket timed out - abort!
    > 31.01 08:43:12.0283 localhost <= 192.168.12.21:80 Error ECONNRESET.  Stopped.
    > 
    > 
    

    Socket timed out - abort! - это ошибка прикладного уровня - истек таймаут ожидания ответа на запрос.

    Сейчас таймаут прикладного уровня 30 сек.

    По этой ошибке закрывается сокет, но плагин не завершается. Если бы были другие запросы - они бы передавались.

    ECONNREFUSED, ECONNRESET - это ошибки системного уровня, плагин их перехватывает и завершает работу.

    ECONNREFUSED - в создании соединения отказано

    ECONNRESET - соединение закрыто ( socket hang up - "повесил трубку" )

    Т.е. контроллер не отвечает на запрос в течение таймаута, установленного на системном уровне (30 сек).

    В этом случае плагин завершает работу и через 5 сек перезагружается.

    @Alex_Jet:

    С зависанием контроллера так и не разобрались, однако можете прокомментировать почему так получается - в 31.01 09:17:34.0278 идет запрос температуры, контроллер вешается и перезагружается встроенным watchdog-ом. В 31.01 09:17:44.0289 видим, что он перезагрузился, однако в 31.01 09:17:46.0964 прилетает значение температуры, которое не запрашивалось у контроллера после его перезагрузки! Как такое может быть?

    > 31.01 09:17:34.0278 localhost => 192.168.12.21:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d&i2c_par=1
    > 31.01 09:17:44.0289 192.168.12.21 => localhost:10021 HTTP GET /mod_megad.php?st=1
    > 31.01 09:17:44.0294 192.168.12.21 <= localhost:10021 
    > 31.01 09:17:46.0964 localhost <= 192.168.12.21:80 HTTP 25.89
    > 
    > 
    

    С таким мы тоже столкнулись, когда тестировали st=1.

    Если передать запрос, а затем перезагрузить контроллер в течение короткого времени, то после перезагрузки он присылает ответ на последний запрос. Объясняется это тем, то по стандарту TCP протокола, "если клиент не получает ответа в течение 10 секунд, то он повторяет процесс соединения заново". Это происходит на сетевом уровне, плагин об этом не знает, он отправил запрос GET и ждет или ответа или ошибки или таймаута. Если укладываемся в таймаут, сокет не закрывается.

    Запрос фактически приходит в контроллер после перезагрузки. Если посмотреть сетевой дамп, это все можно увидеть. Магия сетевых протоколов 🙂



  • Alex_Jet. Прошу подсказать.

    Watchdog в MegaD давно существует или сделан для решения этого вопроса с зависанием MegaD?



  • @intrapro:

    Магия сетевых протоколов 🙂

    Да почему магия? Просто все давно придумано и продумано, а такие как я просто этим никогда не интересовались… дампы анализирую тоже когда реально "приспичит".

    @intrapro:

    Watchdog в MegaD давно существует или сделан для решения этого вопроса с зависанием MegaD?

    Появился совсем недавно. Но с какой точно целью Андрей решил его запустить - не знаю. Вот тут описание релизов: http://www.ab-log.ru/smart-house/ethernet/megad-2561-firmware



  • Подытожу данную тему. Проблема зависания MegaD-2561 при подключенном к нему по I2C датчике HTU21D была в прошивке. Автор не раскрывает секретов что он изменил или сам не понимает какое изменение повлияло на удаление данного бага. К слову сказать с тех пор было много изменений прошивки - добавлена поддержка многих других датчиков, работающих по шине I2C (BH1750, TSL2591, BMP180, BMP/BME280, SI7021, MCP23008), поддержка считывателей и кодовых панелей с Wiegand-26, нативная поддержка OLED-дисплеев на контроллере SSD1306 (также I2C-шина), добавлен новый режим для входов "Click mode", появилась возможность работы с контроллером по MQTT и прочее.

    Напомню, баг проявлялся только при опросе контроллера MegaD-2561 командой /%pwd%/?pt=34&scl=35&i2c_dev=htu21d&i2c_par=1 (запрос температуры с датчика HTU21D) с любой периодичностью (пробовал 60 секунд - 5 минут) - контроллер через какое-то время зависал (промежуток времени от 3 до 24 часов), помогал только ручной сброс (в версии платы контроллера 1.0 - отключение по питанию, в версии 2.0 - сброс кнопкой), пока автором прошивки не был включен встроенный в МК "сторожевой пес".

    В связи с вышеизложенным, выражаю большую признательность авторам IH, что откликнулись и провели большую работу по выявлению описанного бага. Отрицательный результат - также результат!



  • @Alex_Jet:

    Подытожу данную тему

    Большое спасибо за информативный итог по теме :!:


Авторизуйтесь, чтобы ответить