SDK hangs when calling docker-compose stop

[ajcasagrande]

Problem

When running an application using this SDK, the sdk.MakeItRun() function will never relinquish control to the application when it is running under docker-compose. When running natively this does not occur.

It is not an issue with what signals get sent, because as a workaround I have implemented the same signaling logic myself and it works fine.

Sample code

go func() {
    signals := make(chan os.Signal)
    signal.Notify(signals, syscall.SIGINT, syscall.SIGTERM)
    s := <-signals

    lgr.Info(fmt.Sprintf("Received %s signal from OS.", s.String()))
    close(done)
}()

edgexSdk.MakeItRun()
lgr.Info("Exiting.")

Native

Click to show run script

```bash ./rfid-inventory -cp=consul://localhost:8500 -confdir=res & pid=$! sleep 5 kill -TERM "$pid" echo "killed" wait echo "script complete" ```

Sep 23 14:34:39 killed
Sep 23 14:34:39 level=INFO ts=2020-09-23T21:34:39.340105595Z app=rfid-inventory source=sdk.go:173 msg="Terminating: terminated"
Sep 23 14:34:39 level=INFO ts=2020-09-23T21:34:39.340130527Z app=rfid-inventory source=main.go:298 msg="Received terminated signal from OS."
Sep 23 14:34:39 level=INFO ts=2020-09-23T21:34:39.340213773Z app=rfid-inventory source=telemetry.go:84 msg="Exiting CPU Usage Average loop"
Sep 23 14:34:39 level=INFO ts=2020-09-23T21:34:39.340255046Z app=rfid-inventory source=configupdates.go:59 msg="Exiting waiting for App Service configuration updates"
Sep 23 14:34:39 level=INFO ts=2020-09-23T21:34:39.340281375Z app=rfid-inventory source=messaging.go:130 msg="Disconnecting from the message bus"
Sep 23 14:34:39 level=INFO ts=2020-09-23T21:34:39.340976464Z app=rfid-inventory source=main.go:308 msg=Exiting.
Sep 23 14:34:39 script complete

Docker Compose

Click to show run script

```bash docker-compose up & sleep 5 docker-compose stop & echo "killed" wait echo "script complete" ```

Sep 23 14:37:59 killed
Stopping edgex-app-service-rfid-inventory ...
Sep 23 14:37:59 edgex-app-service-rfid-inventory | level=INFO ts=2020-09-23T21:37:59.678202804Z app=rfid-inventory source=sdk.go:173 msg="Terminating: terminated"
Sep 23 14:37:59 edgex-app-service-rfid-inventory | level=INFO ts=2020-09-23T21:37:59.67826475Z app=rfid-inventory source=main.go:298 msg="Received terminated signal from OS."
Sep 23 14:37:59 edgex-app-service-rfid-inventory | level=INFO ts=2020-09-23T21:37:59.678217959Z app=rfid-inventory source=telemetry.go:84 msg="Exiting CPU Usage Average loop"
Sep 23 14:37:59 edgex-app-service-rfid-inventory | level=INFO ts=2020-09-23T21:37:59.678231787Z app=rfid-inventory source=configupdates.go:59 msg="Exiting waiting for App Service configuration updates"
Stopping edgex-app-service-rfid-inventory ... done
Sep 23 14:38:10 edgex-app-service-rfid-inventory exited with code 137
Sep 23 14:38:10 script complete

Notice that my lgr.Info("Exiting.") never ran, and notice how there is a 10 second gap between the last log and when the script completes. This is because docker-compose stop waits 10 seconds for your container to shutdown before forcefully killing it.

As far as the SDK's logs show, this one in particular is missing:

source=messaging.go:130 msg="Disconnecting from the message bus"

[rsdmike]

Unable to reproduce with simple examples provided by EdgeX. Will keep open to see if reproducible with LLRP RFID Application

[AlexCuse]

I have been unable to reproduce this as well.

[lenny-goodell]

Moving to Ice Box until LLRP service are migrated to V2 and attempt to recreate with the LLRP App Service. where this was seen and reported.

[lenny-goodell]

Still unable to reproduce this issue. Logs show the following when going a Docker Stop

level=INFO ts=2023-04-03T23:15:03.9851596Z app=app-rfid-llrp-inventory source=manager.go:109 msg="Exited Metrics Manager Run..."
level=INFO ts=2023-04-03T23:15:03.9852128Z app=app-rfid-llrp-inventory source=configupdates.go:55 msg="Exiting waiting for App Service configuration updates"
level=INFO ts=2023-04-03T23:15:03.9852419Z app=app-rfid-llrp-inventory source=messaging.go:127 msg="Exiting waiting for MessageBus errors and background publishing"
level=INFO ts=2023-04-03T23:15:03.9852355Z app=app-rfid-llrp-inventory source=app.go:158 msg="Received 'terminated' signal from OS."
level=INFO ts=2023-04-03T23:15:03.985254Z app=app-rfid-llrp-inventory source=messaging.go:111 msg="Exiting waiting for MessageBus 'edgex/events/+/device-rfid-llrp/+/+/ROAccessReport' topic messages"
level=INFO ts=2023-04-03T23:15:03.9852507Z app=app-rfid-llrp-inventory source=service.go:222 msg="Terminating signal received: terminated"
level=INFO ts=2023-04-03T23:15:03.9852646Z app=app-rfid-llrp-inventory source=controller.go:205 msg="Stopping task loop."
level=INFO ts=2023-04-03T23:15:03.9852712Z app=app-rfid-llrp-inventory source=messaging.go:111 msg="Exiting waiting for MessageBus 'edgex/edgex/events/+/device-rfid-llrp/+/+/ReaderEventNotification' topic messages"
level=INFO ts=2023-04-03T23:15:03.9853119Z app=app-rfid-llrp-inventory source=config.go:721 msg="Watching for 'Writable' configuration changes has stopped"
level=INFO ts=2023-04-03T23:15:03.9852968Z app=app-rfid-llrp-inventory source=config.go:721 msg="Watching for 'Writable' configuration changes has stopped"
level=INFO ts=2023-04-03T23:15:03.9853049Z app=app-rfid-llrp-inventory source=config.go:659 msg="Watching for 'Writable' configuration changes has stopped"
level=INFO ts=2023-04-03T23:15:03.9852929Z app=app-rfid-llrp-inventory source=config.go:551 msg="Watching for 'AppCustom' configuration changes has stopped"
level=INFO ts=2023-04-03T23:15:03.9853542Z app=app-rfid-llrp-inventory source=messaging.go:95 msg="Disconnected from MessageBus"
level=INFO ts=2023-04-03T23:15:03.9853939Z app=app-rfid-llrp-inventory source=bootstrap.go:146 msg="Un-Registering service from the Registry"
level=INFO ts=2023-04-03T23:15:03.9854229Z app=app-rfid-llrp-inventory source=controller.go:198 msg="Event processor stopped."
level=INFO ts=2023-04-03T23:15:03.9854821Z app=app-rfid-llrp-inventory source=controller.go:296 tags=0 msg="Persisted inventory snapshot."
level=INFO ts=2023-04-03T23:15:03.9855362Z app=app-rfid-llrp-inventory source=controller.go:209 msg="Task loop stopped."
level=INFO ts=2023-04-03T23:15:03.9855517Z app=app-rfid-llrp-inventory source=app.go:141 msg="Task loop has exited."
level=INFO ts=2023-04-03T23:15:04.0004014Z app=app-rfid-llrp-inventory source=messaging.go:159 msg="Disconnecting from the message bus"