reolink_dev icon indicating copy to clipboard operation
reolink_dev copied to clipboard

Home Assistant error: "Host 192.168.110.xxx error renewing the Reolink subscription"

Open rainbowbreeze opened this issue 3 years ago • 70 comments

Describe the bug I've 4 Reolink RLC-811A connected directly to my LAN (no NVR). 192.168.110.121, .122, .124, .125 All the four cameras have the same firmware version, and configurations I've configured all of them under HA using the reolink_dev custom integration

For two of them the following error continues to pop up in HA logs

Host 192.168.110.124 error renewing the Reolink subscription
Host 192.168.110.122 error renewing the Reolink subscription

I removed the cameras, and re-added them, and I get the same error. Interestingly enough, .121 and .125 don't show the error.

Environment: Please provide useful information about your environment, like:

  • Home Assistant version: 2022.08.04
  • Home Assistant IP: 192.168.100.6 (different VLAN from the cameras, but they can both access to each other on all ports)
  • Reolink camera model: RLC-811A
  • Camera firmware number: v3.1.0.956_22042008
  • reolink_dev version: v0.55

Additional context Here the debug logs from HA with the error happens (username and pwd obscured):

2022-08-15 15:55:24.109 DEBUG (MainThread) [reolink.subscription_manager] Host 192.168.110.124: Connection error Cannot connect to host 192.168.110.124:8000 ssl:default [Connect call failed ('192.168.110.124', 8000)]
2022-08-15 15:55:24.109 ERROR (MainThread) [custom_components.reolink_dev.base] Host 192.168.110.124 error renewing the Reolink subscription
2022-08-15 15:55:24.113 DEBUG (MainThread) [reolink.subscription_manager] Reolink host 192.168.110.124 (Subscription) request data:
<soap:Envelope xmlns:add="http://www.w3.org/2005/08/addressing" xmlns:b="http://docs.oasis-open.org/wsn/b-2" xmlns:soap="http://www.w3.org/2003/05/soap-envelope">
<soap:Header><wsse:Security soap:mustUnderstand="true" xmlns:wsse="http://docs.oasis-open.org/wss/2004/01/oasis-200401-wss-wssecurity-secext-1.0.xsd"
xmlns:wsu="http://docs.oasis-open.org/wss/2004/01/oasis-200401-wss-wssecurity-utility-1.0.xsd">
<wsse:UsernameToken wsu:Id="UsernameToken-3839ddc1-4bf7-4ae8-a24d-4fc09e707dd6">
<wsse:Username>XXXXXXXXX</wsse:Username>
<wsse:Password Type="http://docs.oasis-open.org/wss/2004/01/oasis-200401-wss-username-token-profile-1.0#PasswordDigest">XXXXXXXXX</wsse:Password>
<wsse:Nonce EncodingType="http://docs.oasis-open.org/wss/2004/01/oasis-200401-wss-soap-message-security-1.0#Base64Binary">X21BCn+NQzufUwa4LPr+wQ==</wsse:Nonce>
<wsu:Created>2022-08-15T13:55:24.000Z</wsu:Created>
</wsse:UsernameToken>
</wsse:Security>
</soap:Header>
<soap:Body>
<b:Subscribe>
<b:ConsumerReference>
<add:Address>http://192.168.100.6:8123/api/webhook/84118dfcafa7b202eaaeba6c5dc8b5b19a2b65d3ba6a5f1d1157a4e234122e91</add:Address>
</b:ConsumerReference>
<b:InitialTerminationTime>PT15M</b:InitialTerminationTime>
</b:Subscribe>
</soap:Body>
</soap:Envelope>
2022-08-15 15:55:24.119 DEBUG (MainThread) [reolink.subscription_manager] Host 192.168.110.122: Connection error Cannot connect to host 192.168.110.122:8000 ssl:default [Connect call failed ('192.168.110.122', 8000)]
2022-08-15 15:55:24.120 ERROR (MainThread) [custom_components.reolink_dev.base] Host 192.168.110.122 error renewing the Reolink subscription
2022-08-15 15:55:24.125 DEBUG (MainThread) [reolink.subscription_manager] Reolink host 192.168.110.122 (Subscription) request data:
<soap:Envelope xmlns:add="http://www.w3.org/2005/08/addressing" xmlns:b="http://docs.oasis-open.org/wsn/b-2" xmlns:soap="http://www.w3.org/2003/05/soap-envelope">
<soap:Header><wsse:Security soap:mustUnderstand="true" xmlns:wsse="http://docs.oasis-open.org/wss/2004/01/oasis-200401-wss-wssecurity-secext-1.0.xsd"
xmlns:wsu="http://docs.oasis-open.org/wss/2004/01/oasis-200401-wss-wssecurity-utility-1.0.xsd">
<wsse:UsernameToken wsu:Id="UsernameToken-c7d3f96f-9919-44b3-9a9c-a026fe7f6a0f">
<wsse:Username>XXXXXXXXX</wsse:Username>
<wsse:Password Type="http://docs.oasis-open.org/wss/2004/01/oasis-200401-wss-username-token-profile-1.0#PasswordDigest">XXXXXXXXX</wsse:Password>
<wsse:Nonce EncodingType="http://docs.oasis-open.org/wss/2004/01/oasis-200401-wss-soap-message-security-1.0#Base64Binary">/Jiu5g5UQCCNabTVLzTKwg==</wsse:Nonce>
<wsu:Created>2022-08-15T13:55:24.000Z</wsu:Created>
</wsse:UsernameToken>
</wsse:Security>
</soap:Header>
<soap:Body>
<b:Subscribe>
<b:ConsumerReference>
<add:Address>http://192.168.100.6:8123/api/webhook/4ac8c0a4c42b2841ff18f2cd9eb77344463a90dfc62ea073fc060174a64229e5</add:Address>
</b:ConsumerReference>
<b:InitialTerminationTime>PT15M</b:InitialTerminationTime>
</b:Subscribe>
</soap:Body>
</soap:Envelope>
2022-08-15 15:55:24.131 DEBUG (MainThread) [reolink.subscription_manager] Host 192.168.110.124: Connection error Cannot connect to host 192.168.110.124:8000 ssl:default [Connect call failed ('192.168.110.124', 8000)]
2022-08-15 15:55:24.160 DEBUG (MainThread) [reolink.subscription_manager] Host 192.168.110.122: Connection error Cannot connect to host 192.168.110.122:8000 ssl:default [Connect call failed ('192.168.110.122', 8000)]

