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

LoginError happens occasionally #222

Open
llamafilm opened this issue Feb 2, 2023 · 4 comments
Open

LoginError happens occasionally #222

llamafilm opened this issue Feb 2, 2023 · 4 comments

Comments

@llamafilm
Copy link

llamafilm commented Feb 2, 2023 •
edited

I'm using this library via Home Assistant and I occasionally see LoginError in the log. It always resolves itself within a few seconds, I'm just trying to figure out what causes it. I first posted in home-assistant/core#85859.

01:36:28.880 D [amcrest.http] <AMC0015D_FNYHMN:AMC0015DGR1VFNYHMN> Query 52825: Unauthorized (401)
01:36:28.881 E (MainThread) [homeassistant.components.amcrest] Amcrest Camera camera offline: Login error:
01:36:28.888 D [homeassistant.components.amcrest.binary_sensor] Updating Amcrest Camera Online binary sensor
01:36:28.895 E (MainThread) [homeassistant.components.amcrest.camera] Could not get Amcrest Camera camera attributes due to error: LoginError

01:36:28.985 D [amcrest.http] <AMC0015D_FNYHMN:AMC0015DGR1VFNYHMN> Query 52829: Unauthorized (401)
01:36:28.985 D [amcrest.http] <AMC0015D_FNYHMN:AMC0015DGR1VFNYHMN> Trying async Digest Authentication
01:36:28.985 D [amcrest.http] <AMC0015D_FNYHMN:AMC0015DGR1VFNYHMN> Async HTTP query 52830: http:https://192.168.1.26:80/cgi-bin/magicBox.cgi?action=getMachineName
01:36:28.993 D [amcrest.http] <AMC0015D_FNYHMN:AMC0015DGR1VFNYHMN> Running query 52830 attempt 1
01:36:29.050 D [amcrest.http] <AMC0015D_FNYHMN:AMC0015DGR1VFNYHMN> Query 52830 worked. Exit code: <200>

It seems like this library tries Basic Auth first, which always fails (silently), and then it tries Digest Auth which usually succeeds. I've been trying to reproduce the 401 error with DigestAuth by simulating network congestion with iptables but so far I can't. I only notice this happening every few days.

My cameras are model IP5M-T1179EW, but that log snippet came from someone else; I'm not sure what model that is.
@junalmeida
Copy link

Here is my log when the occasional error happens. The model is Amcrest Doorbell AD410. The password does not contain any special chars, as suggested this would be the cause.

