Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Agent Reconnecting to Broker repeatedly #441

Open
neildes2 opened this issue Apr 15, 2024 · 20 comments
Open

Agent Reconnecting to Broker repeatedly #441

neildes2 opened this issue Apr 15, 2024 · 20 comments
Labels
bug can't reproduce

Comments

@neildes2
Copy link
Collaborator

Agent V 2.3.0.7

Agent disconnects and reconnects repeatedly. Is this by design. I think not.

image

This works fine with v2.3.0.2.
@wsobel
Copy link
Member

wsobel commented Apr 15, 2024

Need to reproduce. Can
You give more context?

@neildes2
Copy link
Collaborator Author

neildes2 commented Apr 16, 2024 •
edited

Running agent on desktop connecting to Mosquitto broker with user/pwd only. Running in debug/console mode.

cfg

Devices = Devices.xml
AgentDeviceUUID = "3519a48b-814b-3425-a12d-ef250947ab3d"
PreserveUUID = true
Port = 5000
ReconnectInterval = 1000
BufferSize = 17
MaxAssets = 1024
SchemaVersion = 2.2
ShdrVersion = 1
SuppressIPAddress = false
DisableAgentDevice = ture
MonitorConfigFiles = false
WorkerThreads = 2
JsonVersion = 1
ConversionRequired = true
IgnoreTimestamps = true
Pretty = true

Adapters {

device {

	Url = mqtt://mydomainname.com/
    MqttPort = 1883
    MqttUserName = userid
    MqttPassword = pwd
    Topics = "test/ingest/testmachine/#"
    MqttClientId = test

}

}

Logger Configuration

logger_config
{

logging_level = trace

}

@wsobel
Copy link
Member

wsobel commented Apr 16, 2024

I'm having trouble reproducing. Have your configuration and the connection is remaining solid.

Can you upload the entire log? I need to see what happened before to reproduce. Also, the MQTT feed would be helpful to see if something caused the disconnect cycle.

Here's my log. All looks good.