Happy to provide additional debug info if needed.

rainbowbreeze avatar Aug 15 '22 14:08 rainbowbreeze

I also saw there is a very long standing ussue similar to mine, with issue #110 , but in that issue people have a mix of NVR and direct connected cameras. In my case, I've no NVR at all.

rainbowbreeze avatar Aug 15 '22 14:08 rainbowbreeze

I see you are using firmware v3.1.0.956 for the cameras. Just to check and you probably already checked it yourself but do you have the ports open for ONVIF for all cameras?

I also have the error Host 192.168.110.122 error renewing the Reolink subscription with firmware v3.1.0.956. I downgraded the firmware on the camera but it something you don't really want. Any help from others is appreciated with the error "renewing the Reolink subscription". I thought the error message could have something to do with the SSL certificate but i could be totally wrong here.

GewoonRoy avatar Aug 16 '22 05:08 GewoonRoy

hello, same problem here, i have a nvr410 and 4 cameras, i read several post and decide to uninstall/install again without https and ssl certificat as it is mention in the doc, no change, still the same error and seems my motions sensor in ha doesnt work anymore.

No response from the dev? @fwestenberg is there something we can do for you to solve this please? which logs do you need? thanks

EDIT : sorry...my bad...i have not activate "ONVIF" after update of the NVR...it works now EDIT2 : crash again, no more motion sensor working

EDIT3 : integrate my cameras with https enable and port 443, work like a charm without errors...................

LAST EDIT : after 4 hours...no more sensors working...

EDIT 19/08/2022 : it seems that rename the motion sensors entities in HA (i have 6 camera now on the NVR) cause problems. I rename them in the NVR and redo HACS AddOn and Integration in HA and it works. NVR Just disconnect every 3-5 hours or reboot i dont know, cant see anything in the NVR logs or in HA, just motions sensors "unavailable" for 2 minutes, and 2 minutes is the time to reboot the NVR...perhaps i am wrong.

