Not reading EPC values with Zebra FX7500 Reader about device-rfid-llrp-go HOT 5 OPEN

@micheletroccoli

Are you able to provide us with the logs for the device service? If running in docker you can use something like this (replace container_id with the actual value from docker ps) docker logs container_id > llrp_logs.txt

1. Are you sending those 2 commands again after you restart the device service?
2. After you restart the reader, are you doing anything with regards to the device service, or does it just go from not reading tags to all of a sudden reading tags?
3. Have you tried the same thing but instead of killing the llrp service, gracefully shutting it down?

It is possible that because you "killed" the service the rfid reader does not know the connection is dropped and until the connection timeout occurs will still think it is connected to the device service. Then, when the new service comes up, it is unable to establish a connection with the rfid reader because LLRP has a limit of 1 active session at a time.

This is just an educated guess to help point you in the right direction. If this does not fix your issue, then we will need more information to help. Thanks.

from device-rfid-llrp-go.

Thank you for the answer and I'll reply to your questions.
I'm not running in docker so I could show you the log info and debug level. For other questions:

1. Yes, I'm sending those 2 commands again after I restart the device service;
2. No, I don't modify the device service after the reader restart;
3. For this point, what do you mean with gracefully shutting it down? I've always killed the device service execution with Ctrl+C.

from device-rfid-llrp-go.

Thank you for the answer and I'll reply to your questions. I'm not running in docker so I could show you the log info and debug level. For other questions:

1. Yes, I'm sending those 2 commands again after I restart the device service;
2. No, I don't modify the device service after the reader restart;
3. For this point, what do you mean with gracefully shutting it down? I've always killed the device service execution with Ctrl+C.

Thank you for the answers. I was basically referring to a force kill such as kill -9 not being graceful, but Ctrl-C should be sending the proper close/disconnect messages to the rfid reader, so you should be fine there.

We can review your logs when you post them. If you are able to, please set the LogLevel under the Writable section in the config to Debug.

from device-rfid-llrp-go.

I set the LogLevel to Debug and I obtain this:

