IndexError: bytearray index out of range

[K4KDR]

Using commit 585833f, replayed recorded audio from MinXSS-1 pass 21-Apr-2017 @ 1949 UTC. 84 packets decoded using alternative Windows software. Some of the values displayed in the MinXSS_Beacon_Decoder were outside of expected ranges with the following logged in the terminal window:

Traceback (most recent call last):
  File "minxss_beacon_decoder.py", line 380, in run
    self.target(*args, **kwargs)
  File "minxss_beacon_decoder.py", line 150, in readPort
    selectedTelemetryDictionary = minxssParser.parsePacket(bufferData)
  File "/home/k4kdr/MinXSS_Beacon_Decoder/minxss_parser.py", line 35, in parsePacket
    selectedTelemetryDictionary['FlightModel'] = self.decodeFlightModel(minxssPacket[51])
  # [Unitless]
IndexError: bytearray index out of range

[jmason86]

Try the release 2d2887f (corresponding to release 1.0.2-beta). All the bad decoding has almost certainly been due to KISS special characters, which are now handled.

[K4KDR]

Using commit 23e9bd7, with previously recorded high packet count pass, decode values correct - congrats!! Remaining issue is that the app closes the TCP connection after the first packet (a packet that previously resulted in a "packet size" error"). Log file shows:

2017-04-25 11:07:48,106 INFO Launched app
2017-04-25 11:07:48,117 INFO Opening binary file for buffer data
2017-04-25 11:09:44,763 INFO Attempting to connect to port
2017-04-25 11:09:44,763 INFO Opening IP address: 127.0.0.1 on port: 8100
2017-04-25 11:10:01,763 INFO Packet length [bytes] = 273
2017-04-25 11:10:01,777 INFO From MinXSS parser:
2017-04-25 11:10:01,778 INFO {'SolarPanelPlusYCurrent': 171.9580078125, 'EpsBoardTemperature': 31.8125, 'SpacecraftMode': 4, 'SolarPanelMinusYCurrent': 183.955078125, 'EnableX123': 0, 'SolarPanelPlusYTemperature': 46.995200000000011, 'BatteryDischargeCurrent': 20.206399999999995, 'CommBoardTemperature': 22.625, 'FlightModel': 1, 'MotherboardTemperature': 6.125, 'CommandAcceptCount': 2867, 'PointingMode': 1, 'Eclipse': 0, 'BatteryTemperature': 12.711659999999995, 'BatteryChargeCurrent': 479.03359999999998, 'SolarPanelPlusYVoltage': 16.387998046874998, 'SolarPanelPlusXVoltage': 9.7496191406249988, 'BatteryVoltage': 7.9289166017147314, 'SolarPanelPlusXCurrent': 523.87207031250011, 'SpsX': -0.35670000000000002, 'SpsY': 0.15179999999999999, 'CdhBoardTemperature': 11.0625, 'EnableSps': 1, 'SolarPanelMinusYTemperature': 52.924800000000005, 'Xp': 0, 'SolarPanelMinusYVoltage': 16.747910156250001, 'SolarPanelPlusXTemperature': 52.576000000000022}
2017-04-25 11:10:03,153 ERROR Too many bytes in packet
2017-04-25 11:10:03,153 INFO Packet length [bytes] = 501
2017-04-25 11:10:03,159 INFO No sync bytes found
2017-04-25 11:10:04,636 INFO Packet length [bytes] = 238
2017-04-25 11:10:04,653 INFO Closing ground station link

... and the app's terminal window shows:

k4kdr@:~/MinXSS_Beacon_Decoder$ python minxss_beacon_decoder.py 
Traceback (most recent call last):
  File "minxss_beacon_decoder.py", line 504, in run
    self.target(*args, **kwargs)
  File "minxss_beacon_decoder.py", line 201, in readPort
    selectedTelemetryDictionary = minxssParser.parsePacket(bufferData)
  File "/home/k4kdr/MinXSS_Beacon_Decoder/minxss_parser.py", line 36, in parsePacket
    selectedTelemetryDictionary['FlightModel'] = self.decodeFlightModel(minxssPacket[51])                                       # [Unitless]
IndexError: bytearray index out of range

Great work on the value decoding math!!

[jmason86]

Note to self: the "No sync bytes found" log message is generated in minxss_parser.py, not connect_port_get_packet.py. Looks like the logic is such that in the latter, it generates the "ERROR Too many bytes in packet" message but still returns what it has (which will always be 501 bytes as it stands). This should only happen if the latter also failed to find the sync bytes in the data.

This could occur if there's a bunch of other data coming in over the port (other MinXSS packets or anything else random). The logic should be amended in the latter to detect too many bytes, reset the packet to null and keep reading.

[jmason86]

d9101e6 should address this issue

[jmason86]

Any better when you run old data through?

[K4KDR]

The math appears correct (nominal values appear in GUI !!!), but after a single packet, the app appears to stop processing new receive data.

k4kdr@:~/MinXSS_Beacon_Decoder$ python minxss_beacon_decoder.py 
Traceback (most recent call last):
  File "minxss_beacon_decoder.py", line 524, in run
    self.target(*args, **kwargs)
  File "minxss_beacon_decoder.py", line 202, in readPort
    selectedTelemetryDictionary = minxssParser.parsePacket(bufferData)
  File "/home/k4kdr/MinXSS_Beacon_Decoder/minxss_parser.py", line 36, in parsePacket
    selectedTelemetryDictionary['FlightModel'] = self.decodeFlightModel(minxssPacket[51])                                       # [Unitless]
IndexError: bytearray index out of range

... and in log file:

2017-04-26 12:51:52,877 INFO Launched MinXSS Beacon Decoder
2017-04-26 12:51:52,918 INFO Opening binary file for buffer data
2017-04-26 12:53:23,990 INFO Attempting to connect to port
2017-04-26 12:53:23,991 INFO Opening IP address: 127.0.0.1 on port: 8100
2017-04-26 12:53:40,016 INFO Packet length [bytes] = 273
2017-04-26 12:53:40,029 INFO From MinXSS parser:
2017-04-26 12:53:40,030 INFO {'SolarPanelPlusYCurrent': 171.9580078125, 'EpsBoardTemperature': 31.8125, 'SpacecraftMode': 4, 'SolarPanelMinusYCurrent': 183.955078125, 'EnableX123': 0, 'SolarPanelPlusYTemperature': 46.995200000000011, 'BatteryDischargeCurrent': 20.206399999999995, 'CommBoardTemperature': 22.625, 'FlightModel': 1, 'MotherboardTemperature': 6.125, 'CommandAcceptCount': 2867, 'PointingMode': 1, 'Eclipse': 0, 'BatteryTemperature': 12.711659999999995, 'BatteryChargeCurrent': 479.03359999999998, 'SolarPanelPlusYVoltage': 16.387998046874998, 'SolarPanelPlusXVoltage': 9.7496191406249988, 'BatteryVoltage': 7.9289166017147314, 'SolarPanelPlusXCurrent': 523.87207031250011, 'SpsX': -0.35670000000000002, 'SpsY': 0.15179999999999999, 'CdhBoardTemperature': 11.0625, 'EnableSps': 1, 'SolarPanelMinusYTemperature': 52.924800000000005, 'Xp': 0, 'SolarPanelMinusYVoltage': 16.747910156250001, 'SolarPanelPlusXTemperature': 52.576000000000022}
2017-04-26 12:53:41,386 ERROR Too many bytes in packet, resetting packet buffer
2017-04-26 12:53:41,386 INFO Resetting packet buffer to null
2017-04-26 12:53:42,901 INFO Packet length [bytes] = 238
2017-04-26 12:53:42,916 INFO Closing ground station link
2017-04-26 12:54:08,822 INFO Attempting to disconnect from port
2017-04-26 12:54:08,823 INFO Closing ground station link

[jmason86]

This one is awfully perplexing. Does the GUI disconnect button change to say "connect" afterwards?

[jmason86]

Can you give 7387a25 a try? I added a bunch of additional DEBUG statements to the .log to try to figure out what's going on with this socket close.

[K4KDR]

Does the GUI disconnect button change to say "connect" afterwards?

No, it does not. No additional output to the log file either. However, direwolf continues happily decoding packets from the audio source. Will try 7387a25 now!

[K4KDR]

Cloned 7387a25 into new, empty folder to assure that I had not contaminated any aspect of the app. Same result but with greater amount of debug info logged. Will attach log file. Following screen shots are AFTER first packet caused TCP disconnect between app & direwolf software modem.

k4kdr@:~/MinXSS_Beacon_Decoder$ python minxss_beacon_decoder.py 
Traceback (most recent call last):
  File "minxss_beacon_decoder.py", line 524, in run
    self.target(*args, **kwargs)
  File "minxss_beacon_decoder.py", line 202, in readPort
    selectedTelemetryDictionary = minxssParser.parsePacket(bufferData)
  File "/home/k4kdr/MinXSS_Beacon_Decoder/minxss_parser.py", line 40, in parsePacket
    selectedTelemetryDictionary['FlightModel'] = self.decodeFlightModel(minxssPacket[51])                                       # [Unitless]
IndexError: bytearray index out of range

(( .txt extension added to log file to allow github upload ))

minxss_beacon_decoder_debug.log.txt

[jmason86]

That log file told me what I needed to know, I think. I didn't have a condition enforcing the stop sync bytes be after the start sync bytes. That is now enforced. 5a22838. Lemme know how that works. Thanks for all of this help!!!

[K4KDR]

Glad to help! This will be a spectacular resource - especially for the next satellite.

Using commit 5a22838, the same TCP disconnect behavior results:

k4kdr@:~/MinXSS_Beacon_Decoder$ python minxss_beacon_decoder.py 
Traceback (most recent call last):
  File "minxss_beacon_decoder.py", line 524, in run
    self.target(*args, **kwargs)
  File "minxss_beacon_decoder.py", line 202, in readPort
    selectedTelemetryDictionary = minxssParser.parsePacket(bufferData)
  File "/home/k4kdr/MinXSS_Beacon_Decoder/minxss_parser.py", line 40, in parsePacket
    selectedTelemetryDictionary['FlightModel'] = self.decodeFlightModel(minxssPacket[51])                                       # [Unitless]
IndexError: bytearray index out of range
/usr/lib/python2.7/dist-packages/Crypto/Cipher/blockalgo.py:141: FutureWarning: CTR mode needs counter parameter, not IV
  self._cipher = factory.new(key, *args, **kwargs)
Traceback (most recent call last):
  File "minxss_beacon_decoder.py", line 499, in prepareToExit
    self.uploadData()
  File "minxss_beacon_decoder.py", line 486, in uploadData
    scp_upload.upload(self.bufferOutputBinaryFilename)
  File "/home/k4kdr/MinXSS_Beacon_Decoder/scp_upload.py", line 24, in upload
    scp.put(file, remote_path = directory)
  File "/usr/lib/python2.7/dist-packages/scp.py", line 154, in put
    self._send_files(files)
  File "/usr/lib/python2.7/dist-packages/scp.py", line 238, in _send_files
    self._recv_confirm()
  File "/usr/lib/python2.7/dist-packages/scp.py", line 321, in _recv_confirm
    raise SCPException(asunicode(msg[1:]))
scp.SCPException: scp: Dropbox/minxss_dropbox/data/ham_data/: No such file or directory

... Log file attached

minxss_beacon_decoder_debug.log.txt

[jmason86]

Doh! Forgot to reset a flag in this special case. Newest commit resets that flag and hopefully the logic will work now.

[K4KDR]

Outstanding work! As packets are decoded in direwolf, they continue to display/update in the GUI and echo to the log file. I hope it won't corrupt anything on your end, but I will let this entire capture play from 21-Apr-2017 with the upload flag enabled.

[K4KDR]

Was running perfectly - you could see the GUI update at the same time that direwolf and the log file were reflecting data from each new packet. Unfortunately, there may be either a time, or "number of packets" issue. The GUI crashed with no feedback in the log file. The terminal window where the app was run from displayed as follows:

k4kdr@:~/MinXSS_Beacon_Decoder$ python minxss_beacon_decoder.py 
Segmentation fault

[K4KDR]

Will re-run the high volume capture for a shorter time period to see if a complete capture / upload cycle can be completed...

[K4KDR]

Using commit 37fe0a8, the app properly processed approx. 60 seconds of high-volume packets from a recording made on 21-Apr-2017.

When the playback ended, the "Complete Pass" button was clicked. The "Upload status:" line changed to "Uploading". There was no further update or feedback in the GUI. When the app was closed, feedback in the terminal window indicated that the application ended abnormally. (file attached)

2017-04-26--K4KDR--GUI-term-window.txt

... prior to the abnormal end, below is a shorter display of what was in the terminal windows AFTER the "Complete Pass" button was clicked, but BEFORE the application was ended:

k4kdr@:~/MinXSS_Beacon_Decoder$ python minxss_beacon_decoder.py 
/usr/lib/python2.7/dist-packages/Crypto/Cipher/blockalgo.py:141: FutureWarning: CTR mode needs counter parameter, not IV
  self._cipher = factory.new(key, *args, **kwargs)
Traceback (most recent call last):
  File "minxss_beacon_decoder.py", line 167, in completePassClicked
    self.uploadData()
  File "minxss_beacon_decoder.py", line 486, in uploadData
    scp_upload.upload(self.bufferOutputBinaryFilename)
  File "/home/k4kdr/MinXSS_Beacon_Decoder/scp_upload.py", line 24, in upload
    scp.put(file, remote_path = directory)
  File "/usr/lib/python2.7/dist-packages/scp.py", line 154, in put
    self._send_files(files)
  File "/usr/lib/python2.7/dist-packages/scp.py", line 238, in _send_files
    self._recv_confirm()
  File "/usr/lib/python2.7/dist-packages/scp.py", line 321, in _recv_confirm
    raise SCPException(asunicode(msg[1:]))
scp.SCPException: scp: Dropbox/minxss_dropbox/data/ham_data/: No such file or directory

... also, when the "Complete Pass" button was clicked, here is what was displayed at the end of the LOG file:

2017-04-26 17:19:49,915 DEBUG Found non-log stop sync bytes
2017-04-26 17:19:49,915 DEBUG Found non-log stop sync bytes
2017-04-26 17:19:49,915 DEBUG Found non-log stop sync bytes
2017-04-26 17:20:06,166 INFO Uploading data

[jmason86]

That issue is understood and is a glitch on the server side. Somebody accidentally deleted our whole dropbox folder this morning and I'm in the process of restoring it. So the directory that the app is attempting to upload to doesn't exist at the moment. It may take a day or two to get things patched up, so I've just redirected uploads to a new directory for now in 7f2feb6. Lemme know if that works!

[K4KDR]

Using commit 7f2feb6, the app properly processed approx. 60 seconds of high-volume packets from a recording made on 21-Apr-2017.

When the playback ended, the "Complete Pass" button was clicked. The "Upload status:" line changed to "Complete". Congratulations!

Reflecting the same status after the "Complete Pass" action, the log file ended as follows (below lines are actually after app was closed):

2017-04-26 19:29:20,519 DEBUG Found non-log stop sync bytes
2017-04-26 19:29:20,519 DEBUG Found non-log stop sync bytes
2017-04-26 19:29:32,074 INFO Uploading data
2017-04-26 19:29:33,430 INFO Upload complete
2017-04-26 19:30:40,018 INFO Attempting to disconnect from port
2017-04-26 19:30:40,019 INFO Closing ground station link
2017-04-26 19:30:42,583 INFO About to quit
2017-04-26 19:30:42,584 INFO Uploading data
2017-04-26 19:30:43,938 INFO Upload complete
2017-04-26 19:30:43,939 INFO Closing MinXSS Beacon Decoder

** please note that the "Uploading data" / "Upload complete" lines appear to echo to the log file each time the application is closed, regardless of whether an upload is requested or not.

The remaining issue apparent to my amateur eyes are an apparent crash when the application is closed. The application's terminal window displayed similar lines previously submitted, which start with:

k4kdr@:~/MinXSS_Beacon_Decoder$ python minxss_beacon_decoder.py 
/usr/lib/python2.7/dist-packages/Crypto/Cipher/blockalgo.py:141: FutureWarning: CTR mode needs counter parameter, not IV
  self._cipher = factory.new(key, *args, **kwargs)
QThread: Destroyed while thread is still running
*** Error in `python': free(): invalid pointer: 0x00007fe25b559880 ***
======= Backtrace: =========
/lib/x86_64-linux-gnu/libc.so.6(+0x777e5)[0x7fe25f2887e5]
/lib/x86_64-linux-gnu/libc.so.6(+0x7fe0a)[0x7fe25f290e0a]
/lib/x86_64-linux-gnu/libc.so.6(cfree+0x4c)[0x7fe25f29498c]

... and end with:

7fe23d74b000-7fe23d74d000 r--p 00016000 08:02 274268                     /usr/lib/x86_64-linux-gnu/libbonobo-activation.so.4.0.0
7fe23d74d000-7fe23d74f000 rw-p 00018000 08:02 274268                     /usr/lib/x86_64-linux-gnu/libbonobo-activation.so.4.0.0
7fe23d74f000-7fe23d7af000 r-xp 00000000 08:02 274267                     /usr/lib/x86_64-linux-gnu/libbonobo-2.so.0.0.0
7fe23d7af000-7fe23d9af000 ---p 00060000 08:02 274267                     /usr/lib/x86_64-linux-gnu/libbonobo-2.so.0.0.0Aborted

[jmason86]

"** please note that the "Uploading data" / "Upload complete" lines appear to echo to the log file each time the application is closed, regardless of whether an upload is requested or not."

This is intentional. I want to absolutely make sure I get those data. It won't create duplicates on the server, it'll just replace. Note though that it will not do this on exit if you have the forward data toggle disabled.

Those other errors are basically just warnings. I don't clean up the thread that is running the infinite port read loop on exit like I should. The OS and such make sure that all gets cleared out but complains about it. It's trying to free up resources but they already have been. (I think anyway). I've moved this to my task list but I'm considering it low priority since its all still functional, just whiny. I'll get to it when there's nothing left to do.

Are you able to run for a longer period of time now too?

[K4KDR]

Using commit 5189c6a, I ran what would essentially be a "normal" pass from my 21-Apr-2017 recording... that is, over 2 minutes of packets. All packets that were decoded in direwolf appeared to display on the GUI and echo into the log file. When the "pass" was finished, I clicked the "Complete Pass" button and the status changed to "Complete".

Thank you for the information regarding the terminal window feedback on program exit. A percentage of contributors using the app will be non-programmers such as myself, so that kind of direction from you is much appreciated.

Just outstanding work! Congrats.

[jmason86]

Woo hoo! So glad to see it working. Your feedback has made this so much easier for me and valuable to the community. I can't believe how responsive you are! Closing this issue.