[3.0-beta11] Automation - profile percentage & NSClient sync

vmichalec commented 2 years ago

Hi, I'm using automation rules to set profile percentage. Those 3 rules are like:

BG >= 9.0 & BG delta >= 0.5 then apply 130% for 15 min
BG >= 10.0 & BG delta >= 0.1 then apply 120% for 15 min
BG >= 10.0 & BG delta >= -0.1 then apply 110% for 15 min

What I got today is this (AAPS): Screenshot_20211229-133448

The profile percentage has been applied 3 times. Details from treatments are bellow: first/left screenshot is from treatments from AAPS, second one/right is from NSCLIENT

Screenshot_20211229-133517 & Screenshot_20211229-133703_NSClient

On AAPS side I see that all three rules matched at 12:20. Is this ok? Where those all applied to pump? Or the last one - 110% is the winner? Then we can see there that it was for 15 minutes, but the previous profile was returned at 12:40 and that is 20 minutes. On NSCLIENT side there is only 130% entry at 12:20. Moreover on screenshot bellow from NSCLIENT we can see that only first profile change has some percentage and that doesn't correspond to AAPS.

Screenshot_20211229-133641_NSClient

So please check those screenshots yourself if this behavior is ok or not. From my point of view I prefer/suggest to have this automation rules list as an ordered list by priority and only first matching rule can adjust profile percentage. (Same with temporary target etc.) Logs are here: AndroidAPS_log.zip and NSCLIENT_log.zip

One minor thing hopefully easy to fix - the landscape layout of NSCLIENT. If you compare first and last screenshot (AAPS vs. NSCLIENT) - those buttons in the bottom (CALC here), on AAPS side whole screen is nicely scrollable, but on NSCLIENT side those bottom buttons are not part of scrollable area, are always there and took like 1/4 of the height.

Last thing I noticed while observing synchronization of profile changes to NSCLIENT was that sometimes when I make manual profile change on AAPS side there was no such entry on NSCLIENT, but I can see the change on nightscout frontend. As I investigated I noticed that this change was probably lost in/during websocket connection reset between nightscout and NSCLIENT. I'm running nightscout on heroku and here are some logs from there. Heroku is killing nightscout server from time to time. NSCLIENT reconnects but probably here is the chance to lost profile change notification (or not?).

HEROKU LOG (2021-12-29)
Dec 29 00:20:56 heroku/web.1 Stopping all processes with SIGTERM
Dec 29 00:56:56 heroku/web.1 Stopping all processes with SIGTERM
Dec 29 01:33:20 heroku/web.1 Stopping all processes with SIGTERM
Dec 29 02:10:31 heroku/web.1 Stopping all processes with SIGTERM
Dec 29 02:46:30 heroku/web.1 Stopping all processes with SIGTERM
Dec 29 03:20:48 heroku/web.1 Stopping all processes with SIGTERM
Dec 29 03:53:23 heroku/web.1 Stopping all processes with SIGTERM
Dec 29 04:27:47 heroku/web.1 Stopping all processes with SIGTERM
Dec 29 05:02:15 heroku/web.1 Stopping all processes with SIGTERM
Dec 29 06:07:14 heroku/web.1 Stopping all processes with SIGTERM
Dec 29 06:42:50 heroku/web.1 Stopping all processes with SIGTERM
Dec 29 07:18:29 heroku/web.1 Stopping all processes with SIGTERM
Dec 29 07:53:28 heroku/web.1 Stopping all processes with SIGTERM
Dec 29 08:29:58 heroku/web.1 Stopping all processes with SIGTERM
Dec 29 09:03:47 heroku/web.1 Stopping all processes with SIGTERM
Dec 29 09:40:12 heroku/web.1 Stopping all processes with SIGTERM
Dec 29 10:14:23 heroku/web.1 Stopping all processes with SIGTERM
Dec 29 10:48:57 heroku/web.1 Stopping all processes with SIGTERM
Dec 29 11:24:33 heroku/web.1 Stopping all processes with SIGTERM
Dec 29 13:10:56 heroku/web.1 Stopping all processes with SIGTERM
Dec 29 13:47:12 heroku/web.1 Stopping all processes with SIGTERM
Dec 29 14:23:13 heroku/web.1 Stopping all processes with SIGTERM

