Device not found in cache

[nitu-s-gupta]

Edge Orchestration uses EdgeX Foundry to save the data of the devices. Once the device registers to metadata after device service is started, and once youtryto send data to coredata using the curl API it doesnt work for first time. It works after reboot.

In terms of Edge Orchestration to reproduce the issue follow the steps

• Clear redis database
• Run edge-orchestration with DataStorage configuration files
• Call an API in terms of uploading Int value

curl -X POST "localhost:49986/api/v1/resource/datastorage/int" -H "accept: text/plain" -H "Content-Type: text/plain" -d 123

🐞 Bug Report

Log from edge-orchestration

level=INFO ts=2021-06-08T11:09:41.747141457Z app=datastorage source=config.go:193 msg="Loaded configuration from ./res/configuration.toml"

level=INFO ts=2021-06-08T11:09:41.748290804Z app=datastorage source=config.go:304 msg="Using local configuration from file (0 envVars overrides applied)"
level=INFO ts=2021-06-08T11:09:41.748336679Z app=datastorage source=httpserver.go:99 msg="Web server starting (127.0.0.1:49986)"
level=INFO ts=2021-06-08T11:09:41.748393149Z app=datastorage source=init.go:144 msg="Check Metadata service's status by ping..."
level=INFO ts=2021-06-08T11:09:41.748528479Z app=datastorage source=init.go:144 msg="Check Data service's status by ping..."
level=INFO ts=2021-06-08T11:09:41.749614627Z app=datastorage source=init.go:68 msg="Service clients initialize successful."
level=INFO ts=2021-06-08T11:09:41.750747311Z app=datastorage source=service.go:207 msg="Addressable datastorage doesn't exist, creating a new one"
level=DEBUG ts=2021-06-08T11:09:41.751916563Z app=datastorage source=service.go:153 msg="Trying to find DeviceService: datastorage"
level=INFO ts=2021-06-08T11:09:41.752643978Z app=datastorage source=service.go:157 msg="DeviceService datastorage doesn't exist, creating a new one"
level=DEBUG ts=2021-06-08T11:09:41.754344754Z app=datastorage source=service.go:169 msg="New DeviceService Id: 6faac9ac-6ec1-41ee-8661-927954bb7ea1"
INFO[2021-06-08T11:09:41Z]storagedriver.go:43 Initialize [storagedriver] Device service intialize started
level=DEBUG ts=2021-06-08T11:09:41.75790956Z app=datastorage source=restrouter.go:119 route=/api/v1/resource/{deviceName}/{resourceName} methods=[POST] msg="Route added"
level=INFO ts=2021-06-08T11:09:41.757963324Z app=datastorage source=storagehandler.go:66 msg="Route /api/v1/resource/{deviceName}/{resourceName} added."
level=INFO ts=2021-06-08T11:09:41.759800964Z app=datastorage source=restrouter.go:75 msg="Registering v2 routes..."
level=DEBUG ts=2021-06-08T11:09:41.76021791Z app=datastorage source=profiles.go:47 msg="created absolute path for loading pre-defined Device Profiles: /edge-orchestration/res"
level=DEBUG ts=2021-06-08T11:09:41.76330122Z app=datastorage source=profiles.go:172 msg="Getting EnableValueDescriptorManagement configuration value from Core Metadata"
level=DEBUG ts=2021-06-08T11:09:41.763993203Z app=datastorage source=devices.go:29 msg="Loading pre-define Devices from configuration"
level=DEBUG ts=2021-06-08T11:09:41.764037017Z app=datastorage source=devices.go:35 msg="Device datastorage doesn't exist, creating a new one"
level=DEBUG ts=2021-06-08T11:09:41.764581907Z app=datastorage source=devices.go:75 msg="Adding Device: {"origin":1623150581764,"description":"RESTful Device","name":"datastorage","adminState":"UNLOCKED","operatingState":"ENABLED","protocols":{"other":{}},"labels":["rest","json"],"service":{"origin":1623150581751,"id":"6faac9ac-6ec1-41ee-8661-927954bb7ea1","name":"datastorage","operatingState":"ENABLED","addressable":{"origin":1623150581749,"id":"7b016ca7-5b53-4aa3-88e5-6f4a0b484271","name":"datastorage","protocol":"HTTP","method":"POST","address":"127.0.0.1","port":49986,"path":"/api/v1/callback","baseURL":"http://127.0.0.1:49986\",\"url\":\"http://127.0.0.1:49986/api/v1/callback\"},\"adminState\":\"UNLOCKED\"},\"profile\":{\"description\":\"REST Device","id":"3b356db4-fe39-4dc4-bd25-8bebef5e15ce","name":"datastorage","manufacturer":"Home Edge","model":"Home Edge","labels":["rest","json","numeric","float","int"],"deviceResources":[{"description":"json","name":"json","properties":{"value":{"type":"String","readWrite":"RW","mediaType":"application/json"},"units":{"type":"String","readWrite":"R"}}},{"name":"int","properties":{"value":{"type":"Int64","readWrite":"RW","mediaType":"text/plain"},"units":{"type":"String","readWrite":"R"}}},{"description":"float","name":"float","properties":{"value":{"type":"Float64","readWrite":"RW","mediaType":"text/plain"},"units":{"type":"String","readWrite":"R"}}},{"description":"jpeg","name":"jpeg","properties":{"value":{"type":"Binary","readWrite":"RW","mediaType":"image/jpeg"},"units":{"type":"String","readWrite":"R"}}},{"description":"png","name":"png","properties":{"value":{"type":"Binary","readWrite":"RW","mediaType":"image/png"},"units":{"type":"String","readWrite":"R"}}},{"description":"string","name":"string","properties":{"value":{"type":"String","readWrite":"RW","mediaType":"text/plain"},"units":{"type":"String","readWrite":"R"}}}]}}"
level=INFO ts=2021-06-08T11:09:41.766971106Z app=datastorage source=autodiscovery.go:32 msg="AutoDiscovery stopped: disabled by configuration"
level=INFO ts=2021-06-08T11:09:41.767031297Z app=datastorage source=autodiscovery.go:37 msg="AutoDiscovery stopped: interval error in configuration"
level=INFO ts=2021-06-08T11:09:41.76706353Z app=datastorage source=autodiscovery.go:41 msg="AutoDiscovery stopped: ProtocolDiscovery not implemented"
level=INFO ts=2021-06-08T11:09:41.767094873Z app=datastorage source=message.go:50 msg="Service dependencies resolved..."
level=INFO ts=2021-06-08T11:09:41.767156624Z app=datastorage source=message.go:51 msg="Starting datastorage to be replaced by makefile "
level=INFO ts=2021-06-08T11:09:41.767182718Z app=datastorage source=message.go:58 msg="Service started in: 20.913936ms"