level=INFO ts=2024-01-10T07:30:05.525087914Z app=device-rfid-llrp source=config.go:718 msg="Using Configuration provider (consul) from: http://localhost:8500 with base path of edgex/v3/core-common-config-bootstrapper/all-services"
level=INFO ts=2024-01-10T07:30:05.527940937Z app=device-rfid-llrp source=config.go:442 msg="loading the common configuration for service type device-service"
level=INFO ts=2024-01-10T07:30:05.528086792Z app=device-rfid-llrp source=config.go:718 msg="Using Configuration provider (consul) from: http://localhost:8500 with base path of edgex/v3/core-common-config-bootstrapper/device-services"
level=INFO ts=2024-01-10T07:30:05.529934305Z app=device-rfid-llrp source=config.go:173 msg="Common configuration loaded from the Configuration Provider. No overrides applied"
level=INFO ts=2024-01-10T07:30:05.52995305Z app=device-rfid-llrp source=config.go:718 msg="Using Configuration provider (consul) from: http://localhost:8500 with base path of edgex/v3/device-rfid-llrp"
level=INFO ts=2024-01-10T07:30:05.531753575Z app=device-rfid-llrp source=config.go:218 msg="Private configuration loaded from the Configuration Provider. No overrides applied"
level=INFO ts=2024-01-10T07:30:05.531773012Z app=device-rfid-llrp source=config.go:269 msg="listening for private config changes"
level=INFO ts=2024-01-10T07:30:05.531782539Z app=device-rfid-llrp source=config.go:271 msg="listening for all services common config changes"
level=INFO ts=2024-01-10T07:30:05.531789623Z app=device-rfid-llrp source=config.go:278 msg="listening for device service common config changes"
level=INFO ts=2024-01-10T07:30:05.531806414Z app=device-rfid-llrp source=registry.go:61 msg="Using Registry access token of length 0"
level=INFO ts=2024-01-10T07:30:05.531813227Z app=device-rfid-llrp source=registry.go:89 msg="Using Registry (consul) from http://localhost:8500"
level=INFO ts=2024-01-10T07:30:05.550975882Z app=device-rfid-llrp source=httpserver.go:149 msg="Web server starting (localhost:59989)"
level=INFO ts=2024-01-10T07:30:05.551138167Z app=device-rfid-llrp source=messaging.go:66 msg="Setting options for secure MessageBus with AuthMode='usernamepassword' and SecretName='redisdb"
level=INFO ts=2024-01-10T07:30:05.551491271Z app=device-rfid-llrp source=messaging.go:104 msg="Connected to redis Message Bus @ redis://localhost:6379 with AuthMode='usernamepassword'"
level=INFO ts=2024-01-10T07:30:05.551635833Z app=device-rfid-llrp source=command.go:36 msg="Subscribing to command requests on topic: edgex/device/command/request/device-rfid-llrp/#"
level=INFO ts=2024-01-10T07:30:05.551703871Z app=device-rfid-llrp source=command.go:40 msg="Responses to command requests will be published on topic: edgex/response/device-rfid-llrp/"
level=INFO ts=2024-01-10T07:30:05.553965292Z app=device-rfid-llrp source=callback.go:34 msg="Subscribing to System Events on topic: edgex/system-events/core-metadata/+/+/device-rfid-llrp/#"
level=INFO ts=2024-01-10T07:30:05.555812475Z app=device-rfid-llrp source=validation.go:31 msg="Subscribing to device validation requests on topic: edgex/device-rfid-llrp/validate/device"
level=INFO ts=2024-01-10T07:30:05.555941237Z app=device-rfid-llrp source=validation.go:35 msg="Responses to device validation requests will be published on topic: edgex/response/device-rfid-llrp/"
level=INFO ts=2024-01-10T07:30:05.557609674Z app=device-rfid-llrp source=manager.go:128 msg="Metrics Manager started with a report interval of 30s"
level=INFO ts=2024-01-10T07:30:05.559966334Z app=device-rfid-llrp source=clients.go:190 msg="Using registry for URL for 'core-metadata': http://localhost:59881"
level=INFO ts=2024-01-10T07:30:05.560274173Z app=device-rfid-llrp source=restrouter.go:56 msg="Registering v2 routes..."
level=INFO ts=2024-01-10T07:30:05.567035734Z app=device-rfid-llrp source=devices.go:78 msg="LastConnected-LLRP-EF-19-FB metric has been registered and will be reported (if enabled)"
level=INFO ts=2024-01-10T07:30:05.577468327Z app=device-rfid-llrp source=config.go:576 msg="Checking if custom configuration ('AppCustom') exists in Configuration Provider"
level=INFO ts=2024-01-10T07:30:05.585680355Z app=device-rfid-llrp source=config.go:597 msg="Loaded custom configuration from Configuration Provider, no overrides applied"
level=DEBUG ts=2024-01-10T07:30:05.585824326Z app=device-rfid-llrp source=driver.go:133 msg="Custom config is : &{AppCustom:{DiscoverySubnets:10.17.83.6/22 ProbeAsyncLimit:4000 ProbeTimeoutSeconds:2 ScanPort:5084 MaxDiscoverDurationSeconds:300 ProvisionWatcherDir:}}"
level=INFO ts=2024-01-10T07:30:05.585906972Z app=device-rfid-llrp source=config.go:690 msg="Watching for custom configuration changes has started for AppCustom"
level=DEBUG ts=2024-01-10T07:30:05.585971663Z app=device-rfid-llrp source=service.go:281 msg="trying to find device service device-rfid-llrp"
level=INFO ts=2024-01-10T07:30:05.587534441Z app=device-rfid-llrp source=service.go:299 msg="device service device-rfid-llrp exists, updating it"
level=INFO ts=2024-01-10T07:30:05.590219519Z app=device-rfid-llrp source=profiles.go:89 msg="Loading pre-defined Device Profiles from /home/michele/EdgeX/device-rfid-llrp-go/cmd/res/profiles(2 files found)"
level=DEBUG ts=2024-01-10T07:30:05.590376143Z app=device-rfid-llrp source=callback.go:78 msg="System event received on message queue. Topic: edgex/system-events/core-metadata/deviceservice/update/device-rfid-llrp, Correlation-id: f0da98f2-9838-4379-b594-33d42657682b"
level=DEBUG ts=2024-01-10T07:30:05.590559548Z app=device-rfid-llrp source=callback.go:269 msg="device service updated"
level=INFO ts=2024-01-10T07:30:05.594905679Z app=device-rfid-llrp source=profiles.go:190 msg="Device Profile LLRP-Device-Profile exists, using the existing one"
level=INFO ts=2024-01-10T07:30:05.597201405Z app=device-rfid-llrp source=profiles.go:190 msg="Device Profile LLRP-Impinj-Profile exists, using the existing one"
level=INFO ts=2024-01-10T07:30:05.597336939Z app=device-rfid-llrp source=provisionwatchers.go:79 msg="Loading pre-defined Provision Watchers from /home/michele/EdgeX/device-rfid-llrp-go/cmd/res/provision_watchers(2 files found)"
level=INFO ts=2024-01-10T07:30:05.597527127Z app=device-rfid-llrp source=provisionwatchers.go:165 msg="ProvisionWatcher llrp-impinj-provision-watcher exists, using the existing one"
level=INFO ts=2024-01-10T07:30:05.59767222Z app=device-rfid-llrp source=provisionwatchers.go:165 msg="ProvisionWatcher llrp-provision-watcher exists, using the existing one"
level=DEBUG ts=2024-01-10T07:30:05.597698098Z app=device-rfid-llrp source=utils.go:110 msg="EventsSent metric has been registered and will be reported (if enabled)"
level=DEBUG ts=2024-01-10T07:30:05.597713137Z app=device-rfid-llrp source=utils.go:110 msg="ReadingsSent metric has been registered and will be reported (if enabled)"
level=INFO ts=2024-01-10T07:30:05.597735218Z app=device-rfid-llrp source=message.go:50 msg="Service dependencies resolved..."
level=INFO ts=2024-01-10T07:30:05.597748503Z app=device-rfid-llrp source=message.go:51 msg="Starting device-rfid-llrp 0.0.0 "
level=INFO ts=2024-01-10T07:30:05.597759875Z app=device-rfid-llrp source=message.go:55 msg="device llrp started"
level=INFO ts=2024-01-10T07:30:05.597771446Z app=device-rfid-llrp source=message.go:58 msg="Service started in: 72.855416ms"
level=INFO ts=2024-01-10T07:30:05.597784952Z app=device-rfid-llrp source=bootstrap.go:251 msg="SecuritySecretsRequested metric registered and will be reported (if enabled)"
level=INFO ts=2024-01-10T07:30:05.597798257Z app=device-rfid-llrp source=bootstrap.go:251 msg="SecuritySecretsStored metric registered and will be reported (if enabled)"
level=INFO ts=2024-01-10T07:30:05.59783205Z app=device-rfid-llrp source=driver.go:159 deviceName=LLRP-EF-19-FB msg="Creating a new Reader connection."
level=INFO ts=2024-01-10T07:30:05.59785308Z app=device-rfid-llrp source=autodiscovery.go:46 msg="Starting auto-discovery with duration 1h0m0s"
level=DEBUG ts=2024-01-10T07:30:05.597894778Z app=device-rfid-llrp source=discovery.go:34 msg="protocol discovery triggered"
level=DEBUG ts=2024-01-10T07:30:05.597901411Z app=device-rfid-llrp source=device.go:124 device=LLRP-EF-19-FB msg="Starting Reader management."
level=INFO ts=2024-01-10T07:30:05.597918954Z app=device-rfid-llrp source=driver.go:742 msg="Discover was called."
level=DEBUG ts=2024-01-10T07:30:05.597951675Z app=device-rfid-llrp source=discover.go:120 msg="total estimated network probes: 1022, async limit: 1022, probe timeout: 2s, total estimated time: 2s"
level=DEBUG ts=2024-01-10T07:30:05.597926778Z app=device-rfid-llrp source=device.go:139 address=10.17.83.6:5084 device=LLRP-EF-19-FB msg="Attempting to dial Reader."
level=DEBUG ts=2024-01-10T07:30:05.703788004Z app=device-rfid-llrp source=device.go:151 device=LLRP-EF-19-FB msg="Attempting LLRP Client connection."
level=DEBUG ts=2024-01-10T07:30:05.707539677Z app=device-rfid-llrp source=discover.go:459 msg="Skip scan of 10.17.83.6:5084, device already registered."
level=INFO ts=2024-01-10T07:30:05.776992877Z app=device-rfid-llrp source=logging.go:34 type=MsgReaderEventNotification device=LLRP-EF-19-FB msg="Incoming LLRP message"
level=WARN ts=2024-01-10T07:30:05.777077997Z app=device-rfid-llrp source=logging.go:38 message-version=Version1_0_1 client-version=Version1_1 msg="LLRP incoming message version mismatch"
level=DEBUG ts=2024-01-10T07:30:05.777191129Z app=device-rfid-llrp source=device.go:496 device=LLRP-EF-19-FB msg="Setting Reader KeepAlive spec."
level=DEBUG ts=2024-01-10T07:30:05.777309482Z app=device-rfid-llrp source=device.go:242 device=LLRP-EF-19-FB message=MsgSetReaderConfig msg="Attempting send."
level=INFO ts=2024-01-10T07:30:05.777309953Z app=device-rfid-llrp source=logging.go:25 type=MsgGetSupportedVersion device=LLRP-EF-19-FB msg="Sending LLRP message"
level=DEBUG ts=2024-01-10T07:30:05.804470203Z app=device-rfid-llrp source=logging.go:32 type=MsgKeepAlive device=LLRP-EF-19-FB msg="Incoming LLRP message"
level=WARN ts=2024-01-10T07:30:05.804531278Z app=device-rfid-llrp source=logging.go:38 message-version=Version1_0_1 client-version=Version1_1 msg="LLRP incoming message version mismatch"
level=DEBUG ts=2024-01-10T07:30:05.804563308Z app=device-rfid-llrp source=logging.go:45 type=MsgKeepAlive device=LLRP-EF-19-FB msg="Handled LLRP message."
level=DEBUG ts=2024-01-10T07:30:05.80466Z app=device-rfid-llrp source=logging.go:23 type=MsgKeepAliveAck device=LLRP-EF-19-FB msg="Sending LLRP message"
level=INFO ts=2024-01-10T07:30:05.830959362Z app=device-rfid-llrp source=logging.go:34 type=MsgErrorMessage device=LLRP-EF-19-FB msg="Incoming LLRP message"
level=DEBUG ts=2024-01-10T07:30:05.831065531Z app=device-rfid-llrp source=logging.go:45 type=MsgErrorMessage device=LLRP-EF-19-FB msg="Handled LLRP message."
level=INFO ts=2024-01-10T07:30:05.831129562Z app=device-rfid-llrp source=logging.go:25 type=MsgSetReaderConfig device=LLRP-EF-19-FB msg="Sending LLRP message"
level=INFO ts=2024-01-10T07:30:05.858006119Z app=device-rfid-llrp source=logging.go:34 type=MsgErrorMessage device=LLRP-EF-19-FB msg="Incoming LLRP message"
level=WARN ts=2024-01-10T07:30:05.858200975Z app=device-rfid-llrp source=logging.go:38 message-version=Version1_1 client-version=Version1_0_1 msg="LLRP incoming message version mismatch"
level=DEBUG ts=2024-01-10T07:30:05.858257712Z app=device-rfid-llrp source=logging.go:49 type=MsgErrorMessage device=LLRP-EF-19-FB msg="Ignored LLRP message."
level=INFO ts=2024-01-10T07:30:06.058993047Z app=device-rfid-llrp source=logging.go:34 type=MsgSetReaderConfigResponse device=LLRP-EF-19-FB msg="Incoming LLRP message"
level=DEBUG ts=2024-01-10T07:30:06.05909549Z app=device-rfid-llrp source=logging.go:45 type=MsgSetReaderConfigResponse device=LLRP-EF-19-FB msg="Handled LLRP message."
level=DEBUG ts=2024-01-10T07:30:06.059188986Z app=device-rfid-llrp source=device.go:391 msg="Sending LLRP Event 'ReaderEventNotification'"
level=DEBUG ts=2024-01-10T07:30:06.059320663Z app=device-rfid-llrp source=transform.go:100 msg="failed to read ResourceOperation: failed to find ResourceOpertaion with DeviceResource ReaderEventNotification in Profile LLRP-Device-Profile"
level=DEBUG ts=2024-01-10T07:30:06.059459805Z app=device-rfid-llrp source=transform.go:123 msg="device: LLRP-EF-19-FB DeviceResource: ReaderEventNotification reading: {Id:f47749d0-8a10-4576-9f73-132516903749 Origin:1704871805777111660 DeviceName:LLRP-EF-19-FB ResourceName:ReaderEventNotification ProfileName:LLRP-Device-Profile ValueType:Object Units: Tags:map[] BinaryReading:{BinaryValue:[] MediaType:} SimpleReading:{Value:} ObjectReading:{ObjectValue:0xc000cfc630}}"
level=DEBUG ts=2024-01-10T07:30:06.060637048Z app=device-rfid-llrp source=utils.go:82 msg="Event(profileName: LLRP-Device-Profile, deviceName: LLRP-EF-19-FB, sourceName: ReaderEventNotification, id: 5484e831-1487-4e85-beed-46c65ec5ebae) published to MessageBus on topic: edgex/events/device/device-rfid-llrp/LLRP-Device-Profile/LLRP-EF-19-FB/ReaderEventNotification"
level=INFO ts=2024-01-10T07:30:07.760861011Z app=device-rfid-llrp source=driver.go:777 msg="Discovered 0 new devices in 2.162815459s."
level=DEBUG ts=2024-01-10T07:30:07.761005973Z app=device-rfid-llrp source=async.go:129 msg="Filtered device addition finished"

