Subscriptions are deleted when the connection status changes quickly back to disconnected

[mareksuscak]

Hey there. Following up on the other issue I reported recently, I finally managed to get some additional logs:

I really do not know how to reproduce this issue, but I think this is key to figuring it out. It appears that when the client successfully reconnects here and then goes on to restore subscriptions here the connection may drop again before all subscriptions are re-established when the network isn't stable (or the process is under huge pressure) and that code isn't handling a connection loss event properly which trigger the removal that I don't think is correct behavior. Generally a very specific class of errors should trigger removal of all subscriptions and when the client isn't connected, this should juts eject out of that code and retry the whole reconnection again. Thoughts?

In case it helps, here's our configuration of AdsClient:

connectionCheckInterval: ms('1s'),
timeoutDelay: ms('5s'),
connectionDownDelay: 0,
autoReconnect: true,
reconnectInterval: ms('1s'),

[mareksuscak]

Hi @jisotalo. Did you have a chance to look at this issue?

[jisotalo]

Unfortunately I haven't had time for this. If you could create a some way I could reproduce this, it would help a lot!

[JeysonBarrera]

hi @mareksuscak, Were you able to validate the correction to this problem? I think I'm having the same problem.

I'd like to see if I can fix the problem.

Thanks

[mareksuscak]

@JeysonBarrera no, not really, this is still happening and causing regular disconnects where we're forced to restart the service to make it work again. It's very annoying. I have a note to get back to this at some point.

[jisotalo]

Please let me know if you can arrange an example to reproduce this bug on development setup.

With that, I could try to find a solution!

[mareksuscak]

The problem is I have no clue how to trigger this behavior. It happens infrequently but regularly, sometimes taking over a day to occur. I can put together a script that exhibits this behavior if you want. Note that you may need to let it sit idle for over a day, which makes it hard to troubleshoot with the verbose logging behavior which generates a ton of log data.

[mareksuscak]

https://github.com/mareksuscak/ads-client-bug-repro

@jisotalo I finally extracted a skeleton of our system to show you how we manage PLC connection and how we read/write variables. You're gonna have to create 3 structs (check README) and add some vars to GVL_Remote (also in the README). I don't have any reliable way to reproduce the issue and we've been running our system for several days now without a single issue. Our system is way more complex and does some other things in the background which could also be a factor in theory. We're computing our state from the in memory map every 1 second and writing to the PLC at a few minute intervals throughout the day but I've seen the system drop subscriptions even with no activity whatsoever. We use a free version of Twincat that makes us re-enter a code to acquire a temporary license key (at least in our lab env)

Please let me know if you need anything else from me like versions of various components of Twincat, etc. I do feel like we're still facing an issue with the client not being able to detect all the restarts correctly too btw.

[mareksuscak]

This issue just occurred to us again, although the service was restarted before subscription got dropped but I believe this is what sometimes leads to the race condition where the error is thrown in the middle of subscription restoration and that leads to
the incorrect removal of that subscription. The events shown in the screenshot above are in reverse chronological order so read from bottom to top. We write a variable, then 4 to 5 minutes later ADS router reports a state change to "0" which seems to map to "STOP" and then 15s later we get ECONNRESET -4077 syscall level error which seems to be a forcible close of the connection by the router? Then the connection check attempts to reconnect for a few seconds. This time, the service got restarted by us before it corrupted subscription but often times this process just drops arbitrary subscriptions due to a bug in the implementation I outlined above. I am not yet sure what would cause AMS router to report a stopped state. We did not trigger this explicitly but this may be one way to reproduce this issue although, it seems to be a race condition that is inconsistently reproducible.

[jisotalo]

Thanks @mareksuscak. I wish I had the time to dig into this more.

I added help wanted in case someone could contribute to this issue!

[mareksuscak]

Thank you so much. I'll keep dropping additional bits of info as I learn more about this issue. We could not find any evidence that ADS router was stopped or restarted around the time it was reported by ads-client.

[mareksuscak]

Just to follow up with additional insights. I think one way to force this issue to occur is to apply a lot of pressure (i.e. by hitting the API that makes some async requests to another service under the hood) on the process to get it to a state where the event queue becomes very busy, then release the pressure briefly and re-apply it again.