No autoupdate in basicui after sitemap update

Those two systems on 4.4.0-104-generic still have the 4.4.0-101-generic kernel, but they’re remote to my current location (reachable over a VPN) and I don’t know how to boot to an old kernel remotely. :frowning:

Maybe related to the browser version ? You are using the same for the 3 servers ?
Does it occur even if you don’t update your config files after OH startup (the issue mentioned here) ?

All tests are from Chrome on my Mac.

I’m gonna figure out how to boot the old kernel just to rule that out as an issue. I know I need to edit /etc/default/grub. I’m tied up for the rest of the day, so I’ll do that tomorrow.

Or maybe run a 1140 snashot on your server system1 or system2 and snapshot 1160 on your server system3.

Yes, 1140 on on system 1 or system2 is a good idea, too. system3 is my main prod server, which I don’t want to break.

This will confirm that the problem was not introduced after 1140.

The plot thickens. I reverted to 1140 on one of the systems that was running 1160. I still see the problem.

My next step is to boot the 4.4.0-101-generic kernel. I’m going to do that VERY carefully. :wink: If I fat finger something, I won’t be able to boot it. And, I won’t be in that location to fix it for another week or so…

I’m now running the same OS kernel (4.4.0-101-generic) and OH build (1140) on two systems.

DEBUG logging is enabled on org.eclipse.smarthome.io.rest.sitemap

Sitemap has been simplified to this

sitemap test label="Test Platform"
{
    Frame {
        Text item=CurrentTime  label="Today is [%1$tA, %1$tm/%1$td/%1$tY %1$tl:%1$tM %1$tp]"       icon="calendar"
    }
}

On the system where the time is being updating correctly, I see this in the log.

2018-01-07 09:00:18.319 [DEBUG] [t.sitemap.SitemapSubscriptionService] - Created new subscription with id 6545592a-69f4-4c09-a7a8-60e7b77772fc
2018-01-07 09:00:18.413 [DEBUG] [t.sitemap.SitemapSubscriptionService] - Subscription 6545592a-69f4-4c09-a7a8-60e7b77772fc changed to page 43p of sitemap 43p
2018-01-07 09:00:18.415 [DEBUG] [est.sitemap.internal.SitemapResource] - Client requested sitemap event stream for subscription 6545592a-69f4-4c09-a7a8-60e7b77772fc.
2018-01-07 09:01:04.316 [DEBUG] [.sitemap.internal.SitemapEventOutput] - Sent sitemap event for widget 0000 to subscription 6545592a-69f4-4c09-a7a8-60e7b77772fc.
2018-01-07 09:02:04.314 [DEBUG] [.sitemap.internal.SitemapEventOutput] - Sent sitemap event for widget 0000 to subscription 6545592a-69f4-4c09-a7a8-60e7b77772fc.
2018-01-07 09:03:04.314 [DEBUG] [.sitemap.internal.SitemapEventOutput] - Sent sitemap event for widget 0000 to subscription 6545592a-69f4-4c09-a7a8-60e7b77772fc.
2018-01-07 09:04:04.316 [DEBUG] [.sitemap.internal.SitemapEventOutput] - Sent sitemap event for widget 0000 to subscription 6545592a-69f4-4c09-a7a8-60e7b77772fc.
2018-01-07 09:05:04.319 [DEBUG] [.sitemap.internal.SitemapEventOutput] - Sent sitemap event for widget 0000 to subscription 6545592a-69f4-4c09-a7a8-60e7b77772fc.
2018-01-07 09:06:04.320 [DEBUG] [.sitemap.internal.SitemapEventOutput] - Sent sitemap event for widget 0000 to subscription 6545592a-69f4-4c09-a7a8-60e7b77772fc.

On the system where the time is not updating, I see this. The connection seems to close after 50 seconds. Is that a clue?