This is the case when I don't restart the reader and so I'm not able to read EPC tags. I'm not able to understand this log:
level=DEBUG ts=2024-01-19T15:46:02.075495915Z app=device-rfid-llrp source=transform.go:100 msg="failed to read ResourceOperation: failed to find ResourceOpertaion with DeviceResource ROSpec in Profile LLRP-Device-Profile"
It looks like there is a spelling error, but I don't find it.

from device-rfid-llrp-go.

After reading LLRP standard documentation I've modified the ROSpec.json file in this way:

{
    "ROSpecID": 1,
    "Priority": 0,
    "ROSpecCurrentState": 0,
    "ROBoundarySpec": {
        "StartTrigger": {
            "Trigger": 1,
            "PeriodicTrigger": null,
            "GPITrigger": null
        },
        "StopTrigger": {
            "Trigger": 0,
            "DurationTriggerValue": null,
            "GPITriggerValue": null
        }
    },
    "AISpecs": [
        {
            "AntennaIDs": [
                1, 4
            ],
            "StopTrigger": {
                "Trigger": 0,
                "DurationTriggerValue": null,
                "GPITrigger": null,
                "TagObservationTrigger": null
            },
            "InventoryParameterSpecs": [
                {
                    "InventoryParameterSpecID": 1,
                    "AirProtocolID": 1,
                    "AntennaConfigurations": [
                        {
                            "AntennaID":1,
                            "RFReceiver": 0,
                            "RFTransmitter": {
                                "ChannelIndex": 1,
                                "TransmitPowerIndex": 29
                            }
                        },
                        {
                            "AntennaID":4,
                            "RFReceiver": 0,
                            "RFTransmitter": {
                                "ChannelIndex": 1,
                                "TransmitPowerIndex": 29
                            }
                        }
                    ],
                    "Custom": null
                }
            ],
            "Custom": null
        }
    ],
    "RFSurveySpecs": null,
    "Custom": null,
    "LoopSpec": null,
    "ROReportSpec": {
        "Trigger": 2,
        "N": 1,
        "TagReportContentSelector": {
            "EnableROSpecID": false,
            "EnableSpecIndex": false,
            "EnableInventoryParamSpecID": false,
            "EnableAntennaID": false,
            "EnableChannelIndex": false,
            "EnablePeakRSSI": false,
            "EnableFirstSeenTimestamp": false,
            "EnableLastSeenTimestamp": false,
            "EnableTagSeenCount": false,
            "EnableAccessSpecID": false,
            "Custom": null
        },
        "Custom": null
    }
}

Anyway the problem persists.

from device-rfid-llrp-go.