Works initially, but after some time requests fail & return 'token is expired' message

[NeighborGeek]

I am running bluelinky on a raspberry pi 4, using this code to start a web daemon listening for commands. It works great when I first launch it, but after some period of time commands stop working and I get this error back instead:

/lock 192.168.1.99 token is expired, refreshing access token TypeError: Cannot read property 'RESPONSE_STRING' of null at Vehicle.<anonymous> (/home/pi/Documents/node_modules/bluelinky/dist/index.js:149:34) at Generator.next (<anonymous>) at fulfilled (/home/pi/Documents/node_modules/bluelinky/dist/index.js:52:58) at processTicksAndRejections (internal/process/task_queues.js:93:5)

I don't know what the exact timeout for this is. I'm sure it's at least an hour, because I've seen commands succeed nearly an hour after starting it.

[Hacksore]

Thanks for submitting an issue @NeighborGeek. My best guess is the token refreshing logic is not working as expected hence the error you are getting.

I've been using firebase functions so my token basically refreshes every request. I just added some better error handling to the token refresh logic so could you please update to 0.0.3 and if the issue persists hopefully the logs should give us a better idea.

One thing I might be overlooking is the value coming back from Hyundai API expires_in. I am thinking the value is in seconds but that is quite some time for a token to expire.

{
  "expires_in": "28799"
}

Leaving this issue open until we can find the root cause.

[NeighborGeek]

I updated yesterday and this morning the command still failed with a token is expired message, but the rest of the error was different:

/lock 192.168.1.99 Token is expired, refreshing access token Error: PIN is locked, please correct the isssue before trying again. at Vehicle.<anonymous> (/home/pi/Documents/node_modules/bluelinky/dist/index.js:333:23) at Generator.next (<anonymous>) at fulfilled (/home/pi/Documents/node_modules/bluelinky/dist/index.js:52:58) at processTicksAndRejections (internal/process/task_queues.js:93:5)

[Hacksore]

@NeighborGeek

I was seeing that same issue you had initially which was why I added a check to see if the response from the api says pin locked.

Must be some kind of rate limiting on their side? How frequently are you calling the lock command.

[NeighborGeek]

Hours apart. It worked twice last night around 3 hours apart. This morning, it failed with that error.

[NeighborGeek]

It looks like that expires_in value comes out to just under 8 hours if it is in seconds. Based on the fact that it works for at least a few hours, that seems possible. The times that it stops working for me have been more than 8 hours after starting the program. I don't think I've tried it at all between 4-8 hours after starting it, but I can't be sure. You might consider adding a timestamp to the output, to clearly document when each request was received.

[Hacksore]

@NeighborGeek I published version 0.0.5 so you can start the node server like LOG_LEVEL='debug' node server.js for more verbose output.

Could you please give that a try and report back?

[NeighborGeek]

Done. Having just started it now, I should be able to produce the error late tonight or tomorrow morning.

Thanks!

On Tue, Nov 26, 2019 at 4:11 PM Sean Boult notifications@github.com wrote:

@NeighborGeek https://github.com/NeighborGeek I published version 0.0.5 so you can start the node server like LOG_LEVEL='debug' node server.js for more verbose output.

Could you please give that a try and report back?

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/Hacksore/bluelinky/issues/4?email_source=notifications&email_token=AAZ6RZQIP7GQLJ2Y5KGMT3LQVWNJDA5CNFSM4JQ4H3JKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEFHTOBY#issuecomment-558839559, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAZ6RZQCUBN4PB5RIP2UBBDQVWNJDANCNFSM4JQ4H3JA .

[NeighborGeek]

Here's the log since I started this yesterday:

