Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

AEP Ohio (Opower integration) "async_login not called" #110019

Closed
benhoff opened this issue Feb 8, 2024 · 19 comments
Closed

AEP Ohio (Opower integration) "async_login not called" #110019

benhoff opened this issue Feb 8, 2024 · 19 comments

Comments

@benhoff
Copy link
Contributor

benhoff commented Feb 8, 2024

The problem

2024-02-07 17:05:09.602 ERROR (MainThread) [homeassistant.components.opower.coordinator] Unexpected error fetching Opower data: async_login not called
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 313, in _async_refresh
self.data = await self._async_update_data()
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/components/opower/coordinator.py", line 83, in _async_update_data
forecasts: list[Forecast] = await self.api.async_get_forecast()
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/site-packages/opower/opower.py", line 229, in async_get_forecast
for customer in await self._async_get_customers():
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/site-packages/opower/opower.py", line 301, in _async_get_customers
f"{self._get_subdomain()}"
^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/site-packages/opower/opower.py", line 545, in _get_subdomain
return self.utility.subdomain()
^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/site-packages/opower/utilities/aepbase.py", line 93, in subdomain
assert cls._subdomain, "async_login not called"
AssertionError: async_login not called
2024-02-07 17:05:20.020 ERROR (MainThread) [homeassistant.components.opower.coordinator] Unexpected error fetching Opower data: async_login not called
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 313, in _async_refresh
self.data = await self._async_update_data()
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/components/opower/coordinator.py", line 83, in _async_update_data
forecasts: list[Forecast] = await self.api.async_get_forecast()
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/site-packages/opower/opower.py", line 229, in async_get_forecast
for customer in await self._async_get_customers():
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/site-packages/opower/opower.py", line 301, in _async_get_customers
f"{self._get_subdomain()}"
^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/site-packages/opower/opower.py", line 545, in _get_subdomain
return self.utility.subdomain()
^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/site-packages/opower/utilities/aepbase.py", line 93, in subdomain
assert cls._subdomain, "async_login not called"
AssertionError: async_login not called

What version of Home Assistant Core has the issue?

2024.2.0

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant OS

Integration causing the issue

Opower

Link to integration documentation on our website

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

Diagnostics information

home-assistant_opower_2024-02-08T14-57-06.731Z.log

Example YAML snippet

N/A

Anything in the logs that might be useful for us?

2024-02-07 17:05:09.602 ERROR (MainThread) [homeassistant.components.opower.coordinator] Unexpected error fetching Opower data: async_login not called
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 313, in _async_refresh
    self.data = await self._async_update_data()
                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/opower/coordinator.py", line 83, in _async_update_data
    forecasts: list[Forecast] = await self.api.async_get_forecast()
                                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/opower/opower.py", line 229, in async_get_forecast
    for customer in await self._async_get_customers():
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/opower/opower.py", line 301, in _async_get_customers
    f"{self._get_subdomain()}"
       ^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/opower/opower.py", line 545, in _get_subdomain
    return self.utility.subdomain()
           ^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/opower/utilities/aepbase.py", line 93, in subdomain
    assert cls._subdomain, "async_login not called"
AssertionError: async_login not called
2024-02-07 17:05:20.020 ERROR (MainThread) [homeassistant.components.opower.coordinator] Unexpected error fetching Opower data: async_login not called
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 313, in _async_refresh
    self.data = await self._async_update_data()
                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/opower/coordinator.py", line 83, in _async_update_data
    forecasts: list[Forecast] = await self.api.async_get_forecast()
                                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/opower/opower.py", line 229, in async_get_forecast
    for customer in await self._async_get_customers():
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/opower/opower.py", line 301, in _async_get_customers
    f"{self._get_subdomain()}"
       ^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/opower/opower.py", line 545, in _get_subdomain
    return self.utility.subdomain()
           ^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/opower/utilities/aepbase.py", line 93, in subdomain
    assert cls._subdomain, "async_login not called"
AssertionError: async_login not called

Additional information

This is for AEP Ohio, there's only a username password combination, not sure what the error is. This worked when I first plugged in the credentials, but not since I restarted the system.

@home-assistant
Copy link

