Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

room-assistant does not always test BT addresses #754

Closed
Scott8586 opened this issue Jun 8, 2021 · 2 comments
Closed

room-assistant does not always test BT addresses #754

Scott8586 opened this issue Jun 8, 2021 · 2 comments
Labels
bug

Comments

@Scott8586
Copy link

Scott8586 commented Jun 8, 2021 •
edited
Loading

Describe the bug
room-assistant runs correctly 50% of the time.
When not running correctly, room-assistant goes into a loop that does not include testing addresses in bluetoothClassic mode.
In the log below, the last four lines repeat every 30sec, but bluetooth addresses are never tested.
This is an all-or-none problem - works correctly, or tests nothing.

I suspect this happens in BLE mode too.

To reproduce
Setup a BluetoothClassic configuration, run with -v flag until exposes bug. reboot pi until problem shows in logs

Relevant logs
See last four/eight lines - this repeats, but no testing of BT addresses

Jun  8 16:20:24 raspi8 room-assistant[716]: *** WARNING *** The program 'node' uses the Apple Bonjour compatibility layer of Avahi.
Jun  8 16:20:24 raspi8 room-assistant[716]: *** WARNING *** Please fix your application to use the native API of Avahi!
Jun  8 16:20:24 raspi8 room-assistant[716]: *** WARNING *** For more information see <http://0pointer.de/blog/projects/avahi-compat.html>
Jun  8 16:20:24 raspi8 room-assistant[716]: *** WARNING *** The program 'node' called 'DNSServiceRegister()' which is not supported (or only supported partially) in the Apple Bonjour compatibility layer of Avahi.
Jun  8 16:20:24 raspi8 room-assistant[716]: *** WARNING *** Please fix your application to use the native API of Avahi!
Jun  8 16:20:24 raspi8 room-assistant[716]: *** WARNING *** For more information see <http://0pointer.de/blog/projects/avahi-compat.html>
Jun  8 16:20:30 raspi8 room-assistant[716]: 08/06/2021, 16:20:30 - info - IntegrationsModule: Loading integrations: home-assistant, bluetooth-classic
Jun  8 16:20:36 raspi8 room-assistant[716]: 08/06/2021, 16:20:36 - info - NestFactory: Starting Nest application...
Jun  8 16:20:37 raspi8 room-assistant[716]: 08/06/2021, 16:20:37 - info - InstanceLoader: AppModule dependencies initialized
Jun  8 16:20:37 raspi8 room-assistant[716]: 08/06/2021, 16:20:37 - info - InstanceLoader: ConfigModule dependencies initialized
Jun  8 16:20:37 raspi8 room-assistant[716]: 08/06/2021, 16:20:37 - info - InstanceLoader: NestEmitterModule dependencies initialized
Jun  8 16:20:37 raspi8 room-assistant[716]: 08/06/2021, 16:20:37 - info - InstanceLoader: IntegrationsModule dependencies initialized
Jun  8 16:20:37 raspi8 room-assistant[716]: 08/06/2021, 16:20:37 - info - InstanceLoader: HttpModule dependencies initialized
Jun  8 16:20:37 raspi8 room-assistant[716]: 08/06/2021, 16:20:37 - info - InstanceLoader: DiscoveryModule dependencies initialized
Jun  8 16:20:37 raspi8 room-assistant[716]: 08/06/2021, 16:20:37 - info - InstanceLoader: PrometheusModule dependencies initialized
Jun  8 16:20:37 raspi8 room-assistant[716]: 08/06/2021, 16:20:37 - info - InstanceLoader: EventsModule dependencies initialized
Jun  8 16:20:37 raspi8 room-assistant[716]: 08/06/2021, 16:20:37 - info - InstanceLoader: ClusterModule dependencies initialized
Jun  8 16:20:37 raspi8 room-assistant[716]: 08/06/2021, 16:20:37 - info - InstanceLoader: TerminusModule dependencies initialized
Jun  8 16:20:37 raspi8 room-assistant[716]: 08/06/2021, 16:20:37 - info - InstanceLoader: ScheduleModule dependencies initialized
Jun  8 16:20:37 raspi8 room-assistant[716]: 08/06/2021, 16:20:37 - info - InstanceLoader: BluetoothModule dependencies initialized
Jun  8 16:20:37 raspi8 room-assistant[716]: 08/06/2021, 16:20:37 - info - InstanceLoader: EntitiesModule dependencies initialized
Jun  8 16:20:37 raspi8 room-assistant[716]: 08/06/2021, 16:20:37 - info - InstanceLoader: BluetoothClassicModule dependencies initialized
Jun  8 16:20:37 raspi8 room-assistant[716]: 08/06/2021, 16:20:37 - info - InstanceLoader: HomeAssistantModule dependencies initialized
Jun  8 16:20:37 raspi8 room-assistant[716]: 08/06/2021, 16:20:37 - info - InstanceLoader: StatusModule dependencies initialized
Jun  8 16:20:40 raspi8 room-assistant[716]: 08/06/2021, 16:20:40 - info - RoutesResolver: EntitiesController {/entities}:
Jun  8 16:20:40 raspi8 room-assistant[716]: 08/06/2021, 16:20:40 - info - RouterExplorer: Mapped {/entities, GET} route
Jun  8 16:20:40 raspi8 room-assistant[716]: 08/06/2021, 16:20:40 - info - RoutesResolver: StatusController {/status}:
Jun  8 16:20:40 raspi8 room-assistant[716]: 08/06/2021, 16:20:40 - info - RouterExplorer: Mapped {/status, GET} route
Jun  8 16:20:40 raspi8 room-assistant[716]: 08/06/2021, 16:20:40 - info - RoutesResolver: PrometheusController {/metrics}:
Jun  8 16:20:41 raspi8 room-assistant[716]: 08/06/2021, 16:20:41 - info - RouterExplorer: Mapped {/metrics, GET} route
Jun  8 16:20:43 raspi8 room-assistant[716]: 08/06/2021, 16:20:43 - debug - HomeAssistantService: Marking instance as online
Jun  8 16:20:43 raspi8 room-assistant[716]: 08/06/2021, 16:20:43 - info - HomeAssistantService: Successfully connected to MQTT broker at mqtt://192.168.37.161:1883
Jun  8 16:20:43 raspi8 room-assistant[716]: 08/06/2021, 16:20:43 - info - ConfigService: Loading configuration from /opt/nodejs/lib/node_modules/room-assistant/dist/config/definitions/default.js, config/local.yml (Current: /home/srp/room-assistant)
Jun  8 16:20:44 raspi8 room-assistant[716]: 08/06/2021, 16:20:44 - debug - EntitiesService: Adding new entity bluetooth-classic-inquiries-switch
Jun  8 16:20:44 raspi8 room-assistant[716]: 08/06/2021, 16:20:44 - debug - HomeAssistantService: Registering entity room-assistant-den-tr-bluetooth-classic-inquiries-switch under homeassistant/switch/room-assistant/den-tr-bluetooth-classic-inquiries-switch/config
Jun  8 16:20:44 raspi8 room-assistant[716]: 08/06/2021, 16:20:44 - debug - HomeAssistantService: Marking room-assistant-den-tr-bluetooth-classic-inquiries-switch as online
Jun  8 16:20:44 raspi8 room-assistant[716]: 08/06/2021, 16:20:44 - debug - EntitiesService: Adding new entity status-cluster-size
Jun  8 16:20:44 raspi8 room-assistant[716]: 08/06/2021, 16:20:44 - debug - HomeAssistantService: Registering entity room-assistant-den-tr-status-cluster-size under homeassistant/sensor/room-assistant/den-tr-status-cluster-size/config
Jun  8 16:20:44 raspi8 room-assistant[716]: 08/06/2021, 16:20:44 - debug - HomeAssistantService: Marking room-assistant-den-tr-status-cluster-size as online
Jun  8 16:20:44 raspi8 room-assistant[716]: 08/06/2021, 16:20:44 - debug - EntitiesService: Adding new entity status-cluster-leader
Jun  8 16:20:44 raspi8 room-assistant[716]: 08/06/2021, 16:20:44 - debug - HomeAssistantService: Registering entity room-assistant-den-tr-status-cluster-leader under homeassistant/sensor/room-assistant/den-tr-status-cluster-leader/config
Jun  8 16:20:44 raspi8 room-assistant[716]: 08/06/2021, 16:20:44 - debug - HomeAssistantService: Marking room-assistant-den-tr-status-cluster-leader as online
Jun  8 16:20:44 raspi8 systemd[1]: Started room-assistant service.
Jun  8 16:20:44 raspi8 room-assistant[716]: 08/06/2021, 16:20:44 - info - ClusterService: Starting mDNS advertisements and discovery
Jun  8 16:20:44 raspi8 room-assistant[716]: 08/06/2021, 16:20:44 - info - NestApplication: Nest application successfully started
Jun  8 16:20:45 raspi8 room-assistant[716]: 08/06/2021, 16:20:45 - debug - HomeAssistantService: Sending new state true for room-assistant-den-tr-bluetooth-classic-inquiries-switch
Jun  8 16:20:45 raspi8 room-assistant[716]: 08/06/2021, 16:20:45 - debug - HomeAssistantService: Sending new state 2 for room-assistant-den-tr-status-cluster-size
Jun  8 16:20:45 raspi8 room-assistant[716]: 08/06/2021, 16:20:45 - debug - HomeAssistantService: Sending new state garage-tr for room-assistant-den-tr-status-cluster-leader
Jun  8 16:20:45 raspi8 room-assistant[716]: 08/06/2021, 16:20:45 - debug - HomeAssistantService: Sending new attributes {"nodes":["garage-tr","den-tr"]} for room-assistant-den-tr-status-cluster-size
Jun  8 16:20:45 raspi8 room-assistant[716]: 08/06/2021, 16:20:45 - debug - HomeAssistantService: Sending new attributes {"quorumReached":true} for room-assistant-den-tr-status-cluster-leader
Jun  8 16:21:00 raspi8 room-assistant[716]: 08/06/2021, 16:21:00 - debug - HomeAssistantService: Marking instance as online
Jun  8 16:21:00 raspi8 room-assistant[716]: 08/06/2021, 16:21:00 - debug - HomeAssistantService: Marking room-assistant-den-tr-bluetooth-classic-inquiries-switch as online
Jun  8 16:21:00 raspi8 room-assistant[716]: 08/06/2021, 16:21:00 - debug - HomeAssistantService: Marking room-assistant-den-tr-status-cluster-size as online
Jun  8 16:21:00 raspi8 room-assistant[716]: 08/06/2021, 16:21:00 - debug - HomeAssistantService: Marking room-assistant-den-tr-status-cluster-leader as online
Jun  8 16:21:30 raspi8 room-assistant[716]: 08/06/2021, 16:21:30 - debug - HomeAssistantService: Marking instance as online
Jun  8 16:21:30 raspi8 room-assistant[716]: 08/06/2021, 16:21:30 - debug - HomeAssistantService: Marking room-assistant-den-tr-bluetooth-classic-inquiries-switch as online
Jun  8 16:21:30 raspi8 room-assistant[716]: 08/06/2021, 16:21:30 - debug - HomeAssistantService: Marking room-assistant-den-tr-status-cluster-size as online
Jun  8 16:21:30 raspi8 room-assistant[716]: 08/06/2021, 16:21:30 - debug - HomeAssistantService: Marking room-assistant-den-tr-status-cluster-leader as online

