BasicUI rapidly requests sitemap SSE subscriptions while phone is locked/asleep

[mhilbush]

I've observed this behavior on an Android phone while the phone is locked/asleep. There is at least one other report of this happening on iPhone and Mac as reported in this forum post.

I've recreated the issue with Chrome and Firefox on Android v8.1.0 (on a Pixel 2 XL).

This issue would result in the system reaching the max subscriptions, which would cause BasicUI to display the message SSE subscription failed: running in fallback mode. Prior to PR #5910, these subscriptions would never be released.

Below is an example of the problem using Firefox. While the phone is locked/asleep, subscriptions are created every several milliseconds. Additional information and discussion is in issue #4809.

I've experimented with various lock/sleep settings; however, so far I've found no combination of settings that makes the problem go away.

2018-07-11 20:27:13.935 [DEBUG] [t.sitemap.SitemapSubscriptionService] - Created new subscription with id bb5f74bd-4de8-4689-96d1-8a66d3ec6b8f (24 active subscriptions for a max of 68)
2018-07-11 20:27:13.953 [DEBUG] [t.sitemap.SitemapSubscriptionService] - Subscription bb5f74bd-4de8-4689-96d1-8a66d3ec6b8f changed to page 1410r of sitemap 1410r (24 active subscriptions}
2018-07-11 20:27:13.954 [DEBUG] [est.sitemap.internal.SitemapResource] - Client requested sitemap event stream for subscription bb5f74bd-4de8-4689-96d1-8a66d3ec6b8f.

Phone was locked by pressing the power button.

2018-07-11 20:27:51.649 [DEBUG] [.sitemap.internal.SitemapEventOutput] - Sent sitemap event for widget 0000 to subscription bb5f74bd-4de8-4689-96d1-8a66d3ec6b8f.
2018-07-11 20:28:51.649 [DEBUG] [.sitemap.internal.SitemapEventOutput] - Sent sitemap event for widget 0000 to subscription bb5f74bd-4de8-4689-96d1-8a66d3ec6b8f.
2018-07-11 20:29:51.651 [DEBUG] [.sitemap.internal.SitemapEventOutput] - Sent sitemap event for widget 0000 to subscription bb5f74bd-4de8-4689-96d1-8a66d3ec6b8f.

2018-07-11 20:30:51.653 [DEBUG] [est.sitemap.internal.SitemapResource] - SSE connection for subscription bb5f74bd-4de8-4689-96d1-8a66d3ec6b8f has been closed.
2018-07-11 20:30:51.653 [DEBUG] [t.sitemap.SitemapSubscriptionService] - Removed subscription with id bb5f74bd-4de8-4689-96d1-8a66d3ec6b8f (23 active subscriptions)

2018-07-11 20:36:36.992 [DEBUG] [t.sitemap.SitemapSubscriptionService] - Created new subscription with id 80e9e4ba-24b5-4d9b-ad2c-0b7a65f30525 (24 active subscriptions for a max of 68)
2018-07-11 20:36:37.005 [DEBUG] [t.sitemap.SitemapSubscriptionService] - Created new subscription with id f9655684-6e69-40b1-abe3-a4d867b8d99a (25 active subscriptions for a max of 68)
2018-07-11 20:36:37.010 [DEBUG] [t.sitemap.SitemapSubscriptionService] - Created new subscription with id 40d6133c-d4f4-4c6d-8502-0eca31b4273b (26 active subscriptions for a max of 68)
2018-07-11 20:36:37.016 [DEBUG] [t.sitemap.SitemapSubscriptionService] - Created new subscription with id 564b8d70-0754-45e2-9534-ca7b1bd6e742 (27 active subscriptions for a max of 68)
2018-07-11 20:36:37.023 [DEBUG] [t.sitemap.SitemapSubscriptionService] - Created new subscription with id 95ade8aa-c2e7-421f-a836-5bfcc0fdcf8d (28 active subscriptions for a max of 68)
2018-07-11 20:36:37.029 [DEBUG] [t.sitemap.SitemapSubscriptionService] - Created new subscription with id 346f5ee3-acd7-46f0-ad01-6136b0edfdd6 (29 active subscriptions for a max of 68)
2018-07-11 20:36:37.035 [DEBUG] [t.sitemap.SitemapSubscriptionService] - Created new subscription with id d8203b6c-1c20-4dae-acc7-417cc68e9349 (30 active subscriptions for a max of 68)
2018-07-11 20:36:37.040 [DEBUG] [t.sitemap.SitemapSubscriptionService] - Created new subscription with id 52e2ed41-9e33-49b8-9c5a-a80c965b94ba (31 active subscriptions for a max of 68)