Electronlibre2012 avatar Aug 16 '22 06:08 Electronlibre2012

Hello,

last update of NVR 410 as a new https option :

image

is someone know if it will be helpfull to put the homeassistant certificate?

Electronlibre2012 avatar Aug 17 '22 14:08 Electronlibre2012

I've been seeing this behavior for a long time as well, I've noticed it happens every hour, probably some token expiration from the camera side?

obrazek 2022-08-17 16:35:28.051 WARNING (MainThread) [reolink.subscription_manager] Subscription process ended with wrong HTTP status: 400: Bad Request 2022-08-17 16:35:28.106 WARNING (MainThread) [reolink.subscription_manager] Subscription process ended with wrong HTTP status: 400: Bad Request 2022-08-17 16:35:28.114 ERROR (MainThread) [custom_components.reolink_dev.base] Host 10.75.7.120 error renewing the Reolink subscription 2022-08-17 17:00:41.044 WARNING (MainThread) [reolink.subscription_manager] Subscription process ended with wrong HTTP status: 400: Bad Request 2022-08-17 17:00:41.119 WARNING (MainThread) [reolink.subscription_manager] Subscription process ended with wrong HTTP status: 400: Bad Request 2022-08-17 17:00:41.126 ERROR (MainThread) [custom_components.reolink_dev.base] Host 10.75.7.120 error renewing the Reolink subscription 2022-08-17 17:25:58.058 WARNING (MainThread) [reolink.subscription_manager] Subscription process ended with wrong HTTP status: 400: Bad Request 2022-08-17 17:25:58.111 WARNING (MainThread) [reolink.subscription_manager] Subscription process ended with wrong HTTP status: 400: Bad Request 2022-08-17 17:25:58.118 ERROR (MainThread) [custom_components.reolink_dev.base] Host 10.75.7.120 error renewing the Reolink subscription 2022-08-17 17:36:03.131 ERROR (MainThread) [custom_components.reolink_dev] Unexpected error fetching reolink.Prijezd data: Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 205, in _async_refresh self.data = await self._async_update_data() File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 164, in _async_update_data return await self.update_method() File "/config/custom_components/reolink_dev/__init__.py", line 98, in async_update_data await base.update_states() File "/config/custom_components/reolink_dev/base.py", line 256, in update_states await self._api.get_states() File "/usr/local/lib/python3.10/site-packages/reolink/camera_api.py", line 460, in get_states response = await self.send(body) File "/usr/local/lib/python3.10/site-packages/reolink/camera_api.py", line 1721, in send raise CredentialsInvalidError() reolink.exceptions.CredentialsInvalidError

leroyloren avatar Aug 17 '22 16:08 leroyloren

I've been seeing this behavior for a long time as well, I've noticed it happens every hour, probably some token expiration from the camera side?

obrazek

`2022-08-17 16:35:28.051 WARNING (MainThread) [reolink.subscription_manager] Subscription process ended with wrong HTTP status: 400: Bad Request

2022-08-17 16:35:28.106 WARNING (MainThread) [reolink.subscription_manager] Subscription process ended with wrong HTTP status: 400: Bad Request

2022-08-17 16:35:28.114 ERROR (MainThread) [custom_components.reolink_dev.base] Host 10.75.7.120 error renewing the Reolink subscription

2022-08-17 17:00:41.044 WARNING (MainThread) [reolink.subscription_manager] Subscription process ended with wrong HTTP status: 400: Bad Request

2022-08-17 17:00:41.119 WARNING (MainThread) [reolink.subscription_manager] Subscription process ended with wrong HTTP status: 400: Bad Request

2022-08-17 17:00:41.126 ERROR (MainThread) [custom_components.reolink_dev.base] Host 10.75.7.120 error renewing the Reolink subscription

2022-08-17 17:25:58.058 WARNING (MainThread) [reolink.subscription_manager] Subscription process ended with wrong HTTP status: 400: Bad Request

2022-08-17 17:25:58.111 WARNING (MainThread) [reolink.subscription_manager] Subscription process ended with wrong HTTP status: 400: Bad Request

2022-08-17 17:25:58.118 ERROR (MainThread) [custom_components.reolink_dev.base] Host 10.75.7.120 error renewing the Reolink subscription

2022-08-17 17:36:03.131 ERROR (MainThread) [custom_components.reolink_dev] Unexpected error fetching reolink.Prijezd data:

Traceback (most recent call last):

File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 205, in _async_refresh

self.data = await self._async_update_data()

File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 164, in _async_update_data

return await self.update_method()

File "/config/custom_components/reolink_dev/init.py", line 98, in async_update_data

await base.update_states()

File "/config/custom_components/reolink_dev/base.py", line 256, in update_states

await self._api.get_states()

File "/usr/local/lib/python3.10/site-packages/reolink/camera_api.py", line 460, in get_states

response = await self.send(body)

File "/usr/local/lib/python3.10/site-packages/reolink/camera_api.py", line 1721, in send

raise CredentialsInvalidError()

reolink.exceptions.CredentialsInvalidError`

