search

JnyJny / busylight

Control USB connected presence lights from multiple vendors via the command-line or web API.
Apache License 2.0
220 stars 25 forks source link

[BUG] `open_path` fails on API calls #159

Closed mchaker closed 2 years ago

mchaker commented 2 years ago

Software Versions:

General Type of Problem

Describe the Problem

When starting the web API, a DEBUG message appears stating:

2022-07-17 14:11:06.670 | DEBUG    | busylight.lights.usblight:update:670 - Embrava Blynclight Standard@1-4:1.0 write_strategy returned 9 sent 00000000090080ff22

and then, when attempting to access any API endpoint, the following error appears:

2022-07-17 14:17:38.406 | ERROR    | busylight.lights.usblight:acquire:629 - open_path failed with open failed
2022-07-17 14:17:38.408 | ERROR    | busylight.lights.usblight:all_lights:202 - Blynclight LightUnavailable: 2c0d:000c path=b'1-4:1.0'

Light commands seem to work (on/off, at least), but not much information about the light returns in /light/0/status (missing serial_number, manufacturer_string, usage, perhaps?):

{
  "light_id": 0,
  "name": "Embrava Blynclight Standard",
  "info": {
    "path": "1-4:1.0",
    "vendor_id": 11277,
    "product_id": 12,
    "serial_number": "",
    "release_number": 1,
    "manufacturer_string": "",
    "product_string": "Blynclight Standard",
    "usage_page": 0,
    "usage": 0,
    "interface_number": 0
  },
  "is_on": false,
  "color": "black",
  "rgb": [
    0,
    0,
    0
  ]
}

Perhaps the open_path error is limiting the information obtained from the light? Unsure.

Expected Behavior

No errors to occur.

Error Output

Full log from busyserve start:

2022-07-17 14:11:04.963 | INFO     | busylight.__main__:serve_http_api:380 - serving http api
INFO:     Will watch for changes in these directories: ['/']
INFO:     Uvicorn running on http://0.0.0.0:8080 (Press CTRL+C to quit)
INFO:     Started reloader process [1] using StatReload
2022-07-17 14:11:06.364 | INFO     | busylight.api.busylight_api:__init__:63 - Set up authentication, if environment variables set.
2022-07-17 14:11:06.365 | INFO     | busylight.api.busylight_api:__init__:71 - Did NOT find user credentials in environment.
2022-07-17 14:11:06.365 | INFO     | busylight.api.busylight_api:__init__:72 - Access authentication disabled.
INFO:     Started server process [8]
INFO:     Waiting for application startup.
2022-07-17 14:11:06.659 | INFO     | busylight.lights.usblight:all_lights:203 - BlinkStick found 0 lights
2022-07-17 14:11:06.670 | DEBUG    | busylight.lights.usblight:update:670 - Embrava Blynclight Standard@1-4:1.0 write_strategy returned 9 sent 00000000090080ff22
2022-07-17 14:11:06.671 | INFO     | busylight.lights.usblight:all_lights:203 - Blynclight found 1 lights
2022-07-17 14:11:06.680 | INFO     | busylight.lights.usblight:all_lights:203 - Busylight found 0 lights
2022-07-17 14:11:06.687 | INFO     | busylight.lights.usblight:all_lights:203 - Flag found 0 lights
2022-07-17 14:11:06.697 | INFO     | busylight.lights.usblight:all_lights:203 - Mute found 0 lights
2022-07-17 14:11:06.705 | INFO     | busylight.lights.usblight:all_lights:203 - Orb found 0 lights
2022-07-17 14:11:06.714 | INFO     | busylight.lights.usblight:all_lights:203 - MuteMe found 0 lights
2022-07-17 14:11:06.724 | INFO     | busylight.lights.usblight:all_lights:203 - Status_Indicator found 0 lights
2022-07-17 14:11:06.732 | INFO     | busylight.lights.usblight:all_lights:203 - Blink1 found 0 lights
2022-07-17 14:11:06.733 | INFO     | busylight.lights.usblight:all_lights:195 - USBLight found 1 lights total
2022-07-17 14:11:06.735 | DEBUG    | busylight.lights.usblight:update:670 - Embrava Blynclight Standard@1-4:1.0 write_strategy returned 9 sent 00000000090080ff22
INFO:     Application startup complete.
2022-07-17 14:17:38.389 | INFO     | busylight.lights.usblight:all_lights:203 - BlinkStick found 0 lights
2022-07-17 14:17:38.406 | ERROR    | busylight.lights.usblight:acquire:629 - open_path failed with open failed
2022-07-17 14:17:38.408 | ERROR    | busylight.lights.usblight:all_lights:202 - Blynclight LightUnavailable: 2c0d:000c path=b'1-4:1.0'
2022-07-17 14:17:38.410 | INFO     | busylight.lights.usblight:all_lights:203 - Blynclight found 0 lights
2022-07-17 14:17:38.424 | INFO     | busylight.lights.usblight:all_lights:203 - Busylight found 0 lights
2022-07-17 14:17:38.437 | INFO     | busylight.lights.usblight:all_lights:203 - Flag found 0 lights
2022-07-17 14:17:38.451 | INFO     | busylight.lights.usblight:all_lights:203 - Mute found 0 lights
2022-07-17 14:17:38.464 | INFO     | busylight.lights.usblight:all_lights:203 - Orb found 0 lights
2022-07-17 14:17:38.477 | INFO     | busylight.lights.usblight:all_lights:203 - MuteMe found 0 lights
2022-07-17 14:17:38.491 | INFO     | busylight.lights.usblight:all_lights:203 - Status_Indicator found 0 lights
2022-07-17 14:17:38.504 | INFO     | busylight.lights.usblight:all_lights:203 - Blink1 found 0 lights
2022-07-17 14:17:38.505 | INFO     | busylight.lights.usblight:all_lights:195 - USBLight found 0 lights total
INFO:     100.96.190.102:39376 - "GET /light/0/status HTTP/1.1" 200 OK
JnyJny commented 2 years ago

