Probably an issue with appdaemon

Fraschi · April 30, 2020, 11:59am

Investigating in "Client Exceeded max pending messages" in HomeAssistant i’ve found that
the problem comes from appdaemon (from the client id). Didn’t know if appdaemon is the cause or a symptom. (All appdaemon apps are running for years without issues till now - AppDaemon V 4.0.3)

Here what I’ve found:

That’s from Home Assistant Log --> The client is appdaemon (the only client)

2020-04-29 21:14:05 ERROR (MainThread) [homeassistant.components.webhook] Error processing webhook cb2a6ba9b5719bbc9ca5cc794e7f3aeffde42ddf8c51a950206f38ed1204e58c
2020-04-29 21:15:58 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140692626535536] Client exceeded max pending messages [2]: 512
2020-04-29 21:15:58 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection.140692626535536] Client exceeded max pending messages [2]: 512

That’s from AppDaemon (things starded go bad a little time before):
After Some Messages Like this:

2020-04-29 21:12:27.404924 WARNING cloro: Coroutine (<coroutine object ADAPI.set_state at 0x7fcb742552c8>) took too long (10                                                                 seconds), cancelling the task...
2020-04-29 21:12:27.408978 WARNING HASS: Timeout in set_state(default, sensor.cloro2, {'state': 'Out Of Range'})
2020-04-29 21:12:27.410966 WARNING AppDaemon: callback ppm() in cloro has now completed

I get:

2020-04-29 21:13:30.925645 WARNING HASS: Error setting Home Assistant state default.sensor.cloro1, {'state': 'Out Of Range'}
2020-04-29 21:13:30.926696 WARNING HASS: Code: 502, error: <html>
<head><title>502 Bad Gateway</title></head>
<body bgcolor="white">
<center><h1>502 Bad Gateway</h1></center>
<hr><center>nginx/1.10.3</center>
</body>
</html>

After Some messages like this one, I get the error in Home Assistant log, that degenerates in unresponsive ui…

Meanwhile in nginx:

2020/04/29 21:13:00 [error] 4974#4974: *8530 connect() failed (111: Connection refused) while connecting to upstream, client: ::ffff:127.0.0.1, server: sitename.duckdns.org, request: "POST /api/states/sensor.cloro2 HTTP/1.1", upstream: "http://[::1]:8123/api/states/sensor.cloro2", host: "127.0.0.1"
2020/04/29 21:13:17 [error] 4977#4977: *8508 upstream timed out (110: Connection timed out) while reading response header from upstream, client: ::ffff:127.0.0.1, server: sitename.duckdns.org, request: "POST /api/states/sensor.cloro2 HTTP/1.1", upstream: "http://127.0.0.1:8123/api/states/sensor.cloro2", host: "127.0.0.1"
2020/04/29 21:13:20 [error] 4977#4977: *8511 upstream timed out (110: Connection timed out) while reading response header from upstream, client: ::ffff:127.0.0.1, server: sitename.duckdns.org, request: "POST /api/states/sensor.flag_ph HTTP/1.1", upstream: "http://127.0.0.1:8123/api/states/sensor.flag_ph", host: "127.0.0.1"
2020/04/29 21:13:24 [error] 4974#4974: *8541 connect() failed (111: Connection refused) while connecting to upstream, client: ::ffff:127.0.0.1, server: sitename.duckdns.org, request: "POST /api/states/sensor.flag_ph HTTP/1.1", upstream: "http://[::1]:8123/api/states/sensor.flag_ph", host: "127.0.0.1"
2020/04/29 21:13:30 [error] 4974#4974: *8517 upstream timed out (110: Connection timed out) while reading response header from upstream, client: ::ffff:127.0.0.1, server: sitename.duckdns.org, request: "POST /api/states/sensor.cloro1 HTTP/1.1", upstream: "http://127.0.0.1:8123/api/states/sensor.cloro1", host: "127.0.0.1"

