/// <summary> /// Provides the server specific version of the Part's Main Loop Service method. /// </summary> protected override void PerformMainLoopService() { base.PerformMainLoopService(); InnerServiceFCServerAndStateRelay(); bool portIsConnected = portBaseStateObserver.Object.IsConnected; if (portWriteAction.ActionState.IsPendingCompletion || portFlushAction.ActionState.IsPendingCompletion || portReinitializeAction.ActionState.IsPendingCompletion) { // we cannot service a new request until the write, flush, and/or reinitialize actions started in any prior service loop have completed. return; } bool resyncCommandStream = false; bool startWrite = false; if (portIsConnected && portReadAction.ActionState.CanStart) { if (portReadAction.ActionState.IsComplete) { serverFunctionContainer.requestAdu.PktBuf.numBytes = portReadActionParam.BytesRead; string ec = null; TimeSpan bufferAge = bufferFillStartTime.Age; if (serverFunctionContainer.AttemptToDecodeRequestPkt(out ec)) { if (String.IsNullOrEmpty(ec)) { Log.Trace.Emit("Attempting to perform request ADU:{0}", serverFunctionContainer.requestAdu); if (serverFunctionContainer.ServiceDecodedRequest(fcServer)) { startWrite = true; } else { Log.Trace.Emit("Decoded request produced no response [ADU:{0}]", serverFunctionContainer.requestAdu); } } else { Log.Error.Emit("Invalid request received: {0} [numBytes:{1}]", ec, portReadActionParam.BytesRead); resyncCommandStream = true; } portReadActionParam.BytesRead = 0; } else if (portReadActionParam.BytesRead > 0) { if (port.PortBehavior.IsDatagramPort) { Log.Warning.Emit("Invalid partial request received from datagram port. Discarding {0} bytes", portReadActionParam.BytesRead); portReadActionParam.BytesRead = 0; } else if (bufferAge > Timeout) { Log.Warning.Emit("Incomplete Partial Request timeout after {0:f3} seconds. Discarding {0} bytes", bufferAge.TotalSeconds, portReadActionParam.BytesRead); portReadActionParam.BytesRead = 0; } } else { Log.Trace.Emit("Empty read completed"); } } if (!resyncCommandStream) { // start the read immediately even if we are also starting a write (keep the interface primed) // do not start the next read if we need to resync the command stream if (portReadActionParam.BytesRead == 0) { bufferFillStartTime = QpcTimeStamp.Now; } if (portReadActionParam.Buffer == null) { portReadActionParam.Buffer = serverFunctionContainer.requestAdu.PktBuf.bytes; portReadActionParam.BytesToRead = serverFunctionContainer.requestAdu.PktBuf.bytes.Length; } portReadAction.Start(); } } else if (portReadAction.ActionState.IsComplete && portReadActionParam.BytesRead > 0) { Log.Debug.Emit("Discarding {0} bytes of read data: port is no longer connected"); portReadActionParam.BytesRead = 0; } if (!portIsConnected) { } else if (startWrite) { Log.Trace.Emit("Writing response ADU:{0}", serverFunctionContainer.responseAdu); portWriteActionParam.Buffer = serverFunctionContainer.responseAdu.PktBuf.bytes; portWriteActionParam.BytesToWrite = serverFunctionContainer.responseAdu.PktBuf.numBytes; portWriteActionParam.BytesWritten = 0; portWriteAction.Start(); } else if (resyncCommandStream) { IPortBehavior portBehavior = port.PortBehavior; if (portBehavior.IsDatagramPort) { // there is nothing to do for datagram ports. // Each message is a seperate item so there is no "leftover" bytes from prior requests that we might need to get rid of. } else if (portBehavior.IsByteStreamPort && portBehavior.IsNetworkPort) { Log.Debug.Emit("Forcing port to reset current connection after protocol decode error (drop and immediately reconnect)"); portReinitializeAction.Start(); } else { portFlushAction.Start(); } } }
public void Service(bool sampleTimerTriggered) { TimeSpan stateAge = stateTimeStamp.Age; string ec = string.Empty; for (;;) { switch (state) { case State.RequestFlush: if (!port.BaseState.IsConnected) { ec = port.CreateGoOnlineAction(andInitialize: true).Run(); } if (ec.IsNullOrEmpty()) { ec = portFlushAction.Start(); } if (ec.IsNullOrEmpty()) { SetState(State.WaitUntilForFlushComplete, "Flush requested"); } else { SetState(State.EchoTestFailed, "Flush.Start failed: {0}".CheckedFormat(ec)); } return; case State.WaitUntilForFlushComplete: if (portFlushAction.ActionState.IsComplete) { SetState(State.WriteTestPattern, "Flush {0}".CheckedFormat(portFlushAction.ActionState.ToString())); } return; case State.WriteTestPattern: portWriteActionParam.BufferAsStr = currentTestPattern = GetNextTestDataPattern(); ec = portWriteAction.Start(); if (ec.IsNullOrEmpty()) { SetState(State.WaitForEcho, "Write requested"); } else { SetState(State.EchoTestFailed, "Write.Start failed: {0}".CheckedFormat(ec)); } return; case State.WaitForEcho: lastEchoTestPeriod = stateAge; if (port.HasPacket) { ec = portGetNextPacketAction.Run(); Packet p = portGetNextPacketAction.ResultValue; if (ec.IsNullOrEmpty() && p == null) { ec = "successful {0} action gave null packet".CheckedFormat(portGetNextPacketAction.ToString(ToStringSelect.JustMesg)); } if (ec.IsNullOrEmpty() && !p.IsData) { ec = "successful {0} action gave unexpected packet '{1}'".CheckedFormat(portGetNextPacketAction.ToString(ToStringSelect.JustMesg), p); } if (ec.IsNullOrEmpty() && p.DataStr != currentTestPattern) { ec = "Received unexpected echo [rx:'{0}' != expected:'{1}']".CheckedFormat(p.DataStr, currentTestPattern); } if (ec.IsNullOrEmpty()) { h.Add(lastEchoTestPeriod.TotalSeconds); SetState(State.EchoTestSucceeded, "Echo test succeeded after {0:f6} sec".CheckedFormat(stateAge.TotalSeconds)); return; } else { failureCount++; SetState(State.EchoTestFailed, "Echo response failed: {0} [after {0:f6} sec]".CheckedFormat(stateAge.TotalSeconds)); return; } } else if (stateAge > Config.ResponseTimeLimit) { timeoutCount++; SetState(State.EchoTestFailed, "Echo response time limit reached after {0:f6} sec".CheckedFormat(stateAge.TotalSeconds)); return; } break; case State.EchoTestSucceeded: if (!lastEchoTestSucceeded) { Logger.Debug.Emit("{0}: Echo test on '{1}' succeeded after {2:f6} seconds [Prior test failed]", portConfig.Name, PortTargetSpec, lastEchoTestPeriod.TotalSeconds); lastEchoTestSucceeded = true; } if (!sampleTimerTriggered) { return; } SetState(State.WriteTestPattern, "Starting next sample"); break; case State.EchoTestFailed: if (lastEchoTestSucceeded) { Logger.Debug.Emit("{0}: Echo test on '{1}' failed after {2:f6} seconds [Prior test succeeded]", portConfig.Name, PortTargetSpec, lastEchoTestPeriod.TotalSeconds); lastEchoTestSucceeded = true; } if (!sampleTimerTriggered) { return; } SetState(State.RequestFlush, "Starting next sample (with Flush first)"); break; default: Logger.Error.Emit("{0}: Reached unexpected state {1}", portConfig.Name, state); SetState(State.RequestFlush, "Recovery from unknown state"); break; } } }