Relevant configuration
bluetoothClassic based configuration.

global:
  instanceName: den-tr
  integrations:
    - homeAssistant
    - bluetoothClassic
homeAssistant:
  mqttUrl: 'mqtt://xx.xx.xx.xx:1883'
  mqttOptions:
    username: xxx
    password: xxx
bluetoothClassic:
  interval: 20
  scanTimeLimit: 5
  addresses:
    - A0:FB:C5:DC:XX:YY # Scotts iPhone
  entityOverrides:
    'A0:FB:C5:DC:XX:YY':
        name: Scotts iPhone BT

Expected behavior
Expect to run correctly and test bluetooth addresses after reboot, only works 50% of the time.

Environment

Additional context

This has been difficult to track down. It's been going on since I started using room-asssisant at 2.18.0.
I've updated the pi to buster, and then also updated room-assistant just in case.

Stock room-assistant.service, but I have also tried the following:

  1. adding a preStart of "hciconfig hci0 reset"
  2. also using room-assistant.timer to delay start 5min
  3. turning off wlan0 power saving

1, 2 and 3 together.
@Scott8586 Scott8586 added the bug label Jun 8, 2021
@Scott8586
Copy link
Author

Additional information from status:

{
  "status": "ok",
  "info": {
    "ble_advertisement_timeout": {
      "status": "up"
    },
    "bt_successive_errors": {
      "status": "up"
    },
    "ha_mqtt_connected": {
      "status": "up"
    }
  },
  "error": {},
  "details": {
    "ble_advertisement_timeout": {
      "status": "up"
    },
    "bt_successive_errors": {
      "status": "up"
    },
    "ha_mqtt_connected": {
      "status": "up"
    }
  }
}

and from entities:

[
  {
    "attributes": {},
    "id": "bluetooth-classic-inquiries-switch",
    "name": "den-tr Bluetooth Inquiries",
    "distributed": false,
    "stateLocked": true,
    "state": true
  },
  {
    "attributes": {
      "nodes": [
        "garage-tr",
        "den-tr"
      ]
    },
    "id": "status-cluster-size",
    "name": "den-tr Cluster Size",
    "distributed": false,
    "stateLocked": true,
    "state": 2
  },
  {
    "attributes": {
      "quorumReached": true
    },
    "id": "status-cluster-leader",
    "name": "den-tr Cluster Leader",
    "distributed": false,
    "stateLocked": true,
    "state": "garage-tr"
  }
]

@Scott8586
Copy link
Author

I now believe this behavior to have been the result of YAML syntax errors. yamllint has been a big help.

@Scott8586 Scott8586 mentioned this issue Jun 22, 2021
Open
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@Scott8586