search

digaus / esphome-components-eqiva

Other
18 stars 9 forks source link

[BUG] After some hours the opening won't works.. #5

Closed wes1993 closed 5 months ago

wes1993 commented 6 months ago

Hello, thanks again a lot for your works :-D

I have seen that after many hours that the deivce it's connected the opnening won't work, disconnecting and reconnecting not solve the problem, the only solution is to reboot the ESP by detach the power cord, below some logs:

20:02:57 [D] [esp32_ble_tracker:266] Starting scan...
20:02:57 [D] [text_sensor:064] 'Mac Address': Sending state '00:1A:22:17:67:40'
20:02:57 [D] [text_sensor:064] 'Lock BLE State': Sending state 'ESTABLISHED'
20:02:57 [D] [eqiva_key_ble:073] ESP_GATTC_WRITE_DESCR_EVT
20:02:57 [D] [esp-idf:000]  [0;31mE (98050931) BT_APPL: service change write ccc failed
20:03:16 [D] [lock:042] 'Porta Blindata' Opening.
20:03:16 [I] [eqiva_key_ble:358] Waiting for connection...
20:04:03 [I] [eqiva_key_ble:358] Waiting

If is possible the solution could be schedule a reboot after some time or just add a reboot button the with HA automation I can schedule the reboot.

Best Regards Stefano

digaus commented 6 months ago

My ESP is running since 60 hours without any issues. How long until your issue appeared?

My guess is that you missed something in your yaml.

Would be good if you can post it.

wes1993 commented 6 months ago

Hello @diagus, I have seen that after about 8/12 Hours the opening won't work anymore... Here my yaml:

esphome:
  name: "eqivakeyble"
  friendly_name: "eqivakeyble"

esp32:
  board: esp32dev
  framework:
    type: esp-idf

web_server:
  include_internal: true
  # needs to be false due to a bug: https://github.com/esphome/issues/issues/5188
  local: false 
  port: 80

# Enable logging
logger:

# Enable Home Assistant API
api:
  encryption:
    key: ""

ota:
  password: ""

#wifi:
#  ssid: !secret wifi_ssid
#  password: !secret wifi_password

wifi:
  ssid: !secret wifi_ssid
  password: !secret wifi_password
  # We only start BLE scan after WiFi connected, see https://github.com/esphome/issues/issues/2941#issuecomment-1842369092
  on_connect:
    - esp32_ble_tracker.start_scan:
       continuous: true
    # Use below to apply saved input parameters
    - eqiva_key_ble.connect:
        mac_address: !lambda 'return id(mac_address).state;' 
        user_id: !lambda 'return id(user_id).state;'
        user_key: !lambda 'return id(user_key).state;'
  on_disconnect:
    - esp32_ble_tracker.stop_scan:

  # Enable fallback hotspot (captive portal) in case wifi connection fails
  ap:
    ssid: "Portablindata Fallback Hotspot"
    password: ""

switch:
  - platform: restart
    name: "Riavvia Porta Blindata"

sensor:
  - platform: wifi_signal
    name: "Porta Blindata Segnale Wi-Fi"
    update_interval: 60s
  - platform: uptime
    name: "Porta Blindata Uptime"

# button, number and text input for pairing and setting mac/user_id/user-key via UI
button:
  - platform: template
    id: ble_settings
    name: BLE Settings _Save_
    icon: "mdi:content-save"
    on_press:
      - eqiva_key_ble.connect:
          mac_address: !lambda 'return id(mac_address).state;' 
          user_id: !lambda 'return id(user_id).state;'
          user_key: !lambda 'return id(user_key).state;'

  - platform: template
    id: ble_disconnect
    name: BLE Settings _Disconnect_
    icon: "mdi:clear"
    on_press:
      - eqiva_key_ble.disconnect:

  - platform: template
    id: ble_pair
    name: BLE Pair _Start_
    icon: "mdi:check-underline"
    on_press:
      - eqiva_key_ble.pair:
          card_key: !lambda 'return id(card_key).state;' 

  - platform: template
    id: lock_settings
    name: Lock Settings _Apply_
    icon: "mdi:check-underline"
    on_press:
      - eqiva_key_ble.settings:
          turn_left: !lambda 'return id(direction).state == "Left";' 
          key_horizontal: !lambda 'return id(position).state == "Horizontal";'
          lock_turns: !lambda 'return atoi(id(turns).state.c_str());'

number:
  - platform: template
    mode: box
    name: BLE Settings User ID
    id: user_id
    max_value: 7
    min_value: 0
    step: 1
    optimistic: true
    restore_value: true

text:
  - platform: template
    mode: text
    name: BLE Settings Mac Address
    id: mac_address
    optimistic: true
    restore_value: true
  - platform: template
    mode: text
    name: BLE Settings User Key
    id: user_key
    optimistic: true
    restore_value: true
  - platform: template
    mode: text
    name: BLE Pair Card Key
    id: card_key
    optimistic: true

select:
  - platform: template
    name: Lock Settings Close Direction
    id: direction
    options:
     - "Left"
     - "Right"
    optimistic: true
  - platform: template
    name: Lock Settings Key Position
    id: position
    options:
     - "Vertical"
     - "Horizontal"
    optimistic: true
  - platform: template
    name: Lock Settings Turns
    id: turns
    options:
     - "1"
     - "2"
     - "3"
     - "4"
    optimistic: true

external_components:
  source: github://digaus/esphome-components-eqiva
  # use refresh when you do not get latest version
  # refresh: 0s

eqiva_key_ble:
  id: key_ble

esp32_ble_tracker:
   scan_parameters:
    window: 300ms
    # We do not start scan initialy, see https://github.com/esphome/issues/issues/2941#issuecomment-1842369092
    continuous: false

# used for discovering the lock and get the mac_address, check logger for it
eqiva_ble:

text_sensor: 
  - platform: eqiva_key_ble
    mac_address: 
      name: "Mac Address"
    lock_status:
      id: lock_status
      name: "Lock Status"
    low_battery:
      name: "Low Battery"
    lock_ble_state:
      name: "Lock BLE State"
    user_id:
      name: "User ID"
    user_key:
      name: "User Key"

time:
  - platform: sntp
    on_time:
      # Every 4 minutes
      - seconds: 0
        minutes: /4
        then:
          - eqiva_key_ble.status:

# Lock component for HA, can also create two locks and use connect service to connect/control two different locks
# One ESP per lock is still recommended
lock:
  - platform: template
    name: "Porta Blindata"
    lambda: |-
      if (id(lock_status).state == "LOCKED") {
        return LOCK_STATE_LOCKED;
      } else if (id(lock_status).state == "UNLOCKED" || id(lock_status).state == "OPENED") {
        return LOCK_STATE_UNLOCKED;
      } else if(id(lock_status).state == "MOVING") {
        return {};
      } else if (id(lock_status).state == "UNKNOWN") {
        return LOCK_STATE_JAMMED;
      } 
      return LOCK_STATE_LOCKED;
    lock_action:
      - eqiva_key_ble.lock:
    unlock_action:
      - eqiva_key_ble.unlock:
    open_action:
      - eqiva_key_ble.open:

captive_portal:
digaus commented 6 months ago

Hello @diagus, I have seen that after about 8/12 Hours the opening won't work anymore... Here my yaml:

Hmm yaml looks good. Updated logs now to log the reason why its waiting for connection. Use refresh: 0 to update to latest version.

For me its running flawless since 70 hours

fuatakgun commented 6 months ago

For me, it is working well more than couple of weeks

wes1993 commented 6 months ago

Ok I'll try to update now, could I ask what Equiva Firmware version you have? Mine Firmware: 1.7 | BLE-Chip: 1.5

I have seen that sometimes i have some warning messages that the process it's slow, it's in yellow do you have the same warning?

[09:45:55][W][component:214]: Component api took a long time for an operation (0.06 s).
[09:45:55][W][component:215]: Components should block for at most 20-30ms.
...
[09:45:59][W][component:214]: Component esp32_ble took a long time for an operation (0.20 s).
[09:45:59][W][component:215]: Components should block for at most 20-30ms.

Best Regards Stefano

digaus commented 6 months ago

Ok I'll try to update now, could I ask what Equiva Firmware version you have? Mine Firmware: 1.7 | BLE-Chip: 1.5

I have seen that sometimes i have some warning messages that the process it's slow, it's in yellow do you have the same warning?

Best Regards Stefano

Same Version and yes I also have warnings. This might be cause by the encryption or the sending itself.

It's not something that should cause issues.

wes1993 commented 6 months ago

How can i see my version just to be sure i have updated to the latest version?

digaus commented 6 months ago

How can i see my version just to be sure i have updated to the latest version?

Just added to the log: ESP_LOGCONFIG(TAG, "Eqiva Key-BLE (1.0):");

From now on will update it every commit :)