I have the same problem. Every hour, the camera is temporarily unavailable. I have noticed this problem since version 2022.8. I've been using a Reolink camera for about half a year without a problem. I have model RLC-511, firmware v3.0.0.142_20121803.

radimnemecek avatar Aug 18 '22 09:08 radimnemecek

@radaoggy hello, have you got a NVR or only cameras?

i have finally understand what happened to me : the NVR stop recording randomly ten or more a day, each time almost 2 minutes, so it means that there is a bug in the NVR or he is faulty...i have contacted the reolink support...wait and see, i give us the logs of the NVR...

Home Assistant is not the problem and reolink-dev either not! that the NVR...or a bug in the NVR software...i will come back here to give feedback

Electronlibre2012 avatar Aug 19 '22 14:08 Electronlibre2012

Hi, I have only camera.

radimnemecek avatar Aug 20 '22 07:08 radimnemecek

Hi, I have only camera.

thanks,

and for how long please?

for me it s exactly dead for 1 minute and exactly every 2 hours...too precise...its a token expiration like you said above...so strange its so precise and cyclic

sometimes it works for 4 hours without dead video or sensor but never more than 4 hours.

Sure its not related to HA and Reolink-dev, its a problem with cameras. I have 6 D520 and you, which model please? ok you notice that above RLC-511, firmware v3.0.0.142_20121803

Electronlibre2012 avatar Aug 23 '22 14:08 Electronlibre2012

Same issue, with RLN8-410 NVR and four RLC-822A cameras (all four connected through this NVR). It constantly loses sensors to "Unavailable" state, and then back to "Clear" again, then all good for some time, getting "Detected" notifications, then "Unavailable" again and the cycle repeats... Without any precise timing-pattern in my case - sometimes every minute, sometimes half an hour... Using direct local IP address for HA, so DNS can't be a cause here.

Just installed the latest Reolink firmware to all cameras (v3.1.0.956_22041507 from May 20th 2022) and to NVR (v3.0.0.200_22081500 from August 17th 2022). No difference, still the same issue... Loses a lot of movement-events because of this, while direct Android push-notifications from the NVR itself to Reolink Android App come without losing any movement-events. So I still can not rely on notifications from Home Assistant in any important use-cases... but really would like to switch to HA for that...

Please feel free to let me know if you like me to test something specific on my end. I'll do my best to help you debug this...

JimStar avatar Aug 29 '22 01:08 JimStar

Hello @JimStar ,

if you look at Reolink App , Android or PC, have you grey parts in timeline ? grey parts are no recording time so no sensors too... I think the problem is not in HA or in reolinkDev , the problem is the NVR stop recording and loose sensor, it takes 1mn for me every 2 or 3 hours, its time the NVR takes to reboot...

I have contacted Reolink support but they gived so many possibilities for resolves the problem, like HDD, the network, ect....

wait for your informations,

have a nice day

Electronlibre2012 avatar Aug 29 '22 03:08 Electronlibre2012

Nope, no grey parts on the timeline, neither in Android nor in PC app (see the screenshot). And I have 24/7 recording enabled for all four cameras, so they record to the disk all the time no matter if there is movement detected or not.