2024-04-16T14:24:11.945996Z (0x000000016ff13000) [debug] : topic_name: test/ingest/testmachine/topic
2024-04-16T14:24:11.946399Z (0x000000016ff13000) [debug] : contents: {
  "timestamp": "2023-11-06T12:12:44Z",
  "avail": "AVAILABLE"
}
2024-04-16T14:24:16.695047Z (0x000000016ff9f000) [debug] AgentConfiguration::monitorThread: Monitoring files: "/Users/will/projects/MTConnect/agent/issues/441_broker_reconnection/agent.cfg" and /Users/will/projects/MTConnect/agent/issues/441_broker_reconnection/Devices.xml, will warm start if they change.
2024-04-16T14:24:21.884092Z (0x000000016ff13000) [info] SessionImpl::requested: ReST Request: From [127.0.0.1:63255]: GET /
2024-04-16T14:24:22.067695Z (0x000000016ff13000) [info] SessionImpl::requested: ReST Request: From [127.0.0.1:63257]: GET /apple-touch-icon-precomposed.png
2024-04-16T14:24:22.069634Z (0x000000016ff13000) [warning] SessionImpl::requested: Cannot find file: /apple-touch-icon-precomposed.png
2024-04-16T14:24:22.069700Z (0x000000016ff13000) [warning] SessionImpl::requested: Cannot find file: /apple-touch-icon-precomposed.png
2024-04-16T14:24:22.069747Z (0x000000016ff13000) [warning] SessionImpl::requested->Session::fail: Operation failed: 127.0.0.1: Cannot find handler for: GET /apple-touch-icon-precomposed.png
2024-04-16T14:24:22.069787Z (0x000000016ff13000) [debug] SessionImpl::requested->Session::fail: Returning error INVALID_REQUEST: 127.0.0.1: Cannot find handler for: GET /apple-touch-icon-precomposed.png
2024-04-16T14:24:22.071779Z (0x000000016ff9f000) [info] SessionImpl::requested: ReST Request: From [127.0.0.1:63257]: GET /apple-touch-icon.png
2024-04-16T14:24:22.072731Z (0x000000016ff9f000) [warning] SessionImpl::requested: Cannot find file: /apple-touch-icon.png
2024-04-16T14:24:22.072783Z (0x000000016ff9f000) [warning] SessionImpl::requested: Cannot find file: /apple-touch-icon.png
2024-04-16T14:24:22.072828Z (0x000000016ff9f000) [warning] SessionImpl::requested->Session::fail: Operation failed: 127.0.0.1: Cannot find handler for: GET /apple-touch-icon.png
2024-04-16T14:24:22.072868Z (0x000000016ff9f000) [debug] SessionImpl::requested->Session::fail: Returning error INVALID_REQUEST: 127.0.0.1: Cannot find handler for: GET /apple-touch-icon.png
2024-04-16T14:24:26.696584Z (0x000000016ff13000) [debug] AgentConfiguration::monitorThread: Monitoring files: "/Users/will/projects/MTConnect/agent/issues/441_broker_reconnection/agent.cfg" and /Users/will/projects/MTConnect/agent/issues/441_broker_reconnection/Devices.xml, will warm start if they change.
2024-04-16T14:24:31.388915Z (0x000000016ff9f000) [info] SessionImpl::requested: ReST Request: From [127.0.0.1:63255]: GET /current
2024-04-16T14:24:36.698056Z (0x000000016ff13000) [debug] AgentConfiguration::monitorThread: Monitoring files: "/Users/will/projects/MTConnect/agent/issues/441_broker_reconnection/agent.cfg" and /Users/will/projects/MTConnect/agent/issues/441_broker_reconnection/Devices.xml, will warm start if they change.
2024-04-16T14:24:46.699794Z (0x000000016ff9f000) [debug] AgentConfiguration::monitorThread: Monitoring files: "/Users/will/projects/MTConnect/agent/issues/441_broker_reconnection/agent.cfg" and /Users/will/projects/MTConnect/agent/issues/441_broker_reconnection/Devices.xml, will warm start if they change.
2024-04-16T14:24:52.085882Z (0x000000016ff13000) [warning] SessionImpl::requested->Session::fail: Operation failed: Could not read request
2024-04-16T14:24:52.085988Z (0x000000016ff13000) [warning] SessionImpl::requested->Session::fail: Closing: The socket was closed due to a timeout - The socket was closed due to a timeout
2024-04-16T14:24:56.700958Z (0x000000016ff9f000) [debug] AgentConfiguration::monitorThread: Monitoring files: "/Users/will/projects/MTConnect/agent/issues/441_broker_reconnection/agent.cfg" and /Users/will/projects/MTConnect/agent/issues/441_broker_reconnection/Devices.xml, will warm start if they change.
2024-04-16T14:25:01.395441Z (0x000000016ff9f000) [warning] SessionImpl::requested->Session::fail: Operation failed: Could not read request
2024-04-16T14:25:01.395557Z (0x000000016ff9f000) [warning] SessionImpl::requested->Session::fail: Closing: The socket was closed due to a timeout - The socket was closed due to a timeout
2024-04-16T14:25:06.702751Z (0x000000016ff9f000) [debug] AgentConfiguration::monitorThread: Monitoring files: "/Users/will/projects/MTConnect/agent/issues/441_broker_reconnection/agent.cfg" and /Users/will/projects/MTConnect/agent/issues/441_broker_reconnection/Devices.xml, will warm start if they change.
2024-04-16T14:25:16.704579Z (0x000000016ff9f000) [debug] AgentConfiguration::monitorThread: Monitoring files: "/Users/will/projects/MTConnect/agent/issues/441_broker_reconnection/agent.cfg" and /Users/will/projects/MTConnect/agent/issues/441_broker_reconnection/Devices.xml, will warm start if they change.
2024-04-16T14:25:26.706772Z (0x000000016ff13000) [debug] AgentConfiguration::monitorThread: Monitoring files: "/Users/will/projects/MTConnect/agent/issues/441_broker_reconnection/agent.cfg" and /Users/will/projects/MTConnect/agent/issues/441_broker_reconnection/Devices.xml, will warm start if they change.
2024-04-16T14:25:36.708356Z (0x000000016ff9f000) [debug] AgentConfiguration::monitorThread: Monitoring files: "/Users/will/projects/MTConnect/agent/issues/441_broker_reconnection/agent.cfg" and /Users/will/projects/MTConnect/agent/issues/441_broker_reconnection/Devices.xml, will warm start if they change.
2024-04-16T14:25:46.709658Z (0x000000016ff13000) [debug] AgentConfiguration::monitorThread: Monitoring files: "/Users/will/projects/MTConnect/agent/issues/441_broker_reconnection/agent.cfg" and /Users/will/projects/MTConnect/agent/issues/441_broker_reconnection/Devices.xml, will warm start if they change.
2024-04-16T14:25:56.711903Z (0x000000016ff13000) [debug] AgentConfiguration::monitorThread: Monitoring files: "/Users/will/projects/MTConnect/agent/issues/441_broker_reconnection/agent.cfg" and /Users/will/projects/MTConnect/agent/issues/441_broker_reconnection/Devices.xml, will warm start if they change.
2024-04-16T14:26:06.712951Z (0x000000016ff9f000) [debug] AgentConfiguration::monitorThread: Monitoring files: "/Users/will/projects/MTConnect/agent/issues/441_broker_reconnection/agent.cfg" and /Users/will/projects/MTConnect/agent/issues/441_broker_reconnection/Devices.xml, will warm start if they change.
2024-04-16T14:26:16.715587Z (0x000000016ff9f000) [debug] AgentConfiguration::monitorThread: Monitoring files: "/Users/will/projects/MTConnect/agent/issues/441_broker_reconnection/agent.cfg" and /Users/will/projects/MTConnect/agent/issues/441_broker_reconnection/Devices.xml, will warm start if they change.
2024-04-16T14:26:26.717303Z (0x000000016ff9f000) [debug] AgentConfiguration::monitorThread: Monitoring files: "/Users/will/projects/MTConnect/agent/issues/441_broker_reconnection/agent.cfg" and /Users/will/projects/MTConnect/agent/issues/441_broker_reconnection/Devices.xml, will warm start if they change.

