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



  • Лог системы в скриншоте.

    Разнести вручную конечно можно - для пробы, но вы же понимаете, что для пользователя отслеживать какой канал через сколько должен опрашиваться - просто не верное решение. Как в самописных скриптах php происходит: он вызывается по cron с заданной периодичностью, в нем же идет последовательный опрос всех каналов. Поэтому и тут надо выстраивать последовательный опрос каналов.

    Как мне видится - запускается плагин, проводится анализ какой канал с какой периодичностью должен запускаться, если у нескольких каналов периодичность одинаковая, то ставим их в очередь начиная с меньшего канала. То есть формируем своеобразное cron-расписание.

    Лог с командами на включение актюаторов:

    29.12.2016 16:49:25 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=36&cmd=get
    29.12.2016 16:49:36 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=30&cmd=get
    29.12.2016 16:49:36 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d
    29.12.2016 16:49:36 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d&i2c_par=1
    29.12.2016 16:50:10 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=31&cmd=list
    29.12.2016 16:50:36 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=30&cmd=get
    29.12.2016 16:50:36 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d
    29.12.2016 16:50:37 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d&i2c_par=1
    29.12.2016 16:51:26 localhost => 192.168.12.20:80 HTTP GET /sec/?cmd=22:1
    29.12.2016 16:51:36 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=30&cmd=get
    29.12.2016 16:51:36 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d
    29.12.2016 16:51:37 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d&i2c_par=1
    29.12.2016 16:52:10 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=31&cmd=list
    29.12.2016 16:52:36 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=30&cmd=get
    29.12.2016 16:52:36 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d
    29.12.2016 16:52:37 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d&i2c_par=1
    29.12.2016 16:53:36 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=30&cmd=get
    29.12.2016 16:53:37 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d
    29.12.2016 16:53:37 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d&i2c_par=1
    29.12.2016 16:54:10 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=31&cmd=list
    29.12.2016 16:54:25 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=36&cmd=get
    29.12.2016 16:54:36 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=30&cmd=get
    29.12.2016 16:54:37 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d
    29.12.2016 16:54:37 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d&i2c_par=1
    29.12.2016 16:55:37 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=30&cmd=get
    29.12.2016 16:55:37 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d
    29.12.2016 16:55:37 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d&i2c_par=1
    29.12.2016 16:56:10 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=31&cmd=list
    29.12.2016 16:56:36 localhost => 192.168.12.20:80 HTTP GET /sec/?cmd=22:0
    29.12.2016 16:56:37 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=30&cmd=get
    29.12.2016 16:56:37 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d
    29.12.2016 16:56:37 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d&i2c_par=1
    29.12.2016 16:57:37 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=30&cmd=get
    29.12.2016 16:57:37 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d
    29.12.2016 16:57:37 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d&i2c_par=1
    29.12.2016 16:58:10 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=31&cmd=list
    29.12.2016 16:58:37 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=30&cmd=get
    29.12.2016 16:58:37 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d
    29.12.2016 16:58:37 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d&i2c_par=1
    
    

    Intrahouse_log_20161230.png



  • Только что снова завис. Сделаю разнос по времени, буду наблюдать.

    30.12.2016 22:43:49 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=31&cmd=list
    30.12.2016 22:43:49 localhost <= 192.168.12.20:80 HTTP ff862a831501:25.56;ff6e2a831501:25.62;ff676b821503:25.25
    30.12.2016 22:43:49 MG2?31_ff862a831501=25.56&31_ff6e2a831501=25.62&31_ff676b821503=25.25&
    30.12.2016 22:44:49 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=30&cmd=get
    30.12.2016 22:44:49 localhost <= 192.168.12.20:80 HTTP temp:26.40/hum:24.00
    30.12.2016 22:44:49 MG2?30_1=26.4&30_2=24&
    30.12.2016 22:44:49 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d
    30.12.2016 22:44:49 localhost <= 192.168.12.20:80 HTTP 26.52
    30.12.2016 22:44:49 MG2?341=26.52&
    30.12.2016 22:44:49 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d&i2c_par=1
    30.12.2016 22:44:49 localhost <= 192.168.12.20:80 HTTP 128.85
    30.12.2016 22:44:49 MG2?342=128.85&
    30.12.2016 22:45:49 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=30&cmd=get
    30.12.2016 22:45:49 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d
    30.12.2016 22:45:49 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d&i2c_par=1
    30.12.2016 22:45:50 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=31&cmd=list
    30.12.2016 22:46:28 localhost => 192.168.12.20:80 HTTP GET /sec/?cmd=10:0
    30.12.2016 22:46:32 localhost => 192.168.12.20:80 HTTP GET /sec/?cmd=10:1
    30.12.2016 22:46:34 localhost => 192.168.12.20:80 HTTP GET /sec/?cmd=27:0
    30.12.2016 22:46:36 localhost => 192.168.12.20:80 HTTP GET /sec/?cmd=27:1
    
    

    UPD. Разнес примерно так:

    30.12.2016 22:51:22 MegaD plugin has started.
    30.12.2016 22:51:22 Listening localhost:8020
    30.12.2016 22:51:22 Address 36 (IA36). Loading script
    30.12.2016 22:51:22 Polling   192.168.12.20:80/sec/?cmd=all, interval 0 sek
    30.12.2016 22:51:22 Polling   192.168.12.20:80/sec/?pt=30&cmd=get, interval 60 sek
    30.12.2016 22:51:22 Polling   192.168.12.20:80/sec/?pt=36&cmd=get, interval 320 sek
    30.12.2016 22:51:22 Polling   192.168.12.20:80/sec/?pt=31&cmd=list, interval 70 sek
    30.12.2016 22:51:22 Polling   192.168.12.20:80/sec/?pt=34&scl=35&i2c_dev=htu21d, interval 61 sek
    30.12.2016 22:51:22 Polling   192.168.12.20:80/sec/?pt=34&scl=35&i2c_dev=htu21d&i2c_par=1, interval 62 sek
    
    


  • @Alex_Jet:

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

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

    @Alex_Jet:

    Как в самописных скриптах php происходит: он вызывается по cron с заданной периодичностью, в нем же идет последовательный опрос всех каналов. Поэтому и тут надо выстраивать последовательный опрос каналов.

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

    В принципе, так и происходит, существует очередь опроса, за один раз передается только один запрос. Если время одинаково, то следующий запрос передается с интервалом 100 мсек.



  • Снова плагин завис:

    31.12.2016 02:23:45 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=30&cmd=get
    31.12.2016 02:23:45 localhost <= 192.168.12.20:80 HTTP temp:26.20/hum:19.30
    31.12.2016 02:23:45 MG2?30_1=26.2&30_2=19.3&
    31.12.2016 02:24:04 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=31&cmd=list
    31.12.2016 02:24:04 localhost <= 192.168.12.20:80 HTTP ff862a831501:25.43;ff6e2a831501:25.43;ff676b821503:25.06
    31.12.2016 02:24:04 MG2?31_ff862a831501=25.43&31_ff6e2a831501=25.43&31_ff676b821503=25.06&
    31.12.2016 02:24:14 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d
    31.12.2016 02:24:14 localhost <= 192.168.12.20:80 HTTP 23.48
    31.12.2016 02:24:14 MG2?341=23.48&
    31.12.2016 02:24:36 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d&i2c_par=1
    31.12.2016 02:24:36 localhost <= 192.168.12.20:80 HTTP 128.85
    31.12.2016 02:24:36 MG2?342=128.85&
    31.12.2016 02:24:45 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=30&cmd=get
    31.12.2016 02:24:56 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=36&cmd=get
    31.12.2016 02:25:14 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=31&cmd=list
    31.12.2016 02:25:15 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d
    31.12.2016 02:25:39 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d&i2c_par=1
    31.12.2016 02:25:45 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=30&cmd=get
    31.12.2016 02:26:16 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d
    
    


  • Да, печалька 😞 .

    Значит, дело не в интервалах запросов.

    Добавили в лог более подробный вывод получения ответа (response code), можно обновиться.

    А другие Меги работают?

    Может, с i2C датчиками все не так просто… Надо разбираться.

    С неудержимо наступающим на нас Новым Годом. Интересных задач, успехов и удачи в Новом Году! 🙂



  • @intrapro:

    Да, печалька 😞 .

    Значит, дело не в интервалах запросов.

    Добавили в лог более подробный вывод получения ответа (response code), можно обновиться.

    А другие Меги работают?

    Может, с i2C датчиками все не так просто… Надо разбираться.

    С неудержимо наступающим на нас Новым Годом. Интересных задач, успехов и удачи в Новом Году! 🙂

    С новым годом господа!!! Новых расширений, новых идей, новых спонсоров и новых продуктов Вам желаю!

    Да, дело не в интервалах, а в "нативном" опросе I2C датчика HTU21D - как только исключил опрос данных каналов (в request убрал период запроса), так плагин продолжал бесконечно трудиться. Другой MegaD-2561 (только они имеют "нативную" поддержку HTU21D) пока нет. Обновил систему, включил опрос канала датчика влажности HTU21D. На утро плагин завис:

    02.01.2017 08:59:52 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=36&cmd=get
    02.01.2017 08:59:52 localhost <= 192.168.12.20:80 status code=200
    02.01.2017 08:59:52 localhost <= 192.168.12.20:80 data.chunk=176
    02.01.2017 08:59:52 localhost <= 192.168.12.20:80 data.end
    02.01.2017 08:59:52 localhost <= 192.168.12.20:80 HTTP 176
    02.01.2017 08:59:52 Address 36
    02.01.2017 08:59:52     run script: val=176 depo={ res: [] }
    02.01.2017 08:59:52  script return:{ reqsek: 5 } depo={ res: [ 176 ] }
    02.01.2017 08:59:52 Address 36\. Shift request interval: 5 sek.
    02.01.2017 08:59:52 MG2?
    02.01.2017 08:59:58 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=36&cmd=get
    02.01.2017 08:59:58 localhost <= 192.168.12.20:80 status code=200
    02.01.2017 08:59:58 localhost <= 192.168.12.20:80 data.chunk=176
    02.01.2017 08:59:58 localhost <= 192.168.12.20:80 data.end
    02.01.2017 08:59:58 localhost <= 192.168.12.20:80 HTTP 176
    02.01.2017 08:59:58 Address 36
    02.01.2017 08:59:58     run script: val=176 depo={ res: [ 176 ] }
    02.01.2017 08:59:58  script return:{ reqsek: 5 } depo={ res: [ 176, 176 ] }
    02.01.2017 08:59:58 MG2?
    02.01.2017 09:00:03 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=36&cmd=get
    02.01.2017 09:00:03 localhost <= 192.168.12.20:80 status code=200
    02.01.2017 09:00:03 localhost <= 192.168.12.20:80 data.chunk=174
    02.01.2017 09:00:03 localhost <= 192.168.12.20:80 data.end
    02.01.2017 09:00:03 localhost <= 192.168.12.20:80 HTTP 174
    02.01.2017 09:00:03 Address 36
    02.01.2017 09:00:03     run script: val=174 depo={ res: [ 176, 176 ] }
    02.01.2017 09:00:03  script return:{ reqsek: 5 } depo={ res: [ 176, 176, 174 ] }
    02.01.2017 09:00:03 MG2?
    02.01.2017 09:00:08 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=36&cmd=get
    02.01.2017 09:00:08 localhost <= 192.168.12.20:80 status code=200
    02.01.2017 09:00:08 localhost <= 192.168.12.20:80 data.chunk=176
    02.01.2017 09:00:08 localhost <= 192.168.12.20:80 data.end
    02.01.2017 09:00:08 localhost <= 192.168.12.20:80 HTTP 176
    02.01.2017 09:00:08 Address 36
    02.01.2017 09:00:08     run script: val=176 depo={ res: [ 176, 176, 174 ] }
    02.01.2017 09:00:08  script return:{ reqsek: 5 } depo={ res: [ 176, 176, 174, 176 ] }
    02.01.2017 09:00:08 MG2?
    02.01.2017 09:00:13 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=36&cmd=get
    02.01.2017 09:00:13 localhost <= 192.168.12.20:80 status code=200
    02.01.2017 09:00:13 localhost <= 192.168.12.20:80 data.chunk=176
    02.01.2017 09:00:13 localhost <= 192.168.12.20:80 data.end
    02.01.2017 09:00:13 localhost <= 192.168.12.20:80 HTTP 176
    02.01.2017 09:00:13 Address 36
    02.01.2017 09:00:13     run script: val=176 depo={ res: [ 176, 176, 174, 176 ] }
    02.01.2017 09:00:13  script return:{ val: 1110, reqsek: 300 } depo={ res: [] }
    02.01.2017 09:00:13 Address 36\. Shift request interval: 300 sek.
    02.01.2017 09:00:13 MG2?36=1110&
    02.01.2017 09:00:35 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=31&cmd=list
    02.01.2017 09:00:35 localhost <= 192.168.12.20:80 status code=200
    02.01.2017 09:00:35 localhost <= 192.168.12.20:80 data.chunk=ff862a831501:25.12;ff6e2a831501:25.18;ff676b821503:24.81
    02.01.2017 09:00:35 localhost <= 192.168.12.20:80 data.end
    02.01.2017 09:00:35 localhost <= 192.168.12.20:80 HTTP ff862a831501:25.12;ff6e2a831501:25.18;ff676b821503:24.81
    02.01.2017 09:00:35 MG2?31_ff862a831501=25.12&31_ff6e2a831501=25.18&31_ff676b821503=24.81&
    02.01.2017 09:00:45 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=30&cmd=get
    02.01.2017 09:00:45 localhost <= 192.168.12.20:80 status code=200
    02.01.2017 09:00:45 localhost <= 192.168.12.20:80 data.chunk=temp:25.90/hum:19.80
    02.01.2017 09:00:45 localhost <= 192.168.12.20:80 data.end
    02.01.2017 09:00:45 localhost <= 192.168.12.20:80 HTTP temp:25.90/hum:19.80
    02.01.2017 09:00:45 MG2?30_1=25.9&30_2=19.8&
    02.01.2017 09:00:45 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d
    02.01.2017 09:00:45 localhost <= 192.168.12.20:80 status code=200
    02.01.2017 09:00:45 localhost <= 192.168.12.20:80 data.chunk=21.90
    02.01.2017 09:00:45 localhost <= 192.168.12.20:80 data.end
    02.01.2017 09:00:45 localhost <= 192.168.12.20:80 HTTP 21.90
    02.01.2017 09:00:45 MG2?342=21.9&
    02.01.2017 09:01:45 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=31&cmd=list
    02.01.2017 09:01:45 localhost <= 192.168.12.20:80 status code=200
    02.01.2017 09:01:45 localhost <= 192.168.12.20:80 data.chunk=ff862a831501:25.12;ff6e2a831501:25.18;ff676b821503:24.81
    02.01.2017 09:01:45 localhost <= 192.168.12.20:80 data.end
    02.01.2017 09:01:45 localhost <= 192.168.12.20:80 HTTP ff862a831501:25.12;ff6e2a831501:25.18;ff676b821503:24.81
    02.01.2017 09:01:45 MG2?31_ff862a831501=25.12&31_ff6e2a831501=25.18&31_ff676b821503=24.81&
    02.01.2017 09:01:45 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=30&cmd=get
    02.01.2017 09:01:45 localhost <= 192.168.12.20:80 status code=200
    02.01.2017 09:01:45 localhost <= 192.168.12.20:80 data.chunk=temp:25.80/hum:19.90
    02.01.2017 09:01:45 localhost <= 192.168.12.20:80 data.end
    02.01.2017 09:01:45 localhost <= 192.168.12.20:80 HTTP temp:25.80/hum:19.90
    02.01.2017 09:01:45 MG2?30_1=25.8&30_2=19.9&
    02.01.2017 09:01:46 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d
    02.01.2017 09:01:46 localhost <= 192.168.12.20:80 status code=200
    02.01.2017 09:01:46 localhost <= 192.168.12.20:80 data.chunk=21.92
    02.01.2017 09:01:46 localhost <= 192.168.12.20:80 data.end
    02.01.2017 09:01:46 localhost <= 192.168.12.20:80 HTTP 21.92
    02.01.2017 09:01:46 MG2?342=21.92&
    02.01.2017 09:02:45 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=30&cmd=get
    02.01.2017 09:02:46 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d
    02.01.2017 09:02:55 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=31&cmd=list
    02.01.2017 09:03:45 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=30&cmd=get
    02.01.2017 09:03:46 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d
    02.01.2017 09:04:05 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=31&cmd=list
    02.01.2017 09:04:45 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=30&cmd=get
    02.01.2017 09:04:46 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d
    02.01.2017 09:05:13 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=36&cmd=get
    
    

    Включение/отключение актюатора:

    02.01.2017 10:41:56 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d
    02.01.2017 10:42:14 localhost => 192.168.12.20:80 HTTP GET /sec/?cmd=10:0
    02.01.2017 10:42:15 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=31&cmd=list
    02.01.2017 10:42:16 localhost => 192.168.12.20:80 HTTP GET /sec/?cmd=10:1
    02.01.2017 10:42:56 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=30&cmd=get
    02.01.2017 10:42:56 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d
    
    


  • Да, непонятно, почему связь есть, а ответа от MegaD нет. Нужен анализ сетевого трафика.

    Можно установить tcpdump:

    sudo apt-get install tcpdump
    
    

    и посмотреть трафик с MegaD :

     sudo tcpdump host 192.168.0.14  // MegaD IP
    
    

    Стандартный обмен пакетами такой :

    `10:56:21.270792 IP 192.168.0.238.34130 > 192.168.0.14.http: Flags [s], ..length 0 //SYN- Запрос связи
    10:56:21.271635 IP 192.168.0.14.http > 192.168.0.238.34130: Flags [S.],..length 0 // подтв от Mega 
    10:56:21.271686 IP 192.168.0.238.34130 > 192.168.0.14.http: Flags [.],... length 0 // связь установлена
    10:56:21.271937 IP 192.168.0.238.34130 > 192.168.0.14.http: Flags [P.],..length 76 // PUSH- плагин передает запрос
    10:56:21.273701 IP 192.168.0.14.http > 192.168.0.238.34130: Flags [.],... length 0  // подтв от Mega
    10:56:21.274157 IP 192.168.0.14.http > 192.168.0.238.34130: Flags [FP.],.length 41 // FIN&PUSH- ответ Mega, конец связи
    10:56:21.276393 IP 192.168.0.238.34130 > 192.168.0.14.http: Flags [F.],.. length 0  // FIN - конец св. 
    10:56:21.277288 IP 192.168.0.14.http > 192.168.0.238.34130: Flags [.],.... length 0 // Соединение закрыто` 
    
    Хорошо бы посмотреть, какие идут пакеты в случае зависания.[/s]
    


  • @intrapro:

    Да, непонятно, почему связь есть, а ответа от MegaD нет. Нужен анализ сетевого трафика.

    Повторилась ситуация с кучей запросов к MegaD и отсутствием ответа от нее. До этого экспериментировал с прошивкой MegaD…

    Я Вас удивлю - при зависании плагина (в логе - постоянные запросы к MegaD) обмена пакетами между сервером и MegaD вообще нет! Сервер общается с другими MegaD, с компьютером, роутером, а с искомым MegaD - нет!

    При этом! При замыкании входа на MegaD плагин обрабатывает запрос и отвечает на него. Вот что есть:

    05.01.2017 23:27:42 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=31&cmd=list
    05.01.2017 23:27:42 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d&i2c_par=1
    05.01.2017 23:27:42 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d
    05.01.2017 23:28:27 192.168.12.20 => localhost:8020 HTTP GET /mod_megad.php?pt=1&cnt=1&mdid=
    05.01.2017 23:28:27 MG2?8=TG&
    05.01.2017 23:28:27 192.168.12.20 <= localhost:8020 8:2
    05.01.2017 23:28:41 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=30&cmd=get
    05.01.2017 23:28:42 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=31&cmd=list
    05.01.2017 23:28:42 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d&i2c_par=1
    05.01.2017 23:28:42 localhost => 192.168.12.20:80 HTTP GET /sec/?pt=34&scl=35&i2c_dev=htu21d
    
    

    TCP dump показал обмен пакетами только при вышеописанной ситуации (замыкание входа MegaD). Тут 192.168.12.10 - сервер, 192.168.12.20 - MegaD, Neb.lan - компьютер:

    `23:28:38.996222 IP 192.168.12.20.2883 > 192.168.12.10.8020: Flags [s], seq 14080, win 768, options [mss 790], length 0
    23:28:38.996494 IP 192.168.12.10.8020 > 192.168.12.20.2883: Flags [S.], seq 3115332790, ack 14081, win 29200, options [mss 1460], length 0
    23:28:38.997167 IP 192.168.12.20.2883 > 192.168.12.10.8020: Flags [.], ack 1, win 1024, length 0
    23:28:38.998114 IP 192.168.12.20.2883 > 192.168.12.10.8020: Flags [P.], seq 1:108, ack 1, win 1024, length 107
    23:28:38.998340 IP 192.168.12.10.8020 > 192.168.12.20.2883: Flags [.], ack 108, win 29200, length 0
    23:28:39.036567 IP 192.168.12.10.http > NeB.lan.63743: Flags [P.], seq 4072708747:4072708826, ack 2592931699, win 1332, length 79
    23:28:39.044673 IP 192.168.12.10.8020 > 192.168.12.20.2883: Flags [P.], seq 1:162, ack 108, win 29200, length 161
    23:28:39.046796 IP 192.168.12.20.2883 > 192.168.12.10.8020: Flags [F.], seq 108, ack 162, win 1024, length 0
    23:28:39.059605 IP 192.168.12.10.8020 > 192.168.12.20.2883: Flags [F.], seq 162, ack 109, win 29200, length 0
    23:28:39.060672 IP 192.168.12.20.2883 > 192.168.12.10.8020: Flags [.], ack 163, win 1024, length 0
    23:28:39.239707 IP NeB.lan.63743 > 192.168.12.10.http: Flags [.], ack 79, win 16482, length 0
    23:28:41.586502 IP NeB.lan.53027 > 192.168.12.10.http: Flags [P.], seq 604146295:604146304, ack 76401422, win 16226, length 9
    23:28:41.590171 IP 192.168.12.10.http > NeB.lan.53027: Flags [P.], seq 1:12, ack 9, win 509, length 11
    23:28:41.788640 IP NeB.lan.53027 > 192.168.12.10.http: Flags [.], ack 12, win 16224, length 0
    23:28:44.232830 ARP, Request who-has 192.168.12.10 tell 192.168.12.1, length 48
    23:28:44.233006 ARP, Reply 192.168.12.10 is-at b8:27:eb:93:1e:de (oui Unknown), length 46
    23:28:49.570500 IP NeB.lan.63743 > 192.168.12.10.http: Flags [P.], seq 1:10, ack 79, win 16482, length 9
    23:28:49.574795 IP 192.168.12.10.http > NeB.lan.63743: Flags [P.], seq 79:90, ack 10, win 1332, length 11
    23:28:49.798720 IP NeB.lan.63743 > 192.168.12.10.http: Flags [.], ack 90, win 16479, length 0`[/s]
    


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

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

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

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



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



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

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

    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 раз попадать на момент конвертации данных просто невозможно! Такое ощущение, что это где-то закэшировалось…



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

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

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



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

    Тут уже методом перебора пытаюсь выявить из-за чего плагин зависает, поэтому отключаю по одному из датчиков. Отключил датчик СО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 мин
    }
    
    


  • @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
    
    


  • @Alex_Jet:

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

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

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

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

    @Alex_Jet:

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

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

    @Alex_Jet:

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

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

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

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

    • сохраняются флаги suspend и log для плагинов,

    • сохраняются системные флаги логирования (Трассировка).

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



  • @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 сек, например.



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

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

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



  • @Alex_Jet:

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

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

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

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

    @Alex_Jet:

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

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

    @Alex_Jet:

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

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

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



  • @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.
    
    


  • @Alex_Jet:

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

    Да
    @Alex_Jet:

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

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


Log in to reply