search

wonderslug / MMM-HomeAssistantDisplay

A Magic Mirror Module to display information from Home Assistant.
MIT License
83 stars 6 forks source link

[SOLVED] Won't reconnect after disconnect #6

Closed rbauman70 closed 2 years ago

rbauman70 commented 2 years ago

I've been running Magic Mirror on a Raspberry Pi 3B+ for about a year now. I've just added MMM-HomeAssistantDisplay to display energy values from Home Assistant. After a random time, the display values stop updating. I enabled debuglogging in the config.js for this module but didn't see any additional info. Here's a typical mm-out.log:

[26.05.2022 14:18.04.433] [LOG]   Connecting socket for: MMM-HomeAssistantDisplay
[26.05.2022 14:18.04.436] [LOG]   Sockets connected & modules started ...
[26.05.2022 14:18.04.875] [LOG]   Launching application.
[26.05.2022 14:18.15.275] [LOG]   Create new calendarfetcher for url: http://www.calendarlabs.com/ical-calendar/ics/76/US_Holidays.ics - Interval: 300000
.
.
.
[26.05.2022 14:18.16.607] [INFO]  [MMM-HomeAssistantDisplay] [ 'HomeAssistant connected for module_11_MMM-HomeAssistantDisplay' ]
[26.05.2022 14:18.16.659] [INFO]  Checking git for module: MMM-Remote-Control
[26.05.2022 14:18.16.749] [LOG]   Electron's cache successfully cleared.
[26.05.2022 14:18.16.861] [INFO]  Checking git for module: WallberryTheme
[26.05.2022 14:18.16.983] [INFO]  Checking git for module: MMM-HomeAssistantDisplay
[26.05.2022 14:18.17.085] [INFO]  Checking git for module: default
[26.05.2022 14:18.17.403] [INFO]  [MMM-HomeAssistantDisplay] [
  'Conected to Home Assistant for module_11_MMM-HomeAssistantDisplay after 0 retries'
]
[26.05.2022 14:18.17.706] [INFO]  Calendar-Fetcher: Broadcasting 3 events.
[26.05.2022 14:18.18.592] [INFO]  Calendar-Fetcher: Broadcasting 5 events.
[26.05.2022 14:18.21.564] [INFO]  Calendar-Fetcher: Broadcasting 3 events.
[26.05.2022 14:18.25.384] [DEBUG] [MMM-HomeAssistantDisplay] [
  'Found listening connection (module_11_MMM-HomeAssistantDisplay) for entity sensor.envoy_202151121117_current_power_production'
]
[26.05.2022 14:18.25.451] [DEBUG] [MMM-HomeAssistantDisplay] [
  'Found listening connection (module_11_MMM-HomeAssistantDisplay) for entity sensor.envoy_202151121117_current_power_consumption'
]
[26.05.2022 14:18.25.533] [DEBUG] [MMM-HomeAssistantDisplay] [
  'Found listening connection (module_11_MMM-HomeAssistantDisplay) for entity sensor.grid_export_power'
]
[26.05.2022 14:19.25.330] [DEBUG] [MMM-HomeAssistantDisplay] [
  'Found listening connection (module_11_MMM-HomeAssistantDisplay) for entity sensor.envoy_202151121117_current_power_production'
]
[26.05.2022 14:19.25.421] [DEBUG] [MMM-HomeAssistantDisplay] [
  'Found listening connection (module_11_MMM-HomeAssistantDisplay) for entity sensor.envoy_202151121117_current_power_consumption'
]
[26.05.2022 14:19.25.436] [DEBUG] [MMM-HomeAssistantDisplay] [
  'Found listening connection (module_11_MMM-HomeAssistantDisplay) for entity sensor.grid_export_power'
]
[26.05.2022 14:20.25.528] [DEBUG] [MMM-HomeAssistantDisplay] [
  'Found listening connection (module_11_MMM-HomeAssistantDisplay) for entity sensor.envoy_202151121117_current_power_production'
]
[26.05.2022 14:20.25.608] [DEBUG] [MMM-HomeAssistantDisplay] [
  'Found listening connection (module_11_MMM-HomeAssistantDisplay) for entity sensor.envoy_202151121117_current_power_consumption'
]
[26.05.2022 14:20.25.654] [DEBUG] [MMM-HomeAssistantDisplay] [
  'Found listening connection (module_11_MMM-HomeAssistantDisplay) for entity sensor.grid_export_power'
]
[26.05.2022 14:21.25.434] [DEBUG] [MMM-HomeAssistantDisplay] [
  'Found listening connection (module_11_MMM-HomeAssistantDisplay) for entity sensor.envoy_202151121117_current_power_production'
]
[26.05.2022 14:21.25.507] [DEBUG] [MMM-HomeAssistantDisplay] [
  'Found listening connection (module_11_MMM-HomeAssistantDisplay) for entity sensor.envoy_202151121117_current_power_consumption'
]
[26.05.2022 14:21.25.601] [DEBUG] [MMM-HomeAssistantDisplay] [
  'Found listening connection (module_11_MMM-HomeAssistantDisplay) for entity sensor.grid_export_power'
]
[26.05.2022 14:21.55.554] [DEBUG] [MMM-HomeAssistantDisplay] [ 'Hass WS Disconnected (module_11_MMM-HomeAssistantDisplay)' ]
[26.05.2022 14:21.55.571] [INFO]  [MMM-HomeAssistantDisplay] [
  'Reconnecting to Home Assistant websocket for module_11_MMM-HomeAssistantDisplay'
]
[26.05.2022 14:21.55.636] [INFO]  [MMM-HomeAssistantDisplay] [
  'Unable to connect to Home Assistant for module_11_MMM-HomeAssistantDisplay: socket hang up'
]
[26.05.2022 14:23.18.397] [INFO]  Calendar-Fetcher: Broadcasting 3 events.
[26.05.2022 14:23.19.477] [INFO]  Calendar-Fetcher: Broadcasting 5 events.
[26.05.2022 14:23.25.133] [INFO]  Calendar-Fetcher: Broadcasting 3 events.

