search

home-assistant / core

:house_with_garden: Open source home automation that puts local control and privacy first.
https://www.home-assistant.io
Apache License 2.0
72.1k stars 30.18k forks source link

Onvif: Task exception was never retrieved #111084

Closed mesonium closed 3 months ago

mesonium commented 7 months ago

The problem

Log is spammed by

DEBUG (MainThread) [onvif] $IP: Renew the notification manager
DEBUG (MainThread) [onvif] $IP: Failed to renew notify subscription  (code:SOAP-ENV:Sender) (subcodes:{http://www.onvif.org/ver10/error}InvalidArgs)
DEBUG (MainThread) [onvif] $IP: Setup the PullPoint manager
DEBUG (MainThread) [homeassistant.components.onvif] AXIS M2036-LE: Pulling PullPoint messages timeout=0:01:00 limit=100
DEBUG (MainThread) [homeassistant.components.onvif] AXIS M2036-LE: Failed to fetch PullPoint subscription messages:  (code:SOAP-ENV:Sender) (subcodes:{http://www.onvif.org/ver10/error}InvalidArgs)
ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/onvif/managers.py", line 189, in _renew_or_restart_subscription
    await self._renew_subscription() or await self._restart_subscription()
                                        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/onvif/managers.py", line 154, in _restart_subscription
    return await self._start()
           ^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/onvif/managers.py", line 298, in _start
    result = await events_service.CreatePullPointSubscription(
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/zeep/proxy.py", line 64, in __call__
    return await self._proxy._binding.send_async(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/zeep/wsdl/bindings/soap.py", line 164, in send_async
    return self.process_reply(client, operation_obj, response)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/zeep/wsdl/bindings/soap.py", line 229, in process_reply
    return self.process_error(doc, operation)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/zeep/wsdl/bindings/soap.py", line 391, in process_error
    raise Fault(
zeep.exceptions.Fault

What version of Home Assistant Core has the issue?

core-2024.2.2

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant Container

Integration causing the issue

Onvif

Link to integration documentation on our website

https://www.home-assistant.io/integrations/onvif/

Diagnostics information

config_entry-onvif-273d8b117209a036a07950f0d3a21cff.json

Example YAML snippet

No response

Anything in the logs that might be useful for us?

No response

Additional information

No response

home-assistant[bot] commented 7 months ago

Hey there @hunterjm, mind taking a look at this issue as it has been labeled with an integration (onvif) you are listed as a code owner for? Thanks!

Code owner commands Code owners of `onvif` can trigger bot actions by commenting: - `@home-assistant close` Closes the issue. - `@home-assistant rename Awesome new title` Renames the issue. - `@home-assistant reopen` Reopen the issue. - `@home-assistant unassign onvif` Removes the current integration label and assignees on the issue, add the integration domain after the command. - `@home-assistant add-label needs-more-information` Add a label (needs-more-information, problem in dependency, problem in custom component) to the issue. - `@home-assistant remove-label needs-more-information` Remove a label (needs-more-information, problem in dependency, problem in custom component) on the issue.

(message by CodeOwnersMention)

onvif documentation onvif source (message by IssueLinks)

mesonium commented 7 months ago

Further logs

14:42:16.168 INFO (MainThread) [homeassistant.setup] Setting up onvif
14:42:16.171 INFO (MainThread) [homeassistant.setup] Setup of domain onvif took 0.0 seconds
14:42:16.199 DEBUG (MainThread) [onvif] Creating service ('devicemgmt', None) with http://$IP:80/onvif/device_service
14:42:16.891 DEBUG (MainThread) [homeassistant.components.onvif] AXIS M2036-LE: xaddrs = {'http://www.onvif.org/ver20/analytics/wsdl': 'http://$IP/onvif/services', 'http://www.onvif.org/ver10/events/wsdl': 'http://$IP/onvif/services', 'http://www.onvif.org/ver20/imaging/wsdl': 'http://$IP/onvif/services', 'http://www.onvif.org/ver10/media/wsdl': 'http://$IP/onvif/services'}
14:42:16.891 DEBUG (MainThread) [homeassistant.components.onvif] AXIS M2036-LE: Setting up the ONVIF device management service
14:42:16.891 DEBUG (MainThread) [homeassistant.components.onvif] AXIS M2036-LE: Retrieving current device date/time
14:42:16.933 DEBUG (MainThread) [homeassistant.components.onvif] AXIS M2036-LE: Device time: {
    'DateTimeType': 'NTP',
    'DaylightSavings': True,
    'TimeZone': {
        'TZ': '<-05>5'
    },
    'UTCDateTime': {
        'Time': {
            'Hour': 14,
            'Minute': 42,
            'Second': 16
        },
        'Date': {
            'Year': 2024,
            'Month': 2,
            'Day': 21
        }
    },
    'LocalDateTime': {
        'Time': {
            'Hour': 9,
            'Minute': 42,
            'Second': 16
        },
        'Date': {
            'Year': 2024,
            'Month': 2,
            'Day': 21
        }
    },
    'Extension': None,
    '_attr_1': None
}
14:42:16.935 DEBUG (MainThread) [homeassistant.components.onvif] AXIS M2036-LE: Device date/time: 14:42:16+00:00 | System date/time: 14:42:16.891621+00:00
14:42:17.157 DEBUG (MainThread) [homeassistant.components.onvif] AXIS M2036-LE: camera info = DeviceInfo(manufacturer='AXIS', model='M2036-LE', fw_version='11.8.61', serial_number='<snip>', mac='<snip>')
14:42:17.157 DEBUG (MainThread) [homeassistant.components.onvif] AXIS M2036-LE: fetching initial capabilities
14:42:17.159 DEBUG (MainThread) [onvif] Creating service ('media', None) with http://$IP/onvif/services
14:42:17.578 DEBUG (MainThread) [onvif] Creating service ('imaging', None) with http://$IP/onvif/services
14:42:18.310 DEBUG (MainThread) [homeassistant.components.onvif] AXIS M2036-LE: fetching profiles
14:42:18.310 DEBUG (MainThread) [homeassistant.components.onvif] AXIS M2036-LE: xaddr for media_service: http://$IP/onvif/services
14:42:18.348 DEBUG (MainThread) [homeassistant.components.onvif] Camera AXIS M2036-LE profiles = [Profile(index=0, token='profile_1_h264', name='profile_1 h264', video=Video(encoding='H264', resolution=Resolution(width=2688, height=1512)), ptz=None, video_source_token='0')]
14:42:18.349 DEBUG (MainThread) [homeassistant.components.onvif] AXIS M2036-LE: starting events
14:42:18.349 DEBUG (MainThread) [homeassistant.components.onvif] AXIS M2036-LE: WSPullPointSupport: True
14:42:18.349 DEBUG (MainThread) [homeassistant.components.onvif] AXIS M2036-LE: Starting PullPoint manager
14:42:18.349 DEBUG (MainThread) [onvif] $IP: Setup the PullPoint manager
14:42:18.350 DEBUG (MainThread) [onvif] Creating service ('events', None) with http://$IP/onvif/services
14:42:18.710 DEBUG (MainThread) [onvif] Creating service ('subscription', 'PullPointSubscription') with http://$IP/onvif/services
14:42:18.711 DEBUG (MainThread) [onvif] Creating service ('pullpoint', 'PullPointSubscription') with http://$IP/onvif/services
14:42:18.712 DEBUG (MainThread) [onvif] $IP: Checking for broken relative timestamps: expected_interval: 0:10:00, current_time: 14:42:18+00:00, termination_time: 14:52:18+00:00
14:42:18.713 DEBUG (MainThread) [onvif] $IP: Relative timestamps OK: expected interval: 0:10:00, actual interval: 0:10:00
14:42:18.713 DEBUG (MainThread) [onvif] $IP: Renew notification subscription in 480.0 seconds
14:42:18.713 DEBUG (MainThread) [onvif] $IP: Start the notification manager
14:42:18.735 DEBUG (MainThread) [onvif] /usr/local/lib/python3.12/site-packages/onvif/wsdl/events.wsdl: SetSynchronizationPoint failed
14:42:18.735 DEBUG (MainThread) [homeassistant.components.onvif] AXIS M2036-LE: Starting webhook manager
14:42:18.736 DEBUG (MainThread) [homeassistant.components.onvif] AXIS M2036-LE: Registering webhook: onvif<snip>
14:42:18.736 DEBUG (MainThread) [homeassistant.components.onvif] AXIS M2036-LE: Unregistering webhook onvif<snip>
14:42:18.737 DEBUG (MainThread) [homeassistant.components.onvif] AXIS M2036-LE: Registered webhook: onvif<snip>
14:42:18.737 DEBUG (MainThread) [homeassistant.components.onvif] AXIS M2036-LE: Creating webhook subscription with URL: http://10.0.2.100:8123/api/webhook/onvif<snip>
14:42:18.737 DEBUG (MainThread) [onvif] $IP: Setup the notification manager
14:42:18.738 DEBUG (MainThread) [onvif] Creating service ('notification', None) with http://$IP/onvif/services
14:42:18.768 DEBUG (MainThread) [onvif] Creating service ('pullpoint', 'NotificationConsumer') with http://$IP/onvif/services
14:42:18.771 DEBUG (MainThread) [onvif] Creating service ('subscription', 'NotificationConsumer') with http://$IP/onvif/services
14:42:18.772 DEBUG (MainThread) [onvif] $IP: Checking for broken relative timestamps: expected_interval: 0:10:00, current_time: 14:42:18+00:00, termination_time: 14:52:18+00:00
14:42:18.773 DEBUG (MainThread) [onvif] $IP: Relative timestamps OK: expected interval: 0:10:00, actual interval: 0:10:00
14:42:18.773 DEBUG (MainThread) [onvif] $IP: Renew notification subscription in 480.0 seconds
14:42:18.773 DEBUG (MainThread) [onvif] $IP: Start the notification manager
14:42:18.803 DEBUG (MainThread) [onvif] /usr/local/lib/python3.12/site-packages/onvif/wsdl/events.wsdl: SetSynchronizationPoint failed
14:42:18.803 DEBUG (MainThread) [homeassistant.components.onvif] AXIS M2036-LE: Webhook subscription created with URL: http://10.0.2.100:8123/api/webhook/onvif<snip>
14:42:18.803 DEBUG (MainThread) [homeassistant.components.onvif] Camera AXIS M2036-LE capabilities = Capabilities(snapshot=True, events=True, ptz=False, imaging=True)
14:42:19.487 DEBUG (MainThread) [homeassistant.components.onvif] AXIS M2036-LE: Pulling PullPoint messages timeout=0:01:00 limit=100
14:42:19.516 DEBUG (MainThread) [homeassistant.components.onvif] AXIS M2036-LE: Failed to fetch PullPoint subscription messages:  (code:SOAP-ENV:Sender) (subcodes:{http://www.onvif.org/ver10/error}InvalidArgs)
14:42:19.518 DEBUG (MainThread) [onvif] $IP: Renew the notification manager
14:42:19.542 DEBUG (MainThread) [onvif] $IP: Failed to renew notify subscription  (code:SOAP-ENV:Sender) (subcodes:{http://www.onvif.org/ver10/error}InvalidArgs)
14:42:19.543 DEBUG (MainThread) [onvif] $IP: Setup the PullPoint manager
14:42:19.567 DEBUG (MainThread) [onvif] $IP: Checking for broken relative timestamps: expected_interval: 0:10:00, current_time: 14:42:19+00:00, termination_time: 14:52:19+00:00
14:42:19.567 DEBUG (MainThread) [onvif] $IP: Relative timestamps OK: expected interval: 0:10:00, actual interval: 0:10:00
14:42:19.568 DEBUG (MainThread) [onvif] $IP: Renew notification subscription in 480.0 seconds
14:42:19.568 DEBUG (MainThread) [onvif] $IP: Start the notification manager
14:42:19.703 INFO (MainThread) [homeassistant.components.button] Setting up onvif.button
14:42:19.704 INFO (MainThread) [homeassistant.components.camera] Setting up onvif.camera
14:42:19.704 INFO (MainThread) [homeassistant.components.binary_sensor] Setting up onvif.binary_sensor
14:42:19.732 INFO (MainThread) [homeassistant.components.sensor] Setting up onvif.sensor
14:42:19.743 INFO (MainThread) [homeassistant.components.switch] Setting up onvif.switch
14:42:20.267 DEBUG (MainThread) [homeassistant.components.onvif] AXIS M2036-LE: Pulling PullPoint messages timeout=0:01:00 limit=100
14:42:20.292 DEBUG (MainThread) [homeassistant.components.onvif] AXIS M2036-LE: Failed to fetch PullPoint subscription messages:  (code:SOAP-ENV:Sender) (subcodes:{http://www.onvif.org/ver10/error}InvalidArgs)
14:42:20.293 DEBUG (MainThread) [onvif] $IP: Renew the notification manager
14:42:20.315 DEBUG (MainThread) [onvif] $IP: Failed to renew notify subscription  (code:SOAP-ENV:Sender) (subcodes:{http://www.onvif.org/ver10/error}InvalidArgs)
14:42:20.315 DEBUG (MainThread) [onvif] $IP: Setup the PullPoint manager
14:42:20.335 DEBUG (MainThread) [onvif] $IP: Checking for broken relative timestamps: expected_interval: 0:10:00, current_time: 14:42:20+00:00, termination_time: 14:52:20+00:00
14:42:20.336 DEBUG (MainThread) [onvif] $IP: Relative timestamps OK: expected interval: 0:10:00, actual interval: 0:10:00
14:42:20.336 DEBUG (MainThread) [onvif] $IP: Renew notification subscription in 480.0 seconds
14:42:20.336 DEBUG (MainThread) [onvif] $IP: Start the notification manager
14:42:21.044 DEBUG (MainThread) [homeassistant.components.onvif] AXIS M2036-LE: Pulling PullPoint messages timeout=0:01:00 limit=100
14:42:21.068 DEBUG (MainThread) [homeassistant.components.onvif] AXIS M2036-LE: Failed to fetch PullPoint subscription messages:  (code:SOAP-ENV:Sender) (subcodes:{http://www.onvif.org/ver10/error}InvalidArgs)
The-H23 commented 6 months ago

The same issue on a fresh 2024.3.0 install. I get this error msg roughly every 5sec. Cameras are AXIS P3717-PLE and P3727-PLE.

Because of this I think there is something wrong with the authorization. I didn't touch the camera settings for years. Neither did I update the firmware or something.

DEBUG (MainThread) [onvif] cam-treppe.local.lan: Failed to renew notify subscription Sender not authorized: <Element {http://www.w3.org/2003/05/soap-envelope}Detail at 0x7f392f0e80> (code:SOAP-ENV:Sender) (subcodes:{http://www.onvif.org/ver10/error}NotAuthorized)

2024-03-13 09:13:39.595 DEBUG (MainThread) [homeassistant.components.onvif] cam-treppe: Failed to fetch PullPoint subscription messages: (code:SOAP-ENV:Sender) (subcodes:{http://www.onvif.org/ver10/error}InvalidArgs) 2024-03-13 09:13:39.595 ERROR (MainThread) [homeassistant] Error doing job: Task exception was never retrieved Traceback (most recent call last): File "/usr/local/lib/python3.12/site-packages/onvif/managers.py", line 189, in _renew_or_restart_subscription await self._renew_subscription() or await self._restart_subscription() ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/onvif/managers.py", line 154, in _restart_subscription return await self._start() ^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/onvif/managers.py", line 298, in _start result = await events_service.CreatePullPointSubscription( ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/zeep/proxy.py", line 64, in call return await self._proxy._binding.send_async( ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/zeep/wsdl/bindings/soap.py", line 164, in send_async return self.process_reply(client, operation_obj, response) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/zeep/wsdl/bindings/soap.py", line 229, in process_reply return self.process_error(doc, operation) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/zeep/wsdl/bindings/soap.py", line 391, in process_error raise Fault( zeep.exceptions.Fault 2024-03-13 09:13:39.603 DEBUG (MainThread) [onvif] cam-treppe.local.lan: Renew the notification manager 2024-03-13 09:13:39.606 DEBUG (MainThread) [zeep.transports] HTTP Post to http://192.168.30.202/onvif/services: b'<?xml version=\'1.0\' encoding=\'utf-8\'?>\nhttp://docs.oasis-open.org/wsn/bw-2/SubscriptionManager/RenewRequest</wsa:Action>urn:uuid:06c3440c-bbb5-4265-b9b1-989fc3d6d84b</wsa:MessageID>http://192.168.30.202/onvif/services</wsa:To>homeassistant</wsse:Username>62V/1e01zOL6jfBFaZmEVFYVjJs=</wsse:Password>wQGi8nUtbFrYP3IhOO2quA==</wsse:Nonce>2024-03-13T08:13:39+00:00</wsu:Created></wsse:UsernameToken></wsse:Security></soap-env:Header>PT600S</ns0:TerminationTime></ns0:Renew></soap-env:Body></soap-env:Envelope>' 2024-03-13 09:13:39.621 DEBUG (MainThread) [zeep.transports] HTTP Response from http://192.168.30.202/onvif/services (status: 400): b'<?xml version="1.0" encoding="UTF-8"?>\nurn:uuid:06c3440c-bbb5-4265-b9b1-989fc3d6d84b</wsa5:MessageID>http://192.168.30.202/onvif/services</wsa5:To>http://docs.oasis-open.org/wsn/bw-2/SubscriptionManager/RenewRequest</wsa5:Action></SOAP-ENV:Header>SOAP-ENV:Sender</SOAP-ENV:Value>ter:NotAuthorized</SOAP-ENV:Value></SOAP-ENV:Subcode></SOAP-ENV:Code>Sender not authorized</SOAP-ENV:Text></SOAP-ENV:Reason>The action requested requires authorization and the sender is not authorized</SOAP-ENV:Text></SOAP-ENV:Detail></SOAP-ENV:Fault></SOAP-ENV:Body></SOAP-ENV:Envelope>' 2024-03-13 09:13:39.623 DEBUG (MainThread) [onvif] cam-treppe.local.lan: Failed to renew notify subscription Sender not authorized: <Element {http://www.w3.org/2003/05/soap-envelope}Detail at 0x7f392f0e80> (code:SOAP-ENV:Sender) (subcodes:{http://www.onvif.org/ver10/error}NotAuthorized) 2024-03-13 09:13:39.624 DEBUG (MainThread) [onvif] cam-treppe.local.lan: Setup the PullPoint manager 2024-03-13 09:13:39.626 DEBUG (MainThread) [zeep.transports] HTTP Post to http://cam-treppe.local.lan/onvif/services: b'<?xml version=\'1.0\' encoding=\'utf-8\'?>\nhttp://www.onvif.org/ver10/events/wsdl/EventPortType/CreatePullPointSubscriptionRequest</wsa:Action>urn:uuid:5e0d2121-5984-4978-a40b-ea3af5a58dfc</wsa:MessageID>http://cam-treppe.local.lan/onvif/services</wsa:To>homeassistant</wsse:Username>FZ2w3riiHqtdHXDW0aIMavjEPN4=</wsse:Password>L/wvjWlP6bAkN8stOVPong==</wsse:Nonce>2024-03-13T08:13:39+00:00</wsu:Created></wsse:UsernameToken></wsse:Security></soap-env:Header>PT600S</ns0:InitialTerminationTime></ns0:CreatePullPointSubscription></soap-env:Body></soap-env:Envelope>' 2024-03-13 09:13:39.645 DEBUG (MainThread) [zeep.transports] HTTP Response from http://cam-treppe.local.lan/onvif/services (status: 500): b'<?xml version="1.0" encoding="UTF-8"?>\nhttp://www.w3.org/2005/08/addressing/anonymous</wsa5:To>http://www.w3.org/2005/08/addressing/soap/fault</wsa5:Action></SOAP-ENV:Header>SOAP-ENV:Receiver</SOAP-ENV:Value></SOAP-ENV:Code></SOAP-ENV:Reason>2024-03-13T08:13:39Z</wsrfbf:Timestamp></wsnt:SubscribeCreationFailedFault></SOAP-ENV:Detail></SOAP-ENV:Fault></SOAP-ENV:Body></SOAP-ENV:Envelope>'

The-H23 commented 6 months ago

Further information

I got curious since the OA also uses an AXIS camera like me. I made a test with an old HIKVISION DS-2CD2386G2-IU and there is no such problem! It's running for half an hour now without any trouble. No error messages and it's working.

So it seems to be an issue with some changes in the onvif integration regarding to AXIS cameras. As I said, I didn't touch the camera settings for years. Neither did I update the firmware or something. Auto update is off as well.

The-H23 commented 6 months ago

Further information

I promoted my homeassistant ONVIF user from role "media user" to "operator" and the errors are gone :+1:

Although it's working it seems not like a proper fix for security reasons. I'm no expert what bare minimum permissions are required for just receiving the media stream and nothing more, but operator feels to much. The integration is working just with "media user" permissions but spams the log file.

So the way to go is in improving the exception handling if media user perms are enough. If operator perms are really necessary please add a good message. Just a proposal of course. I'm not authorized to give instructions :)

issue-triage-workflows[bot] commented 3 months ago

There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates. Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment 👍 This issue has now been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.