BTW, maybe the precise time-periods you get could be somehow related to the "part size" setting of the Reolink NVR, which I suppose is a length of each file it creates when records non-stop (you can see these "chunks" above the timeline on my screenshot for example)... In this case the NVR should somehow seamlessly save a current chunk and start a new one... Maybe some interruption happens in that moment... But if that is the case - I would expect it would affect the push-notifications to Android too, but it sill never loses any movement-events in its Android App, it only happens in Home Assistant for me...

Screenshot_20220829-151416_Reolink

JimStar avatar Aug 29 '22 03:08 JimStar

The log is full of errors from reolink_dev.

Screen Shot 2022-08-29 at 17 45 36

This is the top-most one of this list for example, Python traceback. Let me know if you'd need logs in a text-form...

Screen Shot 2022-08-29 at 17 48 49

JimStar avatar Aug 29 '22 05:08 JimStar

... and the log is just full of those:

Screen Shot 2022-08-29 at 17 59 09

JimStar avatar Aug 29 '22 05:08 JimStar

...and more...

Screen Shot 2022-08-29 at 18 02 11

JimStar avatar Aug 29 '22 06:08 JimStar

I'm not sure so far (just a first quick look at this), but the tracebacks look like some Python errors on reolink_dev side, not on the NVR side...

JimStar avatar Aug 29 '22 06:08 JimStar

I see a lot of those:

Screen Shot 2022-08-29 at 18 17 31

Looks like some empty or broken Json response is returned by Reolink NVR to the calling Reolink-Python code. And the Reolink code just blindly passes this broken response to json.loads(response) which in turn stumbles on this Json... At least those are my first thoughts after quick look at this Reolink's get_all_motion_states() Python-API code:

Screen Shot 2022-08-29 at 19 03 23

JimStar avatar Aug 29 '22 07:08 JimStar

Another thought: I see that in the previous logs I posted here, the period of reolink_dev flooding the Reolink NVR with requests is like 40 milliseconds, at least this is the time-period I see between the warning-records of some "empty results"... Could it be that the NVR just gets over-flooded by network-requests (taking into account it needs to do a lot of other job besides answering to API requests), and just gives up with some responses or just sends back some broken responses sometimes... Just a quick assumption...

JimStar avatar Aug 29 '22 07:08 JimStar

It looks like in the Reolink-API's separate get_motion_state() call it is done properly in contrast to get_all_motion_states(): it first checks if the response is empty before passing it to json.loads(response). So in this case it would not fail with traceback in the logs. But this still could not be the main reason, maybe there are some more factors affecting these sensor losses (like possible over-flooding mentioned above)...

Screen Shot 2022-08-29 at 20 00 20

PS. Sorry for this shitload of a brainstorm in the ticket, but I'm really dedicated to get this finally fixed. ;)

JimStar avatar Aug 29 '22 08:08 JimStar

...and I see there is no proper exit with return value in the get_all_motion_states() and no call to clear_token() in the exception case... Could possibly the lack of clear_token() be the problem with motion-callbacks getting lost sometimes?.. Just a thought... So just to check it out I've changed the get_all_motion_states() to be similar to get_motion_state() with all the checks... Will see how it goes with this...

Screen Shot 2022-08-29 at 21 04 07

JimStar avatar Aug 29 '22 08:08 JimStar

Looks like my patch fixed this issue, at least partially. I don't see a shitload of errors and warnings every 40ms in the log anymore - at least for the 10 minutes I had before I left home to my work-office, and I did not see any "Unavailable" states of sensors anymore. And the log is clean of all the previous ton of messages from reolink_dev, so this patch definitely fixed at least these errors logged... There are still few errors logged by reolink_dev during start-up, and I will investigate them further after I'm back home. But so far I've already created a pull-request to the reolink Python package this reolink_dev depends on (you can see it mentioned by GitHub above).

The log is much cleaner now, at least for the 10 minutes I had in the morning to watch it... :) Cameras report movements properly and without any losses, I checked it several times walking in front of them... This is the full content of all the Home Assistant log, just a few lines with errors from reolink_dev during start-up and nothing else:

Screen Shot 2022-08-30 at 05 39 00

