gateway continuously tries to reach a webthing that is offline

[kgiori]

simple "Hello LED" webthing has JSON that looks like this:

{ "name": "Hello LED", "@context": "https://iot.mozilla.org/schemas/", "@type": ["Light"], "properties": { "on": {"title": "Lit", "type": "boolean", "href": "/properties/on", "@type": "OnOffProperty"} } }

It is visible in a browser by IP address (this device does not do mDNS but the problem exists whether it does or not). After adding it to the gateway and then disconnecting it, the log shows repeated attempts to reach it.

2019-05-27 21:16:20.420 INFO : thing-url: Failed to connect to http://192.168.30.161/properties/on: FetchError: request to http://192.168.30.161/properties/on failed, reason: connect EHOSTUNREACH 192.168.30.161:80 2019-05-27 21:16:20.422 INFO : thing-url: Failed to connect to http://192.168.30.161/properties/on: FetchError: request to http://192.168.30.161/properties/on failed, reason: connect EHOSTUNREACH 192.168.30.161:80 2019-05-27 21:16:20.424 INFO : thing-url: Failed to connect to http://192.168.30.161/properties/on: FetchError: request to http://192.168.30.161/properties/on failed, reason: connect EHOSTUNREACH 192.168.30.161:80

and so on... (causing the RPi to be very busy and clog the network with requests)

Upon restarting the "Web Thing" Add-on (v0.2.8), the continuous attempts in the log stop.

Next the "Hello LED" thing was plugged back in. The gateway did not automatically find it. After pressing "+" on the Things page, then it was active and controllable again.

In addition to the main bug of a webthing going offline and the gw continuously searchin for it, when a webthing does come back online on a network, should it do something to announce itself so that the gateway doesn't have to constantly look for it? And if the gateway does need to periodically poll for offline devices to figure out when they come back online, how often does or should that occur?

This problem of continuous searching occurs even if you remove (delete) the offline thing from the Things page. Fortunately, the workaround to disable then enable the Web Thing Add-on stops the recurring attempts to reach the offline device.

[lprader]

In addition to the main bug of a webthing going offline and the gw continuously searchin for it,

My problem is not that the gateway searches for WebThings that have gone offline. That makes sense because it should try to reconnect to that device when it comes back online. My problem is that it spams devices that were removed from the Things page with HTTP requests as if they are saved devices.

So, for example, I connected to a light, then removed it from the Things page. The log shows this event.

2019-05-24 21:59:23.365 INFO   : Successfully deleted http---modLight1.local-80-thng-desc-light from database.

After removing it, I turned the device off. Meanwhile, the gateway starts trying to retrieve its description. I assume the gateway is constantly performing the mDNS scan--that makes sense, but it shouldn't be sending HTTP requests for the description if a device isn't saved. And it certainly shouldn't continue requesting it if it can no longer find the device.

2019-05-24 21:59:23.432 ERROR  : Error getting thing description for thing with id http---modLight1.local-80-thng-desc-light
2019-05-24 21:59:23.434 ERROR  : Error: Error: Unable to find thing with id: http---modLight1.local-80-thng-desc-light
2019-05-24 21:59:23.483 ERROR  : Error getting thing description for thing with id http---modLight1.local-80-thng-desc-light
2019-05-24 21:59:23.484 ERROR  : Error: Error: Unable to find thing with id: http---modLight1.local-80-thng-desc-light

In addition, the gateway continues sending HTTP requests to retrieve the values of the light's on property (as if it's still a saved device). That seems like an obvious bug.