2018-07-11 20:36:37.047 [DEBUG] [t.sitemap.SitemapSubscriptionService] - Created new subscription with id 6c20a7a4-8fd5-4c63-83f7-af6deac369a4 (32 active subscriptions for a max of 68)
2018-07-11 20:36:37.130 [DEBUG] [t.sitemap.SitemapSubscriptionService] - Subscription 6c20a7a4-8fd5-4c63-83f7-af6deac369a4 changed to page 1410r of sitemap 1410r (32 active subscriptions}
2018-07-11 20:36:37.131 [DEBUG] [est.sitemap.internal.SitemapResource] - Client requested sitemap event stream for subscription 6c20a7a4-8fd5-4c63-83f7-af6deac369a4.
2018-07-11 20:36:51.743 [DEBUG] [est.sitemap.internal.SitemapResource] - SSE connection for subscription 6c20a7a4-8fd5-4c63-83f7-af6deac369a4 has been closed.
2018-07-11 20:36:51.744 [DEBUG] [t.sitemap.SitemapSubscriptionService] - Removed subscription with id 6c20a7a4-8fd5-4c63-83f7-af6deac369a4 (31 active subscriptions)

2018-07-11 20:46:42.636 [DEBUG] [t.sitemap.SitemapSubscriptionService] - Created new subscription with id fc06216c-aa58-433a-acb2-c5cf5607bdac (32 active subscriptions for a max of 68)
2018-07-11 20:46:42.644 [DEBUG] [t.sitemap.SitemapSubscriptionService] - Created new subscription with id a3d93f21-a921-44df-ac66-340222f79812 (33 active subscriptions for a max of 68)
2018-07-11 20:46:42.649 [DEBUG] [t.sitemap.SitemapSubscriptionService] - Created new subscription with id 80ac781e-3ed0-4bdb-8b4f-d8177385da49 (34 active subscriptions for a max of 68)
2018-07-11 20:46:42.654 [DEBUG] [t.sitemap.SitemapSubscriptionService] - Created new subscription with id 6427bd23-30f4-42b3-a4c9-61a681813515 (35 active subscriptions for a max of 68)
2018-07-11 20:46:42.658 [DEBUG] [t.sitemap.SitemapSubscriptionService] - Created new subscription with id 9e12abe6-98d9-4692-81b4-66ee44ba4743 (36 active subscriptions for a max of 68)
2018-07-11 20:46:42.664 [DEBUG] [t.sitemap.SitemapSubscriptionService] - Created new subscription with id adfcd2de-06bb-4035-aec7-69705195ac92 (37 active subscriptions for a max of 68)
2018-07-11 20:46:42.667 [DEBUG] [t.sitemap.SitemapSubscriptionService] - Created new subscription with id 93eb0b90-166b-4948-ad06-4b79ad6cde7a (38 active subscriptions for a max of 68)
2018-07-11 20:46:42.670 [DEBUG] [t.sitemap.SitemapSubscriptionService] - Created new subscription with id ce18e25c-d443-4b4c-a2cb-45a50f005d8c (39 active subscriptions for a max of 68)

