Topics

ARDOP_2Win v2.0.4 problems when connection bw is 200


Bob NW8L
 

Hello,

I've run into an problem with ARQ sessions with a connection bandwidth of 200. Although in these cases the connection is established, the subsequent transfer of data frames between the stations is severely degraded. Zero, one or two data frames are transferred, then the process stalls until l the connection times out. I often see in the exception log of the server station a stream of these:

 02:49:10.942 [2.0.4] [ProcessRcvdARQFrame] Trace = 202 Exception: System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at ARDOP_Win.ARDOPprotocol.ProcessRcvdARQFrame(Int32 intFrameType, Byte[] bytData, Boolean blnFrameDecodedOK)

This is true only for a requested connection bandwidth of 200. The strange thing is that with exactly the same hardware and software setup, ARQ connections with a bandwidth of 500 or 2500 work fine, whether negotiation is used or not. Here's a table:

Client 2500 --> Server 2500 good
Client 500 --> Server 2500 good (negotiatebw=true of necessity)
Client 200 --> Server 2500 bad (negotiatebw=true of necessity)
Client 500 --> Server 500 good
Client 200 --> Server 500 bad (negotiatebw=true of necessity)
Client 200 --> Server 200 bad

This is repeatable here, in a test bed consisting of 2 Win10 (v1709) PCs running ARDOP_2Win 2.0.4 and ARIM 2.1, connected by 2 back-to-back USB sound cards. Connections are established and then a file listing request is made by one station to the other (it fails either way).

Below are debug and exception log excerpts from client and server TNCs for a typical case where bw=200. Immediately thereafter, success is achieved if I simply switch to a configuration using arqbw 500 or 2500, or a combination thereof, by issuing the ARQBW command to the TNCs with the new values.

Is any one else having trouble like this? I'll be happy to do more testing and send logs as time permits.

73,
Bob NW8L