wes1993 commented 6 months ago

P.S. For now, after 10 Hours it's stable no need to reboot... Mmm, i dont' have this line in the log, here my config related to the refresh, is this correct?:

external_components:
  source: github://digaus/esphome-components-eqiva
  # use refresh when you do not get latest version
  refresh: 0s
digaus commented 6 months ago

P.S. For now, after 10 Hours it's stable no need to reboot... Mmm, i dont' have this line in the log, here my config related to the refresh, is this correct?:

external_components:
  source: github://digaus/esphome-components-eqiva
  # use refresh when you do not get latest version
  refresh: 0s

yes looks correct.

Should be [C][eqiva_key_ble:016]: Eqiva Key-BLE in the log somewhere when you open logger via esphome menu

wes1993 commented 6 months ago

Perfect i have this line :-D

[09:45:55][W][component:214]: Component api took a long time for an operation (0.06 s).
[09:45:55][W][component:215]: Components should block for at most 20-30ms.
[09:45:55][C][eqiva_key_ble:016]: Eqiva Key-BLE:

So now we just need to wait until the problem comes again :-D, I'll keep you updated :-D

P.S. Relating to the connect instead of keep the connection openend do you think that we could do something? (So if we have internet problem or something else we can still open with App)

And can you confirm that if the ESP is connected the App won't work? (Just to be sure I'm not alone :-D)

Thanks a lot Stefano

digaus commented 6 months ago

you should have [eqiva_key_ble:016]: Eqiva Key-BLE: there. Try update again :)

Maybe make a clean build files

Regarding the other issue, reconnecting and controlling takes 12 seconds so its best to stay connected. How could add a check if you have internet in the esp and then disconnect and connect again when internet is back up.

https://github.com/trombik/esphome-component-ping

Personally I use it with a fingerprint so I do not care if internet is down

wes1993 commented 6 months ago

Ok I'll try with clean build files :-D

wes1993 commented 6 months ago

Perfect now it's ok :-D

[10:07:23][C][esp32_ble:377]:   IO Capability: none
[10:07:23][C][eqiva_key_ble:016]: Eqiva Key-BLE (1.0):
digaus commented 6 months ago

Perfect now it's ok :-D

[10:07:23][C][esp32_ble:377]:   IO Capability: none
[10:07:23][C][eqiva_key_ble:016]: Eqiva Key-BLE (1.0):

Yes

Also maybe we can add ble controller to connect to the ESP via Bluetooth with the smartphone and not to the lock: https://github.com/wifwucite/esphome-ble-controller 🤔

wes1993 commented 6 months ago

Yes, this could be a solution but probably the best way and more secure is connect directly to the lock so if there is anything in the ESP32 we can open with mobile phone.

Do you think that the dosconnection a connection could be slow?

digaus commented 6 months ago

Yes, this could be a solution but probably the best way and more secure is connect directly to the lock so if there is anything in the ESP32 we can open with mobile phone.

Do you think that the dosconnection a connection could be slow?

The ble controller above is also secured.

When you just disconnect on internet loss and connect back when internet is available it would be ok. But alwayse disconnecting will take 12 seconds on next command to work through the ESP. (connecting, exchaning nonce and then sending the command)

wes1993 commented 6 months ago

Ok, i have understand now :-D For secure i mean if for some reason we can't access to the ESP (Homeassistant Instance Dead, or something else).... (I think the BLE to ESP could be a solution)

wes1993 commented 6 months ago

Hello @digaus, the problem happened again.. Uptime is 16 Hours, when i try to open the door nothing happen... image

Here is the log:

INFO Reading configuration /config/esphome/eqivakeyble.yaml...
INFO Updating https://github.com/digaus/esphome-components-eqiva.git@None
INFO Detected timezone 'Europe/Rome'
INFO Starting log output from eqivakeyble.local using esphome API
INFO Successfully connected to eqivakeyble in 0.496s
INFO Successful handshake with eqivakeyble in 0.189s
[14:56:23][I][app:102]: ESPHome version 2023.11.6 compiled on Dec 18 2023, 10:04:59
[14:56:23][C][wifi:559]: WiFi:
[14:56:23][C][wifi:391]:   Local MAC: C0:49:EF:D0:E5:98
[14:56:23][C][wifi:396]:   SSID: [redacted]
[14:56:23][C][wifi:397]:   IP Address: 192.168.0.124
[14:56:23][C][wifi:399]:   BSSID: [redacted]
[14:56:23][C][wifi:400]:   Hostname: 'eqivakeyble'
[14:56:23][C][wifi:402]:   Signal strength: -33 dB ▂▄▆█
[14:56:23][C][wifi:406]:   Channel: 13
[14:56:23][C][wifi:407]:   Subnet: 255.255.255.0
[14:56:23][C][wifi:408]:   Gateway: 192.168.0.1
[14:56:23][C][wifi:409]:   DNS1: 192.168.0.1
[14:56:23][C][wifi:410]:   DNS2: 0.0.0.0
[14:56:23][C][logger:416]: Logger:
[14:56:23][C][logger:417]:   Level: DEBUG
[14:56:23][C][logger:418]:   Log Baud Rate: 115200
[14:56:23][C][logger:420]:   Hardware UART: UART0
[14:56:23][C][uptime.sensor:031]: Uptime Sensor 'Porta Blindata Uptime'
[14:56:23][C][uptime.sensor:031]:   Device Class: 'duration'
[14:56:23][C][uptime.sensor:031]:   State Class: 'total_increasing'
[14:56:23][C][uptime.sensor:031]:   Unit of Measurement: 's'
[14:56:23][C][uptime.sensor:031]:   Accuracy Decimals: 0
[14:56:23][C][uptime.sensor:031]:   Icon: 'mdi:timer-outline'
[14:56:23][C][template.number:050]: Template Number 'BLE Settings User ID'
[14:56:23][C][template.number:051]:   Optimistic: YES
[14:56:23][C][template.number:052]:   Update Interval: 60.0s
[14:56:23][C][template.text:058]: Template Text Input 'BLE Settings Mac Address'
[14:56:23][C][template.text:059]:   Optimistic: YES
[14:56:23][C][template.text:060]:   Update Interval: 60.0s
[14:56:23][C][template.text:058]: Template Text Input 'BLE Settings User Key'
[14:56:23][C][template.text:059]:   Optimistic: YES
[14:56:23][C][template.text:060]:   Update Interval: 60.0s
[14:56:23][C][template.text:058]: Template Text Input 'BLE Pair Card Key'
[14:56:23][C][template.text:059]:   Optimistic: YES
[14:56:23][C][template.text:060]:   Update Interval: 60.0s
[14:56:23][C][template.select:065]: Template Select 'Lock Settings Close Direction'
[14:56:23][C][template.select:066]:   Update Interval: 60.0s
[14:56:23][C][template.select:069]:   Optimistic: YES
[14:56:23][C][template.select:070]:   Initial Option: Left
[14:56:23][C][template.select:071]:   Restore Value: NO
[14:56:23][C][template.select:065]: Template Select 'Lock Settings Key Position'
[14:56:23][C][template.select:066]:   Update Interval: 60.0s
[14:56:23][C][template.select:069]:   Optimistic: YES
[14:56:23][C][template.select:070]:   Initial Option: Vertical
[14:56:23][C][template.select:071]:   Restore Value: NO
[14:56:23][C][template.select:065]: Template Select 'Lock Settings Turns'
[14:56:23][C][template.select:066]:   Update Interval: 60.0s
[14:56:23][C][template.select:069]:   Optimistic: YES
[14:56:23][C][template.select:070]:   Initial Option: 1
[14:56:23][C][template.select:071]:   Restore Value: NO
[14:56:23][C][template.lock:054]: Template Lock 'Porta Blindata'
[14:56:23][C][template.lock:055]:   Optimistic: NO
[14:56:23][C][restart:068]: Restart Switch 'Riavvia Porta Blindata'
[14:56:23][C][restart:070]:   Icon: 'mdi:restart'
[14:56:23][C][restart:091]:   Restore Mode: always OFF
[14:56:23][C][esp32_ble:374]: ESP32 BLE:
[14:56:23][C][esp32_ble:376]:   MAC address: C0:49:EF:D0:E5:9A
[14:56:23][C][esp32_ble:377]:   IO Capability: none
[14:56:23][C][eqiva_key_ble:016]: Eqiva Key-BLE (1.0):
[14:56:23][C][eqiva_key_ble:017]:   Address: 00:1A:22:17:67:40
[14:56:23][C][eqiva_key_ble:018]:   UserKey: HiddenByME
[14:56:23][C][eqiva_key_ble:019]:   UserId: 0
[14:56:23][C][eqiva_key_ble:020]:   CardKey: 
[14:56:23][C][esp32_ble_tracker:645]: BLE Tracker:
[14:56:23][C][esp32_ble_tracker:646]:   Scan Duration: 300 s
[14:56:23][C][esp32_ble_tracker:647]:   Scan Interval: 320.0 ms
[14:56:23][C][esp32_ble_tracker:648]:   Scan Window: 300.0 ms
[14:56:23][C][esp32_ble_tracker:649]:   Scan Type: ACTIVE
[14:56:23][C][esp32_ble_tracker:650]:   Continuous Scanning: True
[14:56:23][C][captive_portal:088]: Captive Portal:
[14:56:23][C][web_server:168]: Web Server:
[14:56:23][C][web_server:169]:   Address: eqivakeyble.local:80
[14:56:23][C][sntp:053]: SNTP Time:
[14:56:23][C][sntp:054]:   Server 1: '0.pool.ntp.org'
[14:56:23][C][sntp:055]:   Server 2: '1.pool.ntp.org'
[14:56:23][C][sntp:056]:   Server 3: '2.pool.ntp.org'
[14:56:23][C][sntp:057]:   Timezone: 'CET-1CEST,M3.5.0,M10.5.0/3'
[14:56:23][C][mdns:115]: mDNS:
[14:56:23][C][mdns:116]:   Hostname: eqivakeyble
[14:56:23][C][ota:097]: Over-The-Air Updates:
[14:56:23][C][ota:098]:   Address: eqivakeyble.local:3232
[14:56:23][C][ota:101]:   Using Password.
[14:56:23][C][api:139]: API Server:
[14:56:23][C][api:140]:   Address: eqivakeyble.local:6053
[14:56:23][C][api:142]:   Using noise encryption: YES
[14:56:23][C][wifi_signal.sensor:009]: WiFi Signal 'Porta Blindata Segnale Wi-Fi'
[14:56:23][C][wifi_signal.sensor:009]:   Device Class: 'signal_strength'
[14:56:23][C][wifi_signal.sensor:009]:   State Class: 'measurement'
[14:56:23][C][wifi_signal.sensor:009]:   Unit of Measurement: 'dBm'
[14:56:23][C][wifi_signal.sensor:009]:   Accuracy Decimals: 0
[14:56:38][D][lock:042]: 'Porta Blindata' Opening.
[14:56:38][I][eqiva_key_ble:358]: Waiting for connection...
[14:56:38][I][eqiva_key_ble:360]: Reason: exchanging nonce
[14:56:38][I][eqiva_key_ble:363]: Reason: no remote session
[14:57:21][D][sensor:094]: 'Porta Blindata Segnale Wi-Fi': Sending state -33.00000 dBm with 0 decimals of accuracy
[14:57:22][D][sensor:094]: 'Porta Blindata Uptime': Sending state 58482.09375 s with 0 decimals of accuracy
[14:58:21][D][sensor:094]: 'Porta Blindata Segnale Wi-Fi': Sending state -34.00000 dBm with 0 decimals of accuracy
[14:58:22][D][sensor:094]: 'Porta Blindata Uptime': Sending state 58542.08984 s with 0 decimals of accuracy
[14:58:44][D][lock:042]: 'Porta Blindata' Opening.
[14:58:44][I][eqiva_key_ble:358]: Waiting for connection...
[14:58:44][I][eqiva_key_ble:360]: Reason: exchanging nonce
[14:58:44][I][eqiva_key_ble:363]: Reason: no remote session
[14:59:18][D][esp-idf:000]: W (58598786) BT_APPL: gattc_conn_cb: if=3 st=0 id=3 rsn=0x16

