search

neil-morrison44 / homebridge-am43-blinds-bluez

A homebridge plugin for AM43 blinds which only works on linux
MIT License
0 stars 1 forks source link

Getting DBusError: Write not permitted trying to authenticate with the motor #2

Open renssies opened 2 years ago

renssies commented 2 years ago

I wanted to start using your implementation so I put it on a spare Pi and started to test it. The plugin can find the motor, it can connect to it, but as soon as I press the "auth" button with a correct pin I get the following error:

[15/05/2022, 17:18:29] [Homebridge UI] [homebridge-am43-blinds-bluez] DBusError: Write not permitted
    at _methodReturnHandlers.<computed> (/var/lib/homebridge/node_modules/.pnpm/dbus-next@0.10.2/node_modules/dbus-next/lib/bus.js:343:27)
    at handleMessage (/var/lib/homebridge/node_modules/.pnpm/dbus-next@0.10.2/node_modules/dbus-next/lib/bus.js:101:11)
    at EventEmitter.<anonymous> (/var/lib/homebridge/node_modules/.pnpm/dbus-next@0.10.2/node_modules/dbus-next/lib/bus.js:151:9)
    at EventEmitter.emit (node:events:527:28)
    at /var/lib/homebridge/node_modules/.pnpm/dbus-next@0.10.2/node_modules/dbus-next/lib/connection.js:132:14
    at USocket.<anonymous> (/var/lib/homebridge/node_modules/.pnpm/dbus-next@0.10.2/node_modules/dbus-next/lib/message.js:65:9)
    at USocket.emit (node:events:527:28)
    at emitReadable_ (node:internal/streams/readable:578:12)
    at processTicksAndRejections (node:internal/process/task_queues:82:21) {
  type: 'org.bluez.Error.NotPermitted',
  text: 'Write not permitted',
  reply: Message {
    type: 3,
    _sent: false,
    _serial: 238,
    path: undefined,
    interface: undefined,
    member: undefined,
    errorName: 'org.bluez.Error.NotPermitted',
    replySerial: 69,
    destination: ':1.6',
    sender: ':1.3',
    signature: 's',
    body: [ 'Write not permitted' ],
    flags: 1
  }
}

I have setup the dbus config file for both the homebridge and pi user but it doesn't seem to make a difference. If I use bluetoothctl everything seems to work fine so it seems to be a communication issue between node-ble and dbus but I have no idea how to resolve it.

Some more details: System: Raspberry Pi 2 Model B Rev 1.1 Image: Homebridge (through Raspberry Pi Imager) Adapter: Ugreen bluetooth 4.0 (Pi has no internal WiFi or Bluetooth) OS: Raspbian v1.0.34 Homebridge version: 1.4.1 Node version: 16.15.0

neil-morrison44 commented 2 years ago

I’ve not seen that error before, makes sense that it’d be something node-ble -> bluez

If you manually put the correct MAC / auth pin into a config does it have the same error?

renssies commented 2 years ago

Nope, still doesn't work.

Error:

[15/05/2022, 18:41:58] [am43-blinds-bluez] Auth Timeout...
[15/05/2022, 18:41:58] [am43-blinds-bluez] Passcode auth failed for Office : 02:86:68:35:3C:51
[15/05/2022, 18:41:59] DBusError: Write not permitted
    at _methodReturnHandlers.<computed> (/var/lib/homebridge/node_modules/.pnpm/dbus-next@0.10.2/node_modules/dbus-next/lib/bus.js:343:27)
    at handleMessage (/var/lib/homebridge/node_modules/.pnpm/dbus-next@0.10.2/node_modules/dbus-next/lib/bus.js:101:11)
    at EventEmitter.<anonymous> (/var/lib/homebridge/node_modules/.pnpm/dbus-next@0.10.2/node_modules/dbus-next/lib/bus.js:151:9)
    at EventEmitter.emit (node:events:527:28)
    at /var/lib/homebridge/node_modules/.pnpm/dbus-next@0.10.2/node_modules/dbus-next/lib/connection.js:132:14
    at USocket.<anonymous> (/var/lib/homebridge/node_modules/.pnpm/dbus-next@0.10.2/node_modules/dbus-next/lib/message.js:65:9)
    at USocket.emit (node:events:527:28)
    at emitReadable_ (node:internal/streams/readable:578:12)
    at processTicksAndRejections (node:internal/process/task_queues:82:21)