and mm-error.out:

[16288:0526/141806.801431:ERROR:gpu_process_host.cc(979)] GPU process exited unexpectedly: exit_code=139
[16288:0526/141808.357494:ERROR:gpu_process_host.cc(979)] GPU process exited unexpectedly: exit_code=139
[16288:0526/141810.036174:ERROR:gpu_process_host.cc(979)] GPU process exited unexpectedly: exit_code=139
[16406:0526/141811.693763:ERROR:sandbox_linux.cc(377)] InitializeSandbox() called with multiple threads in process gpu-process.
[26.05.2022 14:21.55.628] [ERROR] [MMM-HomeAssistantDisplay] [
  'Unable to connect to Home Assistant for module module_11_MMM-HomeAssistantDisplay failed with message: ',
  'socket hang up'
]

This is the module configuration from config.js with some sensitive items replaced:

    {
      disabled: false,
      module: "MMM-HomeAssistantDisplay",
      position: "bottom_right",
      config: {
        host: HOST,
        port: "443",
        useTLS: true,
        ignoreCert: true,
        token: TOKEN,
        title: "Energy Distribution",
        class: "energy-distribution",
        debuglogging: false,
        sections: [{
          triggerEntities: [
            "sensor.grid_import_power",
            "sensor.grid_export_power",
            "sensor.envoy_202151121117_current_power_consumption",
            "sensor.envoy_202151121117_current_power_production",
          ],
          displayTemplate: `
            <table class="medium" style="padding-top:10px;padding-right:20px;">
              <tr>
              <td align="left">Current Power Consumption&nbsp;&nbsp;</td>
              <td align="right">{{states('sensor.envoy_202151121117_current_power_consumption')}} {{state_attr('sensor.envoy_202151121117_current_power_consumption','unit_of_measurement')}}</td>
              </tr>
              <tr>
              <td align="left">Current Power Production&nbsp;&nbsp;</td>
              <td align="right">{{states('sensor.envoy_202151121117_current_power_production')}} {{state_attr('sensor.envoy_202151121117_current_power_consumption','unit_of_measurement')}}</td>
              </tr>
              <tr>
              <td align="left">{{state_attr('sensor.grid_import_power','friendly_name')}}</td>
              <td align="right">{{states('sensor.grid_import_power')}} {{state_attr('sensor.grid_import_power','unit_of_measurement')}}</td>
              </tr>
              <tr>
              <td align="left">{{state_attr('sensor.grid_export_power','friendly_name')}}</td>
              <td align="right">{{states('sensor.grid_export_power')}} {{state_attr('sensor.grid_export_power','unit_of_measurement')}}</td>
              </tr>
            </table>
            `,
          class: "energy-items"
         }]
      },
    },

I've pulled the latest Magic Mirror version from the repository but no difference. Both the RPi and Home Assistant server are on the same LAN. The HA server is proxied by HAProxy (no relation) on my firewall/router. I'm not seeing any errors in the HA logs regarding Magic Mirror. Let me know what additional information I can provide.

rbauman70 commented 2 years ago

After investigating possible causes of the disconnection, I found that HAProxy has a default tunnel timeout of 60 seconds of no activity before closing the tunnel, discussed here. After making the change to my HAProxy configuration, the module stayed connected overnight. However, the module still won't reconnect after a loss of connection to HA. I restarted HA during the following log snippet and did not see reconnection attempts after the socket hang up:

[27.05.2022 08:02.20.404] [DEBUG] [MMM-HomeAssistantDisplay] [
  'Found listening connection (module_11_MMM-HomeAssistantDisplay) for entity sensor.envoy_202151121117_current_power_production'
]
[27.05.2022 08:02.20.483] [DEBUG] [MMM-HomeAssistantDisplay] [
  'Found listening connection (module_11_MMM-HomeAssistantDisplay) for entity sensor.envoy_202151121117_current_power_consumption'
]
[27.05.2022 08:02.20.500] [DEBUG] [MMM-HomeAssistantDisplay] [
  'Found listening connection (module_11_MMM-HomeAssistantDisplay) for entity sensor.grid_export_power'
]
[27.05.2022 08:03.09.549] [INFO]  Calendar-Fetcher: Broadcasting 2 events.
[27.05.2022 08:03.18.037] [DEBUG] [MMM-HomeAssistantDisplay] [ 'Hass WS Disconnected (module_11_MMM-HomeAssistantDisplay)' ]
[27.05.2022 08:03.18.045] [INFO]  [MMM-HomeAssistantDisplay] [
  'Reconnecting to Home Assistant websocket for module_11_MMM-HomeAssistantDisplay'
]
[27.05.2022 08:03.18.106] [INFO]  [MMM-HomeAssistantDisplay] [
  'Unable to connect to Home Assistant for module_11_MMM-HomeAssistantDisplay: socket hang up'
]
[27.05.2022 08:03.35.848] [INFO]  Calendar-Fetcher: Broadcasting 3 events.
[27.05.2022 08:04.35.591] [INFO]  Calendar-Fetcher: Broadcasting 5 events.
[27.05.2022 08:08.11.667] [INFO]  Calendar-Fetcher: Broadcasting 2 events.
[27.05.2022 08:08.36.348] [INFO]  Calendar-Fetcher: Broadcasting 3 events.
[27.05.2022 08:09.36.432] [INFO]  Calendar-Fetcher: Broadcasting 5 events.
[27.05.2022 08:13.13.760] [INFO]  Calendar-Fetcher: Broadcasting 2 events.
[27.05.2022 08:13.36.880] [INFO]  Calendar-Fetcher: Broadcasting 3 events.
[27.05.2022 08:14.37.258] [INFO]  Calendar-Fetcher: Broadcasting 5 events.
[27.05.2022 08:18.15.978] [INFO]  Calendar-Fetcher: Broadcasting 2 events.
[27.05.2022 08:18.37.478] [INFO]  Calendar-Fetcher: Broadcasting 3 events.
[27.05.2022 08:19.38.214] [INFO]  Calendar-Fetcher: Broadcasting 5 events.
[27.05.2022 08:23.18.281] [INFO]  Calendar-Fetcher: Broadcasting 2 events.
[27.05.2022 08:23.38.472] [INFO]  Calendar-Fetcher: Broadcasting 3 events.
[27.05.2022 08:24.39.050] [INFO]  Calendar-Fetcher: Broadcasting 5 events.
rbauman70 commented 2 years ago

[SOLVED] The module was failing to reconnect because reconnectWebSocket in node_helper.js wasn't using the requested TLS protocol. I added useTLS to the connectConfig definition:

async function reconnectWebsocket(payload) {
    const connectionConfig = {
        host: payload.host,
        port: payload.port,
        token: payload.token,
                useTLS: payload.useTLS, //!!! reconnect must use same protocol
        ignoreCert: payload.ignoreCert

I also found the return value test for the backoff call.retryIf was too restrictive. While HA was restarting, HAProxy could return additional errors. I modified it to always allow retries.

    call.retryIf(function(err) {
        //!!! return err.error.code == 'ECONNREFUSED'; 
        return true;  //!!!
    });
wonderslug commented 2 years ago

@rbauman70 thanks! Good catch. Explains why I was not seeing it as I was trying it in non-ssl mode. Ill add these to a PR and do a push.

rbauman70 commented 2 years ago

You're welcome.  Happy to help.  Thanks for the work on a great MM module.

Ron

On 5/28/2022 10:58 AM, Brian Towles wrote:

@rbauman70 https://github.com/rbauman70 thanks! Good catch. Explains why I was not seeing it as I was trying it in non-ssl mode. Ill add these to a PR and do a push.

— Reply to this email directly, view it on GitHub https://github.com/wonderslug/MMM-HomeAssistantDisplay/issues/6#issuecomment-1140279009, or unsubscribe https://github.com/notifications/unsubscribe-auth/ATAHA6KUWDYSDXHLWTHDS43VMIYBVANCNFSM5XCA7WRQ. You are receiving this because you were mentioned.Message ID: @.***>