[14:59:18][D][esp-idf:000]: W (58598791) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x16

[14:59:18][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:67:40'
[14:59:18][D][text_sensor:064]: 'Lock BLE State': Sending state 'IDLE'
[14:59:18][D][text_sensor:064]: 'Lock BLE State': Sending state 'IDLE'
[14:59:18][D][eqiva_key_ble:058]: ESP_GATTC_DISCONNECT_EVT
[14:59:18][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:67:40'
[14:59:18][D][text_sensor:064]: 'Lock BLE State': Sending state 'IDLE'
[14:59:18][D][eqiva_key_ble:229]: OTHER EVENT 5
[14:59:19][I][eqiva_ble:015]: Found Eqiva device (MAC: 00:1A:22:17:67:40) (UUID): 0x1A00  (Name): KEY-BLE
[14:59:19][D][esp32_ble_client:053]: [0] [00:1A:22:17:67:40] Found device
[14:59:19][D][text_sensor:064]: 'Lock BLE State': Sending state 'DISCOVERED'
[14:59:19][D][esp32_ble_tracker:215]: Pausing scan to make connection...
[14:59:19][D][text_sensor:064]: 'Lock BLE State': Sending state 'READY_TO_CONNECT'
[14:59:19][I][esp32_ble_client:069]: [0] [00:1A:22:17:67:40] 0x00 Attempting BLE connection
[14:59:19][D][text_sensor:064]: 'Lock BLE State': Sending state 'CONNECTING'
[14:59:20][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:67:40'
[14:59:20][D][text_sensor:064]: 'Lock BLE State': Sending state 'CONNECTING'
[14:59:20][D][eqiva_key_ble:229]: OTHER EVENT 40
[14:59:20][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:67:40'
[14:59:20][D][text_sensor:064]: 'Lock BLE State': Sending state 'CONNECTING'
[14:59:20][D][eqiva_key_ble:229]: OTHER EVENT 2
[14:59:21][D][sensor:094]: 'Porta Blindata Segnale Wi-Fi': Sending state -33.00000 dBm with 0 decimals of accuracy
[14:59:22][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:67:40'
[14:59:22][D][text_sensor:064]: 'Lock BLE State': Sending state 'CONNECTING'
[14:59:22][D][eqiva_key_ble:229]: OTHER EVENT 46
[14:59:22][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:67:40'
[14:59:22][D][text_sensor:064]: 'Lock BLE State': Sending state 'CONNECTING'
[14:59:22][D][eqiva_key_ble:063]: ESP_GATTC_REG_FOR_NOTIFY_EVT
[14:59:22][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:67:40'
[14:59:22][D][text_sensor:064]: 'Lock BLE State': Sending state 'CONNECTING'
[14:59:22][D][eqiva_key_ble:063]: ESP_GATTC_REG_FOR_NOTIFY_EVT
[14:59:22][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:67:40'
[14:59:22][D][text_sensor:064]: 'Lock BLE State': Sending state 'CONNECTING'
[14:59:22][D][eqiva_key_ble:063]: ESP_GATTC_REG_FOR_NOTIFY_EVT
[14:59:22][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:67:40'
[14:59:22][D][text_sensor:064]: 'Lock BLE State': Sending state 'CONNECTING'
[14:59:22][D][eqiva_key_ble:063]: ESP_GATTC_REG_FOR_NOTIFY_EVT
[14:59:22][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:67:40'
[14:59:22][D][text_sensor:064]: 'Lock BLE State': Sending state 'CONNECTING'
[14:59:22][D][eqiva_key_ble:063]: ESP_GATTC_REG_FOR_NOTIFY_EVT
[14:59:22][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:67:40'
[14:59:22][I][esp32_ble_client:201]: [0] [00:1A:22:17:67:40] Connected
[14:59:22][D][text_sensor:064]: 'Lock BLE State': Sending state 'CONNECTED'
[14:59:22][D][text_sensor:064]: 'Lock BLE State': Sending state 'ESTABLISHED'
[14:59:22][D][eqiva_key_ble:040]: Write (UUID): HiddenByME
[14:59:22][D][eqiva_key_ble:047]: Read (UUID): HiddenByME 
[14:59:22][D][eqiva_key_ble:374]: Check send frag: not-empty, sending
[14:59:22][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:67:40'
[14:59:22][D][text_sensor:064]: 'Lock BLE State': Sending state 'ESTABLISHED'
[14:59:22][D][eqiva_key_ble:229]: OTHER EVENT 18
[14:59:22][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:67:40'
[14:59:22][D][text_sensor:064]: 'Lock BLE State': Sending state 'ESTABLISHED'
[14:59:22][D][eqiva_key_ble:229]: OTHER EVENT 38
[14:59:22][W][component:214]: Component esp32_ble took a long time for an operation (0.16 s).
[14:59:22][W][component:215]: Components should block for at most 20-30ms.
[14:59:22][D][esp32_ble_tracker:266]: Starting scan...
[14:59:22][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:67:40'
[14:59:22][D][text_sensor:064]: 'Lock BLE State': Sending state 'ESTABLISHED'
[14:59:22][D][eqiva_key_ble:073]: ESP_GATTC_WRITE_DESCR_EVT
[14:59:22][D][esp-idf:000]: E (58602552) BT_APPL: service change write ccc failed

[14:59:22][D][sensor:094]: 'Porta Blindata Uptime': Sending state 58602.08984 s with 0 decimals of accuracy
[15:00:00][I][eqiva_key_ble:358]: Waiting for connection...
[15:00:00][I][eqiva_key_ble:360]: Reason: exchanging nonce
[15:00:00][I][eqiva_key_ble:363]: Reason: no remote session
[15:00:21][D][sensor:094]: 'Porta Blindata Segnale Wi-Fi': Sending state -35.00000 dBm with 0 decimals of accuracy
[15:00:22][D][sensor:094]: 'Porta Blindata Uptime': Sending state 58662.08984 s with 0 decimals of accuracy
[15:01:21][D][sensor:094]: 'Porta Blindata Segnale Wi-Fi': Sending state -33.00000 dBm with 0 decimals of accuracy
[15:01:22][D][sensor:094]: 'Porta Blindata Uptime': Sending state 58722.08984 s with 0 decimals of accuracy
[15:02:21][D][sensor:094]: 'Porta Blindata Segnale Wi-Fi': Sending state -33.00000 dBm with 0 decimals of accuracy
[15:02:22][D][sensor:094]: 'Porta Blindata Uptime': Sending state 58782.08984 s with 0 decimals of accuracy
[15:03:21][D][sensor:094]: 'Porta Blindata Segnale Wi-Fi': Sending state -33.00000 dBm with 0 decimals of accuracy
[15:03:21][D][esp-idf:000]: W (58842087) BT_APPL: gattc_conn_cb: if=3 st=0 id=3 rsn=0x16

[15:03:21][D][esp-idf:000]: W (58842092) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x16

[15:03:21][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:67:40'
[15:03:21][D][text_sensor:064]: 'Lock BLE State': Sending state 'IDLE'
[15:03:21][D][text_sensor:064]: 'Lock BLE State': Sending state 'IDLE'
[15:03:21][D][eqiva_key_ble:058]: ESP_GATTC_DISCONNECT_EVT
[15:03:21][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:67:40'
[15:03:21][D][text_sensor:064]: 'Lock BLE State': Sending state 'IDLE'
[15:03:21][D][eqiva_key_ble:229]: OTHER EVENT 5
[15:03:22][I][eqiva_ble:015]: Found Eqiva device (MAC: 00:1A:22:17:67:40) (UUID): 0x1A00  (Name): KEY-BLE
[15:03:22][D][esp32_ble_client:053]: [0] [00:1A:22:17:67:40] Found device
[15:03:22][D][text_sensor:064]: 'Lock BLE State': Sending state 'DISCOVERED'
[15:03:22][D][esp32_ble_tracker:215]: Pausing scan to make connection...
[15:03:22][D][text_sensor:064]: 'Lock BLE State': Sending state 'READY_TO_CONNECT'
[15:03:22][I][esp32_ble_client:069]: [0] [00:1A:22:17:67:40] 0x00 Attempting BLE connection
[15:03:22][D][text_sensor:064]: 'Lock BLE State': Sending state 'CONNECTING'
[15:03:22][D][sensor:094]: 'Porta Blindata Uptime': Sending state 58842.08984 s with 0 decimals of accuracy
[15:03:23][D][esp-idf:000]: W (58843185) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x3e

[15:03:23][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:67:40'
[15:03:23][D][text_sensor:064]: 'Lock BLE State': Sending state 'CONNECTING'
[15:03:23][D][eqiva_key_ble:229]: OTHER EVENT 40
[15:03:23][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:67:40'
[15:03:23][D][text_sensor:064]: 'Lock BLE State': Sending state 'CONNECTING'
[15:03:24][D][eqiva_key_ble:229]: OTHER EVENT 2
[15:03:25][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:67:40'
[15:03:25][D][text_sensor:064]: 'Lock BLE State': Sending state 'CONNECTING'
[15:03:25][D][eqiva_key_ble:229]: OTHER EVENT 46
[15:03:25][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:67:40'
[15:03:25][D][text_sensor:064]: 'Lock BLE State': Sending state 'CONNECTING'
[15:03:25][D][eqiva_key_ble:063]: ESP_GATTC_REG_FOR_NOTIFY_EVT
[15:03:25][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:67:40'
[15:03:25][D][text_sensor:064]: 'Lock BLE State': Sending state 'CONNECTING'
[15:03:25][D][eqiva_key_ble:063]: ESP_GATTC_REG_FOR_NOTIFY_EVT
[15:03:25][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:67:40'
[15:03:25][D][text_sensor:064]: 'Lock BLE State': Sending state 'CONNECTING'
[15:03:25][D][eqiva_key_ble:063]: ESP_GATTC_REG_FOR_NOTIFY_EVT
[15:03:25][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:67:40'
[15:03:25][D][text_sensor:064]: 'Lock BLE State': Sending state 'CONNECTING'
[15:03:25][D][eqiva_key_ble:063]: ESP_GATTC_REG_FOR_NOTIFY_EVT
[15:03:25][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:67:40'
[15:03:25][D][text_sensor:064]: 'Lock BLE State': Sending state 'CONNECTING'
[15:03:25][D][eqiva_key_ble:063]: ESP_GATTC_REG_FOR_NOTIFY_EVT
[15:03:25][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:67:40'
[15:03:25][I][esp32_ble_client:201]: [0] [00:1A:22:17:67:40] Connected
[15:03:25][D][text_sensor:064]: 'Lock BLE State': Sending state 'CONNECTED'
[15:03:25][D][text_sensor:064]: 'Lock BLE State': Sending state 'ESTABLISHED'
[15:03:25][D][eqiva_key_ble:040]: Write (UUID): HiddenByME  
[15:03:25][D][eqiva_key_ble:047]: Read (UUID): HiddenByME
[15:03:25][D][eqiva_key_ble:374]: Check send frag: not-empty, sending
[15:03:25][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:67:40'
[15:03:25][D][text_sensor:064]: 'Lock BLE State': Sending state 'ESTABLISHED'
[15:03:25][D][eqiva_key_ble:229]: OTHER EVENT 18
[15:03:25][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:67:40'
[15:03:25][D][text_sensor:064]: 'Lock BLE State': Sending state 'ESTABLISHED'
[15:03:25][D][eqiva_key_ble:229]: OTHER EVENT 38
[15:03:25][W][component:214]: Component esp32_ble took a long time for an operation (0.17 s).
[15:03:25][W][component:215]: Components should block for at most 20-30ms.
[15:03:25][D][esp32_ble_tracker:266]: Starting scan...
[15:03:25][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:67:40'
[15:03:25][D][text_sensor:064]: 'Lock BLE State': Sending state 'ESTABLISHED'
[15:03:25][D][eqiva_key_ble:073]: ESP_GATTC_WRITE_DESCR_EVT
[15:03:25][D][esp-idf:000]: E (58845628) BT_APPL: service change write ccc failed

[15:04:00][I][eqiva_key_ble:358]: Waiting for connection...
[15:04:00][I][eqiva_key_ble:360]: Reason: exchanging nonce
[15:04:00][I][eqiva_key_ble:363]: Reason: no remote session

Bye Stefano

tosilabs commented 6 months ago

The same problem is happening to me as Stefanos, after a few hours I could not open the door without rebooting esp

tosilabs commented 6 months ago

Here is my log

INFO ESPHome 2023.11.6

INFO Reading configuration /config/esphome/keyup.yaml...

INFO Updating https://github.com/digaus/esphome-components-eqiva.git@None

INFO Detected timezone 'Europe/Tirane'

INFO Starting log output from keyup.local using esphome API

INFO Successfully connected to keyup in 0.180s

INFO Successful handshake with keyup in 0.119s

[09:56:22][I][app:102]: ESPHome version 2023.11.6 compiled on Dec 18 2023, 20:41:52

[09:56:22][C][wifi:559]: WiFi:

[09:56:22][C][wifi:391]:   Local MAC: 08:3A:F2:B8:42:4C

[09:56:22][C][wifi:396]:   SSID: [redacted]

[09:56:22][C][wifi:397]:   IP Address: 10.0.0.219

[09:56:22][C][wifi:399]:   BSSID: [redacted]

[09:56:22][C][wifi:400]:   Hostname: 'keyup'

[09:56:22][C][wifi:402]:   Signal strength: -67 dB ▂▄▆█

[09:56:22][C][wifi:406]:   Channel: 11

[09:56:22][C][wifi:407]:   Subnet: 255.255.255.0

[09:56:22][C][wifi:408]:   Gateway: 10.0.0.254

[09:56:22][C][wifi:409]:   DNS1: 10.0.0.254

[09:56:22][C][wifi:410]:   DNS2: 0.0.0.0

[09:56:22][C][logger:416]: Logger:

[09:56:22][C][logger:417]:   Level: DEBUG

[09:56:22][C][logger:418]:   Log Baud Rate: 115200

[09:56:22][C][logger:420]:   Hardware UART: UART0

[09:56:22][C][template.lock:054]: Template Lock 'KeyUP'

[09:56:22][C][template.lock:055]:   Optimistic: NO

[09:56:22][C][restart:068]: Restart Switch 'Restart GATEWAY'

[09:56:22][C][restart:070]:   Icon: 'mdi:restart'

[09:56:22][C][restart:091]:   Restore Mode: always OFF

[09:56:22][C][esp32_ble:374]: ESP32 BLE:

[09:56:22][C][esp32_ble:376]:   MAC address: 08:3A:F2:B8:42:4E

[09:56:22][C][esp32_ble:377]:   IO Capability: none

[09:56:22][C][esp32_ble_tracker:645]: BLE Tracker:

[09:56:22][C][esp32_ble_tracker:646]:   Scan Duration: 300 s

[09:56:22][C][esp32_ble_tracker:647]:   Scan Interval: 320.0 ms

[09:56:22][C][esp32_ble_tracker:648]:   Scan Window: 30.0 ms

[09:56:22][C][esp32_ble_tracker:649]:   Scan Type: ACTIVE

[09:56:22][C][esp32_ble_tracker:650]:   Continuous Scanning: True

[09:56:22][C][eqiva_key_ble:016]: Eqiva Key-BLE (1.0):

[09:56:22][C][eqiva_key_ble:017]:   Address: 00:1A:22:17:70:99

[09:56:22][C][eqiva_key_ble:018]:   UserKey: ****

[09:56:22][C][eqiva_key_ble:019]:   UserId: *** 

[09:56:22][C][eqiva_key_ble:020]:   CardKey: 

[09:56:22][C][captive_portal:088]: Captive Portal:

[09:56:22][C][sntp:053]: SNTP Time:

[09:56:22][C][sntp:054]:   Server 1: '0.pool.ntp.org'

[09:56:22][C][sntp:055]:   Server 2: '1.pool.ntp.org'

[09:56:22][C][sntp:056]:   Server 3: '2.pool.ntp.org'

[09:56:22][C][sntp:057]:   Timezone: 'CET-1CEST,M3.5.0,M10.5.0/3'

[09:56:22][C][mdns:115]: mDNS:

[09:56:22][C][mdns:116]:   Hostname: keyup

[09:56:22][C][ota:097]: Over-The-Air Updates:

[09:56:22][C][ota:098]:   Address: keyup.local:3232

[09:56:22][C][ota:101]:   Using Password.

[09:56:22][C][api:139]: API Server:

[09:56:22][C][api:140]:   Address: keyup.local:6053

[09:56:22][C][api:142]:   Using noise encryption: YES

[09:57:26][I][eqiva_key_ble:358]: Waiting for connection...

[09:57:26][I][eqiva_key_ble:360]: Reason: exchanging nonce

[09:57:26][I][eqiva_key_ble:363]: Reason: no remote session

[09:58:31][D][esp-idf:000]: W (47131771) BT_APPL: gattc_conn_cb: if=3 st=0 id=3 rsn=0x16

[09:58:31][D][esp-idf:000]: W (47131777) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x16

[09:58:31][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:70:99'

[09:58:31][D][text_sensor:064]: 'Lock BLE State': Sending state 'IDLE'

[09:58:31][D][text_sensor:064]: 'Lock BLE State': Sending state 'IDLE'

[09:58:31][D][eqiva_key_ble:058]: ESP_GATTC_DISCONNECT_EVT

[09:58:31][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:70:99'

[09:58:31][D][text_sensor:064]: 'Lock BLE State': Sending state 'IDLE'

[09:58:31][D][eqiva_key_ble:229]: OTHER EVENT 5

[09:58:37][I][eqiva_ble:015]: Found Eqiva device (MAC: 00:1A:22:17:70:99) (UUID): 0x1A00  (Name): KEY-BLE

[09:58:37][D][esp32_ble_client:053]: [0] [00:1A:22:17:70:99] Found device

[09:58:37][D][text_sensor:064]: 'Lock BLE State': Sending state 'DISCOVERED'

[09:58:37][D][esp32_ble_tracker:215]: Pausing scan to make connection...

[09:58:37][D][text_sensor:064]: 'Lock BLE State': Sending state 'READY_TO_CONNECT'

[09:58:37][I][esp32_ble_client:069]: [0] [00:1A:22:17:70:99] 0x00 Attempting BLE connection

[09:58:37][D][text_sensor:064]: 'Lock BLE State': Sending state 'CONNECTING'

[09:58:39][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:70:99'

[09:58:39][D][text_sensor:064]: 'Lock BLE State': Sending state 'CONNECTING'

[09:58:39][D][eqiva_key_ble:229]: OTHER EVENT 40

[09:58:39][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:70:99'

[09:58:39][D][text_sensor:064]: 'Lock BLE State': Sending state 'CONNECTING'

[09:58:39][D][eqiva_key_ble:229]: OTHER EVENT 2

[09:58:40][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:70:99'

[09:58:40][D][text_sensor:064]: 'Lock BLE State': Sending state 'CONNECTING'

[09:58:40][D][eqiva_key_ble:229]: OTHER EVENT 46

[09:58:40][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:70:99'

[09:58:40][D][text_sensor:064]: 'Lock BLE State': Sending state 'CONNECTING'

[09:58:40][D][eqiva_key_ble:063]: ESP_GATTC_REG_FOR_NOTIFY_EVT

[09:58:40][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:70:99'

[09:58:40][D][text_sensor:064]: 'Lock BLE State': Sending state 'CONNECTING'

[09:58:40][D][eqiva_key_ble:063]: ESP_GATTC_REG_FOR_NOTIFY_EVT

[09:58:40][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:70:99'

[09:58:40][D][text_sensor:064]: 'Lock BLE State': Sending state 'CONNECTING'

[09:58:40][D][eqiva_key_ble:063]: ESP_GATTC_REG_FOR_NOTIFY_EVT

[09:58:40][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:70:99'

[09:58:40][D][text_sensor:064]: 'Lock BLE State': Sending state 'CONNECTING'

[09:58:40][D][eqiva_key_ble:063]: ESP_GATTC_REG_FOR_NOTIFY_EVT

[09:58:40][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:70:99'

[09:58:40][D][text_sensor:064]: 'Lock BLE State': Sending state 'CONNECTING'

[09:58:40][D][eqiva_key_ble:063]: ESP_GATTC_REG_FOR_NOTIFY_EVT

[09:58:40][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:70:99'

[09:58:40][I][esp32_ble_client:201]: [0] [00:1A:22:17:70:99] Connected

[09:58:40][D][text_sensor:064]: 'Lock BLE State': Sending state 'CONNECTED'

[09:58:41][D][text_sensor:064]: 'Lock BLE State': Sending state 'ESTABLISHED'

[09:58:41][D][eqiva_key_ble:040]: Write (UUID): 3141DD40-15DB-11E6-A24B-0002A5D5C51B  

[09:58:41][D][eqiva_key_ble:047]: Read (UUID): 359D4820-15DB-11E6-82BD-0002A5D5C51B  

[09:58:41][D][eqiva_key_ble:374]: Check send frag: not-empty, sending

[09:58:41][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:70:99'

[09:58:41][D][text_sensor:064]: 'Lock BLE State': Sending state 'ESTABLISHED'

[09:58:41][D][eqiva_key_ble:229]: OTHER EVENT 18

[09:58:41][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:70:99'

[09:58:41][D][text_sensor:064]: 'Lock BLE State': Sending state 'ESTABLISHED'

[09:58:41][D][eqiva_key_ble:229]: OTHER EVENT 38

[09:58:41][W][component:214]: Component esp32_ble took a long time for an operation (0.16 s).

[09:58:41][W][component:215]: Components should block for at most 20-30ms.

[09:58:41][D][esp32_ble_tracker:266]: Starting scan...

[09:58:41][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:70:99'

[09:58:41][D][text_sensor:064]: 'Lock BLE State': Sending state 'ESTABLISHED'

[09:58:41][D][eqiva_key_ble:073]: ESP_GATTC_WRITE_DESCR_EVT

[09:58:41][D][esp-idf:000]: E (47141266) BT_APPL: service change write ccc failed

[09:59:15][I][eqiva_key_ble:358]: Waiting for connection...

[09:59:15][I][eqiva_key_ble:360]: Reason: exchanging nonce

[09:59:15][I][eqiva_key_ble:363]: Reason: no remote session

[09:59:17][I][eqiva_key_ble:358]: Waiting for connection...

[09:59:17][I][eqiva_key_ble:360]: Reason: exchanging nonce

[09:59:17][I][eqiva_key_ble:363]: Reason: no remote session
wes1993 commented 6 months ago

Hello @tosilabs, Happy that I'm not alone at this point :-D If you want, waiting for a fix, you could add this code in esphome code and schedule an automation that reboot the ESP every some time, for now i have chose 3 hours and is stable:

switch:
  - platform: restart
    name: "Riavvia Porta Blindata"

Best Regards Stefano

wes1993 commented 6 months ago

@tosilabs, I have changed from 3 to 1 hour because i have seen that after 2 hours won't open..

Best Regards Stefano

digaus commented 6 months ago

Will do some tests tomorrow.

It might be caused by WiFi or BLE disconnect. Will try to reproduce.

wes1993 commented 6 months ago

Ok perfect :-D I can connect via WiFi to my ESP directly and if I try to open the door from the webpage of my ESP the opening won't works...

Could you post the link of you ESP32 board? could be a problem with ESP32

Best Regards Stefano

wes1993 commented 6 months ago

@tosilabs P.S. After 43 minutes won't open so in have changed from 1 hours to 30 minutes and test again.

digaus commented 6 months ago 
[09:58:41][D][eqiva_key_ble:229]: OTHER EVENT 38

[09:58:41][W][component:214]: Component esp32_ble took a long time for an operation (0.16 s).

[09:58:41][W][component:215]: Components should block for at most 20-30ms.

[09:58:41][D][esp32_ble_tracker:266]: Starting scan...

[09:58:41][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:70:99'

[09:58:41][D][text_sensor:064]: 'Lock BLE State': Sending state 'ESTABLISHED'

[09:58:41][D][eqiva_key_ble:073]: ESP_GATTC_WRITE_DESCR_EVT

[09:58:41][D][esp-idf:000]: E (47141266) BT_APPL: service change write ccc failed

[09:59:15][I][eqiva_key_ble:358]: Waiting for connection...

[09:59:15][I][eqiva_key_ble:360]: Reason: exchanging nonce

[09:59:15][I][eqiva_key_ble:363]: Reason: no remote session

[09:59:17][I][eqiva_key_ble:358]: Waiting for connection...

[09:59:17][I][eqiva_key_ble:360]: Reason: exchanging nonce

[09:59:17][I][eqiva_key_ble:363]: Reason: no remote session

Thats really odd, I cannot reproduce this :?

Before the esp-idf error there should be a notify event:


[09:45:41][I][esp32_ble_client:201]: [0] [00:1A:22:18:3F:A4] Connected
[09:45:41][D][text_sensor:064]: 'Lock BLE State': Sending state 'CONNECTED'
[09:45:41][D][text_sensor:064]: 'Lock BLE State': Sending state 'ESTABLISHED'
[09:45:41][D][eqiva_key_ble:040]: Write (UUID): 3141DD40-15DB-11E6-A24B-0002A5D5C51B  
[09:45:41][D][eqiva_key_ble:047]: Read (UUID): 359D4820-15DB-11E6-82BD-0002A5D5C51B  
[09:45:41][D][eqiva_key_ble:374]: Check send frag: not-empty, not-sending
[09:45:41][I][eqiva_key_ble:358]: Waiting for connection...
[09:45:41][I][eqiva_key_ble:360]: Reason: exchanging nonce
[09:45:41][I][eqiva_key_ble:363]: Reason: no remote session
[09:45:41][D][text_sensor:064]: 'Mac Address': Sending state '...'
[09:45:41][D][text_sensor:064]: 'Lock BLE State': Sending state 'ESTABLISHED'
[09:45:41][D][eqiva_key_ble:229]: OTHER EVENT 18
[09:45:41][D][text_sensor:064]: 'Mac Address': Sending state '...'
[09:45:41][D][text_sensor:064]: 'Lock BLE State': Sending state 'ESTABLISHED'
[09:45:41][D][eqiva_key_ble:229]: OTHER EVENT 38
[09:45:41][W][component:214]: Component esp32_ble took a long time for an operation (0.17 s).
[09:45:41][W][component:215]: Components should block for at most 20-30ms.
[09:45:41][D][esp32_ble_tracker:266]: Starting scan...
[09:45:41][D][text_sensor:064]: 'Mac Address': Sending state '...'
[09:45:41][D][text_sensor:064]: 'Lock BLE State': Sending state 'ESTABLISHED'

[09:45:41][D][eqiva_key_ble:077]: ESP_GATTC_NOTIFY_EVT
[09:45:41][D][eqiva_key_ble:084]: LAST
[09:45:41][D][eqiva_key_ble:152]: Case 0x03
[09:45:41][D][eqiva_key_ble:160]: Nonce exchanged: ...
[09:45:41][D][eqiva_key_ble:161]: Remote user_id: ...
[09:45:41][D][text_sensor:064]: 'User Key': Sending state '...'
[09:45:41][D][text_sensor:064]: 'User ID': Sending state '...'
[09:45:41][D][eqiva_key_ble:374]: Check send frag: not-empty, sending
[09:45:41][D][eqiva_key_ble:374]: Check send frag: not-empty, sending
[09:45:41][D][text_sensor:064]: 'Mac Address': Sending state '...'
[09:45:41][D][text_sensor:064]: 'Lock BLE State': Sending state 'ESTABLISHED'
[09:45:41][D][eqiva_key_ble:067]: ESP_GATTC_WRITE_CHAR_EVT
[09:45:41][D][eqiva_key_ble:374]: Check send frag: not-empty, not-sending

[09:45:41][W][component:214]: Component esp32_ble took a long time for an operation (0.08 s).
[09:45:41][W][component:215]: Components should block for at most 20-30ms.
[09:45:42][D][esp-idf:000]: E (50667098) BT_APPL: service change write ccc failed

Please update to latest version and add this to your yaml:

button:
  - platform: template
    id: lock_nonce
    name: Lock Request Nonce
    icon: "mdi:content-save"
    on_press:
      - eqiva_key_ble.nonce:

When the error comes again please press the button in the web ui or trigger the eqiva_key_ble.nonce otherwise and report what happens

digaus commented 6 months ago

Could you post the link of you ESP32 board? could be a problem with ESP32

Best Regards Stefano

I have a custom made ESP32-C3 directly integrated into a fingerprint doorbell:

IMG_3917 IMG_3955 IMG_3963 IMG_3999

wes1993 commented 6 months ago

Wow, this is a wonderful project :-D I'll do the test and poste here the logs.

IDK why we have this problem unfotunately :-(

Best Regards Stefano

wes1993 commented 6 months ago

I have flashed the ESP, inside the logs there is this error:

15:59:23][D][text_sensor:064]: 'Lock BLE State': Sending state 'ESTABLISHED'
[15:59:23][D][esp-idf:000]: E (14868) BT_APPL: service change write ccc failed

I don't know if is normal. Best Regards Stefano

digaus commented 6 months ago

I have flashed the ESP, inside the logs there is this error:

15:59:23][D][text_sensor:064]: 'Lock BLE State': Sending state 'ESTABLISHED'
[15:59:23][D][esp-idf:000]: E (14868) BT_APPL: service change write ccc failed

I don't know if is normal. Best Regards Stefano

thats normal

digaus commented 6 months ago

image Currently designing a custom UI so the ESP can be used and configured without home assistant :)

tosilabs commented 6 months ago

This is a new log, I changed the esp32 board, but the problem was not solved, still the same thing, I put the template button but it doesn't change anything. @digaus and @wes1993 thank you for your commitment to solve the problem!

1INFO ESPHome 2023.12.1

INFO Reading configuration /config/esphome/keyup.yaml...
INFO Updating https://github.com/digaus/esphome-components-eqiva.git@None
INFO Detected timezone 'Europe/Tirane'
INFO Starting log output from 10.0.0.224 using esphome API
INFO Successfully connected to keyup @ 10.0.0.224 in 0.025s
INFO Successful handshake with keyup @ 10.0.0.224 in 0.128s
[11:48:26][I][app:102]: ESPHome version 2023.11.6 compiled on Dec 21 2023, 22:07:58
[11:48:26][C][wifi:559]: WiFi:
[11:48:26][C][wifi:391]:   Local MAC: 78:21:84:9A:6A:5C
[11:48:26][C][wifi:396]:   SSID: [redacted]
[11:48:26][C][wifi:397]:   IP Address: 10.0.0.224
[11:48:26][C][wifi:399]:   BSSID: [redacted]
[11:48:26][C][wifi:400]:   Hostname: 'keyup'
[11:48:26][C][wifi:402]:   Signal strength: -60 dB ▂▄▆█
[11:48:26][C][wifi:406]:   Channel: 11
[11:48:26][C][wifi:407]:   Subnet: 255.255.255.0
[11:48:26][C][wifi:408]:   Gateway: 10.0.0.254
[11:48:26][C][wifi:409]:   DNS1: 10.0.0.254
[11:48:26][C][wifi:410]:   DNS2: 0.0.0.0
[11:48:26][C][logger:416]: Logger:
[11:48:26][C][logger:417]:   Level: DEBUG
[11:48:26][C][logger:418]:   Log Baud Rate: 115200
[11:48:26][C][logger:420]:   Hardware UART: UART0
[11:48:26][C][template.lock:054]: Template Lock 'KeyUP'
[11:48:26][C][template.lock:055]:   Optimistic: NO
[11:48:26][C][restart:068]: Restart Switch 'Restart GATEWAY'
[11:48:26][C][restart:070]:   Icon: 'mdi:restart'
[11:48:26][C][restart:091]:   Restore Mode: always OFF
[11:48:26][C][esp32_ble:374]: ESP32 BLE:
[11:48:26][C][esp32_ble:376]:   MAC address: 78:21:84:9A:6A:5E
[11:48:26][C][esp32_ble:377]:   IO Capability: none
[11:48:26][C][esp32_ble_tracker:645]: BLE Tracker:
[11:48:26][C][esp32_ble_tracker:646]:   Scan Duration: 300 s
[11:48:26][C][esp32_ble_tracker:647]:   Scan Interval: 320.0 ms
[11:48:26][C][esp32_ble_tracker:648]:   Scan Window: 30.0 ms
[11:48:26][C][esp32_ble_tracker:649]:   Scan Type: ACTIVE
[11:48:26][C][esp32_ble_tracker:650]:   Continuous Scanning: True
[11:48:26][C][eqiva_key_ble:016]: Eqiva Key-BLE (1.0):
[11:48:26][C][eqiva_key_ble:017]:   Address: 00:1A:22:17:70:99
[11:48:26][C][eqiva_key_ble:018]:   UserKey: ******
[11:48:26][C][eqiva_key_ble:019]:   UserId: ****
[11:48:26][C][eqiva_key_ble:020]:   CardKey: 
[11:48:26][C][captive_portal:088]: Captive Portal:
[11:48:26][C][sntp:053]: SNTP Time:
[11:48:26][C][sntp:054]:   Server 1: '0.pool.ntp.org'
[11:48:26][C][sntp:055]:   Server 2: '1.pool.ntp.org'
[11:48:26][C][sntp:056]:   Server 3: '2.pool.ntp.org'
[11:48:26][C][sntp:057]:   Timezone: 'CET-1CEST,M3.5.0,M10.5.0/3'
[11:48:26][C][mdns:115]: mDNS:
[11:48:26][C][mdns:116]:   Hostname: keyup
[11:48:27][C][ota:097]: Over-The-Air Updates:
[11:48:27][C][ota:098]:   Address: keyup.local:3232
[11:48:27][C][ota:101]:   Using Password.
[11:48:27][C][api:139]: API Server:
[11:48:27][C][api:140]:   Address: keyup.local:6053
[11:48:27][C][api:142]:   Using noise encryption: YES
[11:49:40][D][esp-idf:000]: W (47719177) BT_APPL: gattc_conn_cb: if=3 st=0 id=3 rsn=0x16
[11:49:40][D][esp-idf:000]: W (47719182) BT_HCI: hcif disc complete: hdl 0x0, rsn 0x16
[11:49:40][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:70:99'
[11:49:40][D][text_sensor:064]: 'Lock BLE State': Sending state 'IDLE'
[11:49:40][D][text_sensor:064]: 'Lock BLE State': Sending state 'IDLE'
[11:49:40][D][eqiva_key_ble:058]: ESP_GATTC_DISCONNECT_EVT
[11:49:40][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:70:99'
[11:49:40][D][text_sensor:064]: 'Lock BLE State': Sending state 'IDLE'
[11:49:40][D][eqiva_key_ble:229]: OTHER EVENT 5
[11:50:00][I][eqiva_ble:015]: Found Eqiva device (MAC: 00:1A:22:17:70:99) (UUID): 0x1A00  (Name): KEY-BLE
[11:50:00][D][esp32_ble_client:053]: [0] [00:1A:22:17:70:99] Found device
[11:50:00][D][text_sensor:064]: 'Lock BLE State': Sending state 'DISCOVERED'
[11:50:00][D][esp32_ble_tracker:215]: Pausing scan to make connection...
[11:50:00][D][text_sensor:064]: 'Lock BLE State': Sending state 'READY_TO_CONNECT'
[11:50:00][I][esp32_ble_client:069]: [0] [00:1A:22:17:70:99] 0x00 Attempting BLE connection
[11:50:00][D][text_sensor:064]: 'Lock BLE State': Sending state 'CONNECTING'
[11:50:08][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:70:99'
[11:50:08][D][text_sensor:064]: 'Lock BLE State': Sending state 'CONNECTING'
[11:50:08][D][eqiva_key_ble:229]: OTHER EVENT 40
[11:50:08][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:70:99'
[11:50:08][D][text_sensor:064]: 'Lock BLE State': Sending state 'CONNECTING'
[11:50:08][D][eqiva_key_ble:229]: OTHER EVENT 2
[11:50:09][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:70:99'
[11:50:09][D][text_sensor:064]: 'Lock BLE State': Sending state 'CONNECTING'
[11:50:09][D][eqiva_key_ble:229]: OTHER EVENT 46
[11:50:10][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:70:99'
[11:50:10][D][text_sensor:064]: 'Lock BLE State': Sending state 'CONNECTING'
[11:50:10][D][eqiva_key_ble:063]: ESP_GATTC_REG_FOR_NOTIFY_EVT
[11:50:10][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:70:99'
[11:50:10][D][text_sensor:064]: 'Lock BLE State': Sending state 'CONNECTING'
[11:50:10][D][eqiva_key_ble:063]: ESP_GATTC_REG_FOR_NOTIFY_EVT
[11:50:10][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:70:99'
[11:50:10][D][text_sensor:064]: 'Lock BLE State': Sending state 'CONNECTING'
[11:50:10][D][eqiva_key_ble:063]: ESP_GATTC_REG_FOR_NOTIFY_EVT
[11:50:10][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:70:99'
[11:50:10][D][text_sensor:064]: 'Lock BLE State': Sending state 'CONNECTING'
[11:50:10][D][eqiva_key_ble:063]: ESP_GATTC_REG_FOR_NOTIFY_EVT
[11:50:10][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:70:99'
[11:50:10][D][text_sensor:064]: 'Lock BLE State': Sending state 'CONNECTING'
[11:50:10][D][eqiva_key_ble:063]: ESP_GATTC_REG_FOR_NOTIFY_EVT
[11:50:10][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:70:99'
[11:50:10][I][esp32_ble_client:201]: [0] [00:1A:22:17:70:99] Connected
[11:50:10][D][text_sensor:064]: 'Lock BLE State': Sending state 'CONNECTED'
[11:50:10][D][text_sensor:064]: 'Lock BLE State': Sending state 'ESTABLISHED'
[11:50:10][D][eqiva_key_ble:040]: Write (UUID): 3141DD40-15DB-11E6-A24B-0002A5D5C51B  
[11:50:10][D][eqiva_key_ble:047]: Read (UUID): 359D4820-15DB-11E6-82BD-0002A5D5C51B  
[11:50:10][D][eqiva_key_ble:374]: Check send frag: not-empty, sending
[11:50:10][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:70:99'
[11:50:10][D][text_sensor:064]: 'Lock BLE State': Sending state 'ESTABLISHED'
[11:50:10][D][eqiva_key_ble:229]: OTHER EVENT 18
[11:50:10][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:70:99'
[11:50:10][D][text_sensor:064]: 'Lock BLE State': Sending state 'ESTABLISHED'
[11:50:10][D][eqiva_key_ble:229]: OTHER EVENT 38
[11:50:10][W][component:214]: Component esp32_ble took a long time for an operation (0.16 s).
[11:50:10][W][component:215]: Components should block for at most 20-30ms.
[11:50:10][D][esp32_ble_tracker:266]: Starting scan...
[11:50:10][D][text_sensor:064]: 'Mac Address': Sending state '00:1A:22:17:70:99'
[11:50:10][D][text_sensor:064]: 'Lock BLE State': Sending state 'ESTABLISHED'
[11:50:10][D][eqiva_key_ble:073]: ESP_GATTC_WRITE_DESCR_EVT
[11:50:10][D][esp-idf:000]: E (47748744) BT_APPL: service change write ccc failed
[11:50:32][I][eqiva_key_ble:358]: Waiting for connection...
[11:50:32][I][eqiva_key_ble:360]: Reason: exchanging nonce
[11:50:32][I][eqiva_key_ble:363]: Reason: no remote session
[11:50:47][D][button:010]: 'Lock Request Nonce' Pressed.
[11:50:47][D][eqiva_key_ble:374]: Check send frag: not-empty, sending
[11:50:57][I][eqiva_key_ble:358]: Waiting for connection...
[11:50:57][I][eqiva_key_ble:360]: Reason: exchanging nonce
[11:50:57][I][eqiva_key_ble:363]: Reason: no remote session
wes1993 commented 6 months ago

Hello @tosilabs, I'll see if works, this morning the ESP recennected automatically to the Lock so can't reproduce the issue, i'll check during the day.

@digaus Thanks a lot for your works :-D

Best Regards Stefano

wes1993 commented 6 months ago

Hello @digaus, Below the LOG:

18:48:32    [I] [esp32_ble_client:201]  [0] [00:1A:22:17:67:40] Connected
18:48:32    [D] [text_sensor:064]   'Lock BLE State': Sending state 'CONNECTED'
18:48:32    [D] [text_sensor:064]   'Lock BLE State': Sending state 'ESTABLISHED'
18:48:32    [D] [eqiva_key_ble:040] Write (UUID): 
18:48:32    [D] [eqiva_key_ble:047] Read (UUID): 
18:48:33    [D] [eqiva_key_ble:374] Check send frag: not-empty, sending
18:48:33    [D] [text_sensor:064]   'Mac Address': Sending state '00:1A:22:17:67:40'
18:48:33    [D] [text_sensor:064]   'Lock BLE State': Sending state 'ESTABLISHED'
18:48:33    [D] [eqiva_key_ble:229] OTHER EVENT 18
18:48:33    [D] [text_sensor:064]   'Mac Address': Sending state '00:1A:22:17:67:40'
18:48:33    [D] [text_sensor:064]   'Lock BLE State': Sending state 'ESTABLISHED'
18:48:33    [D] [eqiva_key_ble:229] OTHER EVENT 38
18:48:33    [W] [component:214] Component esp32_ble took a long time for an operation (0.16 s).
18:48:33    [W] [component:215] Components should block for at most 20-30ms.
18:48:33    [D] [esp32_ble_tracker:266] Starting scan...
18:48:33    [D] [text_sensor:064]   'Mac Address': Sending state '00:1A:22:17:67:40'
18:48:33    [D] [text_sensor:064]   'Lock BLE State': Sending state 'ESTABLISHED'
18:48:33    [D] [eqiva_key_ble:073] ESP_GATTC_WRITE_DESCR_EVT
18:48:33    [D] [esp-idf:000]   E (60803158) BT_APPL: service change write ccc failed
18:48:38    [I] [eqiva_key_ble:358] Waiting for connection...
18:48:38    [I] [eqiva_key_ble:360] Reason: exchanging nonce
18:48:38    [I] [eqiva_key_ble:363] Reason: no remote session
18:48:59    [D] [sensor:094]    'Porta Blindata Segnale Wi-Fi': Sending state -36.00000 dBm with 0 decimals of accuracy
18:49:08    [D] [sensor:094]    'Porta Blindata Uptime': Sending state 60837.88672 s with 0 decimals of accuracy
18:49:41    [D] [lock:042]   'Porta Blindata' Opening.
18:49:41    [I] [eqiva_key_ble:358] Waiting for connection...
18:49:41    [I] [eqiva_key_ble:360] Reason: exchanging nonce
18:49:41    [I] [eqiva_key_ble:363] Reason: no remote session
18:49:57    [D] [button:010]    'Lock Request Nonce' Pressed.
18:49:57    [D] [eqiva_key_ble:374] Check send frag: not-empty, sending
18:49:59    [D] [sensor:094]    'Porta Blindata Segnale Wi-Fi': Sending state -36.00000 dBm with 0 decimals of accuracy
digaus commented 5 months ago

Today my brother also had this issue. So I will look for a fix :)

digaus commented 5 months ago

Updated code, would be nice if you guys could test @wes1993 and @tosilabs

wes1993 commented 5 months ago

Hello @digaus, I have seen that there is the error below when i try to compile:

In file included from src/esphome/components/eqiva_key_ble/eqiva_key_ble.cpp:2:
src/esphome/components/eqiva_key_ble/eqiva_key_ble.cpp: In member function 'virtual bool esphome::eqiva_key_ble::EqivaKeyBle::gattc_event_handler(esp_gattc_cb_event_t, esp_gatt_if_t, esp_ble_gattc_cb_param_t*)':
src/esphome/components/eqiva_key_ble/eqiva_key_ble.cpp:69:21: error: format '%d' expects argument of type 'int', but argument 5 has type 'long unsigned int' [-Werror=format=]
       ESP_LOGI(TAG, "Send successfull: %d | %d | %d", sending, currentMillis,  currentMillis - sending);
                     ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
src/esphome/core/log.h:72:36: note: in definition of macro 'ESPHOME_LOG_FORMAT'
 #define ESPHOME_LOG_FORMAT(format) format
                                    ^~~~~~
src/esphome/core/log.h:151:28: note: in expansion of macro 'esph_log_i'
 #define ESP_LOGI(tag, ...) esph_log_i(tag, __VA_ARGS__)
                            ^~~~~~~~~~
src/esphome/components/eqiva_key_ble/eqiva_key_ble.cpp:69:7: note: in expansion of macro 'ESP_LOGI'
       ESP_LOGI(TAG, "Send successfull: %d | %d | %d", sending, currentMillis,  currentMillis - sending);
       ^~~~~~~~
src/esphome/components/eqiva_key_ble/eqiva_key_ble.cpp:69:21: error: format '%d' expects argument of type 'int', but argument 6 has type 'long unsigned int' [-Werror=format=]
       ESP_LOGI(TAG, "Send successfull: %d | %d | %d", sending, currentMillis,  currentMillis - sending);
                     ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
src/esphome/core/log.h:72:36: note: in definition of macro 'ESPHOME_LOG_FORMAT'
 #define ESPHOME_LOG_FORMAT(format) format
                                    ^~~~~~
src/esphome/core/log.h:151:28: note: in expansion of macro 'esph_log_i'
 #define ESP_LOGI(tag, ...) esph_log_i(tag, __VA_ARGS__)
                            ^~~~~~~~~~
src/esphome/components/eqiva_key_ble/eqiva_key_ble.cpp:69:7: note: in expansion of macro 'ESP_LOGI'
       ESP_LOGI(TAG, "Send successfull: %d | %d | %d", sending, currentMillis,  currentMillis - sending);
       ^~~~~~~~
src/esphome/components/eqiva_key_ble/eqiva_key_ble.cpp:69:21: error: format '%d' expects argument of type 'int', but argument 7 has type 'long unsigned int' [-Werror=format=]
       ESP_LOGI(TAG, "Send successfull: %d | %d | %d", sending, currentMillis,  currentMillis - sending);
                     ^~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
src/esphome/core/log.h:72:36: note: in definition of macro 'ESPHOME_LOG_FORMAT'
 #define ESPHOME_LOG_FORMAT(format) format
                                    ^~~~~~
src/esphome/core/log.h:151:28: note: in expansion of macro 'esph_log_i'
 #define ESP_LOGI(tag, ...) esph_log_i(tag, __VA_ARGS__)
                            ^~~~~~~~~~
src/esphome/components/eqiva_key_ble/eqiva_key_ble.cpp:69:7: note: in expansion of macro 'ESP_LOGI'
       ESP_LOGI(TAG, "Send successfull: %d | %d | %d", sending, currentMillis,  currentMillis - sending);
       ^~~~~~~~
Compiling .pioenvs/eqivakeyble/src/esphome/components/esp32_ble/ble_uuid.o
cc1plus: some warnings being treated as errors
*** [.pioenvs/eqivakeyble/src/esphome/components/eqiva_key_ble/eqiva_key_ble.o] Error 1
========================= [FAILED] Took 110.87 seconds =========================
digaus commented 5 months ago

Have you tried cleaning build? also which esphome version are you on? For me it compiles

wes1993 commented 5 months ago

Yes, I did have clean build, my ESPHome version is:

Current version: 2023.12.5

wes1993 commented 5 months ago

@digaus Did you do the clean build?

digaus commented 5 months ago

Yes I did :( very strange... can you try again?

wes1993 commented 5 months ago

@digaus , I have created a PR, there is also a problem with the nonce template in your files.

I have installed my version, how can i test the changes? i need to check some logs or something else?

Best Regards Stefano

digaus commented 5 months ago

Merged, it should now fix itself when response from lock takes longer than 3 seconds

You can check log if this case happened when you see: Nonce timeout, sending again...

wes1993 commented 5 months ago

Ok, I'll check in few hours.

Best Regards Stefano

wes1993 commented 5 months ago

Hello @digaus After 4 days I can confirm that now work well!!

image

98 Hours uptime and the door open correctly :-D