home-assistant bot commented Feb 8, 2024

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

Code owner commands

Code owners of opower 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 opower 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)


opower documentation
opower source
(message by IssueLinks)

@hiway65n
Copy link

hiway65n commented Feb 8, 2024

I'm seeing this too with PSO (public service Oklahoma)

2024-02-08 09:34:44.408 ERROR (MainThread) [homeassistant.components.opower.coordinator] Unexpected error fetching Opower data: async_login not called
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 313, in _async_refresh
self.data = await self._async_update_data()
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/components/opower/coordinator.py", line 83, in _async_update_data
forecasts: list[Forecast] = await self.api.async_get_forecast()
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/site-packages/opower/opower.py", line 229, in async_get_forecast
for customer in await self._async_get_customers():
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/site-packages/opower/opower.py", line 301, in _async_get_customers
f"{self._get_subdomain()}"
^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/site-packages/opower/opower.py", line 545, in _get_subdomain
return self.utility.subdomain()
^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/site-packages/opower/utilities/aepbase.py", line 93, in subdomain
assert cls._subdomain, "async_login not called"
AssertionError: async_login not called

@max2697
Copy link
Contributor

max2697 commented Feb 8, 2024

Could you please enable debugging for this integration and display debug logs as well? I'm trying to figure out if this was affected by my changes in the opower.py file from the last 0.2.0 release.

UPD: I double checked my changes and aepbase.py. I don't think that my changes broke something here. Maybe it could be caused by login skip part of the login method https://github.com/tronikos/opower/blob/2a84aa97e1fb6ce3eb5a80830a224b12b6b458a9/src/opower/utilities/aepbase.py#L128 but it's require additonal testing and debugging.

@hiway65n
Copy link

hiway65n commented Feb 8, 2024

Here is some additional logging, hopefully this helps some.

2024-02-08 15:52:26.207 ERROR (MainThread) [homeassistant.components.opower.coordinator] Unexpected error fetching Opower data: async_login not called
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 313, in _async_refresh
self.data = await self._async_update_data()
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/components/opower/coordinator.py", line 83, in _async_update_data
forecasts: list[Forecast] = await self.api.async_get_forecast()
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/site-packages/opower/opower.py", line 229, in async_get_forecast
for customer in await self._async_get_customers():
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/site-packages/opower/opower.py", line 301, in _async_get_customers
f"{self._get_subdomain()}"
^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/site-packages/opower/opower.py", line 545, in _get_subdomain
return self.utility.subdomain()
^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/site-packages/opower/utilities/aepbase.py", line 93, in subdomain
assert cls._subdomain, "async_login not called"
AssertionError: async_login not called
2024-02-08 15:52:26.210 DEBUG (MainThread) [homeassistant.components.opower.coordinator] Finished fetching Opower data in 1.450 seconds (success: False)
2024-02-08 15:53:48.065 ERROR (MainThread) [homeassistant.components.opower.coordinator] Unexpected error fetching Opower data: async_login not called
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 313, in _async_refresh
self.data = await self._async_update_data()
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/components/opower/coordinator.py", line 83, in _async_update_data
forecasts: list[Forecast] = await self.api.async_get_forecast()
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/site-packages/opower/opower.py", line 229, in async_get_forecast
for customer in await self._async_get_customers():
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/site-packages/opower/opower.py", line 301, in _async_get_customers
f"{self._get_subdomain()}"
^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/site-packages/opower/opower.py", line 545, in _get_subdomain
return self.utility.subdomain()
^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/site-packages/opower/utilities/aepbase.py", line 93, in subdomain
assert cls._subdomain, "async_login not called"
AssertionError: async_login not called
2024-02-08 15:53:48.074 DEBUG (MainThread) [homeassistant.components.opower.coordinator] Finished fetching Opower data in 1.413 seconds (success: False)
2024-02-08 15:55:09.733 ERROR (MainThread) [homeassistant.components.opower.coordinator] Unexpected error fetching Opower data: async_login not called
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 313, in _async_refresh
self.data = await self._async_update_data()
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/components/opower/coordinator.py", line 83, in _async_update_data
forecasts: list[Forecast] = await self.api.async_get_forecast()
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/site-packages/opower/opower.py", line 229, in async_get_forecast
for customer in await self._async_get_customers():
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/site-packages/opower/opower.py", line 301, in _async_get_customers
f"{self._get_subdomain()}"
^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/site-packages/opower/opower.py", line 545, in _get_subdomain
return self.utility.subdomain()
^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/site-packages/opower/utilities/aepbase.py", line 93, in subdomain
assert cls._subdomain, "async_login not called"
AssertionError: async_login not called
2024-02-08 15:55:09.737 DEBUG (MainThread) [homeassistant.components.opower.coordinator] Finished fetching Opower data in 1.433 seconds (success: False)
2024-02-08 15:56:31.132 ERROR (MainThread) [homeassistant.components.opower.coordinator] Unexpected error fetching Opower data: async_login not called
Traceback (most recent call last):
File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 313, in _async_refresh
self.data = await self._async_update_data()
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/src/homeassistant/homeassistant/components/opower/coordinator.py", line 83, in _async_update_data
forecasts: list[Forecast] = await self.api.async_get_forecast()
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/site-packages/opower/opower.py", line 229, in async_get_forecast
for customer in await self._async_get_customers():
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/site-packages/opower/opower.py", line 301, in _async_get_customers
f"{self._get_subdomain()}"
^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/site-packages/opower/opower.py", line 545, in _get_subdomain
return self.utility.subdomain()
^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/local/lib/python3.12/site-packages/opower/utilities/aepbase.py", line 93, in subdomain
assert cls._subdomain, "async_login not called"
AssertionError: async_login not called
2024-02-08 15:56:31.140 DEBUG (MainThread) [homeassistant.components.opower.coordinator] Finished fetching Opower data in 1.037 seconds (success: False)

