search

jmason86 / MinXSS_Beacon_Decoder

Beacon decoder for the MinXSS CubeSat in space; MinXSS-2 launch on 2018-11-19
http://lasp.colorado.edu/home/minxss
GNU General Public License v3.0
11 stars 6 forks source link

"First" packet not processed by decoder app #3

Closed K4KDR closed 7 years ago

K4KDR commented 7 years ago

Using Latest commit 9190210, repeated testing with recorded packets confirms that after establishing a TCP connection to a KISS source, the first packet decoded by the modem is not heard by the decoder application. The first packet IS logged by the software modem (either Windows on a remote PC or Direwolf on the local linux PC), but there is no evidence of it being received by the app. No telemetry display in the GUI, no hex data in the raw hex window, and no entries in the log file. However, if you replay the exact same recorded packet, it is logged and processed by the app normally. The same issue was seen with two different recorded packets... looks normal in the software modem, but the first packet is always ignored by the app.

jmason86 commented 7 years ago

Hm... can you post what the log does say? There may be some clues in there. If not I'll add some more output to the log to get a better idea as to why this happens.

K4KDR commented 7 years ago

An illustration might explain the scenario better than I can:

Here is the Direwolf window contents after playing a single packet

Dire Wolf version 1.2 Audio device for both receive and transmit: default (channel 0) Channel 0: 9600 baud, K9NG/G3RUH, +, 48000 sample rate x 2. Note: PTT not configured for channel 0. (Ignore this if using VOX.) Ready to accept AGW client application 0 on port 8000 ... Ready to accept KISS client application on port 8100 ... Use -p command line option to enable KISS pseudo terminal.

Connected to KISS client application ...

MINXSS audio level = 69(+61/-52) [NONE] ||||||||| [0.4] MINXSS>CQ:<0x08><0x19>�� Unknown message type, --no-symbol--

... and here is the minxss_beacon_decoder_debug.log after that single packet:

2017-03-14 12:38:56,802 INFO Launched app 2017-03-14 12:39:27,566 INFO Attempting to connect to port 2017-03-14 12:39:27,566 INFO Attempting to connect to port 2017-03-14 12:39:27,568 INFO Opening IP address: 127.0.0.1 on port: 8100 2017-03-14 12:39:27,568 INFO Opening IP address: 127.0.0.1 on port: 8100

... so in the above example, please note that Direwolf received the packet normally.

Without touching anything, but just playing the same recorded packet over again, please note the continuation of the same two sessions (time stamps may help to show that we are still in the same session)

Direwolf after playing the packet a second time:

Dire Wolf version 1.2 Audio device for both receive and transmit: default (channel 0) Channel 0: 9600 baud, K9NG/G3RUH, +, 48000 sample rate x 2. Note: PTT not configured for channel 0. (Ignore this if using VOX.) Ready to accept AGW client application 0 on port 8000 ... Ready to accept KISS client application on port 8100 ... Use -p command line option to enable KISS pseudo terminal.

Connected to KISS client application ...

MINXSS audio level = 69(+61/-52) [NONE] ||||||||| [0.4] MINXSS>CQ:<0x08><0x19>�� Unknown message type, --no-symbol--

MINXSS audio level = 69(+61/-52) [NONE] ||||||||| [0.4] MINXSS>CQ:<0x08><0x19>�� Unknown message type, --no-symbol--

... and minxss_beacon_decoder_debug.log after the second playing of the recorded packet. (Naturally after the second packet, telemetry shows up in the GUI as well)