2023-02-02 10:30:07.080 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Async HTTP query 270: http:https://doorbell.****:80/cgi-bin/storageDevice.cgi?action=getDeviceAllInfo
2023-02-02 10:30:07.112 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Running query 270 attempt 1
2023-02-02 10:30:07.249 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Query 270 worked. Exit code: <200>
2023-02-02 10:30:16.811 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Async HTTP query 271: http:https://doorbell.****:80/cgi-bin/configManager.cgi?action=getConfig&name=LeLensMask
2023-02-02 10:30:16.843 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Running query 271 attempt 1
2023-02-02 10:30:16.859 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Async HTTP query 272: http:https://doorbell.****:80/cgi-bin/configManager.cgi?action=getConfig&name=Encode
2023-02-02 10:30:16.887 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Running query 272 attempt 1
2023-02-02 10:30:16.890 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Async HTTP query 273: http:https://doorbell.****:80/cgi-bin/configManager.cgi?action=getConfig&name=RecordMode
2023-02-02 10:30:16.916 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Running query 273 attempt 1
2023-02-02 10:30:16.918 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Async HTTP query 274: http:https://doorbell.****:80/cgi-bin/configManager.cgi?action=getConfig&name=MotionDetect
2023-02-02 10:30:16.946 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Running query 274 attempt 1
2023-02-02 10:30:16.948 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Async HTTP query 275: http:https://doorbell.****:80/cgi-bin/configManager.cgi?action=getConfig&name=Encode
2023-02-02 10:30:16.973 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Running query 275 attempt 1
2023-02-02 10:30:16.975 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Async HTTP query 276: http:https://doorbell.****:80/cgi-bin/configManager.cgi?action=getConfig&name=MotionDetect
2023-02-02 10:30:17.000 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Running query 276 attempt 1
2023-02-02 10:30:17.003 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Async HTTP query 277: http:https://doorbell.****:80/cgi-bin/configManager.cgi?action=getConfig&name=VideoInOptions
2023-02-02 10:30:17.029 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Running query 277 attempt 1
2023-02-02 10:30:17.087 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Async HTTP query 278: http:https://doorbell.****:80/cgi-bin/storageDevice.cgi?action=getDeviceAllInfo
2023-02-02 10:30:17.111 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Running query 278 attempt 1
2023-02-02 10:30:17.254 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Query 271: Unauthorized (401)
2023-02-02 10:30:17.256 ERROR (MainThread) [homeassistant.components.amcrest] Bell camera offline: Login error: 
2023-02-02 10:30:17.271 ERROR (MainThread) [homeassistant.helpers.entity] Update for switch.bell_privacy_mode fails
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 548, in async_update_ha_state
    await self.async_device_update()
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 746, in async_device_update
    raise exc
  File "/usr/src/homeassistant/homeassistant/components/amcrest/switch.py", line 89, in async_update
    io_res = (await self._api.async_privacy_config()).splitlines()[0].split("=")[1]
  File "/usr/local/lib/python3.10/site-packages/amcrest/privacy_mode.py", line 42, in async_privacy_config
    return await self._async_get_config("LeLensMask")
  File "/usr/local/lib/python3.10/site-packages/amcrest/http.py", line 464, in _async_get_config
    ret = await self.async_command(
  File "/usr/src/homeassistant/homeassistant/components/amcrest/__init__.py", line 205, in async_command
    ret = await super().async_command(*args, **kwargs)
  File "/usr/local/lib/python3.10/site-packages/amcrest/http.py", line 230, in async_command
    return await self._async_command(*args, **kwargs)
  File "/usr/local/lib/python3.10/site-packages/amcrest/http.py", line 351, in _async_command
    raise LoginError()
amcrest.exceptions.LoginError
2023-02-02 10:30:17.319 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Query 274 worked. Exit code: <200>
2023-02-02 10:30:17.320 ERROR (MainThread) [homeassistant.components.amcrest] Bell camera back online
2023-02-02 10:30:17.340 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Query 278 worked. Exit code: <200>
2023-02-02 10:30:17.349 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Query 272 worked. Exit code: <200>
2023-02-02 10:30:17.849 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Query 273 worked. Exit code: <200>
2023-02-02 10:30:18.386 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Query 276 worked. Exit code: <200>
2023-02-02 10:30:18.909 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Query 275 worked. Exit code: <200>
2023-02-02 10:30:18.918 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Query 277 worked. Exit code: <200>
2023-02-02 10:30:27.087 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Trying async Basic Authentication
2023-02-02 10:30:27.087 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Async HTTP query 279: http:https://doorbell.****:80/cgi-bin/magicBox.cgi?action=getMachineName
2023-02-02 10:30:27.117 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Running query 279 attempt 1
2023-02-02 10:30:27.254 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Query 279: Unauthorized (401)
2023-02-02 10:30:27.255 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Trying async Digest Authentication
2023-02-02 10:30:27.255 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Async HTTP query 280: http:https://doorbell.****:80/cgi-bin/magicBox.cgi?action=getMachineName
2023-02-02 10:30:27.285 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Running query 280 attempt 1
2023-02-02 10:30:27.384 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Query 280 worked. Exit code: <200>
2023-02-02 10:30:27.385 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Retrieving serial number
2023-02-02 10:30:27.385 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Async HTTP query 281: http:https://doorbell.****:80/cgi-bin/magicBox.cgi?action=getSerialNo
2023-02-02 10:30:27.411 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Running query 281 attempt 1
2023-02-02 10:30:27.966 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Query 281 worked. Exit code: <200>
2023-02-02 10:30:27.967 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Async HTTP query 282: http:https://doorbell.****:80/cgi-bin/storageDevice.cgi?action=getDeviceAllInfo
2023-02-02 10:30:27.996 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Running query 282 attempt 1
2023-02-02 10:30:28.521 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Query 282 worked. Exit code: <200>

The query that fails seems to be /cgi-bin/configManager.cgi?action=getConfig&name=LeLensMask, but that very same call succeeds right after:

2023-02-02 10:30:46.812 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Async HTTP query 291: http:https://doorbell.****:80/cgi-bin/configManager.cgi?action=getConfig&name=LeLensMask
2023-02-02 10:30:46.840 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Running query 291 attempt 1

2023-02-02 10:30:47.855 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Query 291 worked. Exit code: <200>

Ocasionally I also see this:

2023-02-02 10:38:09.094 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Query 528 failed due to error: ReadTimeout('')
2023-02-02 10:38:09.094 WARNING (MainThread) [amcrest.http] <Bell:Z17****> Trying again due to error: ReadTimeout('')
2023-02-02 10:38:09.097 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Running query 528 attempt 2
2023-02-02 10:38:09.100 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Query 527 failed due to error: ReadTimeout('')
2023-02-02 10:38:09.101 WARNING (MainThread) [amcrest.http] <Bell:Z17****> Trying again due to error: ReadTimeout('')
2023-02-02 10:38:09.102 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Running query 527 attempt 2
2023-02-02 10:38:09.105 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Query 530 failed due to error: ReadTimeout('')
2023-02-02 10:38:09.106 WARNING (MainThread) [amcrest.http] <Bell:Z17****> Trying again due to error: ReadTimeout('')
2023-02-02 10:38:09.108 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Running query 530 attempt 2
2023-02-02 10:38:09.111 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Query 526 failed due to error: ReadTimeout('')
2023-02-02 10:38:09.112 WARNING (MainThread) [amcrest.http] <Bell:Z17****> Trying again due to error: ReadTimeout('')
2023-02-02 10:38:09.117 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Running query 526 attempt 2
2023-02-02 10:38:09.120 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Query 523 failed due to error: ReadTimeout('')
2023-02-02 10:38:09.121 WARNING (MainThread) [amcrest.http] <Bell:Z17****> Trying again due to error: ReadTimeout('')
2023-02-02 10:38:09.123 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Running query 523 attempt 2
2023-02-02 10:38:09.126 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Query 525 failed due to error: ReadTimeout('')
2023-02-02 10:38:09.127 WARNING (MainThread) [amcrest.http] <Bell:Z17****> Trying again due to error: ReadTimeout('')
2023-02-02 10:38:09.130 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Running query 525 attempt 2
2023-02-02 10:38:09.134 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Query 529 failed due to error: ReadTimeout('')
2023-02-02 10:38:09.134 WARNING (MainThread) [amcrest.http] <Bell:Z17****> Trying again due to error: ReadTimeout('')
2023-02-02 10:38:09.140 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Running query 529 attempt 2
2023-02-02 10:38:09.670 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Query 530 worked. Exit code: <200>
2023-02-02 10:38:09.704 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Query 528 worked. Exit code: <200>
2023-02-02 10:38:09.707 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Query 523 worked. Exit code: <200>
2023-02-02 10:38:09.708 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Query 526 worked. Exit code: <200>
2023-02-02 10:38:10.297 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Query 527 worked. Exit code: <200>
2023-02-02 10:38:10.355 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Query 529 worked. Exit code: <200>
2023-02-02 10:38:10.704 DEBUG (MainThread) [amcrest.http] <Bell:Z17****> Query 525 worked. Exit code: <200>

(device serial and domain redacted)

@llamafilm
Copy link
Author

llamafilm commented Feb 4, 2023 •
edited

@junalmeida I think the ReadTimeouts are irrelevant, it just suggests your network is congested or the camera is slow to respond. This LoginError seems to happen randomly with any call. Besides LeLensMask, I've also seen it on getCurrentTime (and probably others, but I haven't been tracking it closely).

