Log files only logging 1 instance of telemetry packet type

[apogeecmb]

I'm having an issue with the contents of telemetry log files. I currently have two periodic telemetry packets being output by my target. Both packets are correctly being received by COSMOS and displayed in the packet viewer in COSMOS. However when I parse the raw binary telemetry log files, there is only one instance of one of the packet types but multiple (i assume all) instances of the other packet type.

I tried a couple telemetry definition changes to see if I could determine what the cause was or affect the behavior. My packet types have a single ID_ITEM UINT field. The packet that has only one instance is the packet with the smaller ID_ITEM value. As a test, I intentionally swapped the ID_ITEM values for the two packets. That caused the log file to flip which packet had just one instance. So I can change the behavior of the bug, but I'm not sure the cause.

My original telemetry definition file is shown below for reference. Originally I was seeing one instance of the MGR_STATUS packet and multiple of the CFDP_SERVER_TLM packet. And then when I switched the ID_ITEM values, I saw multiple MGR_STATUS packets but only one CFDP_SERVER_TLM packet.

Any clue as to what might be going on? Do I have some configuration error or is this a bug? Thanks for any help you can provide.

I'm running COSMOS version 5.1.1 on an Ubuntu 22.04 VM. Both my target and COSMOS are running within the VM.

TELEMETRY TARGET1 CFDP_SERVER_TLM LITTLE_ENDIAN "CFDP Server Telemetry"
  ITEM CCSDS_VER 0 3 UINT "CCSDS packet version number" BIG_ENDIAN
  ITEM CCSDS_TYPE 3 1 UINT "CCSDS packet type (command or telemetry)"
    STATE TLM 0
    STATE CMD 1
  ITEM CCSDS_SHF 4 1 UINT "CCSDS secondary header flag" BIG_ENDIAN
    STATE FALSE 0
    STATE TRUE 1
  ITEM CCSDS_REALTIME 5 1 UINT "Realtime or playback flag" BIG_ENDIAN
    STATE REALTIME 0
    STATE STORED 1
  ID_ITEM CCSDS_APID 6 10 UINT 304 "CCSDS APID" BIG_ENDIAN
  ITEM CCSDS_SEQFLAGS 16 2 UINT "CCSDS sequence flags" BIG_ENDIAN
    STATE FIRST 0
    STATE CONT 1
    STATE LAST 2
    STATE NOGROUP 3
  ITEM CCSDS_SEQCNT 18 14 UINT "CCSDS packet sequence count" BIG_ENDIAN
  ITEM CCSDS_LENGTH 32 16 UINT "CCSDS packet data length" BIG_ENDIAN
  ITEM CCSDS_SECS 48 32 UINT "Seconds since epoch (JANUARY 1, 1970, MIDNIGHT)"
  ITEM CCSDS_SUBSECS 80 8 UINT "Subseconds in hundreds of milliseconds (0: 0, 1: 100, etc)"
  ITEM CCSDS_RESERVED 88 8 UINT "Reserved byte"
  APPEND_ITEM NUM_PENDING_DL_TRANSACTIONS 8 uint "Number of Pending Downlink Transactions"
  APPEND_ITEM NUM_ACTIVE_DL_TRANSACTIONS 8 uint "Number of Active Downlink Transactions"
  APPEND_ITEM NUM_PENDING_UL_TRANSACTIONS 8 uint "Number of Pending Uplink Transactions"
  APPEND_ITEM NUM_ACTIVE_UL_TRANSACTIONS 8 uint "Number of Active Uplink Transactions"
  APPEND_ITEM CMD_ACCEPT_COUNT 8 uint "Number of Commands Accepted"
  APPEND_ITEM CMD_REJECT_COUNT 8 uint "Number of Commands Rejected"
  APPEND_ITEM LAST_CFDP_CMD_TYPE 8 uint "Command Type of Last CFDP Command Received"
    STATE INVALID 0
    STATE START 1
    STATE END 2
    STATE SUSPEND 3
    STATE STATUS 4
  APPEND_ITEM LAST_CMD_STATUS 8 uint "Command Status of Last CFDP Command Received"
    STATE NONE 0
    STATE ACCEPTED 1
    STATE INVALID_CMD 2
    STATE INVALID_OP_CODE 3
    STATE MAX_TRANSACTIONS_EXCEEDED 4
    STATE TRANS_ID_IN_USE 5
    STATE NO_TRANSACTION_FOUND 6
    STATE TRANS_CREATION_FAILED 7
    STATE INVALID_PDU 8