and then:

`2020/04/29 21:25:01 [error] 4977#4977: *8713 connect() failed (111: Connection refused) while connecting to upstream, client: ::ffff:192.168.1.211, server: sitename.duckdns.org, request: "POST /api/webhook/<xxxxxxxxxxxxxxxxxxxxxx> HTTP/1.1", upstream: "http://[::1]:8123/api/webhook/<xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx>", host: "sitename.duckdns.org"`

As it seems is the API that starts not responding to AppDaemon and then this causes all the things

AppDaemon Version 4.0.3
All the apps are running before without issues.
At the time of writing:

Home Assistant V 0.190.0
The app mentioned in logs is disabled but the same error occurs for another app after about 10hrs of system running
Actually renewed the long-living token to see if that can be the cause.

Here the appdaemon config:

secret: /home/pi/.homeassistant/secrets.yaml

logs:
  main_log:
    filename:  /home/pi/logs/appdaemon.log
  access_log:
    filename: /home/pi/logs/access.log
  error_log:
    filename: /home/pi/logs/appdaemon.err
  diag_log:
    filename:  /home/pi/logs/diag.log
    log_generations: 5
    log_size: 1024
    format: "{asctime} {levelname:<8} {appname:<10}: {message}"

appdaemon:
  app_dir: /home/pi/.homeassistant/appdaemon
  total_threads: 50
  time_zone: Europe/Rome
  latitude: <latitude>
  longitude: <longitude>
  elevation: 390
  plugins:
    HASS:
      type: hass
      ha_url: https://127.0.0.1
      token: !secret token
      #cert_path: /etc/letsencrypt/live/<url>/fullchain.pem
      cert_verify: False
      namespace: default
      
http:
  url: https://<url>:5050
  password: !secret pwd
  dash_ssl_certificate: /etc/letsencrypt/live/<url>/fullchain.pem
  dash_ssl_key: /etc/letsencrypt/live/<url>/privkey.pem
api:
admin:
configuration: self.config_dir
apps: self.app_dir
dashboard: self.dashboard_dir

Here the app that is now “causing” the issue:

import hassapi as hass
import datetime
import time



