Gate polling stops working correctly

[gordonparikh]

Rare conditions seem to be able to cause polling of Gate NDORv5 devices (and potentially others) to stop working properly. A server restart is then required to resume normal polling. Issue was observed on D6-80-126-EB. This seems to be related to Issue #41.

Details on the issue:

General Notes

• Communication to this site has been spotty
  • Periodic comm errors and failures, last record of comm restored on 6/17 at 8:50 AM
  • Networking issues confirmed by Seth @ NDOT (details unclear)
  • Other gate sites are showing some similar spotiness (varies depending on the site) - repeated errors over a ~1 min period, comm failure, then restored, then nothing for some time (hours to days) - Seems transient but I don't know the extent of this or the implications
• We have been getting messages from the server about null pointer exceptions when making changes to comm links

Polling History Review

• Polling seemed mostly normal until around 8:55 AM on 6/17 - albeit with near constant timeouts (i.e. polling was working, comm was not)
• See some "ADDING OpQueryGateStatus$QueryStatus ..." indicating the polling job was being added to the queue
• Lots of "DROPPING OpQueryGateStatus$QueryStatus ..." though, indicating polling jobs were being dropped instead of added (will come back to this on code review)
• Logs entries go back to ~3:15 AM 6/11/2022
• First "DROPPING" log entry at 12 PM on 6/11 (one for each gate EB-1 and EB-2 at that time), then nothing for rest of day
• Period of successful communication with gate controller ends on 6/15 at 12:55 AM
• "DROPPING" log entries start just after that at 1 AM on 6/15 - start to see more than 1 per gate (EB-1/2) per polling cycle at this point (sometimes 2 for EB-1, sometimes 2 for EB-2) - this coincides with the begin of connect time out errors as well
• "connect timed out" errors continue continued with this, along with "HANDLING connect timed out" log entries, though these are almost never followed by "DONE HANDLING connect timed out" messages, as would be expected from the code in ThreadedPoller.handleError (the only place this message could have come from)
• One poll got through on 6/17 at 8:50 AM (actually two per gate, so four in total - this makes it seem like polling operations are being duplicated or something, but it's unclear, and in any case WB was showing the same behavior, as do other gates on occassion)
• A flurry of 5 "connect timed out" errors happens after this between 8:55:10 AM and 8:55:46 AM - this is the only time "HANDLING connect timed out" is followed by "DONE HANDLING connect timed out"
  • The number of tries (5) may coincide with the value of the operation_retry_threshold system attribute, which was 5 until I tried setting it to 6 on 6/22 (or this may just be a coincidency)
• Last "connect timed out" error reported at 9:15 AM on 6/17, after which they stop entirely
• "DROPPING" log entries (along with thread start) continue through to now
• Controller status has been "DRAINED" since issue was reported

Code Review

• Networking issues (or thereabouts) were happening, causing comm issues with the controller
• These issues, combined with the way IRIS handles polling errors, seems to have driven the polling operations for this gate into an improper state, where new poll operations are dropped rather than being added to the queue
• Key Questions
  • Why would polling operations be dropped?
  • Why were the majority of "connect timed out" errors logged along with "HANDLING connect timed out" but not "DONE HANDLING connect timed out"

Polling Operation Drops

• GateNdorV5Poller extends ThreadedPoller class
• Polling operations added in ThreadedPoller.addOp method
• Trying to add the operation to the queue and failing (OpQueue.enqueue returns false) will log the "DROPPING ..." message
  • OpQueue.enqueue will return false if queue is closed, or if the operation is already active or queued
  • The queue will only be closed when the poller is destroyed
    • When the poller is destroyed, it will disconnect (logging "THREAD STOP" to the server log), drain the queue (logging a "QUEUE_DRAINED" comm error (I think) just to the comm status/client), then log "DESTROYED" to the server log when this operation is completed
    • "THREAD STOP" is logged, but "DESTROYED" is not - may just be disconnect() being called and not destroy()
    • Changing poll_enabled status (and making some other configuration changes) should call recreatePoller() which should call destroyPoller(), but there are no "DESTROYED" log messages for any gates, so there may be another reason for this
      • THIS SEEMS TO BE RELATED TO THE NULL POINTER EXCEPTIONS SEEN IN THE CLIENT
    • disconnect() is also called when a CommThread exits or in addOp if the thread is null/done, which may be an alternate explanation, but seems less likely
• These can also be triggered when the CommThread attempts to requeue an operation and fails - this seems less likely than it being caused by enqueue, but unclear

Error Handling

• Why are errors not "DONE HANDLING"?
• ThreadedPoller.handleError was triggered by either a ConnectException or IOException (unclear which)
• This goes through all the operations in the queue, handling the comm error for each one
• If queue.tryNext works properly (looks like it should) - this loop should always exit
• The lack of "DONE HANDLING" messages indicates that either this method isn't working as it should, or (more likely), an exception (probably NPE) is being hit somewhere in the loop
• OpController.handleCommError (or the corresponding override method) seems most likely, but that's about as far as I can say now

Null Pointer Exceptions

• Disabling polling on this controller reliably is producing the null pointer exception messages via SONAR
• The server successfully changes the value of poll_enabled in the database
• It also disables the gate arm system by deleting the /var/lib/iris/gate_arm_enable file
• The NPE, therefore, seems to be hit after that - in recreatePoller(), which calls destroy()
• We do get a "THREAD STOP" log entry, so it makes it through disconnect()
• We DON'T get a "DESTROYED" log entry (as noted above), so we most likely hit the NPE in drainQueue()
• drainQueue uses queue.forEach - seems to be written safely but not entirely sure
• For each operation it touches it runs a custom OpHandler.handle() method that calls handleCommError() to set the controller status to DRAINED and update the fail time, etc.
• BUT - the fail time does not update when polling status is changed
• This also points to OpController.handleCommError (or the corresponding override method) as the potential culprit

[gordonparikh]

Attempted to replicate issue on staging server (NDOTIRIS03). Initially no issues as the controller was online so polling was successful. Changing the IP address to an unused one (to replicate the controller being offline) and waiting a polling cycle caused the issue to emerge. Restarting the server (without changing the IP from the "offline" one) did not clear the issue, but restarting and restoring connectivity did.

Issue appears to require hitting a "connect timed out" error, at which point polling will break permanently until connectivity is restored and the server is restarted (in that order).

[gordonparikh]

Potential fix c1fa4cf829003073df533db2d5000f7ee06cecd6 tested on development machine and staging. Appears to fix issue but will perform some additional testing.

[gordonparikh]

Added more null pointer checking in 5817596, and overall exception handling to generic polling code in dd1d803.