JimStar avatar Aug 29 '22 19:08 JimStar

Wahoo! thats a brainstorming!

Dont be sorry, you are the first one who search and found something interesting...well done!

Where is this file please? im under HassOS dont sure i can modify...

Electronlibre2012 avatar Aug 30 '22 03:08 Electronlibre2012

It is /usr/local/share/homeassistant/lib/python3.10/site-packages/reolink/camera_api.py (I run HA as a TrueNAS jail-plugin) but I think should be similar in HassOS too.

But if you patch this file in-place - don't forget to remove all the __pycache__ directories both under /usr/local/share/homeassistant/lib/python3.10/site-packages/reolink and <HA config dir>/custom_components/reolink_dev recursively, and then restart the Home Assistant. Otherwise either it'll not see your changes, or the component would not start properly.

JimStar avatar Aug 30 '22 03:08 JimStar

I will be able to have a look at the full-day logs of running HA with this patch only in about 3 hours - just finishing my workday soon and preparing to go long way home (I'm in NZ, so it's a middle of a day here). So I will let here know later today if the logs got same warnings/errors again from reolink_dev... or if the sensors experienced "Unavailable" state again during the day... But there was definitely a clear effect of my patch already seen in the morning in just 10 minutes of running the HA - because usually I got a shitload of warnings/errors in the logs from reolink_dev in 10 minutes... but after a patch it was just a few during start-up and then quiet... and all cameras' motion-detection working in HA without losses...

JimStar avatar Aug 30 '22 03:08 JimStar

thanks @JimStar

today i notice that i have only 4 grey period yesterday in my time line...i do nothing for that... : first 6 hours, 2nd 4 hours, 3d after 5 hours, seems its no more periodicaly now...perhaps i will try to change the HDD...i reduce the the pack duration to 30mn to see if something changes...

I notice also that there is a lot of user for HA (192.168.1.50 is my HassOs Nuc) : image dont understand why there is a lot of same admin and IP, its an history log?

Electronlibre2012 avatar Aug 30 '22 03:08 Electronlibre2012

OK, there is not even one "error renewing the Reolink subscription" record anymore in the whole log of the day. And my wife told me the whole day all the cameras notified her about all the people and vehicles around the house. I'm not sure though if she didn't notice some detection losses or there wasn't any...

But there is still a bunch of cryptic "Failed to get results for Search, JSON data was was empty?" records in the log. Plus I still see few "Unavailable" states of the sensors popping up during the day. So I will be investigating other issues further... I want this to be completely stable, so that I could trust those sensors...

JimStar avatar Aug 30 '22 05:08 JimStar

Yea, I can see that this "Failed to get results..." message is thrown by the send_search() function that really sends a network request to the NVR! And the fact that I see them with time period of 40 milliseconds! between them in the log means this code just spams the NVR device by a ton of network requests... making it some kind of a "deny of service" attack for the NVR... taking into account the NVR should still do a job of managing all the detections from cameras, collect and write all the streams into disk files, etc... Maybe this could be a reason NVR sometimes does not respond properly and the sensors become "Unavailable"... I will be checking this assumption now...

JimStar avatar Aug 30 '22 05:08 JimStar

Just FYI, this behavior happens even without NVR, I have an 810A with the latest firmware.

leroyloren avatar Aug 30 '22 07:08 leroyloren

I have published 0.56 just now. For your information my cameras are crashing all day long since firmware 3.1+ so I am not sure to what extent these changes will really fix the issues.

cpainchaud avatar Aug 31 '22 07:08 cpainchaud

Thank you, @cpainchaud! No, this pull-request will definitely not fix the main issue, it just makes a log a little cleaner. ;)

I think I've just found some glue to what's happening... debugging it now... Will need some time to investigate this, I only have 1-2 hours in evenings for that... In short: two issues. One very simple (SOAP issue), one more complex (same reason as a reason of mess with camera/NVR names when there are more than one camera). But looks like both fixable on the reolink_dev side, at least I was just a couple of minutes ago able to get a completely stable subscription after some temporary changes in the code... Will be back with a pull-request as soon as I'm done with it (if all turns out to be doable of course). ;)

JimStar avatar Aug 31 '22 08:08 JimStar