class CheckPompe(hass.Hass):
    
    pozzo = 0
    sorgente = 0
    pozzostart = 0
    pozzoend = 0
    sorgenteend = 0
    sorgentestart = 0
    pozzomax = 100
    sorgentemax = 100
    prevevp = False
    prevevs = False
    presspozzo = 0
    presssorge = 0
    pozzocount = 0
  
    def initialize(self):
        runtime = datetime.datetime.now() + datetime.timedelta(seconds=60)
        CheckPompe.pozzo = 0
        CheckPompe.sorgente = 0
        CheckPompe.pozzostart = 0
        CheckPompe.pozzoend = 0
        CheckPompe.sorgenteend = 0
        CheckPompe.sorgentestart = 0
        CheckPompe.pozzomax = 60
        CheckPompe.sorgentemax = 60
        CheckPompe.presspozzo = self.get_state("sensor.pressione_pozzo")
        
        self.log(self.checkEV())
        
        self.set_state("sensor.tempo_pozzo", state = str(CheckPompe.pozzo), attributes = {"friendly_name": "Tempo Pozzo"})
        self.set_state("sensor.tempo_sorgente", state = str(CheckPompe.sorgente), attributes = {"friendly_name": "Tempo Sorgente"})  
        self.set_state("sensor.alert_pozzo", state = "OK" , attributes = {"friendly_name": "Alert Pozzo"})
        self.set_state("sensor.alert_sorgente", state = "OK", attributes = {"friendly_name": "Alert Sorgente"})  
        self.set_state("sensor.pozzocount", state = str(CheckPompe.pozzocount), attributes = {"friendly_name": "Accensioni Pozzo in 1h"})  
        
        self.set_state("binary_sensor.pozzo_pressalert", state = "off", attributes = {"friendly_name": "PressAlert Pozzo"}) 
        self.set_state("binary_sensor.pozzo_noev", state = "off", attributes = {"friendly_name": "NoEv Pozzo"}) 
        self.set_state("binary_sensor.pozzo_termica", state = "off", attributes = {"friendly_name": "Protezione Termica Pozzo "}) 
        self.set_state("binary_sensor.pozzo_high", state = "off", attributes = {"friendly_name": "Pressione Pozzo Elevata"}) 
        self.set_state("binary_sensor.pozzo_low", state = "off", attributes = {"friendly_name": "Pressione Pozzo Bassa"})
        self.log(runtime)
        self.log("Tempo Sorgente " + str(CheckPompe.sorgente))  
        self.log("Tempo Pozzo " + str(CheckPompe.pozzo))
     
        self.listen_state(self.pozzo_callback,"binary_sensor.pressostato_pozzo")
        
        #self.listen_state(self.press_pozzo_callback,"sensor.pressione_pozzo")
        
        self.listen_state(self.sorgente_callback,"binary_sensor.pressostato_sorgente")
        
        self.run_every(self.hourlycheck, runtime, 60*10)
        
        self.run_every(self.presscheck, runtime, 60)
        
        self.run_every(self.press_pozzo_callback, runtime, 60)
    
    def press_pozzo_callback(self, kwargs):
        pressostato = self.get_state("binary_sensor.pressostato_pozzo")
        pressione = self.get_state("sensor.pressione_pozzo")
        self.log(pressostato + " , " + pressione)
        if float(pressione) < 0.3:
           #self.log("Low Pressure")
           if pressostato == "off":
               #self.log("Sgancio Termica Pozzo")
               self.set_state("binary_sensor.pozzo_termica", state = "on", attributes = {"friendly_name": "Protezione Termica Pozzo "})
           else:
               #self.log("Consumo acqua elevato")
               self.set_state("binary_sensor.pozzo_low", state = "on", attributes = {"friendly_name": "Pressione Pozzo Bassa"})
        elif float(pressione) > 3:
           #self.log("High Pressure")    
           self.set_state("binary_sensor.pozzo_high", state = "on", attributes = {"friendly_name": "Pressione Pozzo Elevata"})
        else:
           #self.log("Normal Pressure")
           self.set_state("binary_sensor.pozzo_termica", state = "off", attributes = {"friendly_name": "Protezione Termica Pozzo "}) 
           self.set_state("binary_sensor.pozzo_high", state = "off", attributes = {"friendly_name": "Pressione Pozzo Elevata"}) 
           self.set_state("binary_sensor.pozzo_low", state = "off", attributes = {"friendly_name": "Pressione Pozzo Bassa"})
            
        
    
    
    def checkEV(self):
        evs = self.args["entities"]
        opened = False
        for ev in evs:
            if self.get_state(ev) == "on":
               self.log(ev + " Aperta")
               opened = True
            else:
               self.log(ev + " Chiusa")
        return opened
        
        
    def presscheck(self, kwargs):
        pressnow = self.get_state("sensor.pressione_pozzo")
        self.log("Prev Press: " + str(CheckPompe.presspozzo) + " , Now Press: " + str(pressnow))
        diff = float(CheckPompe.presspozzo) - float(pressnow)
        diff = round(diff,2)
        if diff > 0.1 and not self.checkEV():
            self.log("Perdita o Rubinetto Aperto")
            self.set_state("binary_sensor.pozzo_pressalert", state = "on", attributes = {"friendly_name": "PressAlert Pozzo"})
        else:
            self.set_state("binary_sensor.pozzo_pressalert", state = "off", attributes = {"friendly_name": "PressAlert Pozzo"})
        self.log(str(diff))
        CheckPompe.presspozzo = pressnow
          
    def pozzo_callback(self, entity, attribute, old, new, kwargs):
        self.log("Pozzo " + str(new) + " , " + str(old))
        if not self.checkEV():
            self.log("Elettrovalvole CHIUSE")
            if new == "on":
                 CheckPompe.pozzocount = CheckPompe.pozzocount + 1
                 self.set_state("sensor.pozzocount", state = str(CheckPompe.pozzocount), attributes = {"friendly_name": "Accensioni Pozzo in 1h"})  
                 self.set_state("binary_sensor.pozzo_noev", state = "on", attributes = {"friendly_name": "NoEv Pozzo"})
                 self.log("Pozzo si accende ma ev chiuse --> Inizio conteggio Tempo")
                 CheckPompe.pozzostart = datetime.datetime.now()
                 self.log("Pozzo-On " + CheckPompe.pozzostart.strftime("%Y-%m-%d %H:%M:%S"))
            else:
                if not CheckPompe.prevevp:
                    self.log("Pozzo si spenge, ev chiuse da ciclo precedente --> Concludo Conteggio")
                    CheckPompe.pozzoend = datetime.datetime.now()
                    self.log("Pozzo-Off " + CheckPompe.pozzoend.strftime("%Y-%m-%d %H:%M:%S"))
                    CheckPompe.pozzo = CheckPompe.pozzo + ((CheckPompe.pozzoend - CheckPompe.pozzostart).total_seconds())    
                    self.set_state("sensor.tempo_pozzo", state = str(CheckPompe.pozzo), attributes = {"friendly_name": "Tempo Pozzo"})
                else:
                    self.set_state("binary_sensor.pozzo_noev", state = "off", attributes = {"friendly_name": "NoEv Pozzo"})
                    self.log("Pozzo si spenge, ev chiuse ma aperte in ciclo precedente")
                    CheckPompe.prevevp = False
        else:
            self.log("Elettrovalvole APERTE")
            self.set_state("binary_sensor.pozzo_noev", state = "off", attributes = {"friendly_name": "NoEv Pozzo"})
            CheckPompe.prevevp = True
        
    def sorgente_callback(self, entity, attribute, old, new, kwargs):
        self.log("Sorgente " + str(new) + " , " + str(old))
        if new == "on":
           CheckPompe.sorgentestart = datetime.datetime.now()
           self.log("Sorgente-On " + CheckPompe.sorgentestart.strftime("%Y-%m-%d %H:%M:%S"))
        else:
           CheckPompe.sorgenteend = datetime.datetime.now()
           self.log("Sorgente Off " + CheckPompe.sorgenteend.strftime("%Y-%m-%d %H:%M:%S"))
           CheckPompe.sorgente = CheckPompe.sorgente + ((CheckPompe.sorgenteend - CheckPompe.sorgentestart).total_seconds())
           self.set_state("sensor.tempo_sorgente", state = str(CheckPompe.sorgente), attributes = {"friendly_name": "Tempo sorgente"})
        
    def hourlycheck(self,kwargs):
        self.log("HourlyCheck")
        now = datetime.datetime.now()
        if self.get_state("binary_sensor.pressostato_pozzo") == "on":
           if (now - CheckPompe.pozzostart).total_seconds() > CheckPompe.pozzomax:
               self.set_state("sensor.alert_pozzo", state = "Problemi Gravi" , attributes = {"friendly_name": "Alert Pozzo"})
        else:
           if CheckPompe.pozzo > CheckPompe.pozzomax:
               self.set_state("sensor.alert_pozzo", state = "Problemi" , attributes = {"friendly_name": "Alert Pozzo"})
           else:
               self.set_state("sensor.alert_pozzo", state = "OK" , attributes = {"friendly_name": "Alert Pozzo"})
               
        if self.get_state("binary_sensor.pressostato_sorgente") == "on":
           if (now - CheckPompe.sorgentestart).total_seconds() > CheckPompe.sorgentemax:
               self.set_state("sensor.alert_sorgente", state = "Problemi Gravi" , attributes = {"friendly_name": "Alert Sorgente"})
        else:
           if CheckPompe.sorgente > CheckPompe.sorgentemax:
               self.set_state("sensor.alert_sorgente", state = "Problemi" , attributes = {"friendly_name": "Alert Sorgente"})
           else:
               self.set_state("sensor.alert_sorgente", state = "OK" , attributes = {"friendly_name": "Alert Sorgente"})
        self.log("Tempo Sorgente " + str(CheckPompe.sorgente))  
        self.log("Tempo Pozzo " + str(CheckPompe.pozzo))  
        CheckPompe.pozzo = 0
        self.set_state("sensor.tempo_pozzo", state = str(CheckPompe.pozzo), attributes = {"friendly_name": "Tempo Pozzo"})
        CheckPompe.sorgente = 0
        self.set_state("sensor.tempo_sorgente", state = str(CheckPompe.sorgente), attributes = {"friendly_name": "Tempo sorgente"})
        CheckPompe.pozzocount = 0
        self.set_state("sensor.pozzocount", state = str(CheckPompe.pozzocount), attributes = {"friendly_name": "Accensioni Pozzo in 1h"})         
        self.set_state("binary_sensor.pozzo_noev", state = "off", attributes = {"friendly_name": "NoEv Pozzo"})