[15/05/2022, 18:42:03] [HB Supervisor] Homebridge Process Ended. Code: 143, Signal: null

Config:

{
    "name": "am43-blinds-bluez",
    "platform": "am43-blinds-bluez",
    "allowed_devices": [
        {
            "name": "Office",
            "address": "02:86:68:35:3C:51",
            "pass_code": "8888"
        }
    ]
}
neil-morrison44 commented 2 years ago

Hmm, I've never encountered that - I've been using a Pi3 with the build in bluetooth.

I was considering supporting a web-bluetooth setup to get around node-ble not being able to filter by services but if it's not even doing the regular "bluetooth" bit sometimes that wouldn't be a good solution...

I'm starting to think that node -> BLE just isn't every well supported

drosenberg-gh commented 2 years ago

I'm getting a very similar error when I press the "auth" button

[2022-07-09, 9:26:50 a.m.] [Homebridge UI] [homebridge-am43-blinds-bluez] DBusError: Write not permitted at _methodReturnHandlers. (/usr/lib/node_modules/homebridge-am43-blinds-bluez/node_modules/dbus-next/lib/bus.js:343:27) at handleMessage (/usr/lib/node_modules/homebridge-am43-blinds-bluez/node_modules/dbus-next/lib/bus.js:101:11) at EventEmitter. (/usr/lib/node_modules/homebridge-am43-blinds-bluez/node_modules/dbus-next/lib/bus.js:151:9) at EventEmitter.emit (node:events:527:28) at /usr/lib/node_modules/homebridge-am43-blinds-bluez/node_modules/dbus-next/lib/connection.js:132:14 at USocket. (/usr/lib/node_modules/homebridge-am43-blinds-bluez/nodemodules/dbus-next/lib/message.js:65:9) at USocket.emit (node:events:527:28) at emitReadable (node:internal/streams/readable:578:12) at processTicksAndRejections (node:internal/process/task_queues:82:21) { type: 'org.bluez.Error.NotPermitted', text: 'Write not permitted', reply: Message { type: 3, _sent: false, _serial: 4095, path: undefined, interface: undefined, member: undefined, errorName: 'org.bluez.Error.NotPermitted', replySerial: 72, destination: ':1.238', sender: ':1.2', signature: 's', body: [ 'Write not permitted' ], flags: 1 }

drosenberg-gh commented 2 years ago

If I manually add the device to the config, I get the following error

[2022-07-09, 9:39:18 a.m.] [homebridge-am43-blinds-bluez] Authing...

/usr/lib/node_modules/homebridge-am43-blinds-bluez/node_modules/dbus-next/lib/bus.js:343 return reject(new DBusError(reply.errorName, reply.body[0], reply)); ^ DBusError: Write not permitted at _methodReturnHandlers. (/usr/lib/node_modules/homebridge-am43-blinds-bluez/node_modules/dbus-next/lib/bus.js:343:27) at handleMessage (/usr/lib/node_modules/homebridge-am43-blinds-bluez/node_modules/dbus-next/lib/bus.js:101:11) at EventEmitter. (/usr/lib/node_modules/homebridge-am43-blinds-bluez/node_modules/dbus-next/lib/bus.js:151:9) at EventEmitter.emit (node:events:527:28) at /usr/lib/node_modules/homebridge-am43-blinds-bluez/node_modules/dbus-next/lib/connection.js:132:14 at USocket. (/usr/lib/node_modules/homebridge-am43-blinds-bluez/nodemodules/dbus-next/lib/message.js:65:9) at USocket.emit (node:events:527:28) at emitReadable (node:internal/streams/readable:578:12) at processTicksAndRejections (node:internal/process/task_queues:82:21)

neil-morrison44 commented 2 years ago

This is even with this set up https://github.com/neil-morrison44/homebridge-am43-blinds-bluez#installation right?

drosenberg-gh commented 2 years ago

This is even with this set up https://github.com/neil-morrison44/homebridge-am43-blinds-bluez#installation right?

Yes, it’s after that was set up

drosenberg-gh commented 2 years ago

It's probably worth mentioning that I'm also using a USB Bluetooth adapter

Chester-P commented 1 year ago

getting the same error on both Pi 4 and the integrated Bluetooth on intel NUC

here's the last bit of output of btmon if it helps:

< ACL Data TX: Handle 3585 flags 0x00 dlen 18                                                                            #54 [hci0] 11.291277
      ATT: Prepare Write Request (0x16) len 13
        Handle: 0x000e
        Offset: 0x0000
          Data: 00ff00009aa701013d
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                   #55 [hci0] 11.316912
        Num handles: 1
        Handle: 3585
        Count: 1
> ACL Data RX: Handle 3585 flags 0x02 dlen 9                                                                             #56 [hci0] 11.339918
      ATT: Error Response (0x01) len 4
        Prepare Write Request (0x16)
        Handle: 0x000e
        Error: Write Not Permitted (0x03)
< ACL Data TX: Handle 3585 flags 0x00 dlen 6                                                                             #57 [hci0] 11.340228
      ATT: Execute Write Request (0x18) len 1
        Flags: Cancel all prepared writes (0x00)
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                   #58 [hci0] 11.364767
        Num handles: 1
        Handle: 3585
        Count: 1
> ACL Data RX: Handle 3585 flags 0x02 dlen 5                                                                             #59 [hci0] 11.389641
      ATT: Execute Write Response (0x19) len 0
@ MGMT Command: Disconnect (0x0014) plen 7                                                                          {0x0001} [hci0] 12.723403
        LE Address: 02:3A:B3:37:34:00 (OUI 02-3A-B3)
< HCI Command: Disconnect (0x01|0x0006) plen 3                                                                           #60 [hci0] 12.723444
        Handle: 3585
        Reason: Remote User Terminated Connection (0x13)
> HCI Event: Command Status (0x0f) plen 4                                                                                #61 [hci0] 12.725846
      Disconnect (0x01|0x0006) ncmd 1
        Status: Success (0x00)
> HCI Event: Disconnect Complete (0x05) plen 4                                                                           #62 [hci0] 12.740909
        Status: Success (0x00)
        Handle: 3585
        Reason: Connection Terminated By Local Host (0x16)
@ MGMT Event: Command Complete (0x0001) plen 10                                                                     {0x0001} [hci0] 12.741022
      Disconnect (0x0014) plen 7
        Status: Success (0x00)
        LE Address: 02:3A:B3:37:34:00 (OUI 02-3A-B3)

reading the code I just realised above was AM43_COMMAND_ID_GET_POSITION. Prior to this, I can also see AM43_COMMAND_PASSCODE failing

< ACL Data TX: Handle 3585 flags 0x00 dlen 19                                                                            #39 [hci0] 10.290763
      ATT: Prepare Write Request (0x16) len 14
        Handle: 0x000e
        Offset: 0x0000
          Data: 00ff00009a170222b815
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                   #40 [hci0] 10.330905
        Num handles: 1
        Handle: 3585
        Count: 1
> ACL Data RX: Handle 3585 flags 0x02 dlen 9                                                                             #41 [hci0] 10.374675
      ATT: Error Response (0x01) len 4
        Prepare Write Request (0x16)
        Handle: 0x000e
        Error: Write Not Permitted (0x03)

and below is the complete btmon output:

@ MGMT Event: Device Connected (0x000b) plen 20                                                                      {0x0001} [hci0] 9.466035
        LE Address: 02:3A:B3:37:34:00 (OUI 02-3A-B3)
        Flags: 0x00000008
          Connection Locally Initiated
        Data length: 7
        Flags: 0x06
          LE General Discoverable Mode
          BR/EDR Not Supported
        16-bit Service UUIDs (partial): 1 entry
          Google Inc. (0xfe50)
< HCI Command: LE Read Remote Used Features (0x08|0x0016) plen 2                                                          #11 [hci0] 9.466159
        Handle: 3585
> HCI Event: LE Meta Event (0x3e) plen 4                                                                                  #12 [hci0] 9.466737
      LE Channel Selection Algorithm (0x14)
        Handle: 3585
        Algorithm: #1 (0x00)
> HCI Event: Command Status (0x0f) plen 4                                                                                 #13 [hci0] 9.467740
      LE Read Remote Used Features (0x08|0x0016) ncmd 1
        Status: Success (0x00)
> HCI Event: LE Meta Event (0x3e) plen 12                                                                                 #14 [hci0] 9.520768
      LE Read Remote Used Features (0x04)
        Status: Success (0x00)
        Handle: 3585
        Features: 0x09 0x00 0x00 0x00 0x00 0x00 0x00 0x00
          LE Encryption
          Peripheral-initiated Features Exchange
< ACL Data TX: Handle 3585 flags 0x00 dlen 7                                                                              #15 [hci0] 9.521234
      ATT: Exchange MTU Request (0x02) len 2
        Client RX MTU: 517
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                    #16 [hci0] 9.565895
        Num handles: 1
        Handle: 3585
        Count: 1
> ACL Data RX: Handle 3585 flags 0x02 dlen 7                                                                              #17 [hci0] 9.609691
      ATT: Exchange MTU Response (0x03) len 2
        Server RX MTU: 247
< ACL Data TX: Handle 3585 flags 0x00 dlen 7                                                                              #18 [hci0] 9.610019
      ATT: Read Request (0x0a) len 2
        Handle: 0x0007
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                    #19 [hci0] 9.654899
        Num handles: 1
        Handle: 3585
        Count: 1
> ACL Data RX: Handle 3585 flags 0x02 dlen 11                                                                             #20 [hci0] 9.699705
      ATT: Read Response (0x0b) len 6
        Value: 6261636b7570
< ACL Data TX: Handle 3585 flags 0x00 dlen 7                                                                              #21 [hci0] 9.700028
      ATT: Read Request (0x0a) len 2
        Handle: 0x0009
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                    #22 [hci0] 9.744747
        Num handles: 1
        Handle: 3585
        Count: 1
> ACL Data RX: Handle 3585 flags 0x02 dlen 7                                                                              #23 [hci0] 9.789544
      ATT: Read Response (0x0b) len 2
        Value: 0000
< ACL Data TX: Handle 3585 flags 0x00 dlen 11                                                                             #24 [hci0] 9.789748
      ATT: Read By Type Request (0x08) len 6
        Handle range: 0x0001-0xffff
        Attribute type: Server Supported Features (0x2b3a)
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                    #25 [hci0] 9.834806
        Num handles: 1
        Handle: 3585
        Count: 1
> ACL Data RX: Handle 3585 flags 0x02 dlen 9                                                                              #26 [hci0] 9.879678
      ATT: Error Response (0x01) len 4
        Read By Type Request (0x08)
        Handle: 0x0001
        Error: Attribute Not Found (0x0a)
< ACL Data TX: Handle 3585 flags 0x00 dlen 11                                                                             #27 [hci0] 9.879980
      ATT: Read By Group Type Request (0x10) len 6
        Handle range: 0x0001-0xffff
        Attribute group type: Primary Service (0x2800)
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                    #28 [hci0] 9.924904
        Num handles: 1
        Handle: 3585
        Count: 1
> ACL Data RX: Handle 3585 flags 0x02 dlen 24                                                                             #29 [hci0] 9.969921
      ATT: Read By Group Type Response (0x11) len 19
        Attribute data length: 6
        Attribute group list: 3 entries
        Handle range: 0x0001-0x0004
        UUID: Generic Attribute Profile (0x1801)
        Handle range: 0x0005-0x000b
        UUID: Generic Access Profile (0x1800)
        Handle range: 0x000c-0x0011
        UUID: Google Inc. (0xfe50)
< ACL Data TX: Handle 3585 flags 0x00 dlen 11                                                                             #30 [hci0] 9.970307
      ATT: Read By Group Type Request (0x10) len 6
        Handle range: 0x0012-0xffff
        Attribute group type: Primary Service (0x2800)
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                   #31 [hci0] 10.014906
        Num handles: 1
        Handle: 3585
        Count: 1
> ACL Data RX: Handle 3585 flags 0x02 dlen 9                                                                             #32 [hci0] 10.104734
      ATT: Error Response (0x01) len 4
        Read By Group Type Request (0x10)
        Handle: 0x0012
        Error: Attribute Not Found (0x0a)
< ACL Data TX: Handle 3585 flags 0x00 dlen 9                                                                             #33 [hci0] 10.112601
      ATT: Write Request (0x12) len 4
        Handle: 0x0004
          Data: 0200
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                   #34 [hci0] 10.149896
        Num handles: 1
        Handle: 3585
        Count: 1
> ACL Data RX: Handle 3585 flags 0x02 dlen 5                                                                             #35 [hci0] 10.194707
      ATT: Write Response (0x13) len 0
< ACL Data TX: Handle 3585 flags 0x00 dlen 9                                                                             #36 [hci0] 10.195097
      ATT: Write Request (0x12) len 4
        Handle: 0x000f
          Data: 0100
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                   #37 [hci0] 10.239904
        Num handles: 1
        Handle: 3585
        Count: 1
> ACL Data RX: Handle 3585 flags 0x02 dlen 5                                                                             #38 [hci0] 10.284709
      ATT: Write Response (0x13) len 0
< ACL Data TX: Handle 3585 flags 0x00 dlen 19                                                                            #39 [hci0] 10.290763
      ATT: Prepare Write Request (0x16) len 14
        Handle: 0x000e
        Offset: 0x0000
          Data: 00ff00009a170222b815
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                   #40 [hci0] 10.330905
        Num handles: 1
        Handle: 3585
        Count: 1
> ACL Data RX: Handle 3585 flags 0x02 dlen 9                                                                             #41 [hci0] 10.374675
      ATT: Error Response (0x01) len 4
        Prepare Write Request (0x16)
        Handle: 0x000e
        Error: Write Not Permitted (0x03)
< ACL Data TX: Handle 3585 flags 0x00 dlen 6                                                                             #42 [hci0] 10.375051
      ATT: Execute Write Request (0x18) len 1
        Flags: Cancel all prepared writes (0x00)
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                   #43 [hci0] 10.419909
        Num handles: 1
        Handle: 3585
        Count: 1
> ACL Data RX: Handle 3585 flags 0x02 dlen 5                                                                             #44 [hci0] 10.464642
      ATT: Execute Write Response (0x19) len 0
< ACL Data TX: Handle 3585 flags 0x00 dlen 9                                                                             #45 [hci0] 10.471853
      ATT: Write Request (0x12) len 4
        Handle: 0x000f
          Data: 0000
> ACL Data RX: Handle 3585 flags 0x02 dlen 16                                                                            #46 [hci0] 10.509999
      LE L2CAP: Connection Parameter Update Request (0x12) ident 1 len 8
        Min interval: 20
        Max interval: 20
        Peripheral latency: 0
        Timeout multiplier: 500
@ MGMT Event: New Connection Parameter (0x001c) plen 16                                                             {0x0001} [hci0] 10.510059
        Store hint: No (0x00)
        BR/EDR Address: 01:02:3A:B3:37:34 (OUI 01-02-3A)
        Min connection interval: 20
        Max connection interval: 20
        Connection latency: 0 (0x0000)
        Supervision timeout: 500
< ACL Data TX: Handle 3585 flags 0x00 dlen 10                                                                            #47 [hci0] 10.510067
      LE L2CAP: Connection Parameter Update Response (0x13) ident 1 len 2
        Result: Connection Parameters accepted (0x0000)
< HCI Command: LE Connection Update (0x08|0x0013) plen 14                                                                #48 [hci0] 10.510091
        Handle: 3585
        Min connection interval: 25.00 msec (0x0014)
        Max connection interval: 25.00 msec (0x0014)
        Connection latency: 0 (0x0000)
        Supervision timeout: 5000 msec (0x01f4)
        Min connection length: 0.000 msec (0x0000)
        Max connection length: 0.000 msec (0x0000)
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                   #49 [hci0] 10.510711
        Num handles: 1
        Handle: 3585
        Count: 1
> HCI Event: Command Status (0x0f) plen 4                                                                                #50 [hci0] 10.512900
      LE Connection Update (0x08|0x0013) ncmd 1
        Status: Success (0x00)
> ACL Data RX: Handle 3585 flags 0x02 dlen 5                                                                             #51 [hci0] 10.554919
      ATT: Write Response (0x13) len 0
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                   #52 [hci0] 10.555746
        Num handles: 1
        Handle: 3585
        Count: 1
> HCI Event: LE Meta Event (0x3e) plen 10                                                                                #53 [hci0] 10.889885
      LE Connection Update Complete (0x03)
        Status: Success (0x00)
        Handle: 3585
        Connection interval: 25.00 msec (0x0014)
        Connection latency: 0 (0x0000)
        Supervision timeout: 5000 msec (0x01f4)
< ACL Data TX: Handle 3585 flags 0x00 dlen 18                                                                            #54 [hci0] 11.291277
      ATT: Prepare Write Request (0x16) len 13
        Handle: 0x000e
        Offset: 0x0000
          Data: 00ff00009aa701013d
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                   #55 [hci0] 11.316912
        Num handles: 1
        Handle: 3585
        Count: 1
> ACL Data RX: Handle 3585 flags 0x02 dlen 9                                                                             #56 [hci0] 11.339918
      ATT: Error Response (0x01) len 4
        Prepare Write Request (0x16)
        Handle: 0x000e
        Error: Write Not Permitted (0x03)
< ACL Data TX: Handle 3585 flags 0x00 dlen 6                                                                             #57 [hci0] 11.340228
      ATT: Execute Write Request (0x18) len 1
        Flags: Cancel all prepared writes (0x00)
> HCI Event: Number of Completed Packets (0x13) plen 5                                                                   #58 [hci0] 11.364767
        Num handles: 1
        Handle: 3585
        Count: 1
> ACL Data RX: Handle 3585 flags 0x02 dlen 5                                                                             #59 [hci0] 11.389641
      ATT: Execute Write Response (0x19) len 0
@ MGMT Command: Disconnect (0x0014) plen 7                                                                          {0x0001} [hci0] 12.723403
        LE Address: 02:3A:B3:37:34:00 (OUI 02-3A-B3)
< HCI Command: Disconnect (0x01|0x0006) plen 3                                                                           #60 [hci0] 12.723444
        Handle: 3585
        Reason: Remote User Terminated Connection (0x13)
> HCI Event: Command Status (0x0f) plen 4                                                                                #61 [hci0] 12.725846
      Disconnect (0x01|0x0006) ncmd 1
        Status: Success (0x00)
> HCI Event: Disconnect Complete (0x05) plen 4                                                                           #62 [hci0] 12.740909
        Status: Success (0x00)
        Handle: 3585
        Reason: Connection Terminated By Local Host (0x16)
@ MGMT Event: Command Complete (0x0001) plen 10                                                                     {0x0001} [hci0] 12.741022
      Disconnect (0x0014) plen 7
        Status: Success (0x00)
        LE Address: 02:3A:B3:37:34:00 (OUI 02-3A-B3)

I know nothing about the device/protocol, would be nice if someone more familiar could look into this

aj4m2a commented 3 days ago

I am receiving the same error. Here is the homebridge debug section:

homebridge.log.txt