NSCLIENT LOG (2021-12-29)
00:21:06.575 [RxCachedThreadScheduler-22] D/NSCLIENT: [NSClientPlugin.onStart$lambda-5():124]: AUTH Authenticated (RWT)
00:57:06.944 [RxCachedThreadScheduler-22] D/NSCLIENT: [NSClientPlugin.onStart$lambda-5():124]: AUTH Authenticated (RWT)
01:33:30.892 [RxCachedThreadScheduler-22] D/NSCLIENT: [NSClientPlugin.onStart$lambda-5():124]: AUTH Authenticated (RWT)
02:10:41.247 [RxCachedThreadScheduler-22] D/NSCLIENT: [NSClientPlugin.onStart$lambda-5():124]: AUTH Authenticated (RWT)
02:46:40.045 [RxCachedThreadScheduler-22] D/NSCLIENT: [NSClientPlugin.onStart$lambda-5():124]: AUTH Authenticated (RWT)
03:20:57.751 [RxCachedThreadScheduler-22] D/NSCLIENT: [NSClientPlugin.onStart$lambda-5():124]: AUTH Authenticated (RWT)
03:53:33.341 [RxCachedThreadScheduler-22] D/NSCLIENT: [NSClientPlugin.onStart$lambda-5():124]: AUTH Authenticated (RWT)
04:27:56.460 [RxCachedThreadScheduler-22] D/NSCLIENT: [NSClientPlugin.onStart$lambda-5():124]: AUTH Authenticated (RWT)
05:02:24.797 [RxCachedThreadScheduler-22] D/NSCLIENT: [NSClientPlugin.onStart$lambda-5():124]: AUTH Authenticated (RWT)
06:07:24.604 [RxCachedThreadScheduler-22] D/NSCLIENT: [NSClientPlugin.onStart$lambda-5():124]: AUTH Authenticated (RWT)
06:42:59.594 [RxCachedThreadScheduler-22] D/NSCLIENT: [NSClientPlugin.onStart$lambda-5():124]: AUTH Authenticated (RWT)
07:18:39.163 [RxCachedThreadScheduler-22] D/NSCLIENT: [NSClientPlugin.onStart$lambda-5():124]: AUTH Authenticated (RWT)
07:53:38.648 [RxCachedThreadScheduler-22] D/NSCLIENT: [NSClientPlugin.onStart$lambda-5():124]: AUTH Authenticated (RWT)
08:30:10.950 [RxCachedThreadScheduler-22] D/NSCLIENT: [NSClientPlugin.onStart$lambda-5():124]: AUTH Authenticated (RWT)
09:03:57.931 [RxCachedThreadScheduler-22] D/NSCLIENT: [NSClientPlugin.onStart$lambda-5():124]: AUTH Authenticated (RWT)
09:40:21.605 [RxCachedThreadScheduler-22] D/NSCLIENT: [NSClientPlugin.onStart$lambda-5():124]: AUTH Authenticated (RWT)
10:14:33.584 [RxCachedThreadScheduler-22] D/NSCLIENT: [NSClientPlugin.onStart$lambda-5():124]: AUTH Authenticated (RWT)
10:49:10.686 [RxCachedThreadScheduler-22] D/NSCLIENT: [NSClientPlugin.onStart$lambda-5():124]: AUTH Authenticated (RWT)
11:24:43.826 [RxCachedThreadScheduler-22] D/NSCLIENT: [NSClientPlugin.onStart$lambda-5():124]: AUTH Authenticated (RWT)
11:56:04.192 [RxCachedThreadScheduler-22] D/NSCLIENT: [NSClientPlugin.onStart$lambda-5():124]: AUTH Authenticated (RWT)
12:09:04.422 [RxCachedThreadScheduler-22] D/NSCLIENT: [NSClientPlugin.onStart$lambda-5():124]: AUTH Authenticated (RWT)
13:11:06.160 [RxCachedThreadScheduler-22] D/NSCLIENT: [NSClientPlugin.onStart$lambda-5():124]: AUTH Authenticated (RWT)
13:47:22.809 [RxCachedThreadScheduler-22] D/NSCLIENT: [NSClientPlugin.onStart$lambda-5():124]: AUTH Authenticated (RWT)
14:23:23.244 [RxCachedThreadScheduler-22] D/NSCLIENT: [NSClientPlugin.onStart$lambda-5():124]: AUTH Authenticated (RWT)

MilosKozak commented 2 years ago

i see more issues with current implementation:

applying ProfileSwitch take some time thus another PS rule is executed as well because percentage is not visible immediately
it looks like multiple PS' are deduplicated on NS side even they have slighly different timestamp

but rules are processed in order you see on automation tab (and you can change it by drag&drop)

MilosKozak commented 2 years ago

for TT this is not an issue becaue change is visible immediately

MilosKozak commented 2 years ago

resolved by https://github.com/nightscout/AndroidAPS/commit/40864620e09e4f6b03293eff89228fb2b1f96372

nightscout / AndroidAPS

[3.0-beta11] Automation - profile percentage & NSClient sync #1111