level=DEBUG ts=2021-06-08T11:09:51.973581107Z app=datastorage source=storagehandler.go:84 msg="Received POST for Device=datastorage Resource=int"
level=INFO ts=2021-06-08T11:09:51.973670443Z app=datastorage source=manageddevices.go:71 msg="Device datastorage cannot be found in cache"
level=ERROR ts=2021-06-08T11:09:51.973714012Z app=datastorage source=storagehandler.go:88 msg="Incoming reading ignored. Device 'datastorage' not found"

🔥 Analysis

When looked into the device SDK files, I observed that devices.go file in /internal/provision/devices.go loads the device in cache initially but when the devices are loaded from the config files into database, then cache is not updated which seems to be the issue. I have tested and observed the same issue with the sample device-rest.go code available in edgex github.

🌍 Your Environment

Firmware version: Ubuntu 20.04
Hardware: x86-64
Edge Orchestration Release: Coconut
EdgeX version: Hanoi

[nitu-s-gupta]

lf-edge/edge-home-orchestration-go#312
Issue opened in Home Edge
@cloudxxx8 can you please help in this regard

[cloudxxx8]

cache will be updated via the callback from core-metadata.
thus, your problem might be caused by the core-metadata cannot reach your device service.
do you run the core services in docker container and device service in binary? if so, you need to set the device service host to the docker0 ip address instead of 127.0.0.1

[nitu-s-gupta]

I have tried changing the ip of containers in my configuration.toml file also to 0.0.0.0 since the containers running on the same IP. And one more query if my device service is not accessible then how is it working after reboot and even how the discovery happens?
Attaching the logs of my containers running

CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES
0f8832910ab4 edge-orchestration:coconut "sh run.sh" About an hour ago Up About an hour edge-orchestration
bacbe9c8ae39 emqx/kuiper:1.1.1-alpine "/usr/bin/docker-ent…" 3 weeks ago Up About an hour 0.0.0.0:20498->20498/tcp, 9081/tcp, 0.0.0.0:48075->48075/tcp edgex-kuiper
5a1b2211acca edgexfoundry/docker-sys-mgmt-agent-go:1.3.1 "/sys-mgmt-agent -cp…" 3 weeks ago Up About an hour 0.0.0.0:48090->48090/tcp edgex-sys-mgmt-agent
f240f4e2d8e1 edgexfoundry/docker-app-service-configurable:1.3.1 "/app-service-config…" 3 weeks ago Up About an hour 48095/tcp, 0.0.0.0:48100->48100/tcp edgex-app-service-configurable-rules
ccee3d39d038 edgexfoundry/docker-core-data-go:1.3.1 "/core-data -cp=cons…" 3 weeks ago Up About an hour 0.0.0.0:5563->5563/tcp, 0.0.0.0:48080->48080/tcp edgex-core-data
bcbb686af84b edgexfoundry/docker-core-command-go:1.3.1 "/core-command -cp=c…" 3 weeks ago Up About an hour 0.0.0.0:48082->48082/tcp edgex-core-command
c28e3b873a6f edgexfoundry/docker-core-metadata-go:1.3.1 "/core-metadata -cp=…" 3 weeks ago Up About an hour 0.0.0.0:48081->48081/tcp edgex-core-metadata
4ea90646a284 edgexfoundry/docker-support-notifications-go:1.3.1 "/support-notificati…" 3 weeks ago Up About an hour 0.0.0.0:48060->48060/tcp edgex-support-notifications
44b9dba3cebf edgexfoundry/docker-support-scheduler-go:1.3.1 "/support-scheduler …" 3 weeks ago Up About an hour 0.0.0.0:48085->48085/tcp edgex-support-scheduler
233f2624a284 redis:6.0.9-alpine "docker-entrypoint.s…" 3 weeks ago Up About an hour 0.0.0.0:6379->6379/tcp edgex-redis
cfa8a3c9aef5 edgexfoundry/docker-edgex-consul:1.3.0 "edgex-consul-entryp…" 3 weeks ago Up About an hour 8300-8302/tcp, 8400/tcp, 8301-8302/udp, 8600/tcp, 8600/udp, 0.0.0.0:8500->8500/tcp edgex-core-consul

============================================================================
[Clients]
[Clients.Data]
Protocol = "http"
Host = "0.0.0.0"
Port = 48080
Timeout = 5000

[Clients.Metadata]
Protocol = "http"
Host = "0.0.0.0"
Port = 48081
Timeout = 5000
sample of configuration.toml file

[cloudxxx8]

please use ifconfig command to confirm your docker0 ip address. it's not 0.0.0.0. it should be like 172.17.0.1

[nitu-s-gupta]

Thanks, But I have a question on this
Assume that we have two devices, Device A(enp4s0:192.168.0.7, docker0:172.17.0.1) and B(enp4s0:192.168.0.8, docker0:172.17.0.1).
EdgeX metadata coredata containers are running on Device A and device service on Device B tries to connect to the EdgeX containers on Device A.
If we set the Host to 172.17.0.1 in Device B's configuration.toml, can Device B receive the callback from Device A? or some other setup is required?

[cloudxxx8]

Device Services won't talk to each other by default. The callback is normally received from core-metadata. The best way is to put all of them on the same network.

[nitu-s-gupta]

Yes, but say the coredata is running in different device, and device service in different device. SO in binary we give the IP of the machine where the coredata is running to get the call back. But in dockers how can that be done. The deviceservice and coredata are in same network but different machine. Then will the docker0 IP work?

[cloudxxx8]

docker0 is only for the local machine. you can use the real ip address, but you need to configure your docker network properly.

[nitu-s-gupta]

but coredata running in docker, will it be accessible through the real ip? Can you share me any demo viddeo or documentation where the steps are mentioned? Also configure the network do you mean that bridge has to be setup?

[cloudxxx8]

Please see the docker network related document
https://docs.docker.com/network/

[nitu-s-gupta]

but coredata running in docker, will it be accessible through the just real ip?

[cloudxxx8]

@nitu-s-gupta you can set port mapping for core-data or any other service to expose their access