I added _LOGGER.debug('auth: %s', vars(self._token)) to line 344 just before each get call and I see some interesting things, but I don't know what to make of this.

It fires 7 async queries at the same time (within 300ms), of which 6 use the same nonce. The one that fails is the only one with a different nonce.

The _nonce_count is never 1, it always starts at 2.

@dannybloe
Copy link

dannybloe commented Feb 14, 2023 •
edited

I am seeing the same problems. I also noticed that when Home Assistant (using the library) tries to connect with my doorbell and the log show these timeout errors, I can manually connect with the doorbell's api using PostMan without any problem. All the times this happens. I think that about 50% of the time HA fails to connect with the doorbell when it reboots.
I'm very sure there's no congestion on my local network whatsoever.

I just had to reconnect the doorbell and Home Assistant was not able to reconnect:

2023-02-14 13:56:17.731 WARNING (MainThread) [amcrest.http] <voordeurbel:Z17A9EE3B78E6> Trying again due to error: ConnectTimeout('')
2023-02-14 13:56:17.735 WARNING (MainThread) [amcrest.http] <voordeurbel:Z17A9EE3B78E6> Trying again due to error: ConnectTimeout('')
2023-02-14 13:56:17.739 WARNING (MainThread) [amcrest.http] <voordeurbel:Z17A9EE3B78E6> Trying again due to error: ConnectTimeout('')
2023-02-14 13:56:17.744 WARNING (MainThread) [amcrest.http] <voordeurbel:Z17A9EE3B78E6> Trying again due to error: ConnectTimeout('')
2023-02-14 13:56:17.746 WARNING (MainThread) [amcrest.http] <voordeurbel:Z17A9EE3B78E6> Trying again due to error: ConnectTimeout('')
2023-02-14 13:56:17.751 WARNING (MainThread) [amcrest.http] <voordeurbel:Z17A9EE3B78E6> Trying again due to error: ConnectTimeout('')
2023-02-14 13:56:21.575 WARNING (MainThread) [homeassistant.helpers.entity] Update of camera.voordeurbel is taking over 10 seconds
2023-02-14 13:56:23.795 ERROR (MainThread) [homeassistant.components.amcrest.camera] Could not get Voordeurbel camera attributes due to error: CommError
2023-02-14 13:56:23.808 ERROR (MainThread) [homeassistant.components.amcrest] Voordeurbel camera offline: Too many errors
2023-02-14 13:56:27.578 WARNING (MainThread) [homeassistant.components.binary_sensor] Updating amcrest binary_sensor took longer than the scheduled update interval 0:00:05
2023-02-14 13:56:28.648 WARNING (MainThread) [amcrest.http] <voordeurbel:Z17A9EE3B78E6> Trying again due to error: ConnectTimeout('')
2023-02-14 13:56:32.578 WARNING (MainThread) [homeassistant.components.binary_sensor] Updating amcrest binary_sensor took longer than the scheduled update interval 0:00:05
2023-02-14 13:56:32.580 WARNING (MainThread) [homeassistant.helpers.entity] Update of binary_sensor.voordeurbel_online is taking over 10 seconds
2023-02-14 13:56:49.489 WARNING (MainThread) [homeassistant.components.amcrest.camera] Attempt to take snapshot when Voordeurbel camera is offline
2023-02-14 13:57:17.566 WARNING (Amcrest Voordeurbel) [homeassistant.components.amcrest] Error while processing events from Voordeurbel camera: CommError(ConnectionError(ReadTimeoutError("HTTPConnectionPool(host='10.0.0.7', port=80): Read timed out.")))
2023-02-14 13:57:26.911 WARNING (MainThread) [amcrest.http] <voordeurbel:Z17A9EE3B78E6> Trying again due to error: ConnectError('All connection attempts failed')

