title: RS232 serial-port sniffer bytes out of order
body: <p>This is a simple RS232 serial-port sniffer that logs byte by byte with direction indication.
  There are two sides A and B and packet structure is [STX] [DATA] [ETX] [LRC(check-sum)], then other side replies with [ACK] if [LRC(check-sum)] is correct. The problem is that bytes with probability of ~50/50 get out of order.</p>
  
  <p><strong>OUTPUT OK</strong></p>
  
  <p>Bytes are in correct order [STX] [DATA] [ETX] [LRC] and then [ACK] from other side</p>
  
  <pre><code>&lt;2019-12-03 14:49:23.7629776&gt;;A;STX
  &lt;2019-12-03 14:49:23.7629776&gt;;A;00
  &lt;2019-12-03 14:49:23.7629776&gt;;A;88
  &lt;2019-12-03 14:49:23.7629776&gt;;A;11
  &lt;2019-12-03 14:49:23.7629776&gt;;A;3D
  &lt;2019-12-03 14:49:23.7629776&gt;;A;5D
  &lt;2019-12-03 14:49:23.7629776&gt;;A;AF
  &lt;2019-12-03 14:49:23.7629776&gt;;A;79
  &lt;2019-12-03 14:49:23.7629776&gt;;A;D3
  &lt;2019-12-03 14:49:23.7629776&gt;;A;5F
  &lt;2019-12-03 14:49:23.7785776&gt;;A;EB
  &lt;2019-12-03 14:49:23.7785776&gt;;A;0E
  &lt;2019-12-03 14:49:23.7785776&gt;;A;0A
  &lt;2019-12-03 14:49:23.7785776&gt;;A;4C
  &lt;2019-12-03 14:49:23.7785776&gt;;A;54
  &lt;2019-12-03 14:49:23.7785776&gt;;A;50
  &lt;2019-12-03 14:49:23.7785776&gt;;A;43
  &lt;2019-12-03 14:49:23.7785776&gt;;A;ETX2
  &lt;2019-12-03 14:49:23.7785776&gt;;A;44
  
  &lt;2019-12-03 14:49:23.7785776&gt;;B;ACK2
  
  </code></pre>
  
  <p><strong>OUTPUT NOT OK</strong></p>
  
  <p>Bytes out of order, [STX] [DATA] [ETX], then [ACK] from other side, and only [LRC] after. This is not possible as [ACK] is only returned if [LRC] is correct. Otherwise, return would be [NAK]. The logger must be buggy there.</p>
  
  <pre><code>&lt;2019-12-03 14:49:23.8877778&gt;;A;STX
  &lt;2019-12-03 14:49:23.8877778&gt;;A;50
  &lt;2019-12-03 14:49:23.8877778&gt;;A;4E
  &lt;2019-12-03 14:49:23.8877778&gt;;A;2D
  &lt;2019-12-03 14:49:23.8877778&gt;;A;53
  &lt;2019-12-03 14:49:23.8877778&gt;;A;30
  &lt;2019-12-03 14:49:23.8877778&gt;;A;37
  &lt;2019-12-03 14:49:23.8877778&gt;;A;50
  &lt;2019-12-03 14:49:23.8877778&gt;;A;8E
  &lt;2019-12-03 14:49:23.8877778&gt;;A;22
  &lt;2019-12-03 14:49:23.8877778&gt;;A;59
  &lt;2019-12-03 14:49:23.8877778&gt;;A;DLE
  &lt;2019-12-03 14:49:23.8877778&gt;;A;33
  &lt;2019-12-03 14:49:23.8877778&gt;;A;19
  &lt;2019-12-03 14:49:23.8877778&gt;;A;A0
  &lt;2019-12-03 14:49:23.8877778&gt;;A;19
  &lt;2019-12-03 14:49:23.8877778&gt;;A;12
  &lt;2019-12-03 14:49:23.8877778&gt;;A;DLE
  &lt;2019-12-03 14:49:23.9033779&gt;;A;33
  &lt;2019-12-03 14:49:23.9033779&gt;;A;ETX1
  
  &lt;2019-12-03 14:49:23.9033779&gt;;B;ACK1
  
  &lt;2019-12-03 14:49:23.9033779&gt;;A;72
  
  </code></pre>
  
  <p><strong>CODE</strong></p>
  
  <p>We open 2 COM ports and start logging thread:</p>
  
  <pre><code>        OpenComPortA();
          OpenComPortB();
  
          Task.Factory.StartNew(AddToFile);
  </code></pre>
  
  <p>COM port opening and worker startup:</p>
  
  <pre><code>        private void OpenComPortA()
          {
              _sideAManager = new SerialWorker();    
              _sideAManager.OnException += OnExceptionSideA;   
              new Thread(() =&gt; _sideAManager.Start(_sideASettings)).Start();
          }
  </code></pre>
  
  <pre><code>        public void Start(ComPortSettings settings)
          {
              _side = settings.SideName;
              EventHandler&lt;Exception&gt; onException = OnException;
              try
              {
                  CreateCom(settings);
                  OpenCom();
              }
              catch (Exception ex)
              {
                  onException?.Invoke(this, ex);
              }
  
              Task.Factory.StartNew(ReadComPort);
          }
  </code></pre>
  
  <p>Main process of waiting for byte to read, then adding read argument to concurrent queue:</p>
  
  <pre><code>        private void ReadComPort()
          {
              while (ComPort.IsOpen)
              {
                  EventHandler&lt;Exception&gt; onException = OnException;
                  try
                  {
                      byte byt = (byte)ComPort.ReadByte();
                      ThreadSafe.Queue.Enqueue(new ReadArgument
                      {
                          Side = _side,
                          Time = DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss.fffffff"),
                          Value = ControlCharacters.Convert(BitConverter.ToString(new[] { byt }))
                      });
                  }
                  catch (Exception ex)
                  {
                      onException?.Invoke(this, ex);
                  }
              }
          }
  </code></pre>
  
  <p>Queue that is appended by A, B sides and read by logwriter:</p>
  
  <pre><code>        public static class ThreadSafe
          {
              public static ConcurrentQueue&lt;ReadArgument&gt; Queue = new ConcurrentQueue&lt;ReadArgument&gt;();
          }
  </code></pre>
  
  <p>Spinning loop, waiting for incoming data to log, thread started at the very first code fragment above:</p>
  
  <pre><code>        private void AddToFile()
          {
              while (true)
              {
                  if (ThreadSafe.Queue.TryDequeue(out ReadArgument ra))
                  {
                      _serialLogWriter.Write(ra);
                  }
              }
          }
  </code></pre>
  
  <p>Log write:</p>
  
  <pre><code>        private readonly StreamWriter _writer;
          private string _lastSide;
  
          public SerialLogWriter(string path, bool append)
          {
              _writer = new StreamWriter(path, append);
          }
  
          public void Write(ReadArgument ra)
          {
              lock (_writer)
              {
                  if (_lastSide != null &amp;&amp; _lastSide != ra.Side)
                  {
                      _writer.Write(Environment.NewLine);
                  }
  
                  _writer.Write($"&lt;{ra.Time}&gt;;{ra.Side};{ra.Value}{Environment.NewLine}");
                  _writer.Flush();
  
                  _lastSide = ra.Side;
              }
          }
  </code></pre>
  
  <p>Any insights on synchronization error in code?</p>
  
  <p><strong>EDIT</strong></p>
  
  <p>It seems that it is more hardware error, not software.
  Sniffer software was used on oldschool laptop, that has idle CPU usage of 50-70%, and uses 1,7~/2 RAM on 64-bit WIN7. I couldn't reproduce such byte synchronization error on my development environment with the same initial code posted above.</p>
  
  <p>Tried to optimize my code with several suggestions:</p>
  
  <ul>
  <li>Moved processing/conversions to log writer thread;</li>
  <li>Eliminated mix of TAP and Threads, left only Threads and set priority for writer to lower than COM readers.</li>
  <li>Got rid of tight loop by replacing ConcurrentQueue to BlockingCollection;</li>
  </ul>
  
  <p>Result:</p>
  
  <ul>
  <li>No changes on development environment which is pretty much high-end setup;</li>
  <li>Still same byte synchronization error occurances on old laptop;</li>
  </ul>
  
  <p>I guess it is easier to simply upgrade my hardware then.</p>