Fix handling of controller CAN

[petergebruers]

I simulated a busy network and observed:

2019-12-25 08:48:05.800 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x15) - FUNC_ID_ZW_GET_VERSION: 0x01, 0x03, 0x00, 0x15, 0xe9
2019-12-25 08:48:05.800 Info, contrlr, Encrypted Flag is 0
2019-12-25 08:48:05.801 Detail, Unsolicited message received while waiting for ACK.
2019-12-25 08:48:05.802 Detail, Node012, Received: 0x01, 0x0f, 0x00, 0x04, 0x00, 0x0c, 0x07, 0x60, 0x0d, 0x00, 0x01, 0x25, 0x03, 0xff, 0xdd, 0x00, 0x97
2019-12-25 08:48:05.802 Detail,
2019-12-25 08:48:05.803 Detail, contrlr, CAN received...triggering resend
2019-12-25 08:48:05.803 Detail,
2019-12-25 08:48:05.803 Info, contrlr, Sending (Command) message (Attempt 2, Callback ID=0x00, Expected Reply=0x15) - FUNC_ID_ZW_GET_VERSION: 0x01, 0x03, 0x00, 0x15, 0xe9
2019-12-25 08:48:05.803 Info, contrlr, Encrypted Flag is 0
2019-12-25 08:48:05.803 Detail, Unsolicited message received while waiting for ACK.
2019-12-25 08:48:05.804 Detail, Node012, Received: 0x01, 0x0f, 0x00, 0x04, 0x00, 0x0c, 0x07, 0x60, 0x0d, 0x00, 0x01, 0x25, 0x03, 0x00, 0xdd, 0x00, 0x68
2019-12-25 08:48:05.804 Detail,
2019-12-25 08:48:05.805 Detail, contrlr, CAN received...triggering resend
2019-12-25 08:48:05.805 Detail,

Before this commit, a CAN would lead to an immediate resend of the command, without handling the incoming data.

After this commit, the "threadprocloop" will run once, allowing the handling of data, flushing the buffer and clearing the CAN condition.

2019-12-25 09:27:53.484 Info, contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x15) - FUNC_ID_ZW_GET_VERSION: 0x01, 0x03, 0x00, 0x15, 0xe9
2019-12-25 09:27:53.484 Info, contrlr, Encrypted Flag is 0
2019-12-25 09:27:53.485 Detail, Unsolicited message received while waiting for ACK.
2019-12-25 09:27:53.486 Detail, Node012, Received: 0x01, 0x0f, 0x00, 0x04, 0x00, 0x0c, 0x07, 0x60, 0x0d, 0x00, 0x01, 0x25, 0x03, 0xff, 0xd0, 0x00, 0x9a
2019-12-25 09:27:53.486 Detail,
2019-12-25 09:27:53.487 Detail, contrlr, CAN received...triggering resend
2019-12-25 09:27:53.487 Detail, Unsolicited message received while waiting for ACK.
2019-12-25 09:27:53.488 Detail, Node012, Received: 0x01, 0x0f, 0x00, 0x04, 0x00, 0x0c, 0x07, 0x60, 0x0d, 0x00, 0x01, 0x25, 0x03, 0x00, 0xda, 0x00, 0x6f
2019-12-25 09:27:53.488 Detail,
2019-12-25 09:27:54.492 Detail,
2019-12-25 09:27:54.492 Info, contrlr, Sending (Command) message (Attempt 2, Callback ID=0x00, Expected Reply=0x15) - FUNC_ID_ZW_GET_VERSION: 0x01, 0x03, 0x00, 0x15, 0xe9
2019-12-25 09:27:54.492 Info, contrlr, Encrypted Flag is 0
2019-12-25 09:27:54.492 Detail, contrlr, Notification: Notification - TimeOut
2019-12-25 09:27:54.495 Detail, contrlr, Received: 0x01, 0x10, 0x01, 0x15, 0x5a, 0x2d, 0x57, 0x61, 0x76, 0x65, 0x20, 0x34, 0x2e, 0x36, 0x31, 0x00, 0x01, 0x95
2019-12-25 09:27:54.495 Detail,

So the key change is that before this commit "CAN received...triggering resend" immediately leads to outbound data "Sending (Command) message (Attempt 2".

After this PR then "CAN received...triggering resend will handle the incoming data "Unsolicited message received while waiting for ACK."

Should improve #2036 "Nodes not detected correctly in OZW1.6" by reducing the number of CAN loops.

[Fishwaldo]

Good Catch!

[MarkGodwin]

Hey guys,

I believe the problem with this PR is that it introduces an at least 1 second delay before the message is re-transmitted. And it's much worse if there is more activity on the network.

I suggest the timeout in the DriverThreadProc needs to be taken down to close to zero (probably all the way to zero) when a CAN or a NAK is handled, like so:

				else if (m_waitingForAck || m_expectedCallbackId || m_expectedReply)
				{
					count = 4;
					timeout = !m_waitingForAck ? retryTimeStamp.TimeRemaining() :
						m_currentMsg != NULL && m_currentMsg->isResendDuetoCANorNAK() ? CAN_NAK_TIMEOUT :
						ACK_TIMEOUT;
					if (timeout < 0)
					{
						timeout = 0;
					}
				}

I believe this will help a lot with network latency under load, because the 1 second timeout leaves a wide window for more activity to slip in - thereby resetting the timeout to 1s again and again.

Would you consider a PR to this effect?