Eventually it does seem to connect though.

@drjjr2
Copy link

drjjr2 commented Apr 14, 2023

I see this same issue with an AD410. Intermittent login errors.

2023-04-14 07:29:45.421 DEBUG (MainThread) [homeassistant.components.amcrest.camera] Take snapshot from Front Door Bell
2023-04-14 07:29:45.422 DEBUG (MainThread) [homeassistant.components.amcrest.camera] Take snapshot from Front Door Bell Sub
2023-04-14 07:29:45.431 DEBUG (MainThread) [amcrest.http] <Z17C1C0CFE5F4:Z17C1C0CFE5F4> Async HTTP query 33488: http:https://192.168.0.39:80/cgi-bin/snapshot.cgi
2023-04-14 07:29:45.465 DEBUG (MainThread) [amcrest.http] <Z17C1C0CFE5F4:Z17C1C0CFE5F4> Running query 33488 attempt 1
2023-04-14 07:29:45.467 DEBUG (MainThread) [amcrest.http] <Z17C1C0CFE5F4:Z17C1C0CFE5F4> Async HTTP query 29563: http:https://192.168.0.39:80/cgi-bin/snapshot.cgi
2023-04-14 07:29:45.500 DEBUG (MainThread) [amcrest.http] <Z17C1C0CFE5F4:Z17C1C0CFE5F4> Running query 29563 attempt 1
2023-04-14 07:29:45.724 DEBUG (MainThread) [amcrest.http] <Z17C1C0CFE5F4:Z17C1C0CFE5F4> Query 29558 worked. Exit code: <200>
2023-04-14 07:29:45.775 DEBUG (MainThread) [amcrest.http] <Z17C1C0CFE5F4:Z17C1C0CFE5F4> Query 33487: Unauthorized (401)
2023-04-14 07:29:45.778 ERROR (MainThread) [homeassistant.components.amcrest] Front Door Bell camera offline: Login error: 
2023-04-14 07:29:45.781 DEBUG (MainThread) [homeassistant.components.amcrest.binary_sensor] Updating Front Door Bell Online binary sensor
2023-04-14 07:29:45.803 ERROR (MainThread) [homeassistant.components.amcrest.camera] Could not get Front Door Bell camera attributes due to error: LoginError
2023-04-14 07:29:45.829 DEBUG (MainThread) [amcrest.http] <Z17C1C0CFE5F4:Z17C1C0CFE5F4> Query 29559 worked. Exit code: <200>
2023-04-14 07:29:46.324 DEBUG (MainThread) [amcrest.http] <Z17C1C0CFE5F4:Z17C1C0CFE5F4> Query 29560 worked. Exit code: <200>
2023-04-14 07:29:46.342 DEBUG (MainThread) [amcrest.http] <Z17C1C0CFE5F4:Z17C1C0CFE5F4> Query 29557 worked. Exit code: <200>
2023-04-14 07:29:46.846 DEBUG (MainThread) [amcrest.http] <Z17C1C0CFE5F4:Z17C1C0CFE5F4> Query 29562 worked. Exit code: <200>
2023-04-14 07:29:46.858 DEBUG (MainThread) [amcrest.http] <Z17C1C0CFE5F4:Z17C1C0CFE5F4> Query 33486 worked. Exit code: <200>
2023-04-14 07:29:46.858 ERROR (MainThread) [homeassistant.components.amcrest] Front Door Bell camera back online
2023-04-14 07:29:46.862 DEBUG (MainThread) [homeassistant.components.amcrest.binary_sensor] Updating Front Door Bell Online binary sensor

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@junalmeida @dannybloe @llamafilm @drjjr2