2017-03-14 12:38:56,802 INFO Launched app 2017-03-14 12:39:27,566 INFO Attempting to connect to port 2017-03-14 12:39:27,566 INFO Attempting to connect to port 2017-03-14 12:39:27,568 INFO Opening IP address: 127.0.0.1 on port: 8100 2017-03-14 12:39:27,568 INFO Opening IP address: 127.0.0.1 on port: 8100 2017-03-14 12:41:00,458 ERROR Too many bytes in packet 2017-03-14 12:41:00,458 ERROR Too many bytes in packet 2017-03-14 12:41:00,459 INFO Packet length [bytes] = 529 2017-03-14 12:41:00,459 INFO Packet length [bytes] = 529 2017-03-14 12:41:00,475 INFO From MinXSS parser: 2017-03-14 12:41:00,475 INFO From MinXSS parser: 2017-03-14 12:41:00,475 INFO {'BatteryVoltage': 7.282930631332814, 'SolarPanelPlusXCurrent': 0.0, 'EpsBoardTemperature': 13.375, 'SpsX': 0.0, 'SpsY': 0.0, 'CdhBoardTemperature': 8.1875, 'SolarPanelPlusYCurrent': 0.0, 'SolarPanelMinusYCurrent': 0.0, 'BatteryDischargeCurrent': 720.896, 'BatteryTemperature': 13.086979999999983, 'SolarPanelPlusXVoltage': 0.135966796875, 'SolarPanelPlusYTemperature': -18.579200000000014, 'MotherboardTemperature': 3.6875, 'BatteryChargeCurrent': 5.979199999999999, 'SolarPanelMinusYTemperature': -21.1952, 'SolarPanelPlusYVoltage': 0.119970703125, 'CommBoardTemperature': 6.4375, 'SolarPanelMinusYVoltage': 0.135966796875, 'Xp': 147, 'SolarPanelPlusXTemperature': 0.9535999999999945} 2017-03-14 12:41:00,475 INFO {'BatteryVoltage': 7.282930631332814, 'SolarPanelPlusXCurrent': 0.0, 'EpsBoardTemperature': 13.375, 'SpsX': 0.0, 'SpsY': 0.0, 'CdhBoardTemperature': 8.1875, 'SolarPanelPlusYCurrent': 0.0, 'SolarPanelMinusYCurrent': 0.0, 'BatteryDischargeCurrent': 720.896, 'BatteryTemperature': 13.086979999999983, 'SolarPanelPlusXVoltage': 0.135966796875, 'SolarPanelPlusYTemperature': -18.579200000000014, 'MotherboardTemperature': 3.6875, 'BatteryChargeCurrent': 5.979199999999999, 'SolarPanelMinusYTemperature': -21.1952, 'SolarPanelPlusYVoltage': 0.119970703125, 'CommBoardTemperature': 6.4375, 'SolarPanelMinusYVoltage': 0.135966796875, 'Xp': 147, 'SolarPanelPlusXTemperature': 0.9535999999999945}

K4KDR commented 7 years ago

Just a follow-up; excellent "live" pass processed entirely on linux tonight 0340utc 16-Mar-2017... POWER and TEMPERATURE sections in GUI showing all nominal values (spacecraft in full eclipse, so solar=zero is correct), but only processed second of two packets decoded by Direwolf (same as in previous report). Files attached:

2017-03-15 23:28:58,318 INFO Launched app 2017-03-15 23:29:17,981 INFO Attempting to connect to port 2017-03-15 23:29:17,981 INFO Attempting to connect to port 2017-03-15 23:29:17,981 INFO Opening IP address: 127.0.0.1 on port: 8100 2017-03-15 23:29:17,981 INFO Opening IP address: 127.0.0.1 on port: 8100 2017-03-15 23:39:50,979 ERROR Too many bytes in packet 2017-03-15 23:39:50,979 ERROR Too many bytes in packet 2017-03-15 23:39:50,997 INFO Packet length [bytes] = 529 2017-03-15 23:39:50,997 INFO Packet length [bytes] = 529 2017-03-15 23:39:51,014 INFO From MinXSS parser: 2017-03-15 23:39:51,014 INFO From MinXSS parser: 2017-03-15 23:39:51,014 INFO {'BatteryVoltage': 7.4425565081839435, 'SolarPanelPlusXCurrent': 0.0, 'EpsBoardTemperature': 17.8125, 'SpsX': 0.0, 'SpsY': 0.0, 'CdhBoardTemperature': 11.25, 'SolarPanelPlusYCurrent': 0.0, 'SolarPanelMinusYCurrent': 0.0, 'SolarPanelMinusYTemperature': -16.312000000000012, 'BatteryTemperature': 13.462300000000027, 'SolarPanelPlusXVoltage': 0.055986328125, 'SolarPanelPlusYTemperature': -15.265600000000006, 'MotherboardTemperature': 7.0, 'BatteryChargeCurrent': 2.422400000000003, 'X123Enable': 2, 'SolarPanelPlusYVoltage': 0.055986328125, 'CommBoardTemperature': 9.5, 'SolarPanelMinusYVoltage': 0.063984375, 'BatteryDischargeCurrent': 695.9984, 'Xp': 0, 'SolarPanelPlusXTemperature': 4.2672000000000025} 2017-03-15 23:39:51,014 INFO {'BatteryVoltage': 7.4425565081839435, 'SolarPanelPlusXCurrent': 0.0, 'EpsBoardTemperature': 17.8125, 'SpsX': 0.0, 'SpsY': 0.0, 'CdhBoardTemperature': 11.25, 'SolarPanelPlusYCurrent': 0.0, 'SolarPanelMinusYCurrent': 0.0, 'SolarPanelMinusYTemperature': -16.312000000000012, 'BatteryTemperature': 13.462300000000027, 'SolarPanelPlusXVoltage': 0.055986328125, 'SolarPanelPlusYTemperature': -15.265600000000006, 'MotherboardTemperature': 7.0, 'BatteryChargeCurrent': 2.422400000000003, 'X123Enable': 2, 'SolarPanelPlusYVoltage': 0.055986328125, 'CommBoardTemperature': 9.5, 'SolarPanelMinusYVoltage': 0.063984375, 'BatteryDischargeCurrent': 695.9984, 'Xp': 0, 'SolarPanelPlusXTemperature': 4.2672000000000025} 2017-03-15 23:43:45,616 INFO Attempting to disconnect from port 2017-03-15 23:43:45,616 INFO Attempting to disconnect from port 2017-03-15 23:43:45,617 INFO Closing ground station link 2017-03-15 23:43:45,617 INFO Closing ground station link

screenshot from 2017-03-15 23-45-46

screenshot from 2017-03-15 23-44-04

jmason86 commented 7 years ago

Noted. I'll soon add some more log messages to try to get a handle on why the first packet doesn't get detected/decoded.

jmason86 commented 7 years ago

Could you try it again with the release from a moment ago and post the .log? I added a log message that should help figure out what's going on. Thanks for the help!

K4KDR commented 7 years ago

Gladly! Using audio from a previous pass, here is the result after downloading the latest program code:

(single packet played once, then again after a minute to allow the logfile timestamps to allow easy identification of the separate decodes)

(not shown here, but entire process was repeated with audio from a different known-good packet; results were the same)

>>> First Packet:

Direwolf screen:

MINXSS audio level = 73(+57/-56)   [NONE]   |||||||||
[0.4] MINXSS>CQ:<0x08><0x19>��
Unknown message type, --no-symbol--

MinXSS logfile:

2017-03-20 17:53:25,954 INFO Attempting to connect to port
2017-03-20 17:53:25,954 INFO Attempting to connect to port
2017-03-20 17:53:25,955 INFO Opening IP address: 127.0.0.1 on port: 8100
2017-03-20 17:53:25,955 INFO Opening IP address: 127.0.0.1 on port: 8100
2017-03-20 17:54:09,687 DEBUG ���@@@@`�����������M�Eq
                                                        �T��?��t�7��g_�F��t��%F�O��i�
                                                                                                    ��~<U,4
Pp]�l@�   |�{�LJCC3��                                                                          p�p`
                                    �/ ��e�n�
2017-03-20 17:54:09,687 DEBUG ���@@@@`�����������M�Eq
                                                        �T��?��t�7��g_�F��t��%F�O��i�
                                                                                                    ��~<U,4
Pp]�l@�   |�{�LJCC3��                                                                          p�p`
                                    �/ ��e�n�
��GN!���0 17:54:09,688 DEBUG �
��GN!���0 17:54:09,688 DEBUG �

>>> Second (identical) Packet:

Direwolf screen: (note: TCP connection dropped after decode)


MINXSS audio level = 73(+57/-56)   [NONE]   |||||||||
[0.4] MINXSS>CQ:<0x08><0x19>��
Unknown message type, --no-symbol--

Error reading KISS byte from clent application.  Closing connection.

MinXSS logfile:

2017-03-20 17:56:04,075 DEBUG ���@@@@`�����������M�Eq
                                                        �T��?��t�7��g_�F��t��%F�O��i�
                                                                                                    ��~<U,4
Pp]�l@�   |�{�LJCC3��                                                                          p�p`
                                    �/ ��e�n�
2017-03-20 17:56:04,075 DEBUG ���@@@@`�����������M�Eq
                                                        �T��?��t�7��g_�F��t��%F�O��i�
                                                                                                    ��~<U,4
Pp]�l@�   |�{�LJCC3��                                                                          p�p`
                                    �/ ��e�n�
2017-03-20 17:56:04,075 ERROR Too many bytes in packet
2017-03-20 17:56:04,075 ERROR Too many bytes in packet
2017-03-20 17:56:04,076 INFO Packet length [bytes] = 529
2017-03-20 17:56:04,076 INFO Packet length [bytes] = 529
2017-03-20 17:56:04,095 INFO From MinXSS parser:
2017-03-20 17:56:04,095 INFO From MinXSS parser:
2017-03-20 17:56:04,096 INFO {'SolarPanelPlusYCurrent': 0.0, 'EpsBoardTemperature': 13.375, 'SpacecraftMode': 4, 'SolarPanelMinusYCurrent': 0.0, 'EnableX123': 0, 'SolarPanelPlusYTemperature': -18.579200000000014, 'BatteryDischargeCurrent': 720.896, 'CommBoardTemperature': 6.4375, 'FlightModel': 1, 'MotherboardTemperature': 3.6875, 'CommandAcceptCount': 1498, 'PointingMode': 1, 'Eclipse': 1, 'BatteryTemperature': 13.086979999999983, 'BatteryChargeCurrent': 5.979199999999999, 'SolarPanelPlusYVoltage': 0.119970703125, 'SolarPanelPlusXVoltage': 0.135966796875, 'BatteryVoltage': 7.282930631332814, 'SolarPanelPlusXCurrent': 0.0, 'SpsX': 0.0, 'SpsY': 0.0, 'CdhBoardTemperature': 8.1875, 'EnableSps': 1, 'SolarPanelMinusYTemperature': -21.1952, 'Xp': 147, 'SolarPanelMinusYVoltage': 0.135966796875, 'SolarPanelPlusXTemperature': 0.9535999999999945}
2017-03-20 17:56:04,096 INFO {'SolarPanelPlusYCurrent': 0.0, 'EpsBoardTemperature': 13.375, 'SpacecraftMode': 4, 'SolarPanelMinusYCurrent': 0.0, 'EnableX123': 0, 'SolarPanelPlusYTemperature': -18.579200000000014, 'BatteryDischargeCurrent': 720.896, 'CommBoardTemperature': 6.4375, 'FlightModel': 1, 'MotherboardTemperature': 3.6875, 'CommandAcceptCount': 1498, 'PointingMode': 1, 'Eclipse': 1, 'BatteryTemperature': 13.086979999999983, 'BatteryChargeCurrent': 5.979199999999999, 'SolarPanelPlusYVoltage': 0.119970703125, 'SolarPanelPlusXVoltage': 0.135966796875, 'BatteryVoltage': 7.282930631332814, 'SolarPanelPlusXCurrent': 0.0, 'SpsX': 0.0, 'SpsY': 0.0, 'CdhBoardTemperature': 8.1875, 'EnableSps': 1, 'SolarPanelMinusYTemperature': -21.1952, 'Xp': 147, 'SolarPanelMinusYVoltage': 0.135966796875, 'SolarPanelPlusXTemperature': 0.9535999999999945}
2017-03-20 17:56:04,161 INFO Closing ground station link
2017-03-20 17:56:04,161 INFO Closing ground station link