2018-01-07 09:01:25.948 [DEBUG] [t.sitemap.SitemapSubscriptionService] - Created new subscription with id 480fe861-bbda-4432-86f5-a2880bc4af38
2018-01-07 09:01:26.085 [DEBUG] [t.sitemap.SitemapSubscriptionService] - Subscription 480fe861-bbda-4432-86f5-a2880bc4af38 changed to page test of sitemap test
2018-01-07 09:01:26.085 [DEBUG] [est.sitemap.internal.SitemapResource] - Client requested sitemap event stream for subscription 480fe861-bbda-4432-86f5-a2880bc4af38.
2018-01-07 09:02:15.907 [DEBUG] [est.sitemap.internal.SitemapResource] - SSE connection for subscription 480fe861-bbda-4432-86f5-a2880bc4af38 has been closed.
2018-01-07 09:02:15.908 [DEBUG] [t.sitemap.SitemapSubscriptionService] - Removed subscription with id 480fe861-bbda-4432-86f5-a2880bc4af38
2018-01-07 09:02:25.950 [DEBUG] [t.sitemap.SitemapSubscriptionService] - Created new subscription with id b19ec227-71c7-47c5-af80-ef35621717e9
2018-01-07 09:02:26.088 [DEBUG] [t.sitemap.SitemapSubscriptionService] - Subscription b19ec227-71c7-47c5-af80-ef35621717e9 changed to page test of sitemap test
2018-01-07 09:02:26.089 [DEBUG] [est.sitemap.internal.SitemapResource] - Client requested sitemap event stream for subscription b19ec227-71c7-47c5-af80-ef35621717e9.
2018-01-07 09:03:15.908 [DEBUG] [est.sitemap.internal.SitemapResource] - SSE connection for subscription b19ec227-71c7-47c5-af80-ef35621717e9 has been closed.
2018-01-07 09:03:15.908 [DEBUG] [t.sitemap.SitemapSubscriptionService] - Removed subscription with id b19ec227-71c7-47c5-af80-ef35621717e9
2018-01-07 09:03:25.948 [DEBUG] [t.sitemap.SitemapSubscriptionService] - Created new subscription with id 64d2d11f-2ea2-4c8a-a012-71f2dd729f0f
2018-01-07 09:03:26.078 [DEBUG] [t.sitemap.SitemapSubscriptionService] - Subscription 64d2d11f-2ea2-4c8a-a012-71f2dd729f0f changed to page test of sitemap test
2018-01-07 09:03:26.078 [DEBUG] [est.sitemap.internal.SitemapResource] - Client requested sitemap event stream for subscription 64d2d11f-2ea2-4c8a-a012-71f2dd729f0f.
2018-01-07 09:04:15.908 [DEBUG] [est.sitemap.internal.SitemapResource] - SSE connection for subscription 64d2d11f-2ea2-4c8a-a012-71f2dd729f0f has been closed.
2018-01-07 09:04:15.909 [DEBUG] [t.sitemap.SitemapSubscriptionService] - Removed subscription with id 64d2d11f-2ea2-4c8a-a012-71f2dd729f0f
2018-01-07 09:04:25.952 [DEBUG] [t.sitemap.SitemapSubscriptionService] - Created new subscription with id d2719be6-b047-4d1d-90c5-5dbef28d43b5
2018-01-07 09:04:26.090 [DEBUG] [t.sitemap.SitemapSubscriptionService] - Subscription d2719be6-b047-4d1d-90c5-5dbef28d43b5 changed to page test of sitemap test
2018-01-07 09:04:26.091 [DEBUG] [est.sitemap.internal.SitemapResource] - Client requested sitemap event stream for subscription d2719be6-b047-4d1d-90c5-5dbef28d43b5.
2018-01-07 09:05:15.909 [DEBUG] [est.sitemap.internal.SitemapResource] - SSE connection for subscription d2719be6-b047-4d1d-90c5-5dbef28d43b5 has been closed.
2018-01-07 09:05:15.909 [DEBUG] [t.sitemap.SitemapSubscriptionService] - Removed subscription with id d2719be6-b047-4d1d-90c5-5dbef28d43b5

I’m officially stumped. :confused:

I wonder if there’s something else I can put into debug mode to help narrow things down…

One thing I realize is different between these two systems.

The system that’s working is running on the standard port of 8080.

The system that’s not working is running on port 7000, because 8080 is being used by another app.

Your logs are interesting as they show that the SSE connection is regularly closed and then reopened with a new subscription ID. We just have to understand why and who is closing it ?

The different port is very interesting too. Could you use the REST API documentation UI to try getting a new sitemap subscription and see what the URL is returned. I hope this URL has the right port.

I am hurry to have your feesback but I think you could have found the issue (port).

Note that someone already reported an issue with sitemap SSE when OH is behind a reverse proxy. The fix would be to return a relative URL.
It might solve your issue too.

Checking…

The issue I am talking about: https://github.com/eclipse/smarthome/issues/4859

Using this REST API call, I get the following response. Looks like the port is correct.

http://my-hostname:7000/rest/sitemaps/events/subscribe
{
  "status": "CREATED",
  "context": {
    "headers": {
      "Location": [
        "http://my-hostname:7000/rest/sitemaps/events/32b8cbf7-3816-4a16-b575-11fe4c45febc"
      ]
    },
    "committingOutputStream": {
      "bufferSize": 0,
      "directWrite": true,
      "isCommitted": false,
      "isClosed": false
    },
    "entityAnnotations": [],
    "entityStream": {
      "bufferSize": 0,
      "directWrite": true,
      "isCommitted": false,
      "isClosed": false
    }
  }
}

Ok that is a good news but that means it is not the reason of your problem.

Yeah, I know. :frowning_face:

I’m running out of ideas of things to check…

The 10 seconds between close and open are expected and due to how Basic UI is handling SSE errons. So clearly in your case @mhilbush , the browser is detecting an error on the SSE conection and as a result it closes the connection and try to reconnect it 10 seconds later.
As the result, the server handles the close by removing the subscription ID.
The last question is: why the javascript in your browser detects an error on the SSE connection ?

I am not source if the reverse is possible, that is an exception on the server side leading to the closing of the SSE connection.

Thanks for those ideas.

Whatever the issue, i seems to be independent of client platform (I see it on Mac and Windows) and browser (I see it on Chrome, Firefox, and Safari).

At least I see now that the subscriptions are properly released on the server side, I have a doubt about it :wink:

I am lacking new ideas.