2018-07-11 20:46:42.673 [DEBUG] [t.sitemap.SitemapSubscriptionService] - Created new subscription with id 2031cd38-a653-4bf8-955c-106534c957f7 (40 active subscriptions for a max of 68)
2018-07-11 20:46:42.740 [DEBUG] [t.sitemap.SitemapSubscriptionService] - Subscription 2031cd38-a653-4bf8-955c-106534c957f7 changed to page 1410r of sitemap 1410r (40 active subscriptions}
2018-07-11 20:46:42.741 [DEBUG] [est.sitemap.internal.SitemapResource] - Client requested sitemap event stream for subscription 2031cd38-a653-4bf8-955c-106534c957f7.
2018-07-11 20:46:51.754 [DEBUG] [est.sitemap.internal.SitemapResource] - SSE connection for subscription 2031cd38-a653-4bf8-955c-106534c957f7 has been closed.
2018-07-11 20:46:51.755 [DEBUG] [t.sitemap.SitemapSubscriptionService] - Removed subscription with id 2031cd38-a653-4bf8-955c-106534c957f7 (39 active subscriptions)

[triller-telekom]

@lolodomo and @resetnow Could you please check that? At least this seems to be the first time that the bug is reproducible.

[lolodomo]

I was unable to reproduce it but I have only Android 5 devices.

[triller-telekom]

Thanks for trying. Once I have updated my openHAB to include your fix, I give it a try with my Lineage 14.1 (Android 7.1.2) device.

[mhilbush]

Once I have updated my openHAB to include your fix, I give it a try

Just to clarify, you don't need @lolodomo's PR to reproduce the problem. His PR provides a workaround that periodically frees up the orphaned subscriptions. You might already know that, but it wasn't obvious from your comment above.

[triller-telekom]

My test results:

openhab> bundle:list | grep Sitemap                                             
115 │ Active   │  80 │ 0.10.0.201807241640    │ Eclipse SmartHome Sitemap REST

Android 7.1.2 using Chrome browser

2018-07-27 10:45:58.598 [DEBUG] [t.sitemap.SitemapSubscriptionService] - Created new subscription with id 0453e2cf-bef3-4b2a-888b-ad41f0c1bb4b (2 active subscriptions for a max of 50)
2018-07-27 10:45:58.605 [DEBUG] [est.sitemap.internal.SitemapResource] - Client from IP 192.168.42.30 requested new subscription => got id 0453e2cf-bef3-4b2a-888b-ad41f0c1bb4b.
2018-07-27 10:45:58.780 [DEBUG] [t.sitemap.SitemapSubscriptionService] - Subscription 0453e2cf-bef3-4b2a-888b-ad41f0c1bb4b changed to page stefan of sitemap stefan (2 active subscriptions}
2018-07-27 10:45:58.789 [DEBUG] [est.sitemap.internal.SitemapResource] - Client from IP 192.168.42.30 requested sitemap event stream for subscription 0453e2cf-bef3-4b2a-888b-ad41f0c1bb4b.
2018-07-27 10:49:32.904 [DEBUG] [est.sitemap.internal.SitemapResource] - Run clean SSE subscriptions job
2018-07-27 10:49:32.922 [DEBUG] [.sitemap.internal.SitemapEventOutput] - Sent alive event to subscription c1bb839c-4548-46d6-a549-505e36c45f91.
2018-07-27 10:49:32.927 [DEBUG] [.sitemap.internal.SitemapEventOutput] - Sent alive event to subscription 0453e2cf-bef3-4b2a-888b-ad41f0c1bb4b.
2018-07-27 10:53:53.295 [DEBUG] [.sitemap.internal.SitemapEventOutput] - Sent sitemap event for widget 0106 to subscription c1bb839c-4548-46d6-a549-505e36c45f91.
2018-07-27 10:53:53.310 [DEBUG] [.sitemap.internal.SitemapEventOutput] - Sent sitemap event for widget 0106 to subscription 0453e2cf-bef3-4b2a-888b-ad41f0c1bb4b.
2018-07-27 10:53:53.324 [DEBUG] [est.sitemap.internal.SitemapResource] - SSE connection for subscription c1bb839c-4548-46d6-a549-505e36c45f91 has been closed.
2018-07-27 10:53:53.327 [DEBUG] [t.sitemap.SitemapSubscriptionService] - Removed subscription with id c1bb839c-4548-46d6-a549-505e36c45f91 (1 active subscriptions)
2018-07-27 10:53:53.339 [DEBUG] [.sitemap.internal.SitemapEventOutput] - Sent sitemap event for widget 0104 to subscription 0453e2cf-bef3-4b2a-888b-ad41f0c1bb4b.
2018-07-27 10:54:32.904 [DEBUG] [est.sitemap.internal.SitemapResource] - Run clean SSE subscriptions job
2018-07-27 10:54:32.911 [DEBUG] [.sitemap.internal.SitemapEventOutput] - Sent alive event to subscription 0453e2cf-bef3-4b2a-888b-ad41f0c1bb4b.