/lock 192.168.1.8
[2019-11-26 16:30:09] debug: Fetching CSRF Token ey...longstringhere...Bb-tk
[2019-11-26 16:30:10] debug: Fetching JSON Auth Token, RESPONSE: {"E_IFRESULT":"Z:Success","E_IFFAILMSG":"","Token":{"access_token":"{7586...longstringhere...322b03532ae76b018a0c0e}","refresh_token":"w6q2...longstringhere...tC0vhw__","expires_in":"28799","username":"email@address.here"},"erroCode":"200","s_name":"{c4d...longstringhere...61}"}
[2019-11-26 16:30:10] info: Logged in to bluelink, token expires at 1574836209
[2019-11-26 16:30:10] info: Current time: 1574807410
[2019-11-26 16:30:10] debug: [https://owners.hyundaiusa.com/bin/common/enrollmentStatus] {"service":"getEnrollment"}
[2019-11-26 16:30:10] debug: token time: 1574836209
[2019-11-26 16:30:10] debug: Token is still valid: 28799
[2019-11-26 16:30:28] debug: "{\"E_IFRESULT\":\"Z:Success\",\"E_IFFAILMSG\":\"\",\"ENROLLMENT_DETAILS\":...trimming response for brevity and privacy...",\"appName\":\"ALERT SERVICES\",\"appStatus\":\"DOWNLOADED\"}]}}"
[2019-11-26 16:30:28] debug: [https://owners.hyundaiusa.com/bin/common/remoteAction] {"gen":2,"regId":"VINHERE","service":"remotelock"}
[2019-11-26 16:30:28] debug: token time: 1574836209
[2019-11-26 16:30:28] debug: Token is still valid: 28781
[2019-11-26 16:30:29] debug: "{\"E_IFRESULT\":\"Z:Success\",\"E_IFFAILMSG\":\"\",\"RESPONSE_STRING\":\"\"}"
/lock 192.168.1.22
[2019-11-27 12:42:29] debug: [https://owners.hyundaiusa.com/bin/common/remoteAction] {"gen":2,"regId":"VIN","service":"remotelock"}
[2019-11-27 12:42:29] debug: token time: 1574836209
[2019-11-27 12:42:29] debug: Token is still valid: -43940
[2019-11-27 12:42:30] debug: "PIN Locked = Token has expired"
Error: PIN is locked, please correct the isssue before trying again.
    at Vehicle.<anonymous> (/home/pi/Documents/node_modules/bluelinky/dist/index.js:352:23)
    at Generator.next (<anonymous>)
    at fulfilled (/home/pi/Documents/node_modules/bluelinky/dist/index.js:53:58)
    at processTicksAndRejections (internal/process/task_queues.js:93:5)
/lock 192.168.1.22
[2019-11-27 15:59:39] debug: [https://owners.hyundaiusa.com/bin/common/remoteAction] {"gen":2,"regId":"VIN","service":"remotelock"}
[2019-11-27 15:59:39] debug: token time: 1574836209
[2019-11-27 15:59:39] debug: Token is still valid: -55770
[2019-11-27 15:59:39] debug: "PIN Locked = Token has expired"
Error: PIN is locked, please correct the isssue before trying again.
    at Vehicle.<anonymous> (/home/pi/Documents/node_modules/bluelinky/dist/index.js:352:23)
    at Generator.next (<anonymous>)
    at fulfilled (/home/pi/Documents/node_modules/bluelinky/dist/index.js:53:58)
    at processTicksAndRejections (internal/process/task_queues.js:93:5)
`Here's the log since I started this yesterday.  
`/lock 192.168.1.8
[2019-11-26 16:30:09] debug: Fetching CSRF Token ey...longstringhere...Bb-tk
[2019-11-26 16:30:10] debug: Fetching JSON Auth Token, RESPONSE: {"E_IFRESULT":"Z:Success","E_IFFAILMSG":"","Token":{"access_token":"{7586...longstringhere...322b03532ae76b018a0c0e}","refresh_token":"w6q2...longstringhere...tC0vhw__","expires_in":"28799","username":"email@address.here"},"erroCode":"200","s_name":"{c4d...longstringhere...61}"}
[2019-11-26 16:30:10] info: Logged in to bluelink, token expires at 1574836209
[2019-11-26 16:30:10] info: Current time: 1574807410
[2019-11-26 16:30:10] debug: [https://owners.hyundaiusa.com/bin/common/enrollmentStatus] {"service":"getEnrollment"}
[2019-11-26 16:30:10] debug: token time: 1574836209
[2019-11-26 16:30:10] debug: Token is still valid: 28799
[2019-11-26 16:30:28] debug: "{\"E_IFRESULT\":\"Z:Success\",\"E_IFFAILMSG\":\"\",\"ENROLLMENT_DETAILS\":...trimming response for brevity and privacy...",\"appName\":\"ALERT SERVICES\",\"appStatus\":\"DOWNLOADED\"}]}}"
[2019-11-26 16:30:28] debug: [https://owners.hyundaiusa.com/bin/common/remoteAction] {"gen":2,"regId":"VINHERE","service":"remotelock"}
[2019-11-26 16:30:28] debug: token time: 1574836209
[2019-11-26 16:30:28] debug: Token is still valid: 28781
[2019-11-26 16:30:29] debug: "{\"E_IFRESULT\":\"Z:Success\",\"E_IFFAILMSG\":\"\",\"RESPONSE_STRING\":\"\"}"
/lock 192.168.1.22
[2019-11-27 12:42:29] debug: [https://owners.hyundaiusa.com/bin/common/remoteAction] {"gen":2,"regId":"VIN","service":"remotelock"}
[2019-11-27 12:42:29] debug: token time: 1574836209
[2019-11-27 12:42:29] debug: Token is still valid: -43940
[2019-11-27 12:42:30] debug: "PIN Locked = Token has expired"
Error: PIN is locked, please correct the isssue before trying again.
    at Vehicle.<anonymous> (/home/pi/Documents/node_modules/bluelinky/dist/index.js:352:23)
    at Generator.next (<anonymous>)
    at fulfilled (/home/pi/Documents/node_modules/bluelinky/dist/index.js:53:58)
    at processTicksAndRejections (internal/process/task_queues.js:93:5)
/lock 192.168.1.22
[2019-11-27 15:59:39] debug: [https://owners.hyundaiusa.com/bin/common/remoteAction] {"gen":2,"regId":"VIN","service":"remotelock"}
[2019-11-27 15:59:39] debug: token time: 1574836209
[2019-11-27 15:59:39] debug: Token is still valid: -55770
[2019-11-27 15:59:39] debug: "PIN Locked = Token has expired"
Error: PIN is locked, please correct the isssue before trying again.
    at Vehicle.<anonymous> (/home/pi/Documents/node_modules/bluelinky/dist/index.js:352:23)
    at Generator.next (<anonymous>)
    at fulfilled (/home/pi/Documents/node_modules/bluelinky/dist/index.js:53:58)
    at processTicksAndRejections (internal/process/task_queues.js:93:5)

[Hacksore]

@NeighborGeek I think this was my fault, will release 0.0.6 here shortly.

edit: 0.0.6 is published

[NeighborGeek]

Here's the log entry from today:

/lock 192.168.1.22
[2019-11-28 22:05:03] debug: [https://owners.hyundaiusa.com/bin/common/remoteAction] {"gen":2,"regId":"VIN","service":"remotelock"}
[2019-11-28 22:05:03] debug: token time: 1574938079
[2019-11-28 22:05:03] info: Token is about to expire, refreshing access token 60 seconds early
[2019-11-28 22:05:04] debug: Fetching CSRF Token eyJleHAiOjE1NzUwMDA5MDQsImlhdCI6MTU3NTAwMDMwNH0.WJC0R03ce7buk-7fhIN3VU9Wmen217CraYu2kIi-AIs
[2019-11-28 22:05:05] debug: Fetching JSON Auth Token, RESPONSE: {"E_IFRESULT":"Z:Success","E_IFFAILMSG":"","Token":{"access_token":"{0adca916ef17d58080ecf2a126d7ceb719d09a6bee3232ba726d849595d1dfa592e22e3d0f4ac26d298d3b48fa9ae4e08b5351ba8949474d3f04569769bf1b056fcb37d064b6a0e2fc13de182e4477a36dcf50f9a3896e05088ca152ff3bb7d1750f4219062583d8e357af2326f8f0048c5ab977f2c90202804957deb1c3c23e22fe577dec34eaec256b4d656bd5b227d8da9643e3b17abcae1bcec0acaca9826abadda245a015349f7ec57fd}","refresh_token":"w6q2T/okx5dKu0YxjaGYtZnseBROS8uAOpspFLtX/rnhBTa+yXu6XvpPsTpJJR+73JKBamye1MTkiIklLwPAhrpdiXFrEnXWjm+rCf85wjvm6Vr5K3TMpoVBV0PrwkHTp2+TKTNV8CJpoztq6myD+g5zsl42gsMoyVfA42nJIcCJUSRXaBb+WBEoZH8j58qfBrOAjskxyNiy5PY426FxstzyKDyZ+rZztGBZCENx7zCubTF+jQwnGgooF4+u0iqEy4Ab6ZZQscWDGI57gY3l9jzU2Lv5/EamLM1d+ZKMbsxnzs/MKfnpwxsEB11jK9t3ykd/qnntItHQysWpnu2vMQN7JYbRPkCyysAIKyB1w47eVDV7q55eXwg0WWezFXwtCeEyKOkYbyyVmlGuH9Zx8aoWpToPAdS6C0Fp0sAZZQKfO3B8fxtC3GUE+SLd7lcictCuAf5bWUTcoBJOScgzPVklwTgS59WcdFmCsDj2i66wKjb7Qp6H/CNai2mG1MHyx3cC9MLXotnGTxw1ynyudqg1ok6mxpmxGoQ0YETXbS0t204t+Zfbj/vRbxkrByjNG15I+qxDkhi321VjxpMCf5OUfSHchsXQ9lI67f3E8eSiQCPYdlu7oUYmtghap5R3tAjJRAYwtT78iyfjAcuFybAFXH1QDjH1X9x3jX/5sHcSjAyfgWCUKxB5dgUFFhtd2NZBNP6a4LM0VHWPxBHONwlsebPXOWcJKQhB05N2NDcHJ1ljaD+FI39wz6uKz8wlrOIxdHAyWp5zFFCOeU4wU2xmm2PM+wHCaz1UMPGt1qXKaui0LbZ+r+lP1jHcnYnqG2XoDeBtU6oc7ZOXpB7iWg__","expires_in":"28799","username":"email@address.here"},"erroCode":"200","s_name":"{f3163f061bd9b21e4e8343545b37d2187db8bb9225122c7af58f2fdf27e6f1646c0b500e25b10a01e8fb2b364c88e5ca}"}
[2019-11-28 22:05:05] debug: Token is refreshed {"access_token":"{0adcc5fb2250a60c0ad343fabd4533d261fa50cadcd80452007ea99a3dc667c33cf2a4b0a511bce8f13226e913ba18de101b174364f2b5cf00f89f98fa49450e2eedc4f26d376644cd28d42677d36422e8a6c4a0d2138b3b173946f2d39478f7009573236678032ae282314f565d0a69db7272e0e957139868d3be9252fe64b3eef39021006f3cb4ac922af44b487d05935c24e0d091356da611beb187bf238950e563c75d59f55f3af3027532f828fbe9429faa22ee4b86ff9ac90a8273cc10cf87e6ad02785f1f9a6efe5b8a2d1f96a292ce6489904097121c07445cc4dc3c216141bd289516fac190cb346112f036a07fa6615456d8bf7d9f7860ff507cfb75dc50de8df5193419fc374b11f1154f37e3d1414bbc4ba4e3682cafbfba86c7c0498d469644228bdea5f6924adcc295072b690d7ea192eb80a6d8390bb8b650ffc9aeb9df3852cd79d8d9d9163a7f8606c78ce3180a5884e127cef0eb1d5cc12b8289746cdeb25d5718d8f20ad750daa22917627a189a8bb568ddb976f394de554a12b9060135baa6c490f30c6b3636b0f2fda4b983e7feddec8fb85f06616b757eaf754134a717902f5e697e73680ed1160429833763da2f7e0b6a57407383da50c759c7e3911848f225679b73e4928911cac9bbdf8c206780e3cb5a7a6f555fe04c2db4b6bab6dd1a417be3b7c5341dcc5802b3d4fcc281b7193a415057356496c66d66d4880cb81e7dc04c671d12cfcbbe275533677cc4a12c1a2f010090552dc63cd0b906273ae47e3d4d55de9fa275da5e01f82a77ac11d3509e2655880bf1e9ca258dea76a3219899d8cee67ef3be003a0b8eb6dbf4f6143190e0e9acf1813688b6798f5b29521dc2dfb9264440db9d87b7da916ef17d58080ecf2a126d7ceb719d09a6bee3232ba726d849595d1dfa592e22e3d0f4ac26d298d3b48fa9ae4e08b5351ba8949474d3f04569769bf1b056fcb37d064b6a0e2fc13de182e4477a36dcf50f9a3896e05088ca152ff3bb7d1750f4219062583d8e357af2326f8f0048c5ab977f2c90202804957deb1c3c23e22fe577dec34eaec256b4d656bd5b227d8da9643e3b17abcae1bcec0acaca9826abadda245a015349f7ec57fd}","refresh_token":"w6q2T/okx5dKu0YxjaGYtZnseBROS8uAOpspFLtX/rnhBTa+yXu6XvpPsTpJJR+73JKBamye1MTkiIklLwPAhrpdiXFrEnXWjm+rCf85wjvm6Vr5K3TMpoVBV0PrwkHTp2+TKTNV8CJpoztq6myD+g5zsl42gsMoyVfA42nJIcCJUSRXaBb+WBEoZH8j58qfBrOAjskxyNiy5PY426FxstzyKDyZ+rZztGBZCENx7zCubTF+jQwnGgooF4+u0iqEy4Ab6ZZQscWDGI57gY3l9jzU2Lv5/EamLM1d+ZKMbsxnzs/MKfnpwxsEB11jK9t3ykd/qnntItHQysWpnu2vMQN7JYbRPkCyysAIKyB1w47eVDV7q55eXwg0WWezFXwtCeEyKOkYbyyVmlGuH9Zx8aoWpToPAdS6C0Fp0sAZZQKfO3B8fxtC3GUE+SLd7lcictCuAf5bWUTcoBJOScgzPVklwTgS59WcdFmCsDj2i66wKjb7Qp6H/CNai2mG1MHyx3cC9MLXotnGTxw1ynyudqg1ok6mxpmxGoQ0YETXbS0t204t+Zfbj/vRbxkrByjNG15I+qxDkhi321VjxpMCf5OUfSHchsXQ9lI67f3E8eSiQCPYdlu7oUYmtghap5R3tAjJRAYwtT78iyfjAcuFybAFXH1QDjH1X9x3jX/5sHcSjAyfgWCUKxB5dgUFFhtd2NZBNP6a4LM0VHWPxBHONwlsebPXOWcJKQhB05N2NDcHJ1ljaD+FI39wz6uKz8wlrOIxdHAyWp5zFFCOeU4wU2xmm2PM+wHCaz1UMPGt1qXKaui0LbZ+r+lP1jHcnYnqG2XoDeBtU6oc7ZOXpB7iWg__","expires_in":"28799","username":"email@address.here"}
[2019-11-28 22:05:05] debug: "PIN Locked = Token has expired"
Error: PIN is locked, please correct the isssue before trying again.
    at Vehicle.<anonymous> (/home/pi/Documents/node_modules/bluelinky/dist/index.js:352:23)
    at Generator.next (<anonymous>)
    at fulfilled (/home/pi/Documents/node_modules/bluelinky/dist/index.js:53:58)
    at processTicksAndRejections (internal/process/task_queues.js:93:5)

[Hacksore]

@NeighborGeek https://github.com/Hacksore/bluelinky/commit/7d7494527bafddb7994b9c4ddd91eaeea94594d1#diff-13b5b151431c7e7a17f273559ed212d5R98 That should fix it as I was not saving the token after a new one had been fetched.

[NeighborGeek]

Looks like that did it. Thanks!