Login fail for version >=0.2.4 with Response code 401 (Unauthorized)

[MaxWinterstein]

Starting with version 0.2.4 login is no longer possible for me. I can clearly test it by jumping from 0.2.3 to 0.2.4 forth and back.

Log output:

{23:55}~/tmp ➭ docker run --rm -ti -e NODE_CONSOLE_LOG_LEVEL=debug -v $PWD/config.yml:/app/data/config.yml matijse/eufy-ha-mqtt-bridge:0.2.3

> [email protected] start /app
> NODE_ENV=production node --unhandled-rejections=strict index.js

info: Migrating the database... {"timestamp":"2021-01-24T22:55:26.452Z"}
debug: Subscribed to homeassistant/status {"timestamp":"2021-01-24T22:55:27.037Z"}
debug: Refreshing devices... {"timestamp":"2021-01-24T22:55:27.046Z"}
debug: MQTT message: [homeassistant/status]: online {"timestamp":"2021-01-24T22:55:27.313Z"}
info: Stored device: Garten (T8113NXXXXXXXXXX - type: T8113) {"timestamp":"2021-01-24T22:55:30.092Z"}
info: Stored device: Terrasse (T8113NXXXXXXXXXX - type: T8113) {"timestamp":"2021-01-24T22:55:30.143Z"}
info: No credentials found -> register new... {"timestamp":"2021-01-24T22:55:35.162Z"}
info: Registered Push Token {"response":{"code":0,"msg":"Succeed."},"timestamp":"2021-01-24T22:55:41.826Z"}
debug: Uploading new thumbnail for T8113NXXXXXXXXXX from ... {"timestamp":"2021-01-24T22:55:41.828Z"}
debug: Uploading new thumbnail for T8113NXXXXXXXXXX from ... {"timestamp":"2021-01-24T22:55:42.121Z"}
debug: Publishing battery percentage 41% for T8113NXXXXXXXXXX {"timestamp":"2021-01-24T22:55:42.420Z"}
debug: Publishing battery percentage 96% for T8113NXXXXXXXXXX {"timestamp":"2021-01-24T22:55:42.422Z"}
^C%

{23:56}~/tmp ➭ docker run --rm -ti -e NODE_CONSOLE_LOG_LEVEL=debug -v $PWD/config.yml:/app/data/config.yml matijse/eufy-ha-mqtt-bridge:0.2.4

> [email protected] start /app
> NODE_ENV=production node --unhandled-rejections=strict index.js

info: Migrating the database... {"timestamp":"2021-01-24T22:56:16.178Z"}
debug: MQTT message: [homeassistant/status]: online {"timestamp":"2021-01-24T22:56:16.575Z"}
debug: Refreshing devices... {"timestamp":"2021-01-24T22:56:16.576Z"}
debug: Subscribed to homeassistant/status {"timestamp":"2021-01-24T22:56:16.593Z"}
debug: Refreshing devices... {"timestamp":"2021-01-24T22:56:16.593Z"}
(node:25) UnhandledPromiseRejectionWarning: HTTPError: Response code 401 (Unauthorized)
    at Request.<anonymous> (/app/node_modules/got/dist/source/as-promise/index.js:117:42)
    at processTicksAndRejections (internal/process/task_queues.js:93:5)
(Use `node --trace-warnings ...` to show where the warning was created)
(node:25) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 1)
npm ERR! code ELIFECYCLE
npm ERR! errno 1
npm ERR! [email protected] start: `NODE_ENV=production node --unhandled-rejections=strict index.js`
npm ERR! Exit status 1
npm ERR!
npm ERR! Failed at the [email protected] start script.
npm ERR! This is probably not a problem with npm. There is likely additional logging output above.

npm ERR! A complete log of this run can be found in:
npm ERR!     /root/.npm/_logs/2021-01-24T22_56_18_448Z-debug.log

Also tried running directly from sources via npm, same result.

Even more confusion after looking at the diff between the to releases: 0.2.3...0.2.4

[matijse]

I was thinking it might be due to using the login in 2 different integrations. Do you have another integration running? (official HA eufy integration or ioBroker). The reasoning was that with the changes, there are some more delays and now more often it will call the Eufy API (e.g. hourly for battery percentage). The other script might block this script, as I saw sometimes you are logged out of other sessions when you log in for example at a new phone...

