Fix #2786, include fragment in syslog dump

[jphickey]

Checklist (Please check before submitting)

• I reviewed the Contributing Guide.
• I signed and emailed the appropriate Contributor License Agreement to GSFC-SoftwareRelease@mail.nasa.gov and copied cfs-program@lists.nasa.gov.

Describe the contribution
Do not skip the initial fragment when dumping syslog. Write it to the log with a tag indicating it is a fragment.

Also increases the default log size to 8k, so that all messages in a normal boot can be stored.

Fixes #2786

Testing performed
Issue sys log write command, confirm behavior

Expected behavior changes
Initial fragment (after wrap) is written to the file, along with a fixed-length tag indicating that it is a fragment.

System(s) tested on
Linux

Contributor Info - All information REQUIRED for consideration of pull request
Joseph Hickey, Vantage Systems, Inc.

[ddstewar]

Proven via retest that the 13 bytes added in are consistent with the expected result. The contents and size of files are now fully predictable.

Only anomaly I had was when I set the mode the OVERWRITE, cleared the SYS log, sent 110 start_application commands for the sample_app, which was already running, to have 74 bytes entered into the log each command. After 110, the next one would cause an overwrite.

When sending the last command to overwrite the log (same as all the other commands, so this behavior is expected), the resultant file marked a full entry as a fragment. This is not unexpected, just interesting. Attached are the log files from that test:

test_b4roll.txt
test_afterroll.txt

I do not believe this would warrant further change, but it is left to the developer to determine if this is the behavior they intended or not.

As-is, I am approving this.

[ddstewar]

Proven via retest that the 13 bytes added in are consistent with the expected result. The contents and size of files are now fully predictable.

Only anomaly I had was when I set the mode the OVERWRITE, cleared the SYS log, sent 110 start_application commands for the sample_app, which was already running, to have 74 bytes entered into the log each command. After 110, the next one would cause an overwrite.

When sending the last command to overwrite the log (same as all the other commands, so this behavior is expected), the resultant file marked a full entry as a fragment. This is not unexpected, just interesting. Attached are the log files from that test:

test_b4roll.txt test_afterroll.txt

I do not believe this would warrant further change, but it is left to the developer to determine if this is the behavior they intended or not.

As-is, I am approving this.

After continuing this line of testing, I followed up sending 130 start_app commands to start CS, which was already running. After rolling the file over again the bytes used reached max and the fragment in the file was a true fragment, but the behavior was the same and the file size was as predictable as the previous test. So I am fully confident in the behavior to be repeatable here.

[jphickey]

When sending the last command to overwrite the log (same as all the other commands, so this behavior is expected), the resultant file marked a full entry as a fragment. This is not unexpected, just interesting. Attached are the log files from that test:

Yeah, this is expected behavior. The reality is that the marker is really just indicating that the log has overwritten data, there is no reliable way to tell if the line/message is complete or not, because we don't know what was in it.

Perhaps there is a better word than FRAGMENT here .... maybe just "clipped" or something. I don't know. The goal of this is to convey to the user that the first line they are looking at MAY be incomplete, and also that there were lines before it which are not being shown at all because they are simply lost due to overwrite.

[jphickey]

To clarify this is just a chance operation -- i.e. that writing a new log message in overwrite mode happened to end at exactly the same character position as the start of an old message. The vast majority of times this does not happen and will result in the beginning of the old message being lost .... but every now and then things will line up perfectly and mean that oldest message still happens to be complete. But the FSW can't tell the difference.

[ddstewar]

To clarify this is just a chance operation -- i.e. that writing a new log message in overwrite mode happened to end at exactly the same character position as the start of an old message. The vast majority of times this does not happen and will result in the beginning of the old message being lost .... but every now and then things will line up perfectly and mean that oldest message still happens to be complete. But the FSW can't tell the difference.

Yes I agree, The way the test is structured forces this overwrite of the exact same size. Like I said I found this to be expected once I thought about it. no issues here. As you said most of the time in almost all situations the messages will not line up so nicely and it will be a partial message. I think "FRAGMENT" is fine for this, not need to change it.

[ddstewar]

It appears that it is possible that the FRAGMENT string gets written in rare cases when in DISCARD Mode.

If the log previously wrapped in OVERWRITE mode causing the FRAGMENT string to be written, then the mode is switched to DISCARD but the log is not cleared.

Is this expected or an anomaly? I can go either way.

[ddstewar]

Just some more info on the state of how that occurred:

tlm points at the start of the test:
SYS_LOG_BYTES_USED : 8140
SYS_LOG_SIZE : 8192
SYS_LOG_ENTRIES : 162
SYS_LOG_MODE : 1 (DISCARD)

command sent to write sys log
Event:
CFS-1 1970/01/12 14:54:02.001 scid:66 procid:1 DEBUG CFE_ES 18: /cf/test_syslog.txt written:Size=8217,Entries=162

When calculating from the reported tlm size, in DISCARD mode, no FRAGMENT 13 bytes were expected, so the test here fails:

<!> Failed to verify system Log HK tlm:
SYS_LOG_SIZE verified: True
hk_sys_log_size=8192 should == CFE_PLATFORM_ES_SYSTEM_LOG_SIZE=8192
SYS_LOG_ENTRIES verified: True
hk_sys_log_entries=162 should == em_sys_log_entries=162
SYS_LOG_BYTES_USED verified: False
hk_sys_log_bytes_used=8140 + header_size=64 = 8204 should == em_sys_log_file_size=8217

[ddstewar]

Log file generated from the DISCARD mode write sys log command:
test_syslog.txt

[jphickey]

It appears that it is possible that the FRAGMENT string gets written in rare cases when in DISCARD Mode.

If the log previously wrapped in OVERWRITE mode causing the FRAGMENT string to be written, then the mode is switched to DISCARD but the log is not cleared.

Is this expected or an anomaly? I can go either way.

Yes --- when you switch from OVERWRITE into DISCARD mode, the log not cleared ... so if it had already wrapped (and thus had overwritten entries) you will still get the fragment.