@enter360
Copy link

enter360 commented Feb 9, 2024

This also affects City of Austin Utilities integration. Lines generated are analogous to already posted logs.

@max2697
Copy link
Contributor

max2697 commented Feb 9, 2024

Weird, it's been working fine for my COA account for two days. I've enabled debugging, but I can't see any issues. Even the monthly data loaded successfully.

@benhoff
Copy link
Contributor Author

benhoff commented Feb 9, 2024

Could you please enable debugging for this integration and display debug logs as well? I'm trying to figure out if this was affected by my changes in the opower.py file from the last 0.2.0 release.

Hey, thanks for looking into this! I'm super appreciative. While I'm a pretty competent python dev, the idea of setting up home assistant to debug gives me the shivers.

I see someone else posted their log, but I also attached a log to my original post.

It's a bit noisy, because I have a few things in my system broken, but the net of it is there doesn't appear to be much additional information in there.

Happy to roll up my sleeves if you need some help with something to reproduce, I believe I have ssh access to the instance and am fluent in Linux. I seem to remember that the environment is pretty limited due to HA using buildroot instead of a distro.

@benhoff
Copy link
Contributor Author

benhoff commented Feb 9, 2024

Based on the stack trace, I'm guessing in the below for loop, a check needs to be inserted to see if the user is logged in, and call async login if they are not. Otherwise, it'll keep throwing errors on the assert subdomain.

https://github.com/tronikos/opower/blob/2a84aa97e1fb6ce3eb5a80830a224b12b6b458a9/src/opower/opower.py#L229

@hiway65n
Copy link

hiway65n commented Feb 9, 2024

I just updated to Core 24.2.1 and it appears the issue has been resolved on my instance.

@benhoff
Copy link
Contributor Author

benhoff commented Feb 9, 2024

Same, updated and seems resolved.

Survived a restart as well, so I'll go ahead and close this and then reopen it if it pops back up. If anyone else has issues still and wants me to leave this open, let me know.

@benhoff benhoff closed this as completed Feb 9, 2024
@max2697
Copy link
Contributor

max2697 commented Feb 9, 2024

I'm glad that it was resolved, but I still have no idea how the new release fixed this

@guidoism
Copy link

I had the same exact issue today. Restarting HA solved it.

@enter360
Copy link

enter360 commented Feb 13, 2024