Client station debug log
====================
 02:48:50.114 [2.0.4] [GenerateSessionID] Caller=NW8L,  Target=KA8RYU ID= H11
 02:48:50.119 [2.0.4] [SetARDOPProtocolState]  New State=ISS
 02:48:50.119 [2.0.4] [Main.SendFrame] Send ConReq200: NW8L > KA8RYU  delayed 100 ms
 02:48:50.119 [2.0.4] [GenerateSessionID] Caller=NW8L,  Target=KA8RYU ID= H11
 02:48:50.119 [2.0.4] [SendARQConnectRequest] strMycall=NW8L  strTargetCall=KA8RYU  bytPendingSessionID=H11
 02:48:50.135 [2.0.4] ToolStripLatency.Text = Latency Calculation
 02:48:50.235 [2.0.4] [Main.MainPoll4] objProtocol.Repeating=True ProtocolState=ISS  blnFramePending=True  next Play in 16 ms
 02:48:50.235 [2.0.4] [Main.KeyPTT] True
 02:48:50.235 [2.0.4] [PlaySoundStream] ConReq200: NW8L > KA8RYU
 02:48:50.235 [2.0.4] [Main.PlaySoundStream] set blnSoundStreamPlay to True
 02:48:51.314 [2.0.4] [MainPoll] Play stop. Length = 1079 ms
 02:48:51.352 [2.0.4] [Main.KeyPTT] False
 02:48:51.352 [2.0.4] GetNextARQFrame intPingRpt=0
 02:48:51.352 [2.0.4] [Main.tmrPoll] Frame Pending
 02:48:51.494 [2.0.4] Timeout in T>R Latency calculation
 02:48:51.518 [2.0.4] ToolStripLatency.Text = Latency Measure Timeout 
 02:48:51.835 [2.0.4] [AcquireFrameSyncRSBAvg] Phase1>2Avg=3.14 Phase2>3=.00
 02:48:51.995 [2.0.4] [Frame Type OK]5 ConAck, D1=.00, D2=.00  Ldr; S:N(3KHz) Avg=29.5dB,  Offset=0.00Hz 
 02:48:51.996 [2.0.4] [DecodeFrame] Frame: ConAck PASS, Quality= 96 bytes= 0
 02:48:51.996 [2.0.4] [ARDOPprotocol.ProcessRcvdARQFrame] ISS Measured RoundTrip = 302 ms
 02:48:52.004 [2.0.4] [Main.SendFrame] Send IDFrame_NW8L [EN68]  delayed 100 ms
 02:48:52.004 [2.0.4] [ARDOPprotocol.ProcessRcvdARQFrame] Compatible bandwidth received from IRS ConAck: 200 Hz
 02:48:52.044 [2.0.4] ToolStripLatency.Text = Session Thruput
 02:48:52.132 [2.0.4] [Main.MainPoll4] objProtocol.Repeating=True ProtocolState=ISS  blnFramePending=True  next Play in 28 ms
 02:48:52.133 [2.0.4] [Main.KeyPTT] True
 02:48:52.135 [2.0.4] [PlaySoundStream] IDFrame_NW8L [EN68]
 02:48:52.135 [2.0.4] [Main.PlaySoundStream] set blnSoundStreamPlay to True
 02:48:53.819 [2.0.4] [MainPoll] Play stop. Length = 1684 ms
 02:48:53.852 [2.0.4] [Main.KeyPTT] False
 02:48:53.852 [2.0.4] GetNextARQFrame intPingRpt=0
 02:48:53.852 [2.0.4] [Main.tmrPoll] Frame Pending
 02:48:54.375 [2.0.4] [AcquireFrameSyncRSBAvg] Phase1>2Avg=3.14 Phase2>3=.00
 02:48:54.566 [2.0.4] [Frame Type OK]5 DataACK, D1=.00, D2=.00  Ldr; S:N(3KHz) Avg=30.5dB,  Offset=0.00Hz 
 02:48:54.567 [2.0.4] [DecodeFrame] Frame: DataACK PASS, Quality= 98 bytes= 0
 02:48:54.568 [2.0.4] [ARDOPprotocol.ProcessRcvdARQFrame] ACK to IDFrame received in ARQState ISSConReq  with DataToSend = 0
 02:48:54.568 [2.0.4] [SetARDOPProtocolState]  New State=IDLE
 02:48:54.570 [2.0.4] [Main.SendFrame] Send IDLE  delayed 100 ms
 02:48:54.685 [2.0.4] [Main.MainPoll4] objProtocol.Repeating=True ProtocolState=IDLE  blnFramePending=True  next Play in 15 ms
 02:48:54.685 [2.0.4] [Main.KeyPTT] True
 02:48:54.686 [2.0.4] [PlaySoundStream] IDLE
 02:48:54.686 [2.0.4] [Main.PlaySoundStream] set blnSoundStreamPlay to True
 02:48:55.117 [2.0.4] [MainPoll] Play stop. Length = 431 ms
 02:48:55.149 [2.0.4] [Main.KeyPTT] False
 02:48:55.149 [2.0.4] GetNextARQFrame intPingRpt=0
 02:48:55.149 [2.0.4] [Main.tmrPoll] Frame Pending
 02:48:55.755 [2.0.4] [AcquireFrameSyncRSBAvg] Phase1>2Avg=3.14 Phase2>3=.00
 02:48:55.847 [2.0.4] [Frame Type OK]9 DataACK, D1=.00, D2=.00  Ldr; S:N(3KHz) Avg=30.5dB,  Offset=0.00Hz 
 02:48:55.945 [2.0.4] [DecodeFrame] Frame: DataACK PASS, Quality= 98 bytes= 0
 02:48:57.202 [2.0.4] [Main.MainPoll4] objProtocol.Repeating=True ProtocolState=IDLE  blnFramePending=True  next Play in 53 ms
 02:48:57.203 [2.0.4] [Main.KeyPTT] True
 02:48:57.204 [2.0.4] [PlaySoundStream] IDLE
 02:48:57.204 [2.0.4] [Main.PlaySoundStream] set blnSoundStreamPlay to True
 02:48:57.633 [2.0.4] [MainPoll] Play stop. Length = 429 ms
 02:48:57.669 [2.0.4] [Main.KeyPTT] False
 02:48:57.669 [2.0.4] GetNextARQFrame intPingRpt=0
 02:48:57.669 [2.0.4] [Main.tmrPoll] Frame Pending
 02:48:58.235 [2.0.4] [AcquireFrameSyncRSBAvg] Phase1>2Avg=3.14 Phase2>3=.00
 02:48:58.326 [2.0.4] [Frame Type OK]9 DataACK, D1=.00, D2=.00  Ldr; S:N(3KHz) Avg=28.8dB,  Offset=0.00Hz 
 02:48:58.396 [2.0.4] [DecodeFrame] Frame: DataACK PASS, Quality= 98 bytes= 0
 02:48:59.719 [2.0.4] [Main.MainPoll4] objProtocol.Repeating=True ProtocolState=IDLE  blnFramePending=True  next Play in 50 ms
 02:48:59.720 [2.0.4] [Main.KeyPTT] True
 02:48:59.721 [2.0.4] [PlaySoundStream] IDLE
 02:48:59.721 [2.0.4] [Main.PlaySoundStream] set blnSoundStreamPlay to True
 02:49:00.118 [2.0.4] [MainPoll] Play stop. Length = 398 ms
 02:49:00.154 [2.0.4] [Main.KeyPTT] False
 02:49:00.154 [2.0.4] GetNextARQFrame intPingRpt=0
 02:49:00.154 [2.0.4] [Main.tmrPoll] Frame Pending
 02:49:00.715 [2.0.4] [AcquireFrameSyncRSBAvg] Phase1>2Avg=3.14 Phase2>3=.00
 02:49:00.875 [2.0.4] [Frame Type OK]9 DataACK, D1=.00, D2=.00  Ldr; S:N(3KHz) Avg=33.1dB,  Offset=0.00Hz 
 02:49:00.876 [2.0.4] [DecodeFrame] Frame: DataACK PASS, Quality= 98 bytes= 0
 02:49:00.876 [2.0.4] [ARDOPprotocol.ProcessedRcvdARQFrame] Protocol state IDLE, ACK Received with Data to send. Go to ISS Data state.
 02:49:00.877 [2.0.4] [SetARDOPProtocolState]  New State=ISS
 02:49:00.877 [2.0.4] Temp[ARDOPprotocol.ProcessedRcvdARQFrame] No Initialization: bytCurrentFrameType = 16QAM.200.100.E
 02:49:00.877 [2.0.4] [ARDOPprotocol.SendData] DataToSend = 8 bytes, In ProtocolState ISS
 02:49:00.877 [2.0.4] [ARDOPprotocol.GetNextFrameData]2 Set bytFrameTypeToSend to 15
 02:49:00.877 [2.0.4] [ARDOPprotocol.GetNextFrameData] No shift, Frame Type: 16QAM.200.100.O
 02:49:00.877 [2.0.4] *** GetextFrameData Frame=16QAM.200.100.E DataLen=120 NumCar=1
 02:49:00.877 [2.0.4] *** Call GetDatFromQueue[GetNextFrameData] 1   DataLen=120 bytes
 02:49:00.927 [2.0.4] [Main.SendFrame] Send 16QAM.200.100.O  delayed 100 ms
 02:49:01.045 [2.0.4] [Main.MainPoll4] objProtocol.Repeating=True ProtocolState=ISS  blnFramePending=True  next Play in 18 ms
 02:49:01.046 [2.0.4] [Main.KeyPTT] True
 02:49:01.048 [2.0.4] [PlaySoundStream] 16QAM.200.100.O
 02:49:01.048 [2.0.4] [Main.PlaySoundStream] set blnSoundStreamPlay to True
 02:49:04.752 [2.0.4] [MainPoll] Play stop. Length = 3704 ms
 02:49:04.783 [2.0.4] [Main.KeyPTT] False
 02:49:04.783 [2.0.4] GetNextARQFrame intPingRpt=0
 02:49:04.783 [2.0.4] [Main.tmrPoll] Frame Pending
 02:49:06.311 [2.0.4] [Main.MainPoll4] objProtocol.Repeating=True ProtocolState=ISS  blnFramePending=True  next Play in 28 ms
 02:49:06.312 [2.0.4] [Main.KeyPTT] True
 02:49:06.314 [2.0.4] [PlaySoundStream] 16QAM.200.100.O
 02:49:06.314 [2.0.4] [Main.PlaySoundStream] set blnSoundStreamPlay to True
 02:49:10.004 [2.0.4] [MainPoll] Play stop. Length = 3689 ms
 02:49:10.038 [2.0.4] [Main.KeyPTT] False
 02:49:10.038 [2.0.4] GetNextARQFrame intPingRpt=0
 02:49:10.038 [2.0.4] [Main.tmrPoll] Frame Pending
 02:49:11.577 [2.0.4] [Main.MainPoll4] objProtocol.Repeating=True ProtocolState=ISS  blnFramePending=True  next Play in 39 ms
 02:49:11.578 [2.0.4] [Main.KeyPTT] True
 02:49:11.580 [2.0.4] [PlaySoundStream] 16QAM.200.100.O
 02:49:11.580 [2.0.4] [Main.PlaySoundStream] set blnSoundStreamPlay to True
 02:49:15.300 [2.0.4] [MainPoll] Play stop. Length = 3721 ms
 02:49:15.335 [2.0.4] [Main.KeyPTT] False
 02:49:15.335 [2.0.4] GetNextARQFrame intPingRpt=0
 02:49:15.335 [2.0.4] [Main.tmrPoll] Frame Pending
 02:49:16.848 [2.0.4] [Main.MainPoll4] objProtocol.Repeating=True ProtocolState=ISS  blnFramePending=True  next Play in 13 ms
 02:49:16.848 [2.0.4] [Main.KeyPTT] True
 02:49:16.851 [2.0.4] [PlaySoundStream] 16QAM.200.100.O
 02:49:16.851 [2.0.4] [Main.PlaySoundStream] set blnSoundStreamPlay to True
 02:49:20.555 [2.0.4] [MainPoll] Play stop. Length = 3704 ms
 02:49:20.592 [2.0.4] [Main.KeyPTT] False
 02:49:20.592 [2.0.4] GetNextARQFrame intPingRpt=0
 02:49:20.592 [2.0.4] [Main.tmrPoll] Frame Pending
 02:49:22.133 [2.0.4] [Main.MainPoll4] objProtocol.Repeating=True ProtocolState=ISS  blnFramePending=True  next Play in 41 ms
 02:49:22.134 [2.0.4] [Main.KeyPTT] True
 02:49:22.137 [2.0.4] [PlaySoundStream] 16QAM.200.100.O
 02:49:22.137 [2.0.4] [Main.PlaySoundStream] set blnSoundStreamPlay to True
 02:49:25.829 [2.0.4] [MainPoll] Play stop. Length = 3691 ms
 02:49:25.863 [2.0.4] [Main.KeyPTT] False
 02:49:25.863 [2.0.4] GetNextARQFrame intPingRpt=0
 02:49:25.863 [2.0.4] [Main.tmrPoll] Frame Pending
 02:49:27.421 [2.0.4] [Main.MainPoll4] objProtocol.Repeating=True ProtocolState=ISS  blnFramePending=True  next Play in 59 ms
 02:49:27.422 [2.0.4] [Main.KeyPTT] True
 02:49:27.424 [2.0.4] [PlaySoundStream] 16QAM.200.100.O
 02:49:27.424 [2.0.4] [Main.PlaySoundStream] set blnSoundStreamPlay to True
 02:49:31.132 [2.0.4] [MainPoll] Play stop. Length = 3708 ms
 02:49:31.161 [2.0.4] [Main.KeyPTT] False
 02:49:31.161 [2.0.4] GetNextARQFrame intPingRpt=0
 02:49:31.161 [2.0.4] [Main.tmrPoll] Frame Pending
 02:49:32.662 [2.0.4] [Main.MainPoll4] objProtocol.Repeating=True ProtocolState=ISS  blnFramePending=True  next Play in 1 ms
 02:49:32.663 [2.0.4] [Main.KeyPTT] True
 02:49:32.665 [2.0.4] [PlaySoundStream] 16QAM.200.100.O
 02:49:32.665 [2.0.4] [Main.PlaySoundStream] set blnSoundStreamPlay to True
 02:49:36.357 [2.0.4] [MainPoll] Play stop. Length = 3691 ms
 02:49:36.392 [2.0.4] [Main.KeyPTT] False
 02:49:36.392 [2.0.4] GetNextARQFrame intPingRpt=0
 02:49:36.392 [2.0.4] [Main.tmrPoll] Frame Pending
 02:49:37.901 [2.0.4] [Main.MainPoll4] objProtocol.Repeating=True ProtocolState=ISS  blnFramePending=True  next Play in 9 ms
 02:49:37.901 [2.0.4] [Main.KeyPTT] True
 02:49:37.903 [2.0.4] [PlaySoundStream] 16QAM.200.100.O
 02:49:37.903 [2.0.4] [Main.PlaySoundStream] set blnSoundStreamPlay to True
 02:49:41.607 [2.0.4] [MainPoll] Play stop. Length = 3704 ms
 02:49:41.641 [2.0.4] [Main.KeyPTT] False
 02:49:41.641 [2.0.4] GetNextARQFrame intPingRpt=0
 02:49:41.641 [2.0.4] [Main.tmrPoll] Frame Pending
 02:49:43.171 [2.0.4] [Main.MainPoll4] objProtocol.Repeating=True ProtocolState=ISS  blnFramePending=True  next Play in 30 ms
 02:49:43.172 [2.0.4] [Main.KeyPTT] True
 02:49:43.174 [2.0.4] [PlaySoundStream] 16QAM.200.100.O
 02:49:43.174 [2.0.4] [Main.PlaySoundStream] set blnSoundStreamPlay to True
 02:49:46.880 [2.0.4] [MainPoll] Play stop. Length = 3706 ms
 02:49:46.916 [2.0.4] [Main.KeyPTT] False
 02:49:46.917 [2.0.4] GetNextARQFrame intPingRpt=0
 02:49:46.917 [2.0.4] [Main.tmrPoll] Frame Pending
 02:49:48.440 [2.0.4] [Main.MainPoll4] objProtocol.Repeating=True ProtocolState=ISS  blnFramePending=True  next Play in 24 ms
 02:49:48.441 [2.0.4] [Main.KeyPTT] True
 02:49:48.443 [2.0.4] [PlaySoundStream] 16QAM.200.100.O
 02:49:48.443 [2.0.4] [Main.PlaySoundStream] set blnSoundStreamPlay to True
 02:49:52.165 [2.0.4] [MainPoll] Play stop. Length = 3722 ms
 02:49:52.201 [2.0.4] [Main.KeyPTT] False
 02:49:52.202 [2.0.4] GetNextARQFrame intPingRpt=0
 02:49:52.202 [2.0.4] [Main.tmrPoll] Frame Pending
 02:49:53.727 [2.0.4] [Main.MainPoll4] objProtocol.Repeating=True ProtocolState=ISS  blnFramePending=True  next Play in 25 ms
 02:49:53.728 [2.0.4] [Main.KeyPTT] True
 02:49:53.730 [2.0.4] [PlaySoundStream] 16QAM.200.100.O
 02:49:53.730 [2.0.4] [Main.PlaySoundStream] set blnSoundStreamPlay to True
 02:49:57.454 [2.0.4] [MainPoll] Play stop. Length = 3724 ms
 02:49:57.489 [2.0.4] [Main.KeyPTT] False
 02:49:57.489 [2.0.4] GetNextARQFrame intPingRpt=0
 02:49:57.489 [2.0.4] [Main.tmrPoll] Frame Pending
 02:49:59.030 [2.0.4] [Main.MainPoll4] objProtocol.Repeating=True ProtocolState=ISS  blnFramePending=True  next Play in 41 ms
 02:49:59.031 [2.0.4] [Main.KeyPTT] True
 02:49:59.033 [2.0.4] [PlaySoundStream] 16QAM.200.100.O
 02:49:59.033 [2.0.4] [Main.PlaySoundStream] set blnSoundStreamPlay to True
 02:50:02.741 [2.0.4] [MainPoll] Play stop. Length = 3708 ms
 02:50:02.775 [2.0.4] [Main.KeyPTT] False
 02:50:02.775 [2.0.4] GetNextARQFrame intPingRpt=0
 02:50:02.775 [2.0.4] [Main.tmrPoll] Frame Pending
 02:50:04.321 [2.0.4] [Main.MainPoll4] objProtocol.Repeating=True ProtocolState=ISS  blnFramePending=True  next Play in 45 ms
 02:50:04.321 [2.0.4] [Main.KeyPTT] True
 02:50:04.328 [2.0.4] [PlaySoundStream] 16QAM.200.100.O
 02:50:04.328 [2.0.4] [Main.PlaySoundStream] set blnSoundStreamPlay to True
 02:50:08.056 [2.0.4] [MainPoll] Play stop. Length = 3728 ms
 02:50:08.090 [2.0.4] [Main.KeyPTT] False
 02:50:08.090 [2.0.4] GetNextARQFrame intPingRpt=0
 02:50:08.090 [2.0.4] [Main.tmrPoll] Frame Pending
 02:50:09.635 [2.0.4] [Main.MainPoll4] objProtocol.Repeating=True ProtocolState=ISS  blnFramePending=True  next Play in 45 ms
 02:50:09.636 [2.0.4] [Main.KeyPTT] True
 02:50:09.638 [2.0.4] [PlaySoundStream] 16QAM.200.100.O
 02:50:09.638 [2.0.4] [Main.PlaySoundStream] set blnSoundStreamPlay to True
 02:50:13.344 [2.0.4] [MainPoll] Play stop. Length = 3706 ms
 02:50:13.379 [2.0.4] [Main.KeyPTT] False
 02:50:13.379 [2.0.4] GetNextARQFrame intPingRpt=0
 02:50:13.379 [2.0.4] [Main.tmrPoll] Frame Pending
 02:50:14.891 [2.0.4] [Main.MainPoll4] objProtocol.Repeating=True ProtocolState=ISS  blnFramePending=True  next Play in 12 ms
 02:50:14.892 [2.0.4] [Main.KeyPTT] True
 02:50:14.894 [2.0.4] [PlaySoundStream] 16QAM.200.100.O
 02:50:14.894 [2.0.4] [Main.PlaySoundStream] set blnSoundStreamPlay to True
 02:50:18.610 [2.0.4] [MainPoll] Play stop. Length = 3716 ms
 02:50:18.645 [2.0.4] [Main.KeyPTT] False
 02:50:18.645 [2.0.4] GetNextARQFrame intPingRpt=0
 02:50:18.645 [2.0.4] [Main.tmrPoll] Frame Pending
 02:50:20.156 [2.0.4] [Main.MainPoll4] objProtocol.Repeating=True ProtocolState=ISS  blnFramePending=True  next Play in 11 ms
 02:50:20.157 [2.0.4] [Main.KeyPTT] True
 02:50:20.159 [2.0.4] [PlaySoundStream] 16QAM.200.100.O
 02:50:20.159 [2.0.4] [Main.PlaySoundStream] set blnSoundStreamPlay to True
 02:50:23.850 [2.0.4] [MainPoll] Play stop. Length = 3692 ms
 02:50:23.883 [2.0.4] [Main.KeyPTT] False
 02:50:23.883 [2.0.4] GetNextARQFrame intPingRpt=0
 02:50:23.883 [2.0.4] [Main.tmrPoll] Frame Pending
 02:50:25.397 [2.0.4] [Main.MainPoll4] objProtocol.Repeating=True ProtocolState=ISS  blnFramePending=True  next Play in 14 ms
 02:50:25.398 [2.0.4] [Main.KeyPTT] True
 02:50:25.400 [2.0.4] [PlaySoundStream] 16QAM.200.100.O
 02:50:25.400 [2.0.4] [Main.PlaySoundStream] set blnSoundStreamPlay to True
 02:50:29.097 [2.0.4] [MainPoll] Play stop. Length = 3697 ms
 02:50:29.124 [2.0.4] [Main.KeyPTT] False
 02:50:29.124 [2.0.4] GetNextARQFrame intPingRpt=0
 02:50:29.124 [2.0.4] [Main.tmrPoll] Frame Pending
 02:50:30.629 [2.0.4] [Main.MainPoll4] objProtocol.Repeating=True ProtocolState=ISS  blnFramePending=True  next Play in 5 ms
 02:50:30.629 [2.0.4] [Main.KeyPTT] True
 02:50:30.632 [2.0.4] [PlaySoundStream] 16QAM.200.100.O
 02:50:30.632 [2.0.4] [Main.PlaySoundStream] set blnSoundStreamPlay to True
 02:50:34.337 [2.0.4] [MainPoll] Play stop. Length = 3705 ms
 02:50:34.366 [2.0.4] [Main.KeyPTT] False
 02:50:34.366 [2.0.4] GetNextARQFrame intPingRpt=0
 02:50:34.366 [2.0.4] [Main.tmrPoll] Frame Pending
 02:50:35.883 [2.0.4] [Main.MainPoll4] objProtocol.Repeating=True ProtocolState=ISS  blnFramePending=True  next Play in 17 ms
 02:50:35.884 [2.0.4] [Main.KeyPTT] True
 02:50:35.886 [2.0.4] [PlaySoundStream] 16QAM.200.100.O
 02:50:35.886 [2.0.4] [Main.PlaySoundStream] set blnSoundStreamPlay to True
 02:50:39.580 [2.0.4] [MainPoll] Play stop. Length = 3695 ms
 02:50:39.615 [2.0.4] [Main.KeyPTT] False
 02:50:39.615 [2.0.4] GetNextARQFrame intPingRpt=0
 02:50:39.615 [2.0.4] [Main.tmrPoll] Frame Pending
 02:50:41.160 [2.0.4] [Main.MainPoll4] objProtocol.Repeating=True ProtocolState=ISS  blnFramePending=True  next Play in 45 ms
 02:50:41.161 [2.0.4] [Main.KeyPTT] True
 02:50:41.163 [2.0.4] [PlaySoundStream] 16QAM.200.100.O
 02:50:41.163 [2.0.4] [Main.PlaySoundStream] set blnSoundStreamPlay to True
 02:50:44.876 [2.0.4] [MainPoll] Play stop. Length = 3713 ms
 02:50:44.911 [2.0.4] [Main.KeyPTT] False
 02:50:44.911 [2.0.4] GetNextARQFrame intPingRpt=0
 02:50:44.911 [2.0.4] [Main.tmrPoll] Frame Pending
 02:50:46.438 [2.0.4] [Main.MainPoll4] objProtocol.Repeating=True ProtocolState=ISS  blnFramePending=True  next Play in 27 ms
 02:50:46.439 [2.0.4] [Main.KeyPTT] True
 02:50:46.441 [2.0.4] [PlaySoundStream] 16QAM.200.100.O
 02:50:46.441 [2.0.4] [Main.PlaySoundStream] set blnSoundStreamPlay to True
 02:50:50.128 [2.0.4] [MainPoll] Play stop. Length = 3687 ms
 02:50:50.163 [2.0.4] [Main.KeyPTT] False
 02:50:50.163 [2.0.4] GetNextARQFrame intPingRpt=0
 02:50:50.163 [2.0.4] [Main.tmrPoll] Frame Pending
 02:50:51.689 [2.0.4] [Main.MainPoll4] objProtocol.Repeating=True ProtocolState=ISS  blnFramePending=True  next Play in 26 ms
 02:50:51.689 [2.0.4] [Main.KeyPTT] True
 02:50:51.692 [2.0.4] [PlaySoundStream] 16QAM.200.100.O
 02:50:51.692 [2.0.4] [Main.PlaySoundStream] set blnSoundStreamPlay to True
 02:50:55.396 [2.0.4] [MainPoll] Play stop. Length = 3704 ms
 02:50:55.434 [2.0.4] [Main.KeyPTT] False
 02:50:55.434 [2.0.4] GetNextARQFrame intPingRpt=0
 02:50:55.434 [2.0.4] [Main.tmrPoll] Frame Pending
 02:50:56.964 [2.0.4] [Main.MainPoll4] objProtocol.Repeating=True ProtocolState=ISS  blnFramePending=True  next Play in 30 ms
 02:50:56.965 [2.0.4] [Main.KeyPTT] True
 02:50:56.967 [2.0.4] [PlaySoundStream] 16QAM.200.100.O
 02:50:56.967 [2.0.4] [Main.PlaySoundStream] set blnSoundStreamPlay to True
 02:51:00.686 [2.0.4] [MainPoll] Play stop. Length = 3719 ms
 02:51:00.720 [2.0.4] [Main.KeyPTT] False
 02:51:00.720 [2.0.4] GetNextARQFrame intPingRpt=0
 02:51:00.720 [2.0.4] [Main.tmrPoll] Frame Pending
 02:51:00.964 [2.0.4] [ARDOPprotocol.PollARQTimeout] Timeout setting SendTimeout timer to start.
 02:51:01.072 [2.0.4] ARDOPprotocol.tmrSendTimeout]  ARQ Timeout from ProtocolState: ISS  Going to DISC state
 02:51:01.080 [2.0.4] [Main.SendFrame] Send IDFrame_NW8L [EN68]  delayed 100 ms
 02:51:01.196 [2.0.4] [Main.MainPoll4] objProtocol.Repeating=True ProtocolState=ISS  blnFramePending=True  next Play in 17 ms
 02:51:01.196 [2.0.4] [Main.KeyPTT] True
 02:51:01.197 [2.0.4] [PlaySoundStream] IDFrame_NW8L [EN68]
 02:51:01.197 [2.0.4] [Main.PlaySoundStream] set blnSoundStreamPlay to True
 02:51:01.537 [2.0.4] [SetARDOPProtocolState]  New State=DISC
 02:51:02.879 [2.0.4] [MainPoll] Play stop. Length = 1681 ms
 02:51:02.914 [2.0.4] [Main.KeyPTT] False
 02:51:03.298 [2.0.4] [Main.SendFrame] Send DISC  delayed 100 ms
 02:51:03.420 [2.0.4] [Main.MainPoll4] objProtocol.Repeating=True ProtocolState=DISC  blnFramePending=True  next Play in 23 ms
 02:51:03.421 [2.0.4] [Main.KeyPTT] True
 02:51:03.422 [2.0.4] [PlaySoundStream] DISC
 02:51:03.422 [2.0.4] [Main.PlaySoundStream] set blnSoundStreamPlay to True
 02:51:03.854 [2.0.4] [MainPoll] Play stop. Length = 433 ms
 02:51:03.888 [2.0.4] [Main.KeyPTT] False
 02:51:05.454 [2.0.4] [AcquireFrameSyncRSBAvg] Phase1>2Avg=3.14 Phase2>3=.00
 02:51:05.635 [2.0.4] [Frame Type OK]2 IDFrame, D1=.00, D2=.00  Ldr; S:N(3KHz) Avg=30.8dB,  Offset=0.00Hz 
 02:51:06.919 [2.0.4] [DecodeFrame] Frame: IDFrame PASS, Quality= 89 bytes= 18
 02:51:07.663 [2.0.4] [AcquireFrameSyncRSBAvg] Phase1>2Avg=3.14 Phase2>3=.00
 02:51:07.834 [2.0.4] [Frame Type OK]1 DISC, D1=.00, D3=.00  Ldr; S:N(3KHz) Avg=33.5dB,  Offset=0.00Hz 
 02:51:07.836 [2.0.4] [DecodeFrame] Frame: DISC PASS, Quality= 97 bytes= 0