TELEMETRY TARGET1 MGR_STATUS LITTLE_ENDIAN "Manager Health and Status"
  ITEM CCSDS_VER 0 3 UINT "CCSDS packet version number" BIG_ENDIAN
  ITEM CCSDS_TYPE 3 1 UINT "CCSDS packet type (command or telemetry)"
    STATE TLM 0
    STATE CMD 1
  ITEM CCSDS_SHF 4 1 UINT "CCSDS secondary header flag" BIG_ENDIAN
    STATE FALSE 0
    STATE TRUE 1
  ITEM CCSDS_REALTIME 5 1 UINT "Realtime or playback flag" BIG_ENDIAN
    STATE REALTIME 0
    STATE STORED 1
  ID_ITEM CCSDS_APID 6 10 UINT 272 "CCSDS APID" BIG_ENDIAN
  ITEM CCSDS_SEQFLAGS 16 2 UINT "CCSDS sequence flags" BIG_ENDIAN
    STATE FIRST 0
    STATE CONT 1
    STATE LAST 2
    STATE NOGROUP 3
  ITEM CCSDS_SEQCNT 18 14 UINT "CCSDS packet sequence count" BIG_ENDIAN
  ITEM CCSDS_LENGTH 32 16 UINT "CCSDS packet data length" BIG_ENDIAN
  ITEM CCSDS_SECS 48 32 UINT "Seconds since epoch (JANUARY 1, 1970, MIDNIGHT)"
  ITEM CCSDS_SUBSECS 80 8 UINT "Subseconds in hundreds of milliseconds (0: 0, 1: 100, etc)"
  ITEM CCSDS_RESERVED 88 8 UINT "Reserved byte"
  APPEND_ITEM TLM_COLLECTOR_CMD_ACCEPT_COUNT 8 uint "Number of Commands Accepted"
  APPEND_ITEM TLM_COLLECTOR_CMD_REJECT_COUNT 8 uint "Number of Commands Rejected"
  APPEND_ITEM TLM_COLLECTOR_LAST_CMD_TYPE 8 uint "Command Type of Last Command Received"
    STATE INVALID 0
    STATE DOWNLINK 1
    STATE DOWNLINK_END 2
  APPEND_ITEM TLM_COLLECTOR_LAST_CMD_STATUS 8 uint "Command Status of Last Command Received"
    STATE NONE 0
    STATE ACCEPTED 1
    STATE INVALID_CMD 2
    STATE INVALID_OP_CODE 3

[ryanmelt]

I've never seen this CCSDS header field before:

 ITEM CCSDS_REALTIME 5 1 UINT "Realtime or playback flag" BIG_ENDIAN
    STATE REALTIME 0
    STATE STORED 1

Do you have other packets that have the standard 11-bit APID?

If so you might need to use the UNIQUE_ID_MODE flags in your target.txt file: https://openc3.com/docs/v5/target#tlm_unique_id_mode

Are any of your packets actually marked "STORED"? We logged stored and realtime packets into different files.

How are you reading back the packets?

Otherwise, it might be a bug, but I haven't seen this yet, and everything in our demo appears to be logging correctly.

[apogeecmb]

Ryan,

We're using the standard 11-bit APID field but repurposing the 11th bit to indicate whether the telemetry is stored or realtime. It's a carryover implementation from a spacecraft vendor we've used in the past. All packets are using the same ID, so I wouldn't expect the UNIQUE_ID_MODE flag to be required.

For this test, there are only realtime packets. I am parsing the log file using a custom python script. I'm pretty confident my parser is working correctly. And when I look at the raw log file just in a text editor, I can clearly see the MGR_STATUS packet identifier followed by one raw packet and then the CFDP_SERVER_TLM identifier followed by all the rest of the packets.

