Possible Solution for HTTP2 blocking operation

jleinenbach commented 6 days ago

Describe the bug

A blocking operation was detected in the http2_connect() function in the alexa_media integration. Specifically, the function load_verify_locations was being called inside the event loop, which caused performance issues and blocked other tasks.

To Reproduce

Integrate the Alexa Media Player into Home Assistant.
Reboot.
Watch for the warning message related to blocking calls in the logs.

Expected behavior

The http2_connect() function should complete without blocking the event loop, allowing the system to handle multiple tasks concurrently without performance issues.

System details

Home Assistant version: Core: 2024.9.1 Frontend: 20240906.0
alexa_media version: 4.12.12
alexapy version: 1.29.2
Is Amazon 2FA/2SV enabled (y/n): y
Amazon Domain: amazon.de

Debug Logs (alexa_media & alexapy)

Please refer to the following error message from the debug logs:

Detected blocking call to load_verify_locations with args (<ssl.SSLContext object at 0x7fcbde43ca50>,) inside the event loop by custom integration 'alexa_media' at custom_components/alexa_media/__init__.py, line 876: http2 = HTTP2EchoClient(
(offender: /usr/local/lib/python3.12/site-packages/httpx/_config.py, line 147: context.load_verify_locations(cafile=cafile))

Additional context

I was able to fix the issue by modifying the http2_connect() function to offload the SSL initialization to a separate thread using hass.async_add_executor_job. Here is the change that fixed the issue:

The Problem:

In Home Assistant, the Alexa Media integration was causing performance issues due to the SSL certificate loading (load_verify_locations) being called inside the event loop. This caused the event loop to block, slowing down the system.

The Solution:

I adjusted the code to ensure that the SSL certificate loading happens in a separate thread, outside the event loop, allowing the system to run smoothly.

Code Changes:

Offloaded the Blocking Operation: I added the following line to move the SSL initialization into a separate thread using hass.async_add_executor_job:

await hass.async_add_executor_job(
    login_obj.session.context.load_verify_locations, cafile=cafile
)

Retained the HTTP2 Client Creation: After offloading the SSL operation, the rest of the code for creating and running HTTP2EchoClient remains unchanged.

Here is the full function after the change:

async def http2_connect() -> Optional[HTTP2EchoClient]:
    """Open HTTP2 Push connection.

    This will only attempt one login before failing.
    """
    http2: Optional[HTTP2EchoClient] = None
    email = login_obj.email
    try:
        if login_obj.session.closed:
            _LOGGER.debug(
                "%s: HTTP2 creation aborted. Session is closed.",
                hide_email(email),
            )
            return
        # Offloading SSL initialization to a separate thread
        await hass.async_add_executor_job(
            login_obj.session.context.load_verify_locations, cafile=cafile
        )

        # Create HTTP2EchoClient
        http2 = HTTP2EchoClient(
            login_obj,
            msg_callback=http2_handler,
            open_callback=http2_open_handler,
            close_callback=http2_close_handler,
            error_callback=http2_error_handler,
            loop=hass.loop,
        )
        _LOGGER.debug("%s: HTTP2 created: %s", hide_email(email), http2)

        # Start HTTP2 connection
        await http2.async_run()

    except AlexapyLoginError as exception_:
        _LOGGER.debug(
            "%s: Login Error detected from http2: %s",
            hide_email(email),
            exception_,
        )
        hass.bus.async_fire(
            "alexa_media_relogin_required",
            event_data={"email": hide_email(email), "url": login_obj.url},
        )
        return
    except BaseException as exception_:  # pylint: disable=broad-except
        _LOGGER.debug(
            "%s: HTTP2 creation failed: %s", hide_email(email), exception_
        )
        return
    return http2

Since making this change, the warning is no longer appearing.

balubone commented 6 days ago

Hi jleinenbach, I got the same error message from the debug logs. But I'm a noob; can you explain me how to make this change?

Gajotres commented 6 days ago

Unfortunately the step 1 is still a no go for some of us, many non .com users (.de in my case) cannot go pass 2FA step during the integration process. Downgrade to the older AMP is also not working.

jleinenbach commented 6 days ago

Unfortunately the step 1 is still a no go for some of us, many non .com users (.de in my case) cannot go pass 2FA step during the integration process. Downgrade to the older AMP is also not working.

This is a different issue. I am a .de user and I can go pass the 2FA step. This solution is for the HTTP2 blocking issue only.

jamesonuk commented 6 days ago

I just did a little bit of digging and I think the root cause is https://gitlab.com/keatontaylor/alexapy/-/blob/dev/alexapy/alexalogin.py#L100 it should probably be addressed there (probably having an SSL context created and reused here)

jleinenbach commented 6 days ago

I just did a little bit of digging and I think the root cause is https://gitlab.com/keatontaylor/alexapy/-/blob/dev/alexapy/alexalogin.py#L100 it should probably be addressed there (probably having an SSL context created and reused here)

I tried all possible workarounds here, but only the HTTP2 blocking warning disappeared.

init.py.txt

Here are the relevant libraries and modules responsible for the reported blocking call error:

aiohttp:
- Used for HTTP requests and session management.
- Cause: The SSL handling within aiohttp triggers blocking operations during SSL connection initialization, particularly when loading certificates with load_verify_locations.
ssl (part of the Python standard library):
- Cause: The load_verify_locations function in the ssl library is responsible for loading certificate files. This operation is blocking and is internally called by aiohttp to verify SSL connections.
certifi:
- Provides certificate files.
- Cause: This library is used by aiohttp to specify the path to SSL certificates, which can lead to blocking operations.
AlexaLogin (from the alexapy library):
- Used for authentication with Amazon Alexa.
- Cause: The instantiation of the AlexaLogin object and its login function indirectly cause blocking SSL calls, as they rely on aiohttp sessions.
alexapy:
- The primary library for interacting with Alexa APIs.
- Cause: This library uses aiohttp for HTTP requests, which can trigger blocking SSL initialization.

Summary of Responsible Libraries:

aiohttp – For HTTP and SSL connections (responsible for the blocking SSL initialization).
ssl – Python's standard library for SSL handling (the actual blocking occurs via load_verify_locations).
certifi – Provides SSL certificates that are loaded by ssl.
AlexaLogin (from alexapy) – Indirectly responsible as it utilizes aiohttp.

Primary Cause:

The direct cause is the combination of aiohttp and the ssl library, specifically the call to load_verify_locations during SSL initialization.

danielbrunt57 commented 4 days ago

I can confirm that making the above change to __init__.py has eliminated one of my 5 warnings:

Logger: homeassistant.util.loop
Source: util/loop.py:136
First occurred: 10:41:41 PM (5 occurrences)
Last logged: 10:41:51 PM

This one is now resolved:

Detected blocking call to load_verify_locations with args (<ssl.SSLContext object at 0xffff322c5750>,) inside the event loop by custom integration 'alexa_media' at custom_components/alexa_media/__init__.py, line 876: http2 = HTTP2EchoClient( (offender: /usr/local/lib/python3.12/site-packages/httpx/_config.py, line 147: context.load_verify_locations(cafile=cafile)), please create a bug report

One of my remaining 4 is from custom integration 'smartthinq_sensors': Detected blocking call to load_default_certs with args (<ssl.SSLContext object at 0xffff62e1f050>. I just found a PR that fixes it: Using get_default_context() for ssl context to avoid blocking call #791 I made the code change and that warning is gone:

Detected blocking call to load_default_certs with args (<ssl.SSLContext object at 0xffff48ce1ed0>, <Purpose.SERVER_AUTH: _ASN1Object(nid=129, shortname='serverAuth', longname='TLS Web Server Authentication', oid='1.3.6.1.5.5.7.3.1')>) inside the event loop by custom integration 'smartthinq_sensors' at custom_components/smartthinq_sensors/wideq/core_async.py, line 149: context = ssl.create_default_context() (offender: /usr/local/lib/python3.12/ssl.py, line 713: context.load_default_certs(purpose)), please create a bug report

I applied the smartthinq_sensors change to alexalogin.py and resolved another warning.

"""Python Package for controlling Alexa devices (echo dot, etc) programmatically.

SPDX-License-Identifier: Apache-2.0

Login class.

This file could not have been written without referencing MIT code from https://github.com/Apollon77/alexa-remote.

For more details about this api, please refer to the documentation at
https://gitlab.com/keatontaylor/alexapy
"""

import asyncio
import base64
from binascii import Error
import datetime
import hashlib
from homeassistant.util.ssl import get_default_context
from http.cookies import Morsel, SimpleCookie

...

    def __init__(
        self,
        url: str,
        email: str,
        password: str,
        outputpath: Callable[[str], str],
        debug: bool = False,
        otp_secret: str = "",
        oauth: Optional[dict[Any, Any]] = None,
        uuid: Optional[str] = None,
        oauth_login: bool = True,
    ) -> None:
        # pylint: disable=too-many-arguments,import-outside-toplevel
        """Set up initial connection and log in."""
#        import ssl

#        import certifi

        oauth = oauth or {}
        self._hass_domain: str = "alexa_media"
        self._prefix: str = "https://alexa."
        self._url: str = url
        self._email: str = email
        self._password: str = password
        self._session: Optional[aiohttp.ClientSession] = None
        self._ssl = get_default_context()
#        self._ssl = ssl.create_default_context(
#            purpose=ssl.Purpose.SERVER_AUTH, cafile=certifi.where()
#        )
        self._headers: dict[str, str] = {}

I also made a change in alexalogin.py async def load_cookie using asyncio.run_coroutine_threadsafe() to execute localfile.write(cookies_txt):

    async def load_cookie(self, cookies_txt: str = "") -> Optional[dict[str, str]]:
        # pylint: disable=import-outside-toplevel
        """Load cookie from disk."""
        from collections import defaultdict
        import http.cookiejar

        from requests.cookies import RequestsCookieJar

        cookies: Optional[
            Union[RequestsCookieJar, http.cookiejar.MozillaCookieJar]
        ] = None
        return_cookies = {}
        numcookies: int = 0
        loaded: bool = False
        if self._cookiefile:
            if cookies_txt:
                _LOGGER.debug(
                    "Saving passed in cookie to %s\n%s",
                    self._cookiefile[0],
                    repr(cookies_txt),
                )
                async with aiofiles.open(self._cookiefile[0], mode="w") as localfile:
                    try:
                        asyncio.run_coroutine_threadsafe(localfile.write(cookies_txt), loop)
                    except (OSError, EOFError, TypeError, AttributeError) as ex:
                        _LOGGER.debug(
                            "Error saving passed in cookie to %s: %s",
                            self._cookiefile[0],
                            EXCEPTION_TEMPLATE.format(type(ex).__name__, ex.args),
                        )

I'm now down to two warnings:

Logger: homeassistant.util.loop
Source: util/loop.py:136
First occurred: 7:09:08 PM (2 occurrences)
Last logged: 7:09:11 PM

Detected blocking call to open with args (PosixPath('/config/.storage/alexa_media.daniel@brunt.ca.pickle'),) 
inside the event loop by custom integration 'alexa_media' at custom_components/alexa_media/__init__.py, 
line 372: await login.login(cookies=await login.load_cookie()) 
(offender: /usr/local/lib/python3.12/site-packages/aiohttp/cookiejar.py, 
line 118: with file_path.open(mode="rb") as f:), 
please create a bug report at https://github.com/alandtse/alexa_media_player/issues 
For developers, please see https://developers.home-assistant.io/docs/asyncio_blocking_operations/#open 

Traceback (most recent call last): File "<frozen runpy>", 
line 198, in _run_module_as_main File "<frozen runpy>", 
line 88, in _run_code File "/usr/src/homeassistant/homeassistant/__main__.py", 
line 223, in <module> sys.exit(main()) File "/usr/src/homeassistant/homeassistant/__main__.py", 
line 209, in main exit_code = runner.run(runtime_conf) File "/usr/src/homeassistant/homeassistant/runner.py", 
line 189, in run return loop.run_until_complete(setup_and_run_hass(runtime_config)) File "/usr/local/lib/python3.12/asyncio/base_events.py", 
line 674, in run_until_complete self.run_forever() File "/usr/local/lib/python3.12/asyncio/base_events.py", 
line 641, in run_forever self._run_once() File "/usr/local/lib/python3.12/asyncio/base_events.py", 
line 1990, in _run_once handle._run() File "/usr/local/lib/python3.12/asyncio/events.py", 
line 88, in _run self._context.run(self._callback, *self._args) File "/usr/src/homeassistant/homeassistant/config_entries.py", 
line 752, in async_setup_locked await self.async_setup(hass, integration=integration) File "/usr/src/homeassistant/homeassistant/config_entries.py",
 line 604, in async_setup result = await component.async_setup_entry(hass, self) File "/config/custom_components/alexa_media/__init__.py", 
line 372, in async_setup_entry await login.login(cookies=await login.load_cookie())

Detected blocking call to open with args (PosixPath('/config/.storage/alexa_media.daniel@brunt.ca.pickle'),) 
inside the event loop by custom integration 'alexa_media' at custom_components/alexa_media/__init__.py, 
line 372: await login.login(cookies=await login.load_cookie()) 
(offender: /usr/local/lib/python3.12/site-packages/aiohttp/cookiejar.py, 
line 113: with file_path.open(mode="wb") as f:), 
please create a bug report at https://github.com/alandtse/alexa_media_player/issues 
For developers, please see https://developers.home-assistant.io/docs/asyncio_blocking_operations/#open 

Traceback (most recent call last): File "<frozen runpy>", line 198, in _run_module_as_main File "<frozen runpy>", 
line 88, in _run_code File "/usr/src/homeassistant/homeassistant/__main__.py", 
line 223, in <module> sys.exit(main()) File "/usr/src/homeassistant/homeassistant/__main__.py", 
line 209, in main exit_code = runner.run(runtime_conf) File "/usr/src/homeassistant/homeassistant/runner.py", 
line 189, in run return loop.run_until_complete(setup_and_run_hass(runtime_config)) File "/usr/local/lib/python3.12/asyncio/base_events.py", 
line 674, in run_until_complete self.run_forever() File "/usr/local/lib/python3.12/asyncio/base_events.py", 
line 641, in run_forever self._run_once() File "/usr/local/lib/python3.12/asyncio/base_events.py", 
line 1990, in _run_once handle._run() File "/usr/local/lib/python3.12/asyncio/events.py", 
line 88, in _run self._context.run(self._callback, *self._args) File "/usr/src/homeassistant/homeassistant/config_entries.py", 
line 752, in async_setup_locked await self.async_setup(hass, integration=integration) File "/usr/src/homeassistant/homeassistant/config_entries.py", 
line 604, in async_setup result = await component.async_setup_entry(hass, self) File "/config/custom_components/alexa_media/__init__.py", 
line 372, in async_setup_entry await login.login(cookies=await login.load_cookie())

danielbrunt57 commented 4 days ago

I just now successfully eliminated the last two warnings!!! I've been chasing the wrong code for I don't know how many hours now!

This fixes them... Change (~line 380)

                        cookie_jar.load(cookiefile)

to:

                        await self.async_add_executor_job(
                            cookie_jar.load, cookiefile
                        )

and ~line 735:

                    cookie_jar.save(self._cookiefile[0])

to:

                    await self.async_add_executor_job(
                        cookie_jar.save, self._cookiefile[0]
                    )

jleinenbach commented 4 days ago

I just now successfully eliminated the last two warnings!!! I've been chasing the wrong code for I don't know how many hours now!

This fixes them... Change (~line 380)

You mean cookiejar.py? https://github.com/alandtse/alexa_media_player/issues/2520

danielbrunt57 commented 3 days ago

Yes. Your solution is much better than mine though! Thanks!

danielbrunt57 commented 2 days ago

@jleinenbach I've just noticed that with your patch:

await hass.async_add_executor_job(
    login_obj.session.context.load_verify_locations, cafile=cafile
)

my http2 connection fails to connect:

2024-09-16 01:13:06.010 DEBUG (MainThread) [custom_components.alexa_media] dl@b**a: HTTP2 creation failed: 'ClientSession' object has no attribute 'context'

I removed the patch and http2 is connected and running:

2024-09-16 00:58:03.983 WARNING (MainThread) [homeassistant.util.loop] Detected blocking call to load_verify_locations with args (<ssl.SSLContext object at 0xffff3d0e37d0>,) inside the event loop by custom integration 'alexa_media' at custom_components/alexa_media/__init__.py, line 1002: http2 = HTTP2EchoClient( (offender: /usr/local/lib/python3.12/site-packages/httpx/_config.py, line 147: context.load_verify_locations(cafile=cafile)), please create a bug report at https://github.com/alandtse/alexa_media_player/issues
await http2_connect()
File "/config/custom_components/alexa_media/__init__.py", line 1002, in http2_connect
http2 = HTTP2EchoClient(
2024-09-16 00:58:04.012 DEBUG (MainThread) [custom_components.alexa_media] d****l@b******a: HTTP2 created: <alexapy.alexahttp2.HTTP2EchoClient object at 0xffff3d102f30>
2024-09-16 00:58:04.013 DEBUG (MainThread) [custom_components.alexa_media] d****l@b******a: HTTP2push successfully connected
2024-09-16 00:58:04.029 DEBUG (MainThread) [alexapy.alexahttp2] Starting message parsing loop.
2024-09-16 00:58:04.029 DEBUG (MainThread) [alexapy.alexahttp2] Connecting to https://alexa.na.gateway.devices.a2z.com/v20160207/directives with {'method': 'GET', 'path': '/v20160207/directives', 'authority': 'alexa.na.gateway.devices.a2z.com', 'scheme': 'https', 'authorization': 'Bearer Atna|EwICIJ2X3tg12G_a08w6MlI1rgf0rKp4eVH1XJu3-2Lvs_iCJQXqIunba9MNQacYNQume51Hvx6xGq4TKDPWCANcF44M3lWbNQEIXqWkj8Z5RMe4FG_rVgNPCrnVJSiohUOpPRJ-3Aht07wlfD0pdYYGYF7U-YVWvxNt06TSOR6zx9IC92AZa2ZjQoN1YO-C2qTNlMbK5Od3-_GHZLXOC0miw5Ivq5XCfp8wMLOi9zcd59ymKZhB5IKCM1134mTdcvL29q8CrEt5Hnj02yKaglem-f2h3-NW_lPBzY9U05WSYCjqDBPqQizBOmdYJ58Pt3YwJmEaH3il9qx45d8xoKk53wPF'}
2024-09-16 00:58:04.030 DEBUG (MainThread) [alexapy.alexahttp2] Preparing ping to https://alexa.na.gateway.devices.a2z.com/ping
2024-09-16 00:58:05.862 DEBUG (MainThread) [alexapy.alexahttp2] Received raw message: --------abcde123
2024-09-16 00:58:05.954 DEBUG (MainThread) [alexapy.alexahttp2] Received response: 204:

jleinenbach commented 2 days ago

@danielbrunt57

It seems that the issue you're facing is likely due to the shift in Alexapy from using the native Python ssl to homeassistant.util.ssl. This change can cause compatibility issues, especially when Alexapy's internal processes no longer use the expected SSL handling. It didn’t occur when no separate thread was used because the SSL context, including the cafile, was executed directly within the event loop. By keeping everything in the event loop, Alexapy managed the SSL context internally, ensuring all resources were available. However, when we switched to executing the SSL setup in a separate thread (using async_add_executor_job), the thread lost access to some of the SSL resources like the cafile, leading to the issue.

jleinenbach commented 2 days ago

@danielbrunt57

You may try this patch instead, as I’m unable to test your Alexapy SSL changes on my side.

__init__.py: Please add the following import statement at the beginning of the file, in the import section:

from homeassistant.util.ssl import get_default_context

Then replace this method:

    async def http2_connect() -> Optional[HTTP2EchoClient]:
        """Open HTTP2 Push connection.

        This will only attempt one login before failing.
        """
        http2: Optional[HTTP2EchoClient] = None
        email = login_obj.email
        try:
            if login_obj.session.closed:
                _LOGGER.debug(
                    "%s: HTTP2 creation aborted. Session is closed.",
                    hide_email(email),
                )
                return

            # Get the SSL context from Home Assistant
            ssl_context = get_default_context()
            _LOGGER.debug("Using Home Assistant's get_default_context for SSL.")

            # Extract the cafile from the Alexapy login object to maintain consistency
            cafile = login_obj.session._ssl_context.get_ca_certs()[0]['path']  # Retrieve the CA certificate path from Alexapy

            # Load the SSL context in a separate thread to prevent blocking the event loop
            try:
                await hass.async_add_executor_job(
                    ssl_context.load_verify_locations, cafile=cafile
                )
                _LOGGER.debug("SSL context loaded successfully and certificates verified.")
            except Exception as e:
                _LOGGER.error(f"Failed to load SSL context: {e}")

            # Create HTTP2EchoClient
            http2 = HTTP2EchoClient(
                login_obj,
                msg_callback=http2_handler,
                open_callback=http2_open_handler,
                close_callback=http2_close_handler,
                error_callback=http2_error_handler,
                loop=hass.loop,
            )
            _LOGGER.debug("%s: HTTP2 created: %s", hide_email(email), http2)

            # Start HTTP2 connection
            await http2.async_run()
        except AlexapyLoginError as exception_:
            _LOGGER.debug(
                "%s: Login Error detected from http2: %s",
                hide_email(email),
                exception_,
            )
            hass.bus.async_fire(
                "alexa_media_relogin_required",
                event_data={"email": hide_email(email), "url": login_obj.url},
            )
            return
        except BaseException as exception_:  # pylint: disable=broad-except
            _LOGGER.debug(
                "%s: HTTP2 creation failed: %s", hide_email(email), exception_
            )
            return
        return http2

danielbrunt57 commented 2 days ago

I will try that.
In the meantime, I just tried offloading the entire HTTP2EchoClient and it worked. This currently is in addition to the ssl change I made in alexalogin.py, which I will try without changing it (alexalogin.py). I have no warnings and HHTP2 is connected.

# Offloading SSL initialization to a separate thread
#            await hass.async_add_executor_job(
#                login_obj.session.context.load_verify_locations, cafile=cafile
#            )
            msg_callback=http2_handler,
            open_callback=http2_open_handler
            close_callback=http2_close_handler
            error_callback=http2_error_handler
            loop=hass.loop
            http2 = await hass.async_add_executor_job(
                HTTP2EchoClient,
                login_obj,
                msg_callback,
                open_callback,
                close_callback,
                error_callback,
                loop,
            )               

            # Create HTTP2EchoClient
#            http2 = HTTP2EchoClient(
#                login_obj,
#                msg_callback=http2_handler,
#                open_callback=http2_open_handler,
#                close_callback=http2_close_handler,
#                error_callback=http2_error_handler,
#                loop=hass.loop,
#            )

What's your take on this approach??

danielbrunt57 commented 2 days ago

I removed my changes in alexalogin.py and the verify warning returned:

Logger: homeassistant.util.loop Source: util/loop.py:136 First occurred: 5:17:04 AM (1 occurrences) Last logged: 5:17:04 AM

Detected blocking call to load_verify_locations with args (<ssl.SSLContext object at 0xffff793785d0>, '/usr/local/lib/python3.12/site-packages/certifi/cacert.pem', None, None) inside the event loop by custom integration 'alexa_media' at custom_components/alexa_media/init.py, line 448: AlexaLogin( (offender: /usr/local/lib/python3.12/ssl.py, line 708: context.load_verify_locations(cafile, capath, cadata)), please create a bug report at https://github.com/alandtse/alexa_media_player/issues For developers, please see https://developers.home-assistant.io/docs/asyncio_blocking_operations/#load_verify_locations Traceback (most recent call last): File "", line 198, in _run_module_as_main File "", line 88, in _run_code File "/usr/src/homeassistant/homeassistant/main.py", line 223, in sys.exit(main()) File "/usr/src/homeassistant/homeassistant/main.py", line 209, in main exit_code = runner.run(runtime_conf) File "/usr/src/homeassistant/homeassistant/runner.py", line 189, in run return loop.run_until_complete(setup_and_run_hass(runtime_config)) File "/usr/local/lib/python3.12/asyncio/base_events.py", line 674, in run_until_complete self.run_forever() File "/usr/local/lib/python3.12/asyncio/base_events.py", line 641, in run_forever self._run_once() File "/usr/local/lib/python3.12/asyncio/base_events.py", line 1990, in _run_once handle._run() File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run self._context.run(self._callback, *self._args) File "/usr/src/homeassistant/homeassistant/setup.py", line 165, in async_setup_component result = await _async_setup_component(hass, domain, config) File "/usr/src/homeassistant/homeassistant/setup.py", line 461, in _async_setup_component await asyncio.gather( File "/usr/src/homeassistant/homeassistant/setup.py", line 463, in create_eagertask( File "/usr/src/homeassistant/homeassistant/util/async.py", line 45, in create_eager_task return Task(coro, loop=loop, name=name, eager_start=True) File "/usr/src/homeassistant/homeassistant/config_entries.py", line 752, in async_setup_locked await self.async_setup(hass, integration=integration) File "/usr/src/homeassistant/homeassistant/config_entries.py", line 604, in async_setup result = await component.async_setup_entry(hass, self) File "/config/custom_components/alexa_media/init.py", line 448, in async_setup_entry AlexaLogin(

jleinenbach commented 2 days ago

That's a much better solution than my approach. This ensures that all operations related to HTTP2EchoClient, including SSL initialization and connection setup, are handled in the background. And your code becomes more maintainable.

danielbrunt57 commented 2 days ago

Confirmed that I do need the ssl change in alexalogin.py to eliminate the error in addition to offloading the HTTP2EchoClient.

        """Set up initial connection and log in."""
#        import ssl
        from homeassistant.util import ssl

        import certifi

        oauth = oauth or {}
        self._hass_domain: str = "alexa_media"
        self._prefix: str = "https://alexa."
        self._url: str = url
        self._email: str = email
        self._password: str = password
        self._session: Optional[aiohttp.ClientSession] = None
#        self._ssl = ssl.create_default_context(
#            purpose=ssl.Purpose.SERVER_AUTH, cafile=certifi.where()
#        )
        self._ssl = ssl.get_default_context()

jleinenbach commented 2 days ago

AlexaLogin(

It's because Alexapy uses /usr/local/lib/python3.12/ssl.py and AMP uses AlexaLogin(

danielbrunt57 commented 2 days ago

I just don't comprehend the difference between Alan's approach using python's ssl vs the get_default_context in homeassistant.util. I'm thinking maybe his coding predates the existence of homeassistant.util.ssl?

danielbrunt57 commented 2 days ago

So, are you happy/comfortable with my code? It will mean yet another alexapy version bump...

danielbrunt57 commented 2 days ago

Here is my current __init__.py (which is yours + my edits): init.zip and alexalogin.py: alexalogin.zip

jleinenbach commented 2 days ago

I just don't comprehend the difference between Alan's approach using python's ssl vs the get_default_context in homeassistant.util. I'm thinking maybe his coding predates the existence of homeassistant.util.ssl?

Based on Alen's documentation, Alexapy was "was originally designed for alexa_media_player". However, I think this also implies that its approach has since evolved to be more general and applicable beyond just Home Assistant.

danielbrunt57 commented 2 days ago

Based on Alen's documentation, Alexapy was "was originally designed for alexa_media_player". However, I think this also implies that its approach has since evolved to be more general and applicable beyond just Home Assistant.

Yes but I think his basic code is many years old now and I do not know when HA's util.ssl was added.

jleinenbach commented 2 days ago

Here is my current __init__.py (which is yours + my edits): init.zip

I think this should work, but maybe more logging? We could also try to reconnect/retry if something fails, but this may be too much at once.

try:
    http2 = await hass.async_add_executor_job(
        HTTP2EchoClient,
        login_obj,
        msg_callback,
        open_callback,
        close_callback,
        error_callback,
        loop,
    )
    _LOGGER.debug("%s: HTTP2 client successfully created: %s", hide_email(email), http2)
except (AlexapyConnectionError, AlexapyLoginError) as conn_error:
    _LOGGER.error("Connection or login error with HTTP2Client for %s: %s", hide_email(email), conn_error)
except Exception as e:
    # Using _LOGGER.exception to include the full stack trace for debugging purposes
    _LOGGER.exception("Unexpected error when initializing HTTP2 client for %s: %s", hide_email(email), e)

jleinenbach commented 2 days ago

@danielbrunt57

I now solved this problem (hopefully) without a new homeassistant.util import ssland keep everything compatible to the same time.

Please test my (non-HA-exclusive) alexalogin.py version: alexalogin.zip

And this is your __init__.py - but with additional logging (see above). init.zip

This is the only warning I get for alexa* (huge list of almost all integrations, but without any details):

jleinenbach commented 2 days ago

@danielbrunt57

I have found another issue: The HTTP/2 connection status isn't updated properly. I asked ChatGPT to write the following:

Here's an improved version of the response, incorporating your feedback about the importance of jitter handling and focusing more on points 1 and 2:

Issues and Solutions Related to the HTTP/2 Connection in `init.py`

After analyzing the __init__.py file, I’ve identified key problems that explain why the HTTP/2 connection status isn't updated properly and why it fails to reopen. Here's a breakdown:

1. HTTP/2 Connection Status Not Updating Properly

When the HTTP/2 connection closes, the status in Home Assistant is set to None:

hass.data[DATA_ALEXAMEDIA]["accounts"][email]["http2"] = None

This causes the should_poll property to return True, indicating that polling should be enabled, as the system is no longer using an HTTP/2 push connection:

@property
def should_poll(self):
    return not (self.hass.data[DATA_ALEXAMEDIA]["accounts"][self._account]["http2"])

However, if the connection is not properly reopened, the http2 value remains None, causing persistent polling, which isn't ideal for real-time updates like Alexa reminders.

2. Reconnection Fails Due to Incomplete Error Handling

The logic to reopen the HTTP/2 connection after it closes is handled by the http2_close_handler(), which attempts to reconnect up to five times:

while errors < 5 and not (http2_enabled):
    _LOGGER.debug(
        "%s: HTTP2 push closed; reconnect #%i in %is",
        hide_email(email),
        errors,
        delay,
    )
    http2_enabled = hass.data[DATA_ALEXAMEDIA]["accounts"][email]["http2"] = (
        await http2_connect()
    )
    errors = hass.data[DATA_ALEXAMEDIA]["accounts"][email]["http2error"] = (
        hass.data[DATA_ALEXAMEDIA]["accounts"][email]["http2error"] + 1
    )
    delay = 5 * 2**errors
    await asyncio.sleep(delay)

Problem 1: If the reconnection attempts fail, the connection may not be properly reestablished, leaving http2 as None indefinitely.
Problem 2: The status of the HTTP/2 connection (http2_enabled) is not updated reliably if the connection fails, preventing the system from properly detecting whether the connection was reestablished.

3. Lack of Jitter in Retry Logic

A critical issue is the lack of jitter in the retry logic for reconnecting. The current reconnection logic uses exponential backoff:

delay = 5 * 2**errors
await asyncio.sleep(delay)

While exponential backoff is useful, adding jitter (randomness) to the retry delay would prevent potential "thundering herd" problems, where multiple clients attempt to reconnect simultaneously, leading to network congestion or API rate limits.

Recommendations:

Improve the Reconnection Logic:
- Add jitter to the retry logic to avoid simultaneous reconnection attempts by multiple clients, which could lead to rate-limiting or connection failures. For example, instead of a fixed delay, you can use a random factor:
```
import random
delay = 5 * 2**errors + random.uniform(0, 1)
await asyncio.sleep(delay)
```
- Reduce the maximum delay in the exponential backoff to ensure faster retries when the connection fails repeatedly.
Expand Error and Success Logs:
- Add detailed logging for each reconnection attempt, including whether it was successful. This will help in tracking when the connection is lost and when it's reestablished. For example:
```
if http2_enabled:
   _LOGGER.info("HTTP2 reconnected successfully for %s", hide_email(email))
else:
   _LOGGER.error("HTTP2 reconnection failed for %s on attempt #%i", hide_email(email), errors)
```
Polling as a Temporary Fallback:
- While polling can act as a temporary fallback mechanism when HTTP/2 fails, it’s more important to ensure that HTTP/2 reconnects reliably. Relying solely on polling would lead to slower updates and higher resource usage, which is why jitter and more robust reconnection attempts are critical.

jleinenbach commented 2 days ago

@danielbrunt57 __init__.py with fixes for the above and at least I could restart without additional warnings and errors: init.zip

danielbrunt57 commented 1 day ago

So, not sure what I might have done wrong but with no alexa_media integration yet, I'm getting this error:

File "/config/custom_components/alexa_media/__init__.py", line 58, in <module>
    from .config_flow import in_progress_instances
ImportError: cannot import name 'in_progress_instances' from 'custom_components.alexa_media.config_flow' (/config/custom_components/alexa_media/config_flow.py)

danielbrunt57 commented 1 day ago

Here is the log sequence...

2024-09-16 18:09:42.557 DEBUG (ImportExecutor_0) [alexapy.alexalogin] http.cookies patch: Morsel._reserved: {'partitioned': 'Partitioned'}; Morsel._flags: {'partitioned', 'httponly', 'secure'}
2024-09-16 18:09:42.602 WARNING (MainThread) [homeassistant.util.loop] Detected blocking call to import_module with args ('custom_components.alexa_media.notify',) in /usr/src/homeassistant/homeassistant/loader.py, line 1296: return importlib.import_module(f"{self.pkg_path}.{platform_name}") inside the event loop; This is causing stability issues. Please create a bug report at https://github.com/home-assistant/core/issues?q=is%3Aopen+is%3Aissue
For developers, please see https://developers.home-assistant.io/docs/asyncio_blocking_operations/#import_module
Traceback (most recent call last):
File "<frozen runpy>", line 198, in _run_module_as_main
File "<frozen runpy>", line 88, in _run_code
File "/usr/src/homeassistant/homeassistant/__main__.py", line 223, in <module>
sys.exit(main())
File "/usr/src/homeassistant/homeassistant/__main__.py", line 209, in main
exit_code = runner.run(runtime_conf)
File "/usr/src/homeassistant/homeassistant/runner.py", line 189, in run
return loop.run_until_complete(setup_and_run_hass(runtime_config))
File "/usr/local/lib/python3.12/asyncio/base_events.py", line 674, in run_until_complete
self.run_forever()
File "/usr/local/lib/python3.12/asyncio/base_events.py", line 641, in run_forever
self._run_once()
File "/usr/local/lib/python3.12/asyncio/base_events.py", line 1990, in _run_once
handle._run()
File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run
self._context.run(self._callback, *self._args)
File "/usr/src/homeassistant/homeassistant/config.py", line 1413, in _async_load_and_validate_platform_integration
platform = await p_integration.integration.async_get_platform(domain)
File "/usr/src/homeassistant/homeassistant/loader.py", line 1100, in async_get_platform
platforms = await self.async_get_platforms((platform_name,))
File "/usr/src/homeassistant/homeassistant/loader.py", line 1165, in async_get_platforms
platforms.update(self._load_platforms(platform_names))
File "/usr/src/homeassistant/homeassistant/loader.py", line 1090, in _load_platforms
platform_name: self._load_platform(platform_name)
File "/usr/src/homeassistant/homeassistant/loader.py", line 1264, in _load_platform
cache[full_name] = self._import_platform(platform_name)
File "/usr/src/homeassistant/homeassistant/loader.py", line 1296, in _import_platform
return importlib.import_module(f"{self.pkg_path}.{platform_name}")

2024-09-16 18:09:42.630 ERROR (MainThread) [homeassistant.config] Platform error: notify - cannot import name 'in_progress_instances' from 'custom_components.alexa_media.config_flow' (/config/custom_components/alexa_media/config_flow.py)
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/config.py", line 1413, in _async_load_and_validate_platform_integration
platform = await p_integration.integration.async_get_platform(domain)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/loader.py", line 1100, in async_get_platform
platforms = await self.async_get_platforms((platform_name,))
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/loader.py", line 1177, in async_get_platforms
import_future.result()
File "/usr/src/homeassistant/homeassistant/loader.py", line 1165, in async_get_platforms
platforms.update(self._load_platforms(platform_names))
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/loader.py", line 1090, in _load_platforms
platform_name: self._load_platform(platform_name)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/loader.py", line 1264, in _load_platform
cache[full_name] = self._import_platform(platform_name)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/loader.py", line 1296, in _import_platform
return importlib.import_module(f"{self.pkg_path}.{platform_name}")
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/util/loop.py", line 200, in protected_loop_func
return func(*args, **kwargs)
^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/importlib/__init__.py", line 90, in import_module
return _bootstrap._gcd_import(name[level:], package, level)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "<frozen importlib._bootstrap>", line 1387, in _gcd_import
File "<frozen importlib._bootstrap>", line 1360, in _find_and_load
File "<frozen importlib._bootstrap>", line 1310, in _find_and_load_unlocked
File "<frozen importlib._bootstrap>", line 488, in _call_with_frames_removed
File "<frozen importlib._bootstrap>", line 1387, in _gcd_import
File "<frozen importlib._bootstrap>", line 1360, in _find_and_load
File "<frozen importlib._bootstrap>", line 1331, in _find_and_load_unlocked
File "<frozen importlib._bootstrap>", line 935, in _load_unlocked
File "<frozen importlib._bootstrap_external>", line 995, in exec_module
File "<frozen importlib._bootstrap>", line 488, in _call_with_frames_removed
File "/config/custom_components/alexa_media/__init__.py", line 58, in <module>
from .config_flow import in_progress_instances
ImportError: cannot import name 'in_progress_instances' from 'custom_components.alexa_media.config_flow' (/config/custom_components/alexa_media/config_flow.py)

danielbrunt57 commented 1 day ago

I tried adding the integration and alexa auth was successful (using my workaround) but on return to HA, it just sat there spinning its wheels eventually ending with... The logs show initial success until an error...


2024-09-16 18:21:02.285 DEBUG (MainThread) [alexapy.alexalogin] Generating OTP 508781

2024-09-16 18:21:02.285 DEBUG (MainThread) [custom_components.alexa_media.config_flow] Generating OTP from 508781

2024-09-16 18:21:04.937 DEBUG (MainThread) [custom_components.alexa_media.config_flow] Starting proxy for d****l@b******a - amazon.ca

2024-09-16 18:21:04.938 DEBUG (MainThread) [alexapy.alexalogin] Attempting oauth login to https://www.amazon.com/ap/signin?openid.return_to=https://www.amazon.com/ap/maplanding&openid.assoc_handle=amzn_dp_project_dee_ios&openid.identity=http://specs.openid.net/auth/2.0/identifier_select&pageId=amzn_dp_project_dee_ios&accountStatusPolicy=P1&openid.claimed_id=http://specs.openid.net/auth/2.0/identifier_select&openid.mode=checkid_setup&openid.ns.oa2=http://www.amazon.com/ap/ext/oauth/2&openid.oa2.client_id=device:306332613434373737663435316666316161363763666236643834666439623032333431333234393536346335363335353634643332353733383331&openid.ns.pape=http://specs.openid.net/extensions/pape/1.0&openid.oa2.response_type=code&openid.ns=http://specs.openid.net/auth/2.0&openid.pape.max_auth_age=0&openid.oa2.scope=device_auth_access&openid.oa2.code_challenge_method=S256&openid.oa2.code_challenge=eIdnFOE75N0zKcTmHRafZJlFNSnZIhI1d1r_t2l7qLQ&language=en_CA

2024-09-16 18:21:04.956 WARNING (MainThread) [homeassistant.util.loop] Detected blocking call to load_verify_locations with args (<ssl.SSLContext object at 0xffff2c07e5d0>,) inside the event loop by custom integration 'alexa_media' at custom_components/alexa_media/config_flow.py, line 368: self.proxy = AlexaProxy( (offender: /usr/local/lib/python3.12/site-packages/httpx/_config.py, line 147: context.load_verify_locations(cafile=cafile)), please create a bug report at https://github.com/alandtse/alexa_media_player/issues
For developers, please see https://developers.home-assistant.io/docs/asyncio_blocking_operations/#load_verify_locations
Traceback (most recent call last):
File "<frozen runpy>", line 198, in _run_module_as_main
File "<frozen runpy>", line 88, in _run_code
File "/usr/src/homeassistant/homeassistant/__main__.py", line 223, in <module>
sys.exit(main())
File "/usr/src/homeassistant/homeassistant/__main__.py", line 209, in main
exit_code = runner.run(runtime_conf)
File "/usr/src/homeassistant/homeassistant/runner.py", line 189, in run
return loop.run_until_complete(setup_and_run_hass(runtime_config))
File "/usr/local/lib/python3.12/asyncio/base_events.py", line 674, in run_until_complete
self.run_forever()
File "/usr/local/lib/python3.12/asyncio/base_events.py", line 641, in run_forever
self._run_once()
File "/usr/local/lib/python3.12/asyncio/base_events.py", line 1990, in _run_once
handle._run()
File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run
self._context.run(self._callback, *self._args)
File "/usr/local/lib/python3.12/site-packages/aiohttp/web_protocol.py", line 462, in _handle_request
resp = await request_handler(request)
File "/usr/local/lib/python3.12/site-packages/aiohttp/web_app.py", line 537, in _handle
resp = await handler(request)
File "/usr/local/lib/python3.12/site-packages/aiohttp/web_middlewares.py", line 114, in impl
return await handler(request)
File "/usr/src/homeassistant/homeassistant/components/http/security_filter.py", line 92, in security_filter_middleware
return await handler(request)
File "/usr/src/homeassistant/homeassistant/components/http/forwarded.py", line 210, in forwarded_middleware
return await handler(request)
File "/usr/src/homeassistant/homeassistant/components/http/request_context.py", line 26, in request_context_middleware
return await handler(request)
File "/usr/src/homeassistant/homeassistant/components/http/auth.py", line 242, in auth_middleware
return await handler(request)
File "/usr/src/homeassistant/homeassistant/components/http/headers.py", line 32, in headers_middleware
response = await handler(request)
File "/usr/src/homeassistant/homeassistant/helpers/http.py", line 73, in handle
result = await handler(request, **request.match_info)
File "/usr/src/homeassistant/homeassistant/components/http/decorators.py", line 81, in with_admin
return await func(self, request, *args, **kwargs)
File "/usr/src/homeassistant/homeassistant/components/config/config_entries.py", line 222, in post
return await super().post(request, flow_id)
File "/usr/src/homeassistant/homeassistant/components/http/data_validator.py", line 74, in wrapper
return await method(view, request, data, *args, **kwargs)
File "/usr/src/homeassistant/homeassistant/helpers/data_entry_flow.py", line 122, in post
result = await self._flow_mgr.async_configure(flow_id, data)
File "/usr/src/homeassistant/homeassistant/data_entry_flow.py", line 366, in async_configure
result = await self._async_configure(flow_id, user_input)
File "/usr/src/homeassistant/homeassistant/data_entry_flow.py", line 413, in _async_configure
result = await self._async_handle_step(
File "/usr/src/homeassistant/homeassistant/data_entry_flow.py", line 516, in _async_handle_step
result: _FlowResultT = await getattr(flow, method)(user_input)
File "/config/custom_components/alexa_media/config_flow.py", line 563, in async_step_totp_register
return await self.async_step_start_proxy(user_input)
File "/config/custom_components/alexa_media/config_flow.py", line 368, in async_step_start_proxy
self.proxy = AlexaProxy(

2024-09-16 18:21:04.979 DEBUG (MainThread) [alexapy.alexalogin] Generating OTP 508781

2024-09-16 18:21:04.980 DEBUG (MainThread) [alexapy.alexalogin] Generating OTP 508781

2024-09-16 18:21:05.156 DEBUG (MainThread) [custom_components.alexa_media.config_flow] Found flow_id; adding fe80::4fd5:bdbe:e926:2a44 to known_ips for 300 seconds

2024-09-16 18:21:20.380 DEBUG (MainThread) [custom_components.alexa_media.config_flow] Checking proxy response for d****l@b******a - amazon.ca

2024-09-16 18:21:20.389 DEBUG (MainThread) [alexapy.alexalogin] Attempting to register with amazon.ca

2024-09-16 18:21:20.996 DEBUG (MainThread) [alexapy.alexalogin] auth response <ClientResponse(https://api.amazon.ca/auth/register) [200 OK]>
<CIMultiDictProxy('Server': 'Server', 'Date': 'Tue, 17 Sep 2024 01:21:20 GMT', 'Content-Type': 'application/json;charset=UTF-8', 'Content-Length': '5790', 'Connection': 'keep-alive', 'x-amz-rid': 'M3BEQPDPAJ38S4YS8ZFG', 'x-amzn-RequestId': '2526bc64-70a9-4b94-ae72-d672f61c8fce', 'X-Amz-Date': 'Tue, 17 Sep 2024 01:21:20 GMT', 'Cache-Control': 'no-cache, no-store, must-revalidate', 'Pragma': 'no-cache', 'Vary': 'Content-Type,Accept-Encoding,User-Agent', 'Strict-Transport-Security': 'max-age=47474747; includeSubDomains; preload')>
with
{"requested_extensions": ["device_info", "customer_info"], "cookies": {"website_cookies": [], "domain": ".amazon.ca"}, "registration_data": {"domain": "Device", "app_version": "2.2.556530.0", "device_type": "A2IVLV5VM2W81", "device_name": "%FIRST_NAME%'s%DUPE_STRATEGY_1ST%Alexa Media Player", "os_version": "16.6", "device_serial": "0c2a44777f451ff1aa67cfb6d84fd9b0", "device_model": "iPhone", "app_name": "Alexa Media Player", "software_version": "1"}, "auth_data": {"client_id": "306332613434373737663435316666316161363763666236643834666439623032333431333234393536346335363335353634643332353733383331", "authorization_code": "ANAdeKJBKhmOHoKQhXRPiBQe", "code_verifier": "gJhzPv1uXBqCRDezZmhSuRmMUPPBenp0cnBYknS5sfI", "code_algorithm": "SHA-256", "client_domain": "DeviceLegacy"}, "user_context_map": {"frc": "bnsBYs/D8tYUY74D0G+0MHNcMKE/3Y7eSL7n/YPNdYKelDQkZ9h702dk6KKTMngkumu8AqLwlgKBgqasgpT7lo7FWixgSfd7AxMASLb2+grFEAMPGWgESze4t0anxp0t+vNVC4Yw3jCh4Sjo8E3fwk+h9VauPXmIj+rmgYqLbG+mrA3d44NDIbYDlt3I8amflMZzxxP3GzoFrfzvCCW8v882mZIAY/stCZhq88/j8z612SaUXedxZ6U2+M3UacwL+SjSE7ed+hhgeRSBad+p6HK/owKULGoPX0Y9LpqvHXHvqsBr+CwFtnBPMmMGULM+1hMn3gKgW2OWlvGC9TBAUx5mk3i1T1zPqUzmIASsZoKN8cbz9iECUNSBtSMe/SmbGsTlsdLx2ESXDmec/kgB++qCCTxx1fA9Ww"}, "requested_token_type": ["bearer", "mac_dms", "website_cookies"]}

2024-09-16 18:21:20.997 DEBUG (MainThread) [alexapy.alexalogin] Successfully registered Daniel's 2nd Alexa Media Player device with Amazon

2024-09-16 18:21:20.997 DEBUG (MainThread) [alexapy.alexalogin] New access token(396) received which expires at 2024-09-16 19:21:20.997092 in 0:59:59.999971

2024-09-16 18:21:21.227 DEBUG (MainThread) [alexapy.alexalogin] capabilities response <ClientResponse(https://api.amazonalexa.com/v1/devices/@self/capabilities) [204 No Content]>
<CIMultiDictProxy('Connection': 'keep-alive', 'Server': 'Server', 'Date': 'Tue, 17 Sep 2024 01:21:21 GMT', 'x-amz-rid': 'DK5NPPSB6N46599Q61W9', 'Vary': 'Content-Type,Accept-Encoding,User-Agent', 'Strict-Transport-Security': 'max-age=47474747; includeSubDomains; preload', 'X-Cache': 'Miss from cloudfront', 'Via': '1.1 c18b7bdf64a187bba2ae3e11390c2510.cloudfront.net (CloudFront)', 'X-Amz-Cf-Pop': 'YVR52-P1', 'X-Amz-Cf-Id': 'CelwMquCqDT5M3DGaqX_WJQ88CNis5R-OTKYzZpk5m880ueJ-21Eiw==')>
with
{"legacyFlags": {"SUPPORTS_COMMS": true, "SUPPORTS_ARBITRATION": true, "SCREEN_WIDTH": 1170, "SUPPORTS_SCRUBBING": true, "SPEECH_SYNTH_SUPPORTS_TTS_URLS": false, "SUPPORTS_HOME_AUTOMATION": true, "SUPPORTS_DROPIN_OUTBOUND": true, "FRIENDLY_NAME_TEMPLATE": "VOX", "SUPPORTS_SIP_OUTBOUND_CALLING": true, "VOICE_PROFILE_SWITCHING_DISABLED": true, "SUPPORTS_LYRICS_IN_CARD": false, "SUPPORTS_DATAMART_NAMESPACE": "Vox", "SUPPORTS_VIDEO_CALLING": true, "SUPPORTS_PFM_CHANGED": true, "SUPPORTS_TARGET_PLATFORM": "TABLET", "SUPPORTS_SECURE_LOCKSCREEN": false, "AUDIO_PLAYER_SUPPORTS_TTS_URLS": false, "SUPPORTS_KEYS_IN_HEADER": false, "SUPPORTS_MIXING_BEHAVIOR_FOR_AUDIO_PLAYER": false, "AXON_SUPPORT": true, "SUPPORTS_TTS_SPEECHMARKS": true}, "envelopeVersion": "20160207", "capabilities": [{"version": "0.1", "interface": "CardRenderer", "type": "AlexaInterface"}, {"interface": "Navigation", "type": "AlexaInterface", "version": "1.1"}, {"type": "AlexaInterface", "version": "2.0", "interface": "Alexa.Comms.PhoneCallController"}, {"type": "AlexaInterface", "version": "1.1", "interface": "ExternalMediaPlayer"}, {"type": "AlexaInterface", "interface": "Alerts", "configurations": {"maximumAlerts": {"timers": 2, "overall": 99, "alarms": 2}}, "version": "1.3"}, {"version": "1.0", "interface": "Alexa.Display.Window", "type": "AlexaInterface", "configurations": {"templates": [{"type": "STANDARD", "id": "app_window_template", "configuration": {"sizes": [{"id": "fullscreen", "type": "DISCRETE", "value": {"value": {"height": 1440, "width": 3200}, "unit": "PIXEL"}}], "interactionModes": ["mobile_mode", "auto_mode"]}}]}}, {"type": "AlexaInterface", "interface": "AccessoryKit", "version": "0.1"}, {"type": "AlexaInterface", "interface": "Alexa.AudioSignal.ActiveNoiseControl", "version": "1.0", "configurations": {"ambientSoundProcessingModes": [{"name": "ACTIVE_NOISE_CONTROL"}, {"name": "PASSTHROUGH"}]}}, {"interface": "PlaybackController", "type": "AlexaInterface", "version": "1.0"}, {"version": "1.0", "interface": "Speaker", "type": "AlexaInterface"}, {"version": "1.0", "interface": "SpeechSynthesizer", "type": "AlexaInterface"}, {"version": "1.0", "interface": "AudioActivityTracker", "type": "AlexaInterface"}, {"type": "AlexaInterface", "interface": "Alexa.Camera.LiveViewController", "version": "1.0"}, {"type": "AlexaInterface", "version": "1.0", "interface": "Alexa.Input.Text"}, {"type": "AlexaInterface", "interface": "Alexa.PlaybackStateReporter", "version": "1.0"}, {"version": "1.1", "interface": "Geolocation", "type": "AlexaInterface"}, {"interface": "Alexa.Health.Fitness", "version": "1.0", "type": "AlexaInterface"}, {"interface": "Settings", "type": "AlexaInterface", "version": "1.0"}, {"configurations": {"interactionModes": [{"dialog": "SUPPORTED", "interactionDistance": {"value": 18, "unit": "INCHES"}, "video": "SUPPORTED", "keyboard": "SUPPORTED", "id": "mobile_mode", "uiMode": "MOBILE", "touch": "SUPPORTED"}, {"video": "UNSUPPORTED", "dialog": "SUPPORTED", "interactionDistance": {"value": 36, "unit": "INCHES"}, "uiMode": "AUTO", "touch": "SUPPORTED", "id": "auto_mode", "keyboard": "UNSUPPORTED"}]}, "type": "AlexaInterface", "interface": "Alexa.InteractionMode", "version": "1.0"}, {"type": "AlexaInterface", "configurations": {"catalogs": [{"type": "IOS_APP_STORE", "identifierTypes": ["URI_HTTP_SCHEME", "URI_CUSTOM_SCHEME"]}]}, "version": "0.2", "interface": "Alexa.Launcher"}, {"interface": "System", "version": "1.0", "type": "AlexaInterface"}, {"interface": "Alexa.IOComponents", "type": "AlexaInterface", "version": "1.4"}, {"type": "AlexaInterface", "interface": "Alexa.FavoritesController", "version": "1.0"}, {"version": "1.0", "type": "AlexaInterface", "interface": "Alexa.Mobile.Push"}, {"type": "AlexaInterface", "interface": "InteractionModel", "version": "1.1"}, {"interface": "Alexa.PlaylistController", "type": "AlexaInterface", "version": "1.0"}, {"interface": "SpeechRecognizer", "type": "AlexaInterface", "version": "2.1"}, {"interface": "AudioPlayer", "type": "AlexaInterface", "version": "1.3"}, {"type": "AlexaInterface", "version": "3.1", "interface": "Alexa.RTCSessionController"}, {"interface": "VisualActivityTracker", "version": "1.1", "type": "AlexaInterface"}, {"interface": "Alexa.PlaybackController", "version": "1.0", "type": "AlexaInterface"}, {"type": "AlexaInterface", "interface": "Alexa.SeekController", "version": "1.0"}, {"interface": "Alexa.Comms.MessagingController", "type": "AlexaInterface", "version": "1.0"}]}
{"User-Agent": "AmazonWebView/Amazon Alexa/2.2.556530.0/iOS/16.6/iPhone", "Accept-Language": "en-US", "Accept-Charset": "utf-8", "Connection": "keep-alive", "Content-type": "application/json; charset=UTF-8", "authorization": "Bearer Atna|EwICIFClISxi-ClG9hTi6d58rQZM5VdNMmjcFk3HbyBTK_IC3z4CVHbobh222pcm51kmp6qWKdpLbxqFRCpsgtYCOp05zKnIO8Va33l7u1EMMt_0uKSydxzqemMeSEpSDmK2N3C6XGHOENYiJXZmtdd2EUppGe2wksXD0c4YsdnOh-cAgLx_i9HnDuNpxS3336P4gtyYJ6qnGxXzX_09cj7YngbgfzpntAjt7tjpqepQ_ELBMHB9eoch1N-qCdk_R1daxoGVyvbQOtlR2aJ5IRDm9uecVW_5IwWqOy_kCIsgR3tev5683jm_RbQ2DYMCIAZJXukVXeiNqOlawRBxFWOsTNvmO1Rhars3N8NUV5LDNo9aJeHyVsDcwl_wrehnwJn0kwQ"}

2024-09-16 18:21:21.518 DEBUG (MainThread) [alexapy.alexalogin] updating jar with cookie Set-Cookie: session-id=142-3680275-3273900; Domain=.amazon.ca; expires=12 Sep 2044 01:21:21 GMT; Path=/; Secure

2024-09-16 18:21:21.518 DEBUG (MainThread) [alexapy.alexalogin] updating jar with cookie Set-Cookie: ubid-acbca=132-3692717-2730845; Domain=.amazon.ca; expires=12 Sep 2044 01:21:21 GMT; Path=/; Secure

2024-09-16 18:21:21.518 DEBUG (MainThread) [alexapy.alexalogin] updating jar with cookie Set-Cookie: x-acbca="5QtWE5BSOKElfAex9I1Y?WhbVDrN0Kom"; Domain=.amazon.ca; expires=12 Sep 2044 01:21:21 GMT; Path=/; Secure
2024-09-16 18:21:21.519 DEBUG (MainThread) [alexapy.alexalogin] updating jar with cookie Set-Cookie: at-acbca=Atza|IwEBIH6rs7Epi_Vc9gQjuavvcWw6QinX1yOl_a4PuXnjsQvoiKRLtOBL7DXlDGboe57--uzqN9E1wR7B5XTJUtWj01VfeV8cEBtuI-qW4L7BC1Iix_Tk9TCs3tIzVx0oFGTu-LCH4vg5ZSHyBH0XcMHok3Cd_U2gcWn30QfFPqp6Z8pdAljf0wrablHTLk7A3ejEcX7iRKfd6RBFeJFGsLp1aUMKyexIGS76lvewmYzHVuj1FmI33jOu0OQ3RGwsgM_ExBdittELV-lfPciAXoiCkNc1pn0rln532Sq1m4zd8FqvLeS6pSh-rJeA-1NYwh_d8zyPM9UJZ5-VviD7kkHd8t_DCZSx9TFweuCgT2nC-jQrIhvE9pegH4latPrIunVQouBbzVTEzEHbfdUsVkdDZKC-; Domain=.amazon.ca; expires=18 Sep 2024 01:21:21 GMT; HttpOnly; Path=/; Secure

2024-09-16 18:21:21.519 DEBUG (MainThread) [alexapy.alexalogin] updating jar with cookie Set-Cookie: sess-at-acbca="9kjji92tC3jX2voDtAfiZdwLtWuCl92d2+22Fs92+xw="; Domain=.amazon.ca; expires=18 Sep 2024 01:21:21 GMT; HttpOnly; Path=/; Secure

2024-09-16 18:21:21.519 INFO (MainThread) [alexapy.alexalogin] Exchanged refresh token for 5 .amazon.ca cookies: ['session-id', 'ubid-acbca', 'x-acbca', 'at-acbca', 'sess-at-acbca']

2024-09-16 18:21:21.520 DEBUG (MainThread) [alexapy.alexalogin] Attempting to discover CSRF token

2024-09-16 18:21:21.520 DEBUG (MainThread) [alexapy.alexalogin] Session cookies for 'https://alexa.amazon.ca/spa/index.html': ['session-id', 'session-id-time', 'lc-main', 'ubid-main', 'session-token', 'x-main', 'at-main', 'sess-at-main', 'ubid-acbca', 'x-acbca', 'at-acbca', 'sess-at-acbca']

2024-09-16 18:21:21.759 DEBUG (MainThread) [alexapy.alexalogin] CSRF token not found from /spa/index.html

2024-09-16 18:21:21.760 DEBUG (MainThread) [alexapy.alexalogin] Session cookies for 'https://alexa.amazon.ca/api/language': ['session-id', 'session-id-time', 'lc-main', 'ubid-main', 'session-token', 'x-main', 'at-main', 'sess-at-main', 'ubid-acbca', 'x-acbca', 'at-acbca', 'sess-at-acbca']

2024-09-16 18:21:22.108 DEBUG (MainThread) [alexapy.alexalogin] CSRF token found from /api/language

2024-09-16 18:21:22.108 DEBUG (MainThread) [alexapy.alexalogin] Session cookies for 'https://alexa.amazon.com/api/bootstrap': ['session-id', 'session-id-time', 'lc-main', 'ubid-main', 'session-token', 'x-main', 'at-main', 'sess-at-main']

2024-09-16 18:21:22.385 DEBUG (MainThread) [alexapy.alexalogin] GET:
https://alexa.amazon.com/api/bootstrap returned 200:OK with response <CIMultiDictProxy('Content-Type': 'application/json', 'Content-Length': '170', 'Connection': 'keep-alive', 'Server': 'Server', 'Date': 'Tue, 17 Sep 2024 01:21:22 GMT', 'Vary': 'Content-Type,Accept-Encoding,User-Agent', 'x-amz-rid': '580H2WX9C5BZM5YVHWGN', 'Set-Cookie': 'csrf=1904105646; expires=Sun, 17-Sep-2034 01:21:22 GMT; Domain=.amazon.com; Path=/', 'x-amzn-RequestId': '580H2WX9C5BZM5YVHWGN', 'x-amzn-alt-domain': 'https://alexa.amazon.ca/logout', 'X-Cache': 'Miss from cloudfront', 'Via': '1.1 c9e55bdb1ad65ca3c90f27d27baa2eba.cloudfront.net (CloudFront)', 'X-Amz-Cf-Pop': 'YVR52-P2', 'X-Amz-Cf-Id': 'qy8IG_V6WCBCKtRKKBP5E9tmJSWKFz06wtUVveVaYXnCZl6ixtTu8Q==')>

2024-09-16 18:21:22.388 DEBUG (MainThread) [alexapy.alexalogin] Session cookies for 'https://alexa.amazon.ca/api/bootstrap': ['session-id', 'session-id-time', 'lc-main', 'ubid-main', 'session-token', 'x-main', 'at-main', 'sess-at-main', 'ubid-acbca', 'x-acbca', 'at-acbca', 'sess-at-acbca', 'csrf']

2024-09-16 18:26:23.265 ERROR (MainThread) [aiohttp.server] Error handling request

danielbrunt57 commented 1 day ago

There's no pickle file...

➜  /config ls -al /config/.storage/*pickle
zsh: no matches found: /config/.storage/*pickle

and there's no entry in core.config_entries either.

danielbrunt57 commented 1 day ago

I noticed there was a new alexa_auth file in .storage.

I tried adding the integration again:

danielbrunt57 commented 1 day ago

I've gone back to square one with vanilla 1.29.2 and 4.13.0. I'm now looking at this error again: Detected blocking call to load_verify_locations with args (<ssl.SSLContext object at 0xffff3d2c0dd0>

I re-added your patch:

        # Offloading SSL initialization to a separate thread
        await hass.async_add_executor_job(
            login_obj.session.context.load_verify_locations, cafile=cafile
        )

but the blocking warning still appears referencing: File "/config/custom_components/alexa_media/__init__.py", line 341, in async_setup_entry AlexaLogin(

jleinenbach commented 1 day ago

It seems likely that the issue arises because the context wasn't offloaded properly. I'll attach both the __init__.py and the alexalogin.py files later on. With these files, I was able to successfully generate a new configuration. However, before attaching them, I want to double-check everything first.

The primary goal is to get this working without needing changes to the alexalogin.py file, but I still want to address the issue in that file as well. I'm unsure whether the changes in just the __init__.py will eliminate all blocking warnings, though.

danielbrunt57 commented 1 day ago

The primary goal is to get this working without needing changes to the alexalogin.py file

Changes might be required there but I understand the desire to keep it non-HA related. It would be nice to know from Alan though if we really need to! Will wait for your files...

danielbrunt57 commented 1 day ago

I suppose I could try a MR with my homeassistant.util.ssl import and see if he accepts it or rejects it. It wouldn't be the first time he scolded me!

jleinenbach commented 1 day ago

Ok, this works for me. I removed my configuration and recreated a new one - and it works. At least both together, but I tried to make it compatible, so please try the __init__.py file alone first.

init.zip alexalogin.zip

There are no more blocking call warnings, but this one:

Detected blocking call to load_verify_locations ... for config_flow.py

It's because of the AlexaProxy.

danielbrunt57 commented 1 day ago

Removed config entry, replaced __init__.py, restarted and tried adding config_entry:

Restarted and two errors:

Logger: homeassistant.config
Source: config.py:1413
First occurred: 11:47:55 AM (1 occurrences)
Last logged: 11:47:55 AM

Platform error: notify - cannot import name 'in_progress_instances' from 'custom_components.alexa_media.config_flow' (/config/custom_components/alexa_media/config_flow.py)

File "/config/custom_components/alexa_media/__init__.py", line 60, in <module>
    from .config_flow import in_progress_instances

Logger: homeassistant.setup
Source: setup.py:334
First occurred: 11:48:10 AM (1 occurrences)
Last logged: 11:48:10 AM

Setup failed for custom integration 'alexa_media': Unable to import component: cannot import name 'in_progress_instances' from 'custom_components.alexa_media.config_flow' (/config/custom_components/alexa_media/config_flow.py)

File "/config/custom_components/alexa_media/__init__.py", line 60, in <module>
    from .config_flow import in_progress_instances

danielbrunt57 commented 1 day ago

And I'm now unable to delete it.

but it remains:

danielbrunt57 commented 1 day ago

I left the config entry in place, restored __init__.py, restarted and the config entry from the failed attempt then initialized correctly.

I will try both files a little later...

jleinenbach commented 1 day ago

Oh no, I'm so sorry, that happend to you as I fixed the typos in my setup: https://github.com/alandtse/alexa_media_player/issues/2523

in_progess_instances vs in_progress_instances

grep -r "in_progess_instances" /config/custom_components/alexa_media/
grep -r "in_progress_instances" /config/custom_components/alexa_media/

danielbrunt57 commented 1 day ago

I found it in config_flow.py and it's in 4.13.1! I don't see a PR to fix it...

Everything is working fine now with just your __init__.py after fixing the typo in config_flow.py. Just this error:

Logger: homeassistant
Source: components/notify/legacy.py:131
First occurred: 3:00:43 PM (1 occurrences)
Last logged: 3:00:43 PM

Error doing job: Task exception was never retrieved (None)
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/notify/legacy.py", line 131, in async_setup_platform
    await notify_service.async_setup(
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
AttributeError: 'bool' object has no attribute 'async_setup'

and this warning:


Logger: homeassistant.util.loop
Source: util/loop.py:136
First occurred: 3:08:22 PM (1 occurrences)
Last logged: 3:08:22 PM

Detected blocking call to load_verify_locations with args (<ssl.SSLContext object at 0xffff10a23b50>,) 
inside the event loop by custom integration 'alexa_media' 
at custom_components/alexa_media/config_flow.py, line 368: self.proxy = AlexaProxy( 

(offender: /usr/local/lib/python3.12/site-packages/httpx/_config.py, line 147: context.load_verify_locations(cafile=cafile)), 
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^

please create a bug report at https://github.com/alandtse/alexa_media_player/issues 
For developers, please see https://developers.home-assistant.io/docs/asyncio_blocking_operations/#load_verify_locations 

Traceback (most recent call last): 
File "/config/custom_components/alexa_media/config_flow.py", line 368, in async_step_start_proxy self.proxy = AlexaProxy(

danielbrunt57 commented 22 hours ago

Just this error:

Logger: homeassistant
Source: components/notify/legacy.py:131
First occurred: 3:00:43 PM (1 occurrences)
Last logged: 3:00:43 PM

Error doing job: Task exception was never retrieved (None)
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/notify/legacy.py", line 131, in async_setup_platform
    await notify_service.async_setup(
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
AttributeError: 'bool' object has no attribute 'async_setup'

I finally found the source for this error! I still had a legacy leftover!

danielbrunt57 commented 22 hours ago

This is weird though. The WARNING is also gone!

danielbrunt57 commented 21 hours ago

in_progess_instances vs in_progress_instances

See PR 2541

danielbrunt57 commented 13 hours ago

@jleinenbach I submitted alexapy MR !390 to change import ssl to from homeassistant.util import ssl to fix the Detected blocking call to load_verify_locations warning in HA but it failed.

$ make lint
poetry run black alexapy
Skipping virtualenv creation, as specified in config file.
reformatted /builds/b366/alexapy/alexapy/alexaapi.py
reformatted /builds/b366/alexapy/alexapy/alexalogin.py
All done! ✨ 🍰 ✨
2 files reformatted, 7 files left unchanged.
poetry run flake8 alexapy
Skipping virtualenv creation, as specified in config file.
poetry run pydocstyle alexapy
Skipping virtualenv creation, as specified in config file.
poetry run pylint alexapy
Skipping virtualenv creation, as specified in config file.
************* Module alexapy.alexalogin
alexapy/alexalogin.py:92:8: E0401: Unable to import 'homeassistant.util' (import-error)

So I would say that option is a no-go!

danielbrunt57 commented 12 hours ago

I installed your alexalogin.py and yes, it resolves the load verify_locations blocking call but AMP initialization now takes forever but finally does load but I see new errors in HA logs. Followed by Failed: login_obj is not defined and then initializing again at which point it loads and is working albeit after the HA startup event has fired and triggered my startup automation, which cannot speak...

danielbrunt57 commented 12 hours ago

I restarted twice and same scenario each time. Removed the config entry, re-added it (all okay), restarted and same scenario again!

Restored alexalogin.py 1.29.2, restarted and everything back to normal with the verify_locations warning!

alandtse / alexa_media_player