Server station debug log
====================
 02:48:51.335 [2.0.4]      Command Trace TO Host: BUSY TRUE
 02:48:51.476 [2.0.4] [AcquireFrameSyncRSBAvg] Phase1>2Avg=3.14 Phase2>3=.00
 02:48:51.667 [2.0.4] [Frame Type OK]1 ConReq200, D1=.00, Parity of ID1 OK
 02:48:51.667 [2.0.4]      Command Trace TO Host: PENDING
 02:48:51.925 [2.0.4]      Command Trace from HOST: PROTOCOLMODE ARQ
 02:48:51.926 [2.0.4]      Command Trace TO Host: PROTOCOLMODE NOW ARQ
 02:48:52.239 [2.0.4] [DecodeFrame] Frame: ConReq200 PASS, Quality= 87 bytes= 7
 02:48:52.239 [2.0.4] [ProcessRcvdARQFrame]1 ConReq200 bytSessionID=11
 02:48:52.239 [2.0.4]      Command Trace TO Host: TARGET KA8RYU
 02:48:52.240 [2.0.4]      Command Trace TO Host: NEWSTATE IRS
 02:48:52.240 [2.0.4] [SetARDOPProtocolState]  New State=IRS
 02:48:52.242 [2.0.4] [Main.SendFrame] Send ConAck  delayed 100 ms
 02:48:52.283 [2.0.4] ToolStripLatency.Text = Session Thruput
 02:48:52.377 [2.0.4] [Main.MainPoll4] objProtocol.Repeating=True ProtocolState=IRS  blnFramePending=True  next Play in 36 ms
 02:48:52.377 [2.0.4]      Command Trace TO Host: PTT TRUE
 02:48:52.377 [2.0.4] [Main.KeyPTT] True
 02:48:52.378 [2.0.4] [PlaySoundStream] ConAck
 02:48:52.378 [2.0.4] [Main.PlaySoundStream] set blnSoundStreamPlay to True
 02:48:52.803 [2.0.4] [MainPoll] Play stop. Length = 425 ms
 02:48:52.835 [2.0.4]      Command Trace TO Host: PTT FALSE
 02:48:52.835 [2.0.4] [Main.KeyPTT] False
 02:48:52.835 [2.0.4] GetNextARQFrame intPingRpt=0
 02:48:53.367 [2.0.4] [AcquireFrameSyncRSBAvg] Phase1>2Avg=3.14 Phase2>3=.00
 02:48:53.527 [2.0.4] [Frame Type OK]5 IDFrame, D1=.00, D2=.00  Ldr; S:N(3KHz) Avg=33.9dB,  Offset=0.00Hz 
 02:48:54.811 [2.0.4] [DecodeFrame] Frame: IDFrame PASS, Quality= 83 bytes= 16
 02:48:54.813 [2.0.4] [Main.SendFrame] Send DataACK  delayed 100 ms
 02:48:54.813 [2.0.4]      Command Trace TO Host: CONNECTED NW8L 200 [EN68]
 02:48:54.813 [2.0.4]      Command Trace TO Host: STATUS ARQ CONNECTION ESTABLISHED WITH NW8L,BW=200,GS=[EN68]
 02:48:54.939 [2.0.4] [Main.MainPoll4] objProtocol.Repeating=True ProtocolState=IRS  blnFramePending=True  next Play in 27 ms
 02:48:54.939 [2.0.4]      Command Trace TO Host: PTT TRUE
 02:48:54.939 [2.0.4] [Main.KeyPTT] True
 02:48:54.940 [2.0.4] [PlaySoundStream] DataACK
 02:48:54.941 [2.0.4] [Main.PlaySoundStream] set blnSoundStreamPlay to True
 02:48:55.366 [2.0.4] [MainPoll] Play stop. Length = 425 ms
 02:48:55.403 [2.0.4]      Command Trace TO Host: PTT FALSE
 02:48:55.403 [2.0.4] [Main.KeyPTT] False
 02:48:55.404 [2.0.4] GetNextARQFrame intPingRpt=0
 02:48:55.936 [2.0.4] [AcquireFrameSyncRSBAvg] Phase1>2Avg=3.14 Phase2>3=.00
 02:48:56.097 [2.0.4] [Frame Type OK]9 IDLE, D1=.00, D2=.00  Ldr; S:N(3KHz) Avg=27.8dB,  Offset=0.00Hz 
 02:48:56.098 [2.0.4] [DecodeFrame] Frame: IDLE PASS, Quality= 96 bytes= 0
 02:48:56.098 [2.0.4] [ARDOPprotocol.ProcessRcvdARQFrame]  IDLE received in ProtocolState IRS, substate: IRSData
 02:48:56.100 [2.0.4] [Main.SendFrame] Send DataACK  delayed 100 ms
 02:48:56.236 [2.0.4] [Main.MainPoll4] objProtocol.Repeating=True ProtocolState=IRS  blnFramePending=True  next Play in 36 ms
 02:48:56.236 [2.0.4]      Command Trace TO Host: PTT TRUE
 02:48:56.236 [2.0.4] [Main.KeyPTT] True
 02:48:56.237 [2.0.4] [PlaySoundStream] DataACK
 02:48:56.237 [2.0.4] [Main.PlaySoundStream] set blnSoundStreamPlay to True
 02:48:56.658 [2.0.4] [MainPoll] Play stop. Length = 422 ms
 02:48:56.697 [2.0.4]      Command Trace TO Host: PTT FALSE
 02:48:56.697 [2.0.4] [Main.KeyPTT] False
 02:48:56.697 [2.0.4] GetNextARQFrame intPingRpt=0
 02:48:58.387 [2.0.4] [AcquireFrameSyncRSBAvg] Phase1>2Avg=3.14 Phase2>3=.00
 02:48:58.577 [2.0.4] [Frame Type OK]9 IDLE, D1=.00, D2=.00  Ldr; S:N(3KHz) Avg=31.1dB,  Offset=0.00Hz 
 02:48:58.578 [2.0.4] [DecodeFrame] Frame: IDLE PASS, Quality= 96 bytes= 0
 02:48:58.578 [2.0.4] [ARDOPprotocol.ProcessRcvdARQFrame]  IDLE received in ProtocolState IRS, substate: IRSData
 02:48:58.580 [2.0.4] [Main.SendFrame] Send DataACK  delayed 100 ms
 02:48:58.704 [2.0.4] [Main.MainPoll4] objProtocol.Repeating=True ProtocolState=IRS  blnFramePending=True  next Play in 25 ms
 02:48:58.705 [2.0.4]      Command Trace TO Host: PTT TRUE
 02:48:58.705 [2.0.4] [Main.KeyPTT] True
 02:48:58.706 [2.0.4] [PlaySoundStream] DataACK
 02:48:58.706 [2.0.4] [Main.PlaySoundStream] set blnSoundStreamPlay to True
 02:48:59.129 [2.0.4] [MainPoll] Play stop. Length = 423 ms
 02:48:59.160 [2.0.4]      Command Trace TO Host: PTT FALSE
 02:48:59.160 [2.0.4] [Main.KeyPTT] False
 02:48:59.160 [2.0.4] GetNextARQFrame intPingRpt=0
 02:49:00.967 [2.0.4] [AcquireFrameSyncRSBAvg] Phase1>2Avg=3.14 Phase2>3=.00
 02:49:01.117 [2.0.4] [Frame Type OK]9 IDLE, D1=.00, D2=.00  Ldr; S:N(3KHz) Avg=28.9dB,  Offset=0.00Hz 
 02:49:01.118 [2.0.4] [DecodeFrame] Frame: IDLE PASS, Quality= 96 bytes= 0
 02:49:01.118 [2.0.4] [ARDOPprotocol.ProcessRcvdARQFrame]  IDLE received in ProtocolState IRS, substate: IRSData
 02:49:01.120 [2.0.4] [Main.SendFrame] Send DataACK  delayed 100 ms
 02:49:01.222 [2.0.4] [Main.MainPoll4] objProtocol.Repeating=True ProtocolState=IRS  blnFramePending=True  next Play in 2 ms
 02:49:01.222 [2.0.4]      Command Trace TO Host: PTT TRUE
 02:49:01.223 [2.0.4] [Main.KeyPTT] True
 02:49:01.224 [2.0.4] [PlaySoundStream] DataACK
 02:49:01.224 [2.0.4] [Main.PlaySoundStream] set blnSoundStreamPlay to True
 02:49:01.643 [2.0.4] [MainPoll] Play stop. Length = 419 ms
 02:49:01.681 [2.0.4]      Command Trace TO Host: PTT FALSE
 02:49:01.681 [2.0.4] [Main.KeyPTT] False
 02:49:01.681 [2.0.4] GetNextARQFrame intPingRpt=0
 02:49:02.247 [2.0.4] [AcquireFrameSyncRSBAvg] Phase1>2Avg=3.14 Phase2>3=.00
 02:49:02.407 [2.0.4] [Frame Type OK]9A 16QAM.200.100.O, D1=.00, D2=.00  Ldr; S:N(3KHz) Avg=30.7dB,  Offset=0.00Hz 
 02:49:05.729 [2.0.4] [CorrectPhaseForTuningOffset] 16QAM AvgOffset=0 AccOffsetCnt=326/326
 02:49:05.730 [2.0.4] [Decode16QAMData] 16QAM.200.100.O 100%  decoded
 02:49:05.730 [2.0.4] [DecodeFrame] Frame: 16QAM.200.100.O PASS, Quality= 98 bytes= 8
 02:49:05.730 [2.0.4] [ARDOPprotocol.ProcessRcvdARQFrame] Add ARQ Tag to data and send to Host
 02:49:05.731 [2.0.4] [AddTagToDataAndSendToHost] Tag:ARQ +bytes=8
 02:49:05.731 [2.0.4]      Command Trace from HOST: Data (length = 11)
 02:49:05.758 [2.0.4] ToolStripLatency.Text = 36 bytes/min
 02:49:06.175 [2.0.4]      Command Trace from HOST: 13 bytes received by objTCPIPData
 02:49:06.175 [2.0.4]      Command Trace TO Host: BUFFER 11
 02:49:06.861 [2.0.4]      Command Trace from HOST: 35 bytes received by objTCPIPData
 02:49:06.861 [2.0.4]      Command Trace TO Host: BUFFER 44
 02:49:07.516 [2.0.4] [AcquireFrameSyncRSBAvg] Phase1>2Avg=3.14 Phase2>3=.00
 02:49:07.550 [2.0.4]      Command Trace from HOST: 35 bytes received by objTCPIPData
 02:49:07.550 [2.0.4]      Command Trace TO Host: BUFFER 77
 02:49:07.707 [2.0.4] [Frame Type OK]9A 16QAM.200.100.O, D1=.00, D2=.00  Ldr; S:N(3KHz) Avg=34.8dB,  Offset=0.00Hz 
 02:49:08.238 [2.0.4]      Command Trace from HOST: 35 bytes received by objTCPIPData
 02:49:08.238 [2.0.4]      Command Trace TO Host: BUFFER 110
 02:49:08.987 [2.0.4]      Command Trace from HOST: 35 bytes received by objTCPIPData
 02:49:08.987 [2.0.4]      Command Trace TO Host: BUFFER 143
 02:49:09.674 [2.0.4]      Command Trace from HOST: 35 bytes received by objTCPIPData
 02:49:09.674 [2.0.4]      Command Trace TO Host: BUFFER 176
 02:49:10.364 [2.0.4]      Command Trace from HOST: 35 bytes received by objTCPIPData
 02:49:10.364 [2.0.4]      Command Trace TO Host: BUFFER 209
 02:49:10.939 [2.0.4] [CorrectPhaseForTuningOffset] 16QAM AvgOffset=0 AccOffsetCnt=326/326
 02:49:10.941 [2.0.4] [Decode16QAMData] 16QAM.200.100.O 100%  decoded
 02:49:10.941 [2.0.4] [DecodeFrame] Frame: 16QAM.200.100.O PASS, Quality= 98 bytes= 8
 02:49:11.050 [2.0.4]      Command Trace from HOST: 35 bytes received by objTCPIPData
 02:49:11.050 [2.0.4]      Command Trace TO Host: BUFFER 242
 02:49:11.799 [2.0.4]      Command Trace from HOST: 6 bytes received by objTCPIPData
 02:49:11.799 [2.0.4]      Command Trace TO Host: BUFFER 246
 02:49:12.826 [2.0.4] [AcquireFrameSyncRSBAvg] Phase1>2Avg=3.14 Phase2>3=.00
 02:49:12.977 [2.0.4] [Frame Type OK]9A 16QAM.200.100.O, D1=.00, D2=.00  Ldr; S:N(3KHz) Avg=31.8dB,  Offset=0.00Hz 
 02:49:16.248 [2.0.4] [CorrectPhaseForTuningOffset] 16QAM AvgOffset=0 AccOffsetCnt=326/326
 02:49:16.250 [2.0.4] [Decode16QAMData] 16QAM.200.100.O 100%  decoded
 02:49:16.250 [2.0.4] [DecodeFrame] Frame: 16QAM.200.100.O PASS, Quality= 98 bytes= 8
 02:49:18.037 [2.0.4] [AcquireFrameSyncRSBAvg] Phase1>2Avg=3.14 Phase2>3=.00
 02:49:18.195 [2.0.4] [Frame Type OK]9A 16QAM.200.100.O, D1=.00, D2=.00  Ldr; S:N(3KHz) Avg=32.1dB,  Offset=0.00Hz 
 02:49:21.518 [2.0.4] [CorrectPhaseForTuningOffset] 16QAM AvgOffset=0 AccOffsetCnt=326/326
 02:49:21.520 [2.0.4] [Decode16QAMData] 16QAM.200.100.O 100%  decoded
 02:49:21.520 [2.0.4] [DecodeFrame] Frame: 16QAM.200.100.O PASS, Quality= 98 bytes= 8
 02:49:23.306 [2.0.4] [AcquireFrameSyncRSBAvg] Phase1>2Avg=3.14 Phase2>3=.00
 02:49:23.497 [2.0.4] [Frame Type OK]9A 16QAM.200.100.O, D1=.00, D2=.00  Ldr; S:N(3KHz) Avg=32.5dB,  Offset=0.00Hz 
 02:49:26.828 [2.0.4] [CorrectPhaseForTuningOffset] 16QAM AvgOffset=0 AccOffsetCnt=326/326
 02:49:26.830 [2.0.4] [Decode16QAMData] 16QAM.200.100.O 100%  decoded
 02:49:26.831 [2.0.4] [DecodeFrame] Frame: 16QAM.200.100.O PASS, Quality= 98 bytes= 8
 02:49:28.616 [2.0.4] [AcquireFrameSyncRSBAvg] Phase1>2Avg=3.14 Phase2>3=.00
 02:49:28.767 [2.0.4] [Frame Type OK]9A 16QAM.200.100.O, D1=.00, D2=.00  Ldr; S:N(3KHz) Avg=28.6dB,  Offset=0.00Hz 
 02:49:32.096 [2.0.4] [CorrectPhaseForTuningOffset] 16QAM AvgOffset=0 AccOffsetCnt=326/326
 02:49:32.097 [2.0.4] [Decode16QAMData] 16QAM.200.100.O 100%  decoded
 02:49:32.097 [2.0.4] [DecodeFrame] Frame: 16QAM.200.100.O PASS, Quality= 98 bytes= 8
 02:49:33.886 [2.0.4] [AcquireFrameSyncRSBAvg] Phase1>2Avg=3.14 Phase2>3=.00
 02:49:34.077 [2.0.4] [Frame Type OK]9A 16QAM.200.100.O, D1=.00, D2=.00  Ldr; S:N(3KHz) Avg=33.4dB,  Offset=0.00Hz 
 02:49:37.309 [2.0.4] [CorrectPhaseForTuningOffset] 16QAM AvgOffset=0 AccOffsetCnt=326/326
 02:49:37.310 [2.0.4] [Decode16QAMData] 16QAM.200.100.O 100%  decoded
 02:49:37.310 [2.0.4] [DecodeFrame] Frame: 16QAM.200.100.O PASS, Quality= 98 bytes= 8
 02:49:39.095 [2.0.4] [AcquireFrameSyncRSBAvg] Phase1>2Avg=3.14 Phase2>3=.00
 02:49:39.287 [2.0.4] [Frame Type OK]9A 16QAM.200.100.O, D1=.00, D2=.00  Ldr; S:N(3KHz) Avg=27.8dB,  Offset=0.00Hz 
 02:49:42.618 [2.0.4] [CorrectPhaseForTuningOffset] 16QAM AvgOffset=0 AccOffsetCnt=326/326
 02:49:42.620 [2.0.4] [Decode16QAMData] 16QAM.200.100.O 100%  decoded
 02:49:42.620 [2.0.4] [DecodeFrame] Frame: 16QAM.200.100.O PASS, Quality= 98 bytes= 8
 02:49:44.406 [2.0.4] [AcquireFrameSyncRSBAvg] Phase1>2Avg=3.14 Phase2>3=.00
 02:49:44.566 [2.0.4] [Frame Type OK]9A 16QAM.200.100.O, D1=.00, D2=.00  Ldr; S:N(3KHz) Avg=27.9dB,  Offset=0.00Hz 
 02:49:47.829 [2.0.4] [CorrectPhaseForTuningOffset] 16QAM AvgOffset=0 AccOffsetCnt=326/326
 02:49:47.830 [2.0.4] [Decode16QAMData] 16QAM.200.100.O 100%  decoded
 02:49:47.830 [2.0.4] [DecodeFrame] Frame: 16QAM.200.100.O PASS, Quality= 98 bytes= 8
 02:49:49.676 [2.0.4] [AcquireFrameSyncRSBAvg] Phase1>2Avg=3.14 Phase2>3=.00
 02:49:49.867 [2.0.4] [Frame Type OK]9A 16QAM.200.100.O, D1=.00, D2=.00  Ldr; S:N(3KHz) Avg=34.3dB,  Offset=0.00Hz 
 02:49:53.097 [2.0.4] [CorrectPhaseForTuningOffset] 16QAM AvgOffset=0 AccOffsetCnt=326/326
 02:49:53.099 [2.0.4] [Decode16QAMData] 16QAM.200.100.O 100%  decoded
 02:49:53.099 [2.0.4] [DecodeFrame] Frame: 16QAM.200.100.O PASS, Quality= 98 bytes= 8
 02:49:54.976 [2.0.4] [AcquireFrameSyncRSBAvg] Phase1>2Avg=3.14 Phase2>3=.00
 02:49:55.137 [2.0.4] [Frame Type OK]9A 16QAM.200.100.O, D1=.00, D2=.00  Ldr; S:N(3KHz) Avg=34.9dB,  Offset=0.00Hz 
 02:49:58.409 [2.0.4] [CorrectPhaseForTuningOffset] 16QAM AvgOffset=0 AccOffsetCnt=326/326
 02:49:58.410 [2.0.4] [Decode16QAMData] 16QAM.200.100.O 100%  decoded
 02:49:58.410 [2.0.4] [DecodeFrame] Frame: 16QAM.200.100.O PASS, Quality= 98 bytes= 8
 02:50:00.276 [2.0.4] [AcquireFrameSyncRSBAvg] Phase1>2Avg=3.14 Phase2>3=.00
 02:50:00.436 [2.0.4] [Frame Type OK]9A 16QAM.200.100.O, D1=.00, D2=.00  Ldr; S:N(3KHz) Avg=29.6dB,  Offset=0.00Hz 
 02:50:03.679 [2.0.4] [CorrectPhaseForTuningOffset] 16QAM AvgOffset=0 AccOffsetCnt=326/326
 02:50:03.680 [2.0.4] [Decode16QAMData] 16QAM.200.100.O 100%  decoded
 02:50:03.681 [2.0.4] [DecodeFrame] Frame: 16QAM.200.100.O PASS, Quality= 98 bytes= 8
 02:50:05.546 [2.0.4] [AcquireFrameSyncRSBAvg] Phase1>2Avg=3.14 Phase2>3=.00
 02:50:05.737 [2.0.4] [Frame Type OK]9A 16QAM.200.100.O, D1=.00, D2=.00  Ldr; S:N(3KHz) Avg=27.5dB,  Offset=0.00Hz 
 02:50:08.979 [2.0.4] [CorrectPhaseForTuningOffset] 16QAM AvgOffset=0 AccOffsetCnt=326/326
 02:50:08.980 [2.0.4] [Decode16QAMData] 16QAM.200.100.O 100%  decoded
 02:50:08.980 [2.0.4] [DecodeFrame] Frame: 16QAM.200.100.O PASS, Quality= 98 bytes= 8
 02:50:10.856 [2.0.4] [AcquireFrameSyncRSBAvg] Phase1>2Avg=3.14 Phase2>3=.00
 02:50:11.017 [2.0.4] [Frame Type OK]9A 16QAM.200.100.O, D1=.00, D2=.00  Ldr; S:N(3KHz) Avg=27.6dB,  Offset=0.00Hz 
 02:50:14.349 [2.0.4] [CorrectPhaseForTuningOffset] 16QAM AvgOffset=0 AccOffsetCnt=326/326
 02:50:14.350 [2.0.4] [Decode16QAMData] 16QAM.200.100.O 100%  decoded
 02:50:14.350 [2.0.4] [DecodeFrame] Frame: 16QAM.200.100.O PASS, Quality= 98 bytes= 8
 02:50:16.126 [2.0.4] [AcquireFrameSyncRSBAvg] Phase1>2Avg=3.14 Phase2>3=.00
 02:50:16.317 [2.0.4] [Frame Type OK]9A 16QAM.200.100.O, D1=.00, D2=.00  Ldr; S:N(3KHz) Avg=28.8dB,  Offset=0.00Hz 
 02:50:19.549 [2.0.4] [CorrectPhaseForTuningOffset] 16QAM AvgOffset=0 AccOffsetCnt=326/326
 02:50:19.550 [2.0.4] [Decode16QAMData] 16QAM.200.100.O 100%  decoded
 02:50:19.550 [2.0.4] [DecodeFrame] Frame: 16QAM.200.100.O PASS, Quality= 98 bytes= 8
 02:50:21.336 [2.0.4] [AcquireFrameSyncRSBAvg] Phase1>2Avg=3.14 Phase2>3=.00
 02:50:21.527 [2.0.4] [Frame Type OK]9A 16QAM.200.100.O, D1=.00, D2=.00  Ldr; S:N(3KHz) Avg=27.8dB,  Offset=0.00Hz 
 02:50:24.859 [2.0.4] [CorrectPhaseForTuningOffset] 16QAM AvgOffset=0 AccOffsetCnt=326/326
 02:50:24.860 [2.0.4] [Decode16QAMData] 16QAM.200.100.O 100%  decoded
 02:50:24.860 [2.0.4] [DecodeFrame] Frame: 16QAM.200.100.O PASS, Quality= 98 bytes= 8
 02:50:26.646 [2.0.4] [AcquireFrameSyncRSBAvg] Phase1>2Avg=3.14 Phase2>3=.00
 02:50:26.807 [2.0.4] [Frame Type OK]9A 16QAM.200.100.O, D1=.00, D2=.00  Ldr; S:N(3KHz) Avg=31.1dB,  Offset=0.00Hz 
 02:50:30.038 [2.0.4] [CorrectPhaseForTuningOffset] 16QAM AvgOffset=0 AccOffsetCnt=326/326
 02:50:30.040 [2.0.4] [Decode16QAMData] 16QAM.200.100.O 100%  decoded
 02:50:30.040 [2.0.4] [DecodeFrame] Frame: 16QAM.200.100.O PASS, Quality= 98 bytes= 8
 02:50:31.826 [2.0.4] [AcquireFrameSyncRSBAvg] Phase1>2Avg=3.14 Phase2>3=.00
 02:50:32.017 [2.0.4] [Frame Type OK]9A 16QAM.200.100.O, D1=.00, D2=.00  Ldr; S:N(3KHz) Avg=29.2dB,  Offset=0.00Hz 
 02:50:35.338 [2.0.4] [CorrectPhaseForTuningOffset] 16QAM AvgOffset=0 AccOffsetCnt=326/326
 02:50:35.340 [2.0.4] [Decode16QAMData] 16QAM.200.100.O 100%  decoded
 02:50:35.340 [2.0.4] [DecodeFrame] Frame: 16QAM.200.100.O PASS, Quality= 98 bytes= 8
 02:50:37.136 [2.0.4] [AcquireFrameSyncRSBAvg] Phase1>2Avg=3.14 Phase2>3=.00
 02:50:37.287 [2.0.4] [Frame Type OK]9A 16QAM.200.100.O, D1=.00, D2=.00  Ldr; S:N(3KHz) Avg=34.9dB,  Offset=0.00Hz 
 02:50:40.548 [2.0.4] [CorrectPhaseForTuningOffset] 16QAM AvgOffset=0 AccOffsetCnt=326/326
 02:50:40.550 [2.0.4] [Decode16QAMData] 16QAM.200.100.O 100%  decoded
 02:50:40.550 [2.0.4] [DecodeFrame] Frame: 16QAM.200.100.O PASS, Quality= 98 bytes= 8
 02:50:42.346 [2.0.4] [AcquireFrameSyncRSBAvg] Phase1>2Avg=3.14 Phase2>3=.00
 02:50:42.497 [2.0.4] [Frame Type OK]9A 16QAM.200.100.O, D1=.00, D2=.00  Ldr; S:N(3KHz) Avg=31.8dB,  Offset=0.00Hz 
 02:50:45.828 [2.0.4] [CorrectPhaseForTuningOffset] 16QAM AvgOffset=0 AccOffsetCnt=326/326
 02:50:45.830 [2.0.4] [Decode16QAMData] 16QAM.200.100.O 100%  decoded
 02:50:45.830 [2.0.4] [DecodeFrame] Frame: 16QAM.200.100.O PASS, Quality= 98 bytes= 8
 02:50:47.616 [2.0.4] [AcquireFrameSyncRSBAvg] Phase1>2Avg=3.14 Phase2>3=.00
 02:50:47.807 [2.0.4] [Frame Type OK]9A 16QAM.200.100.O, D1=.00, D2=.00  Ldr; S:N(3KHz) Avg=28.3dB,  Offset=0.00Hz 
 02:50:51.129 [2.0.4] [CorrectPhaseForTuningOffset] 16QAM AvgOffset=0 AccOffsetCnt=326/326
 02:50:51.130 [2.0.4] [Decode16QAMData] 16QAM.200.100.O 100%  decoded
 02:50:51.131 [2.0.4] [DecodeFrame] Frame: 16QAM.200.100.O PASS, Quality= 98 bytes= 8
 02:50:52.925 [2.0.4] [AcquireFrameSyncRSBAvg] Phase1>2Avg=3.14 Phase2>3=.00
 02:50:53.075 [2.0.4] [Frame Type OK]9A 16QAM.200.100.O, D1=.00, D2=.00  Ldr; S:N(3KHz) Avg=28.4dB,  Offset=0.00Hz 
 02:50:56.338 [2.0.4] [CorrectPhaseForTuningOffset] 16QAM AvgOffset=0 AccOffsetCnt=326/326
 02:50:56.340 [2.0.4] [Decode16QAMData] 16QAM.200.100.O 100%  decoded
 02:50:56.340 [2.0.4] [DecodeFrame] Frame: 16QAM.200.100.O PASS, Quality= 98 bytes= 8
 02:50:58.196 [2.0.4] [AcquireFrameSyncRSBAvg] Phase1>2Avg=3.14 Phase2>3=.00
 02:50:58.387 [2.0.4] [Frame Type OK]9A 16QAM.200.100.O, D1=.00, D2=.00  Ldr; S:N(3KHz) Avg=30.2dB,  Offset=0.00Hz 
 02:51:01.618 [2.0.4] [CorrectPhaseForTuningOffset] 16QAM AvgOffset=0 AccOffsetCnt=326/326
 02:51:01.620 [2.0.4] [Decode16QAMData] 16QAM.200.100.O 100%  decoded
 02:51:01.620 [2.0.4] [DecodeFrame] Frame: 16QAM.200.100.O PASS, Quality= 98 bytes= 8
 02:51:02.396 [2.0.4] [AcquireFrameSyncRSBAvg] Phase1>2Avg=3.14 Phase2>3=.00
 02:51:02.547 [2.0.4] [Frame Type OK]11 16QAM.500.100.E, D2=.00  Ldr; S:N(3KHz) Avg=30.5dB,  Offset=0.00Hz 
 02:51:05.753 [2.0.4] [ARDOPprotocol.PollARQTimeout] Timeout setting SendTimeout timer to start.
 02:51:05.861 [2.0.4] ARDOPprotocol.tmrSendTimeout]  ARQ Timeout from ProtocolState: IRS  Going to DISC state
 02:51:05.868 [2.0.4] [Main.SendFrame] Send IDFrame_KA8RYU [DM65]  delayed 100 ms
 02:51:05.878 [2.0.4] [CorrectPhaseForTuningOffset] 16QAM AvgOffset=12 AccOffsetCnt=302/326
 02:51:05.908 [2.0.4] [CorrectPhaseForTuningOffset] 16QAM  AvgOffsetBeginning=11  AvgOffsetEnd=3 AccOffsetCnt=309/326
 02:51:05.911 [2.0.4] [Decode16QAMData] 16QAM.500.100.E 0%  decoded
 02:51:05.911 [2.0.4] [DecodeFrame] Frame: 16QAM.500.100.E FAIL, Quality= 68
 02:51:05.911 [2.0.4] [ARDOPprotocol.ProcessNewSamples] blnTimeoutTriggered blocks ProcessRcvdARQFrame 
 02:51:05.988 [2.0.4] [Main.MainPoll4] objProtocol.Repeating=True ProtocolState=IRS  blnFramePending=True  next Play in 20 ms
 02:51:05.988 [2.0.4]      Command Trace TO Host: PTT TRUE
 02:51:05.988 [2.0.4] [Main.KeyPTT] True
 02:51:05.989 [2.0.4] [PlaySoundStream] IDFrame_KA8RYU [DM65]
 02:51:05.989 [2.0.4] [Main.PlaySoundStream] set blnSoundStreamPlay to True
 02:51:06.065 [2.0.4]      Command Trace TO Host: DISCONNECTED