I have the updated core and the issue persist for me. City of Austin Utilities. I have deleted and reinstalled the Opower integration.

Steps taken to resolve

  1. Delete Integration from HA.
  2. Restart HA.
  3. Install Opower Integration from Integrations Store.
  4. Select City of Austin Utilities from drop down.
  5. Enter customer creds.
  6. Initialization failure occurs.

Below is the error that I pulled form the HA logs with debugger logging enabled.

Logger: homeassistant.components.opower.coordinator
Source: helpers/update_coordinator.py:313
Integration: Opower (documentation, issues)
First occurred: 11:04:40 PM (13 occurrences)
Last logged: 11:18:41 PM

Unexpected error fetching Opower data:
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 313, in _async_refresh
    self.data = await self._async_update_data()
                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/opower/coordinator.py", line 83, in _async_update_data
    forecasts: list[Forecast] = await self.api.async_get_forecast()
                                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/opower/opower.py", line 229, in async_get_forecast
    for customer in await self._async_get_customers():
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/opower/opower.py", line 297, in _async_get_customers
    await self._async_get_user_accounts()
  File "/usr/local/lib/python3.12/site-packages/opower/opower.py", line 342, in _async_get_user_accounts
    assert self.user_accounts
AssertionError

@enter360
Copy link

@benhoff should I open a new issue or can you reopen this one ? I provided logs and reproduction steps. This integration is still broken for me.

@benhoff benhoff reopened this Feb 16, 2024
@benhoff
Copy link
Contributor Author

benhoff commented Feb 16, 2024

@enter360 , reopened!

@benhoff
Copy link
Contributor Author

benhoff commented Feb 23, 2024

It looks like if the original get on the account usage page doesn't return a "Password" field, the async login function will return without setting the cls._subdomain instance. This will cause the async_login not called error.

Code issues highlighted below

    @classmethod
    async def async_login(
        cls,
        session: aiohttp.ClientSession,
        username: str,
        password: str,
        optional_mfa_secret: Optional[str],
    ) -> None:
        """Login in AEP using user/pass and then do the SAML call to opower."""
        login_parser = AEPLoginParser(username, password)
        token_parser = AEPTokenParser()

        # Get the login page and parse the ASP.Net Form Field that have generated names
        async with session.get(
            f"https://www.{cls.hostname()}/account/usage/",
            headers={"User-Agent": USER_AGENT},
            raise_for_status=True,
        ) as resp:
            login_parser.feed(await resp.text())

        if not login_parser.password_field_found: # <---- this is where we can return prematurely
            # Assume we are already logged in
            return

        # Post the login page with the user credentials and get the cookieKey
        async with session.post(
            f"https://www.{cls.hostname()}/account/usage/",
            headers={"User-Agent": USER_AGENT},
            raise_for_status=True,
            data=login_parser.inputs,
        ) as resp:
            html = await resp.text()
            token_parser.feed(html)

        if token_parser.token_url is None or token_parser.cookieKey is None:
            raise InvalidAuth("Username/Password are invalid")

        match = re.search(r"https://([^.]*).opower.com", html)
        assert match
        cls._subdomain = match.group(1) # <---- if this isn't set, we'll encounter async_login error

https://github.com/tronikos/opower/blob/2a84aa97e1fb6ce3eb5a80830a224b12b6b458a9/src/opower/utilities/aepbase.py#L126

I've tried to modify the function here, but I haven't had time to test it yet:
benhoff/opower@d0da40b

@benhoff
Copy link
Contributor Author

benhoff commented Feb 23, 2024

Opened a pull request in the opower repo that should resolve above.

Not sure how aggressive Home Assistant is in updating it's dependencies, but the opower integration will need to release a new version and then have HA update the opower dependency as well.

Looks like it's defined here, but I'm not familiar with how HA handles updating dependencies:

"requirements": ["opower==0.3.0"]

@benhoff benhoff mentioned this issue Feb 24, 2024
19 tasks
@benhoff
Copy link
Contributor Author

benhoff commented Feb 25, 2024

This should be fixed in 2024.2.4.

@benhoff
Copy link
Contributor Author

benhoff commented Feb 27, 2024

update and enjoy!

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests

5 participants