[ryanmelt]

The log file format changed quite a bit in the 5.1 release to support reducing file sizes....

Try this ruby script (or something like it) that will read a log with our code and see what it sees:

read_test.rb

# Fix these paths to your file system
ENV['RUBYLIB'] = '/Users/ryanmelt/git/openc3/cosmos/openc3/lib'
ENV['OPENC3_DEVEL'] = '/Users/ryanmelt/git/openc3/cosmos/openc3'

require 'openc3'
require 'openc3/logs/packet_log_reader'

plr = OpenC3::PacketLogReader.new
plr.each(ARGV[0]) do |packet|
  puts "#{packet.read('RECEIVED_TIMEFORMATTED')} #{packet.target_name} #{packet.packet_name}"
end

Usage: ruby read_test.rb <filename> Filename should not be gziped.

[apogeecmb]

I just created the parser this morning using the current documentation on openc3.com, so I'm pretty confident it is parsing correctly. I tried your code snippet, but ruby is having issues finding the openc3 module.

Here's the first part of an example log file for reference to show what I'm seeing. The actual target name is actually MIDNIGHT.

b'COSMOS5_\x00\x00\x00\n\x10\x00MIDNIGHT\x00\x00\x00\x0e \x00\x00\x00MGR_STATUS\x00\x00\x00\x1c0\x00\x00\x00\x17-\x03WP\x8f\xba\xad\t\x10\xc0\x00\x00\t\xd6\x18\x8ac\x03\x00\x00\x00\x00\x00\x00\x00\x00\x13 \x00\x00\x00CFDP_SERVER_TLM\x00\x00\x00 0'

[apogeecmb]

Actually here's the whole log.

tlm_test3.zip

[ryanmelt]

Confirmed file is good. Has alternating packets throughout. Also confirmed our log file format documentation is out of date, but I don't think that is your problem either because this is a raw log file, and it was the decom files that changed.

2022-12-02 08:25:10 -0700 MIDNIGHT MGR_STATUS
2022-12-02 08:25:10 -0700 MIDNIGHT CFDP_SERVER_TLM
2022-12-02 08:25:11 -0700 MIDNIGHT MGR_STATUS
2022-12-02 08:25:11 -0700 MIDNIGHT CFDP_SERVER_TLM
2022-12-02 08:25:12 -0700 MIDNIGHT MGR_STATUS
2022-12-02 08:25:12 -0700 MIDNIGHT CFDP_SERVER_TLM
2022-12-02 08:25:13 -0700 MIDNIGHT MGR_STATUS
2022-12-02 08:25:13 -0700 MIDNIGHT CFDP_SERVER_TLM
2022-12-02 08:25:14 -0700 MIDNIGHT MGR_STATUS
2022-12-02 08:25:14 -0700 MIDNIGHT CFDP_SERVER_TLM
2022-12-02 08:25:15 -0700 MIDNIGHT MGR_STATUS
2022-12-02 08:25:15 -0700 MIDNIGHT CFDP_SERVER_TLM
2022-12-02 08:25:16 -0700 MIDNIGHT MGR_STATUS
2022-12-02 08:25:16 -0700 MIDNIGHT CFDP_SERVER_TLM
etc.

[ryanmelt]

Here is an updated script with our code that works:

require 'openc3'
require 'openc3/logs/packet_log_reader'

plr = OpenC3::PacketLogReader.new
plr.each(ARGV[0], false) do |packet|
  puts "#{packet.received_time} #{packet.target_name} #{packet.packet_name}\n#{packet.buffer.formatted}\n"
end

Usage: RUBYLIB=/Users/ryanmelt/git/openc3/cosmos/openc3/lib OPENC3_DEVEL=/Users/ryanmelt/git/openc3/cosmos/openc3 ruby read_test.rb tlm_test3.bin

You might have to rake build in your cosmos/openc3 folder before it will work.

[apogeecmb]

Apologize for wasting your time! Guess I haven't totally wrapped my mind correctly around how to parse this logging convention. Thanks for confirming the data looks accurate though.