PLEASE NOTE: after second packet (the successful decode, but crash of TCP connection), the following is displayed in the terminal windows where the MinXSS decoder app was run from:


Traceback (most recent call last):
  File "minxss_beacon_decoder.py", line 345, in run
    self.target(*args, **kwargs)
  File "minxss_beacon_decoder.py", line 146, in readSerial
    self.label_enablex123.setText("No")
AttributeError: 'MainWindow' object has no attribute 'label_enablex123'
K4KDR commented 7 years ago

In an effort to understand how & when the app would process packets (or not process them), I have experimented with the settings in connect_port_get_packet.py. Specifically, it seems that nothing happens until the value in line 111 is exceeded. If I change that to a larger value (& recompile connect_port_get_packet.pyc), the app will run until many packets are sent over from Direwolf. Once the line 111 value is exceeded, a telemetry decode will be logged and the TCP connection will crash.

Similarly, if you set the line 111 value to a very small number, the very first packet received will be decoded, and the TCP connection will be immediately closed.

For example, with the line 111 value set to "10", the very first packet is decoded & logged as follows (duplicate entries removed):

2017-03-23 23:16:07,746 INFO Launched app
2017-03-23 23:16:33,511 INFO Attempting to connect to port
2017-03-23 23:16:33,512 INFO Opening IP address: 127.0.0.1 on port: 8100
2017-03-23 23:16:39,651 DEBUG ���@@@@`��������D�,1�E|�Tx���cu�dt�ga�R�#��t���D2O����
                                         ;L��Z����P
                                                       �
                                                        �
                                                         �"� 0��p� ��\z}�&LJEF3��aQ ^�!�/'������
                                                    .�
2017-03-23 23:16:39,652 ERROR Too many bytes in packet
2017-03-23 23:16:39,652 INFO Packet length [bytes] = 256
2017-03-23 23:16:39,670 INFO From MinXSS parser:
2017-03-23 23:16:39,671 INFO {'SolarPanelPlusYCurrent': 127.96875, 'EpsBoardTemperature': 34.0, 'SpacecraftMode': 4, 'SolarPanelMinusYCurrent': 131.9677734375, 'EnableX123': 0, 'SolarPanelPlusYTemperature': 44.379200000000026, 'BatteryDischargeCurrent': 23.763200000000005, 'CommBoardTemperature': 11.9375, 'FlightModel': 1, 'MotherboardTemperature': 11.875, 'CommandAcceptCount': 1912, 'PointingMode': 1, 'Eclipse': 0, 'BatteryTemperature': 13.462300000000027, 'BatteryChargeCurrent': 265.62559999999996, 'SolarPanelPlusYVoltage': 16.7958984375, 'SolarPanelPlusXVoltage': 9.765615234375, 'BatteryVoltage': 7.9887763055339045, 'SolarPanelPlusXCurrent': 523.8720703125001, 'SpsX': 19.305, 'SpsY': 0.1635, 'CdhBoardTemperature': 15.0625, 'EnableSps': 1, 'SolarPanelMinusYTemperature': 46.64639999999997, 'Xp': 200, 'SolarPanelMinusYVoltage': 16.963857421874998, 'SolarPanelPlusXTemperature': 57.45920000000001}
2017-03-23 23:16:39,705 INFO Closing ground station link

In contrast, if you set the line 111 value to "2000", it takes about 8 packets before an actual decode happens: (non-decoded hex dumps from the log omitted):

2017-03-23 23:31:34,289 INFO Packet length [bytes] = 2170
2017-03-23 23:31:34,318 INFO From MinXSS parser:
2017-03-23 23:31:34,319 INFO {'SolarPanelPlusYCurrent': 127.96875, 'EpsBoardTemperature': 34.0, 'SpacecraftMode': 4, 'SolarPanelMinusYCurrent': 131.9677734375, 'EnableX123': 0, 'SolarPanelPlusYTemperature': 44.379200000000026, 'BatteryDischargeCurrent': 23.763200000000005, 'CommBoardTemperature': 11.9375, 'FlightModel': 1, 'MotherboardTemperature': 11.875, 'CommandAcceptCount': 1912, 'PointingMode': 1, 'Eclipse': 0, 'BatteryTemperature': 13.462300000000027, 'BatteryChargeCurrent': 265.62559999999996, 'SolarPanelPlusYVoltage': 16.7958984375, 'SolarPanelPlusXVoltage': 9.765615234375, 'BatteryVoltage': 7.9887763055339045, 'SolarPanelPlusXCurrent': 523.8720703125001, 'SpsX': 19.305, 'SpsY': 0.1635, 'CdhBoardTemperature': 15.0625, 'EnableSps': 1, 'SolarPanelMinusYTemperature': 46.64639999999997, 'Xp': 200, 'SolarPanelMinusYVoltage': 16.963857421874998, 'SolarPanelPlusXTemperature': 57.45920000000001}
2017-03-23 23:31:34,588 INFO Closing ground station link

... I hope that helps clarify how the flow of incoming packets is interacting with the app for you.

K4KDR commented 7 years ago

UPDATE: While I have no idea what negative effects the following work-around might cause (mainly because I don't know what the lines of code actually DO), I have found a work-around that allows me to use the beacon decoder app non-stop for as many incoming packets as you care to throw at it.

Based on the error in the terminal window that I was seeing after the TCP disconnect:

Traceback (most recent call last):
  File "minxss_beacon_decoder.py", line 346, in run
    self.target(*args, **kwargs)
  File "minxss_beacon_decoder.py", line 147, in readSerial
    self.label_enablex123.setText("No")
AttributeError: 'MainWindow' object has no attribute 'label_enablex123'

... I commented out lines 144-147 in minxss_beacon_decoder.py:

                   #if selectedTelemetryDictionary['EnableX123'] == 1:
                        #self.label_enablex123.setText("Yes")
                    #else:
                        #self.label_enablex123.setText("No")

... and recompiled minxss_beacon_decoder.pyc

Following that work-around, minxss_beacon_decoder.py ran normally and using my recording of the 134 packets from 22-Mar, was able to enjoy seeing the data readings change from packet-to-packet as you would expect. (there were some obvoiusly bad decodes in there, but the majority were nominal)

Here is an image and an animated .GIF showing the app's readings change over the course of 3 different packets:

screenshot from 2017-03-24 03-27-19

animation

... of course please let me know if I can provide any additional info to help with your project.

jmason86 commented 7 years ago

That really narrows it down! I know exactly which logic must be failing now and can write up a fix. Thanks!!!

jmason86 commented 7 years ago

The "EnableX123" stuff is just due to a single character typo. The label is supposed to be label_enableX123 not label_enablex123. That shows up in 2 lines. That's been fixed in the newest commit.

jmason86 commented 7 years ago

The logic for identifying packets has been updated so that the first packet won't get dropped. It was because the code would see the start sync bytes in one buffer read and then the stop sync bytes in another buffer read, but not both at the same time. Now a flag gets set when each one is found. Once both flags are set, the while loop can exit and the function returns the packet. The latest commit includes these updates.