Here the nginx config:

map $http_upgrade $connection_upgrade {
    default upgrade;
    '' close;
}
server {
    # Update this line to be your domain
    server_name sitename.duckdns.org;
    # These shouldn't need to be changed
    listen [::]:80 default_server ipv6only=off;
    return 301 https://$host$request_uri;
}
server {
    # Update this line to be your domain
    server_name sitename.duckdns.org;
    # Ensure these lines point to your SSL certificate and key
    ssl_certificate /etc/letsencrypt/live/sitename.duckdns.org/fullchain.pem;
    # managed by Certbot
    ssl_certificate_key /etc/letsencrypt/live/sitename.duckdns.org/privkey.pem; # managed by Certbot
    # Ensure this line points to your dhparams file
    ssl_dhparam /etc/nginx/ssl/dhparams.pem;
    # These shouldn't need to be changed
    listen [::]:443 default_server ipv6only=off; # if your nginx version  is >= 1.9.5 you can also add the "http2" flag here
    add_header Strict-Transport-Security "max-age=31536000; includeSubdomains";
    ssl on;
    ssl_protocols TLSv1 TLSv1.1 TLSv1.2;
    ssl_ciphers "EECDH+AESGCM:EDH+AESGCM:AES256+EECDH:AES256+EDH:!aNULL:!eNULL:!EXPORT:!DES:!MD5:!PSK:!RC4";
    ssl_prefer_server_ciphers on;
    ssl_session_cache shared:SSL:10m;
    proxy_buffering off;
    location / {
        proxy_pass http://localhost:8123;
        proxy_set_header Host $host;
        proxy_redirect http:// https://;
        proxy_http_version 1.1;
        proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
        proxy_set_header Upgrade $http_upgrade;
        proxy_set_header Connection $connection_upgrade;
    }
      location /api/appdaemon/ {
      allow all;
      proxy_pass http://localhost:5555;
      proxy_set_header Host $host;
      proxy_redirect http:// http://;
}

   location /configurator/ {
   proxy_pass https://192.168.1.236:3218;
   #proxy_set_header Host $host;
   #proxy_redirect http:// https://;
   #proxy_http_version 1.1;
   #proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
   #proxy_set_header Upgrade $http_upgrade;
   #proxy_set_header Connection $connection_upgrade;
   }


   location /picapport/ {
   proxy_pass https://192.168.1.236:8080;
   proxy_http_version 1.1;        # default proxy http version = 1.0
   }

   location /grafana/ {
   proxy_pass https://192.168.1.236:3001;
   }

   location /vs/ {
   proxy_pass https://192.168.1.3:4433;
   proxy_set_header Host $host;
   proxy_redirect http:// https://;
   proxy_http_version 1.1;
   proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
   proxy_set_header Upgrade $http_upgrade;
   proxy_set_header Connection $connection_upgrade;

   }

}