2019-05-24 21:59:39.809 INFO   : thing-url: Failed to connect to http://modlight1.local/thng/prop/light/on: FetchError: request to http://modlight1.local/thng/prop/light/on failed, reason: getaddrinfo ENOTFOUND modlight1.local modlight1.local:80
2019-05-24 21:59:43.735 INFO   : thing-url: Failed to connect to http://modlight1.local/thng/prop/light/on: FetchError: request to http://modlight1.local/thng/prop/light/on failed, reason: getaddrinfo ENOTFOUND modlight1.local modlight1.local:80
2019-05-24 21:59:44.814 INFO   : thing-url: Failed to connect to http://modlight1.local/thng/prop/light/on: FetchError: request to http://modlight1.local/thng/prop/light/on failed, reason: getaddrinfo ENOTFOUND modlight1.local modlight1.local:80
2019-05-24 21:59:48.738 INFO   : thing-url: Failed to connect to http://modlight1.local/thng/prop/light/on: FetchError: request to http://modlight1.local/thng/prop/light/on failed, reason: getaddrinfo ENOTFOUND modlight1.local modlight1.local:80

I'm using a development board and reprogramming it to act as different WebThings. So later I reprogrammed the light to become a sign. I connect to the sign from the gateway, and then remove it from the Things page. As before, this all shows up in the logs as expected.

2019-05-24 21:59:55.267 INFO   : Successfully created new thing sign
...
2019-05-24 22:20:29.239 INFO   : Successfully deleted http---modSign1.local-80-thng-desc-sign from database.

After removing the sign, the gateway continues to send requests to the sign and the light. This goes on indefinitely, as far as I can tell.

2019-05-24 22:20:29.282 ERROR  : Error getting thing description for thing with id http---modSign1.local-80-thng-desc-sign
2019-05-24 22:20:29.284 ERROR  : Error: Error: Unable to find thing with id: http---modSign1.local-80-thng-desc-sign
2019-05-24 22:20:29.328 ERROR  : Error getting thing description for thing with id http---modSign1.local-80-thng-desc-sign
2019-05-24 22:20:29.330 ERROR  : Error: Error: Unable to find thing with id: http---modSign1.local-80-thng-desc-sign
2019-05-24 22:20:30.289 INFO   : thing-url: Failed to connect to http://modlight1.local/thng/prop/light/on: FetchError: request to http://modlight1.local/thng/prop/light/on failed, reason: getaddrinfo ENOTFOUND modlight1.local modlight1.local:80
2019-05-24 22:20:30.858 INFO   : thing-url: Failed to connect to http://modlight1.local/thng/prop/light/on: FetchError: request to http://modlight1.local/thng/prop/light/on failed, reason: getaddrinfo ENOTFOUND modlight1.local modlight1.local:80
2019-05-24 22:20:35.296 INFO   : thing-url: Failed to connect to http://modlight1.local/thng/prop/light/on: FetchError: request to http://modlight1.local/thng/prop/light/on failed, reason: getaddrinfo ENOTFOUND modlight1.local modlight1.local:80
...

If I then reprogram the device to be a light again, the HTTP requests to retrieve the value of its on property are still coming in--before I've saved the device in the gateway. And because the light is back online, it responds to them. The gateway doesn't do anything with the response because it's not a saved device. But it's spamming the device with unnecessary HTTP requests.

[hobinjk]

Sorry for the difficulty! I believe https://github.com/mozilla-iot/thing-url-adapter/pull/74 should fix most of these issues (version 0.3.1, available soon). The main behavior that I think it won't fix is when a device is unsaved there might still be extraneous requests for the description and properties but they should at least be less frequent.

[benfrancis]

@lprader Are you able to verify that this add-on update fixes (or at least alleviates) your problem?

Thank you very much for reporting.

[lprader]

@benfrancis it does exactly what @hobinjk said it would. That is, it seems to make the requests less frequent, but definitely doesn't fix the problem as there are still extraneous requests :)

I'm curious what happens when you delete a device from the Things page--does it just remove it from the Things page but do nothing else?

@kgiori mentioned that disabling the adapter stops recurring attempts to reach an offline device. Why isn't this behavior just applied to deleted devices?

[mrstegeman]

Note to self: use handleDeviceSaved() to figure out which devices to poll.