What you are seeing here is an artifact of the busylight_api class checking to see if there have been any new lights added to the USB bus(es) since the last endpoint was serviced. The busylight_api instance will call update which then calls USBLight.all_lights() which calls the all_lights class method for all supported lights. The busylight_api instance has a list of lights that it currently knows about and are held open to disallow another process from writing to them while they are under control of busylight_api. So when the update happens and we try to open the light a second time, open_path will fail. This lets us know that it isn't a new light we have to initialize in the update. In the output above:

2022-07-17 14:11:06.733 | INFO     | busylight.lights.usblight:all_lights:195 - USBLight found 1 lights total
...
2022-07-17 14:17:38.505 | INFO     | busylight.lights.usblight:all_lights:195 - USBLight found 0 lights total

The first line indicates one light was found, the second indicates that no new lights were found. Which is expected if you haven't attached any new lights in the interval between the two calls.

The light/N/status endpoint is doing the best it can :)

Most USB lights are essentially "write-only" and all but a few return zeros when read. The info section of the status response is the initial information read from the device via hid.enumerate. The USB standard(s) have a list of possible values that devices "should" implement but are not strictly required. So the empty fields in info are fields the manufacturers decided not to populate.

All the other information in the status response is state maintained in busylight_api (one reason to keep all the lights open exclusively is to keep other processes from modifying the state of the light, causing state information of the light to become incomplete).

One thing I could do here is reduce the default logging level for the webapi which will hide some of these distressing messages, but given the output you provided I don't see any evidence of a bug.

mchaker commented 2 years ago

Ah, I understand now. Thanks for explaining! This is not a bug - closing the issue.

JnyJny commented 2 years ago

I appreciate you giving it a work out and calling me on anything that's confusing. I've spent so much time looking at this stuff that it's difficult for me to see how this code looks from a fresh perspective.

mchaker commented 2 years ago

I'm glad to help! I've just published a repository called busylight-docker which is a way to run busyserve in a Docker container (I have all my lights connected to a single server on my desk :) )