Android 8.1.0 using Chrome browser

2018-07-27 10:57:24.190 [DEBUG] [t.sitemap.SitemapSubscriptionService] - Created new subscription with id 11ff1580-f9c7-4272-a9bd-2e431e6f1f08 (2 active subscriptions for a max of 50)
2018-07-27 10:57:24.196 [DEBUG] [est.sitemap.internal.SitemapResource] - Client from IP 192.168.42.25 requested new subscription => got id 11ff1580-f9c7-4272-a9bd-2e431e6f1f08.
2018-07-27 10:57:24.250 [DEBUG] [t.sitemap.SitemapSubscriptionService] - Subscription 11ff1580-f9c7-4272-a9bd-2e431e6f1f08 changed to page stefan of sitemap stefan (2 active subscriptions}
2018-07-27 10:57:24.254 [DEBUG] [est.sitemap.internal.SitemapResource] - Client from IP 192.168.42.25 requested sitemap event stream for subscription 11ff1580-f9c7-4272-a9bd-2e431e6f1f08.
2018-07-27 10:59:32.904 [DEBUG] [est.sitemap.internal.SitemapResource] - Run clean SSE subscriptions job
2018-07-27 10:59:32.910 [DEBUG] [est.sitemap.internal.SitemapResource] - SSE connection for subscription 0453e2cf-bef3-4b2a-888b-ad41f0c1bb4b has been closed.
2018-07-27 10:59:32.913 [DEBUG] [t.sitemap.SitemapSubscriptionService] - Removed subscription with id 0453e2cf-bef3-4b2a-888b-ad41f0c1bb4b (1 active subscriptions)
2018-07-27 10:59:32.921 [DEBUG] [.sitemap.internal.SitemapEventOutput] - Sent alive event to subscription 11ff1580-f9c7-4272-a9bd-2e431e6f1f08.
2018-07-27 11:03:53.525 [DEBUG] [.sitemap.internal.SitemapEventOutput] - Sent sitemap event for widget 0103 to subscription 11ff1580-f9c7-4272-a9bd-2e431e6f1f08.
2018-07-27 11:04:32.904 [DEBUG] [est.sitemap.internal.SitemapResource] - Run clean SSE subscriptions job
2018-07-27 11:04:32.911 [DEBUG] [.sitemap.internal.SitemapEventOutput] - Sent alive event to subscription 11ff1580-f9c7-4272-a9bd-2e431e6f1f08.

So no suspicious re-creating of subscriptions...

EDIT: I opened the main page and left it open for around 10minutes

[mhilbush]

Thanks for trying to reproduce. Right after you opened the main page, did you lock the phone using the power button?

Somehow I knew this was going to be one of those problems... I'll continue to try to determine what setting(s) is causing this behavior.

One thing I noticed in my most recent test (and I can't say that I've observed this in every test) is that the flurry of subscription requests occurred precisely when the phone made a notification sound. I had turned off notifications to the display. Maybe I'll try turning off notifications altogether.

[triller-telekom]

Right after you opened the main page, did you lock the phone using the power button?

Yes thats what I did. And then I left it like that for about 10 minutes.

[justClouds]

I am also witnessing "SSE subscription failed: running in fallback mode" on Windows 10 (1809) with Chrome (build 69) simply accessing the Basic UI.

[sparetimetherapist]

Same here with Chrome Version 70.0.3538.110 on Windows 10 - using BasicUI with openHAB v2.4.0~M8-1.