But seeing these logs, I don't think that is the case. It still is a good idea to only use an account for one integration. But what I see here is that your installation sends online to homeassistant/status immediately when MQTT subscribes... This is not the case for me. I don't know if your HA setup does this, or that the message is wrongly published with a retain flag in the MQTT broker...

Due to this, you see it very quickly after each other is refreshing the devices twice. I build a solution that the answer to this request is cached, so it is not requested too often. But as shown here, in this situation it is called twice in the same second, so the first request is not finished before the second one starts. This probably means both requests are doing the full request, with both doing a login and then a request. This makes one of them fail.

I think it can be fixed by re-arranging the code a bit... maybe first refreshing the devices and only when that is finished subscribing to MQTT...

[MaxWinterstein]

Should be a uniqe account, but having two addons, iobroker and mobile phones i might have messed up a little bit...

Talking about twice, using more debug on 0.2.5 i saw this:

{0:45}~/tmp/eufy/eufy-ha-mqtt-bridge:main ✗ ➭ NODE_CONSOLE_LOG_LEVEL=silly DEBUG=true npm run dev

> [email protected] dev /Users/winterstein/tmp/eufy/eufy-ha-mqtt-bridge
> NODE_CONSOLE_LOG_LEVEL=debug node --unhandled-rejections=strict index.js

info: Migrating the database... {"timestamp":"2021-01-24T23:45:05.200Z"}
debug: ---- EUFY INITIALIZE START ---- {"timestamp":"2021-01-24T23:45:05.206Z"}
debug: ----  Created classes... {"timestamp":"2021-01-24T23:45:05.207Z"}
debug: ----  Set up MQTT handler {"timestamp":"2021-01-24T23:45:05.207Z"}
debug: Subscribed to homeassistant/status {"timestamp":"2021-01-24T23:45:06.011Z"}
debug: ----  Connected to MQTT {"timestamp":"2021-01-24T23:45:06.011Z"}
debug: Refreshing devices... {"timestamp":"2021-01-24T23:45:06.013Z"}
debug: MQTT message: [homeassistant/status]: online {"timestamp":"2021-01-24T23:45:06.059Z"}
debug: Refreshing devices... {"timestamp":"2021-01-24T23:45:06.060Z"}
(node:67911) UnhandledPromiseRejectionWarning: Error: Request failed: https://mysecurity.eufylife.com/api/v1/passport/login -> 100028 - Failed to request.
    at /Users/winterstein/tmp/eufy/eufy-ha-mqtt-bridge/node_modules/eufy-node-client/build/http/http.utils.js:24:15
    at Generator.next (<anonymous>)
    at fulfilled (/Users/winterstein/tmp/eufy/eufy-ha-mqtt-bridge/node_modules/eufy-node-client/build/http/http.utils.js:5:58)
    at processTicksAndRejections (internal/process/task_queues.js:93:5)
(Use `node --trace-warnings ...` to show where the warning was created)
(node:67911) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 1)
(node:67911) UnhandledPromiseRejectionWarning: Error: Request failed: https://mysecurity.eufylife.com/api/v1/passport/login -> 100028 - Failed to request.
    at /Users/winterstein/tmp/eufy/eufy-ha-mqtt-bridge/node_modules/eufy-node-client/build/http/http.utils.js:24:15
    at Generator.next (<anonymous>)
    at fulfilled (/Users/winterstein/tmp/eufy/eufy-ha-mqtt-bridge/node_modules/eufy-node-client/build/http/http.utils.js:5:58)
    at processTicksAndRejections (internal/process/task_queues.js:93:5)
(node:67911) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 2)

[matijse]

Yes, here you see the same thing happening (2 x refreshing devices), but with different error.

Above the error is Response code 401 (Unauthorized), which I believe is due to both requesting the device list after logging in, and one of them failing, because the last login invalidated the first login.

This error is 100028 - Failed to request, which happens when you try to login. This means your account got blocked, and logging in is not possible. (Again it does the login twice, or at least tries it twice)

I think I can make a new version tonight which should not request the device list twice, hopefully fixing the issue...

[matijse]

Version 0.2.6 changes the startup order, hopefully fixing the issue...

[MaxWinterstein]

Quick try with your docker image 0.2.6 worked, locally checkout out not, but had add on phone logged on that account.

More later 👍

[MaxWinterstein]

Okay, had some tests, Eufy is still confused about my accounts. Smartphone app still showed 401, one second later it worked fine...

Thanks for release 0.2.6 (or 0.2.7 now), works fine for me. Add-on updated as well ✌️