server {
    # Update this line to be your domain
    server_name sitename2.duckdns.org; # managed by Certbot
    # Ensure these lines point to your SSL certificate and key
    ssl_certificate /etc/letsencrypt/live/sitename2.duckdns.org/fullchain.pem;
    # managed by Certbot
    ssl_certificate_key /etc/letsencrypt/live/sitename2.duckdns.org/privkey.pem; # managed by Certbot
    # Ensure this line points to your dhparams file
    ssl_dhparam /etc/nginx/ssl/dhparams.pem;
    # These shouldn't need to be changed
    listen [::]:443  ; # if your nginx version  is >= 1.9.5 you can also add the "http2" flag here
    add_header Strict-Transport-Security "max-age=31536000; includeSubdomains";
    ssl on;
    ssl_protocols TLSv1 TLSv1.1 TLSv1.2;
    ssl_ciphers "EECDH+AESGCM:EDH+AESGCM:AES256+EECDH:AES256+EDH:!aNULL:!eNULL:!EXPORT:!DES:!MD5:!PSK:!RC4";
    ssl_prefer_server_ciphers on;
    ssl_session_cache shared:SSL:10m;
    proxy_buffering off;
    location / {
        proxy_pass http://localhost:8123;
        proxy_set_header Host $host;
        proxy_redirect http:// https://;
        proxy_http_version 1.1;
        proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
        proxy_set_header Upgrade $http_upgrade;
        proxy_set_header Connection $connection_upgrade;
    }
      location /api/appdaemon/ {
      allow all;
      proxy_pass http://localhost:5555;
      proxy_set_header Host $host;
      proxy_redirect http:// http://;
}

   location /configurator/ {
   proxy_pass https://192.168.1.236:3218;
   #proxy_set_header Host $host;
   #proxy_redirect http:// https://;
   #proxy_http_version 1.1;
   #proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
   #proxy_set_header Upgrade $http_upgrade;
   #proxy_set_header Connection $connection_upgrade;
   }


   location /picapport/ {
   proxy_pass https://192.168.1.236:8080;
   proxy_http_version 1.1;        # default proxy http version = 1.0
   }

   location /grafana/ {
   proxy_pass https://192.168.1.236:3001;
   }

   location /vs/ {
   proxy_pass https://192.168.1.3:4433;
   proxy_set_header Host $host;
   proxy_redirect http:// https://;
   proxy_http_version 1.1;
   proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
   proxy_set_header Upgrade $http_upgrade;
   proxy_set_header Connection $connection_upgrade;

   }
}

Fraschi · April 30, 2020, 12:08pm

Re-reading my post… a question:
Didn’t remeber why in nginx the proxy pass is set to port 5555, but, now… With AppDaemon 4.0.3 is the same? Or I have to set it to port 5050? can be this the cause?

Fraschi · April 30, 2020, 5:44pm

Same problem also with port 5050…
But now I get the following messages on home assistant log:

2020-04-30 15:21:44 WARNING (MainThread) [homeassistant.components.websocket_api.http.connection.140323770648392] Disconnected: Received non-Text message.
2020-04-30 15:22:49 WARNING (MainThread) [homeassistant.components.websocket_api.http.connection.140323807358536] Disconnected: Received non-Text message.
2020-04-30 15:28:47 WARNING (MainThread) [homeassistant.components.websocket_api.http.connection.140323071623240] Disconnected: Did not receive auth message within 10 seconds

Fraschi · May 1, 2020, 9:39pm

Also in 109.1… Removed another appdaemon app… Detailed log messages in other specific post: Probably an issue with appdaemon