@neildes2
Copy link
Collaborator Author

No logs just trace output on debug console. Never sent payload. just started up and got the reconnects.
V2.3.7.zip

@neildes2
Copy link
Collaborator Author

if I exchange the exe to 2.3.0.2 it works just fine

@wsobel
Copy link
Member

wsobel commented Apr 16, 2024

I've been testing on MacOS. I'll test on windows and see if I get the same behavior. I don't have a windows machine to test with aside from my VM, so milage may vary.

@wsobel
Copy link
Member

wsobel commented Apr 16, 2024

What version of Windows?

@wsobel
Copy link
Member

wsobel commented Apr 16, 2024

tested on windows and can't reproduce

2024-04-16T14:59:41.875382Z (0x00000998) [warning] MAIN->Agent::start->pipeline.deliver: Could not find data item: mqtt://10.211.55.2:1883_observation_update_rate, exiting metrics
2024-04-16T14:59:41.891031Z (0x00000998) [warning] MAIN->Agent::start->pipeline.deliver: Could not find data item: mqtt://10.211.55.2:1883_asset_update_rate, exiting metrics
2024-04-16T14:59:41.891031Z (0x00000998) [warning] MAIN->Agent::start->pipeline.deliver: Could not find data item: mqtt://10.211.55.2:1883_observation_update_rate, exiting metrics
2024-04-16T14:59:41.891031Z (0x00000998) [warning] MAIN->Agent::start->pipeline.deliver: Could not find data item: mqtt://10.211.55.2:1883_asset_update_rate, exiting metrics
2024-04-16T14:59:41.891031Z (0x00000998) [warning] MAIN->Agent::start->pipeline.deliver: Could not find data item: mqtt://10.211.55.2:1883_observation_update_rate, exiting metrics
2024-04-16T14:59:41.891031Z (0x00003378) [info] : MqttClientImpl::connect: connected
2024-04-16T14:59:41.891031Z (0x00001230) [info] : MQTT ConnAck: MQTT Connected
2024-04-16T14:59:41.891031Z (0x00001230) [info] : MqttClientImpl::connect: subscribing to topics
2024-04-16T14:59:41.891031Z (0x00001230) [debug] MqttClientImpl::subscribe: Subscribing to topic: test/ingest/testmachine/#
2024-04-16T14:59:41.906664Z (0x00001230) [debug] : Subscribed to: test/ingest/testmachine/#
2024-04-16T15:01:07.408800Z (0x00003378) [debug] : topic_name: test/ingest/testmachine/topic
2024-04-16T15:01:07.409823Z (0x00003378) [debug] : contents: {
  "avail": "AVAILABLE"
}

Stable using your exec and configured to point at external broker on my mac.

@wsobel
Copy link
Member

wsobel commented Apr 16, 2024

Configuration:

 device {
        
        Url = mqtt://10.211.55.2/
        MqttPort = 1883
        MqttUserName = testuser
        MqttPassword = testpasswd
        Topics = "test/ingest/testmachine/#"
        MqttClientId = Neil
 }

@wsobel
Copy link
Member

wsobel commented Apr 16, 2024

Also, I'm testing with mosquitto. What broker are you working with?

@neildes2
Copy link
Collaborator Author

Mosquitto

@wsobel
Copy link
Member

wsobel commented Apr 17, 2024

Are you using TLS or websockets?

@neildes2
Copy link
Collaborator Author

no

@wsobel
Copy link
Member

wsobel commented Apr 17, 2024

Is the broker local or remote?

Any other info you can send me? Broker config? More logging?

@neildes2
Copy link
Collaborator Author

Mosquitto Broker is remote (aws). Could this be some sort of a timeout issue? Do the Heatbeat param etc effect broker connections?

@wsobel
Copy link
Member

wsobel commented Apr 17, 2024

No idea. I'm trying to reproduce and have had no luck. It could be heartbeat or some other param. Do you have the aws mosquitto config? I could try to replicate.

@wsobel
Copy link
Member

wsobel commented Apr 17, 2024

Or could you give me access to the aws broker or a similar instance?

@neildes2
Copy link
Collaborator Author

Not able to provide access to this or duplicate broker. But the cfg file is attached. It uses a pwd file for you will need to modify to use.
mosquitto.txt

@robot-ranger
Copy link
Contributor

robot-ranger commented Apr 24, 2024 •
edited

posting in hopes this is a clue... we had this problem before when the agent was creating a unique client connection to the broker for the sink as well as any adapters using mqtt. iirc, both connections were using the same id and the broker was kicking one off immediately.

@wsobel
Copy link
Member

wsobel commented Apr 30, 2024

I thought we had addressed this by changing the client id. Neil can you test with a specific client id for each connection?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug can't reproduce
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@wsobel @robot-ranger @neildes2