Server station exception log
====================
 02:49:05.731 [2.0.4] [ProcessRcvdARQFrame] Trace = 202 Exception: System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at ARDOP_Win.ARDOPprotocol.ProcessRcvdARQFrame(Int32 intFrameType, Byte[] bytData, Boolean blnFrameDecodedOK)
 02:49:10.942 [2.0.4] [ProcessRcvdARQFrame] Trace = 202 Exception: System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at ARDOP_Win.ARDOPprotocol.ProcessRcvdARQFrame(Int32 intFrameType, Byte[] bytData, Boolean blnFrameDecodedOK)
 02:49:16.251 [2.0.4] [ProcessRcvdARQFrame] Trace = 202 Exception: System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at ARDOP_Win.ARDOPprotocol.ProcessRcvdARQFrame(Int32 intFrameType, Byte[] bytData, Boolean blnFrameDecodedOK)
 02:49:21.521 [2.0.4] [ProcessRcvdARQFrame] Trace = 202 Exception: System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at ARDOP_Win.ARDOPprotocol.ProcessRcvdARQFrame(Int32 intFrameType, Byte[] bytData, Boolean blnFrameDecodedOK)
 02:49:26.831 [2.0.4] [ProcessRcvdARQFrame] Trace = 202 Exception: System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at ARDOP_Win.ARDOPprotocol.ProcessRcvdARQFrame(Int32 intFrameType, Byte[] bytData, Boolean blnFrameDecodedOK)
 02:49:32.097 [2.0.4] [ProcessRcvdARQFrame] Trace = 202 Exception: System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at ARDOP_Win.ARDOPprotocol.ProcessRcvdARQFrame(Int32 intFrameType, Byte[] bytData, Boolean blnFrameDecodedOK)
 02:49:37.311 [2.0.4] [ProcessRcvdARQFrame] Trace = 202 Exception: System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at ARDOP_Win.ARDOPprotocol.ProcessRcvdARQFrame(Int32 intFrameType, Byte[] bytData, Boolean blnFrameDecodedOK)
 02:49:42.621 [2.0.4] [ProcessRcvdARQFrame] Trace = 202 Exception: System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at ARDOP_Win.ARDOPprotocol.ProcessRcvdARQFrame(Int32 intFrameType, Byte[] bytData, Boolean blnFrameDecodedOK)
 02:49:47.831 [2.0.4] [ProcessRcvdARQFrame] Trace = 202 Exception: System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at ARDOP_Win.ARDOPprotocol.ProcessRcvdARQFrame(Int32 intFrameType, Byte[] bytData, Boolean blnFrameDecodedOK)
 02:49:53.099 [2.0.4] [ProcessRcvdARQFrame] Trace = 202 Exception: System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at ARDOP_Win.ARDOPprotocol.ProcessRcvdARQFrame(Int32 intFrameType, Byte[] bytData, Boolean blnFrameDecodedOK)
 02:49:58.411 [2.0.4] [ProcessRcvdARQFrame] Trace = 202 Exception: System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at ARDOP_Win.ARDOPprotocol.ProcessRcvdARQFrame(Int32 intFrameType, Byte[] bytData, Boolean blnFrameDecodedOK)
 02:50:03.681 [2.0.4] [ProcessRcvdARQFrame] Trace = 202 Exception: System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at ARDOP_Win.ARDOPprotocol.ProcessRcvdARQFrame(Int32 intFrameType, Byte[] bytData, Boolean blnFrameDecodedOK)
 02:50:08.981 [2.0.4] [ProcessRcvdARQFrame] Trace = 202 Exception: System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at ARDOP_Win.ARDOPprotocol.ProcessRcvdARQFrame(Int32 intFrameType, Byte[] bytData, Boolean blnFrameDecodedOK)
 02:50:14.351 [2.0.4] [ProcessRcvdARQFrame] Trace = 202 Exception: System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at ARDOP_Win.ARDOPprotocol.ProcessRcvdARQFrame(Int32 intFrameType, Byte[] bytData, Boolean blnFrameDecodedOK)
 02:50:19.551 [2.0.4] [ProcessRcvdARQFrame] Trace = 202 Exception: System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at ARDOP_Win.ARDOPprotocol.ProcessRcvdARQFrame(Int32 intFrameType, Byte[] bytData, Boolean blnFrameDecodedOK)
 02:50:24.861 [2.0.4] [ProcessRcvdARQFrame] Trace = 202 Exception: System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at ARDOP_Win.ARDOPprotocol.ProcessRcvdARQFrame(Int32 intFrameType, Byte[] bytData, Boolean blnFrameDecodedOK)
 02:50:30.041 [2.0.4] [ProcessRcvdARQFrame] Trace = 202 Exception: System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at ARDOP_Win.ARDOPprotocol.ProcessRcvdARQFrame(Int32 intFrameType, Byte[] bytData, Boolean blnFrameDecodedOK)
 02:50:35.341 [2.0.4] [ProcessRcvdARQFrame] Trace = 202 Exception: System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at ARDOP_Win.ARDOPprotocol.ProcessRcvdARQFrame(Int32 intFrameType, Byte[] bytData, Boolean blnFrameDecodedOK)
 02:50:40.551 [2.0.4] [ProcessRcvdARQFrame] Trace = 202 Exception: System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at ARDOP_Win.ARDOPprotocol.ProcessRcvdARQFrame(Int32 intFrameType, Byte[] bytData, Boolean blnFrameDecodedOK)
 02:50:45.831 [2.0.4] [ProcessRcvdARQFrame] Trace = 202 Exception: System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at ARDOP_Win.ARDOPprotocol.ProcessRcvdARQFrame(Int32 intFrameType, Byte[] bytData, Boolean blnFrameDecodedOK)
 02:50:51.131 [2.0.4] [ProcessRcvdARQFrame] Trace = 202 Exception: System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at ARDOP_Win.ARDOPprotocol.ProcessRcvdARQFrame(Int32 intFrameType, Byte[] bytData, Boolean blnFrameDecodedOK)
 02:50:56.341 [2.0.4] [ProcessRcvdARQFrame] Trace = 202 Exception: System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at ARDOP_Win.ARDOPprotocol.ProcessRcvdARQFrame(Int32 intFrameType, Byte[] bytData, Boolean blnFrameDecodedOK)
 02:51:01.621 [2.0.4] [ProcessRcvdARQFrame] Trace = 202 Exception: System.IndexOutOfRangeException: Index was outside the bounds of the array.
   at ARDOP_Win.ARDOPprotocol.ProcessRcvdARQFrame(Int32 intFrameType, Byte[] bytData, Boolean blnFrameDecodedOK)