Switch to U64 Logger Tests by Willmac16 · Pull Request #4262 · nasa/fprime

Willmac16 · 2025-10-03T23:25:36Z


*Related Issue(s)*
*Has Unit Tests (y/n)*	y
*Documentation Included (y/n)*	N/A
*Generative AI was used in this contribution (y/n)*	n

Change Description

add pip to the requirements.txt (fprime depends on the python pip module, which causes issues when installed requirements using another python package manager e.g. uv)
add *.swp to gitignore to prevent vim swapfiles from marking the repo as dirty
Switch the LoggerTests to U64 %llu since unsinged longs are 64 bits wide on aarch64 linux and variadic args break w/ the old code @ 7 args

Rationale

I would like the unit tests to pass on my aarch64 linux machine, and I believe that U64 + llu should behave correctly on all systems.

Testing/Review Recommendations

If a locked version of pip is required I am happy to modify the requirements.txt line

It would be good to get to the bottom of the behavior I saw with the old unit test; however, I suspect it is a case of the non-type safety of va_list + slightly different register layouts/contents between the two calls to vformat.

An integer width safe logger would be a nice feature, but seems unlikely to achieve through va_list.

Willmac16 · 2025-10-03T23:37:52Z

For reference, the issue I saw can legibly reproduced w/ the following slightly modified version of LogGood:

/**
 * Test for 64 bit logging
 */
TEST(LoggerTests, SixtyFourTest) {
    // Basic discard logging
    MockLogging::FakeLogger truth;
    Fw::Logger::registerLogger(&truth);
    truth.s_current = nullptr;

    printf("sizeof(unsigned long long) = %lu;\n", sizeof(unsigned long long));
    printf("sizeof(unsigned long) = %lu;\n", sizeof(unsigned long));
    printf("sizeof(U32) = %lu;\n", sizeof(U32));

    U32 ra[10];
    for (int i = 0; i < 10; ++i) {
        ra[i] = STest::Pick::lowerUpper(0, 0xffffffff);
    }
    Fw::String correct;

    Fw::Logger::log("No args");
    correct = "No args";
    truth.check(correct.toChar());
    truth.reset();

    Fw::Logger::log("One arg: %lu", ra[0]);
    correct.format("One arg: %lu", ra[0]);
    truth.check(correct.toChar());
    truth.reset();

    Fw::Logger::log("Two arg: %lu  %lu", ra[0], ra[1]);
    correct.format("Two arg: %lu  %lu", ra[0], ra[1]);
    truth.check(correct.toChar());
    truth.reset();

    Fw::Logger::log("Three arg: %lu  %lu  %lu", ra[0], ra[1], ra[2]);
    correct.format("Three arg: %lu  %lu  %lu", ra[0], ra[1], ra[2]);
    truth.check(correct.toChar());
    truth.reset();

    Fw::Logger::log("Four arg: %lu  %lu  %lu  %lu", ra[0], ra[1], ra[2], ra[3]);
    correct.format("Four arg: %lu  %lu  %lu  %lu", ra[0], ra[1], ra[2], ra[3]);
    truth.check(correct.toChar());
    truth.reset();

    Fw::Logger::log("Five arg: %lu  %lu  %lu  %lu  %lu", ra[0], ra[1], ra[2], ra[3], ra[4]);
    correct.format("Five arg: %lu  %lu  %lu  %lu  %lu", ra[0], ra[1], ra[2], ra[3], ra[4]);
    truth.check(correct.toChar());
    truth.reset();
    
    Fw::Logger::log("Six arg: %lu  %lu  %lu  %lu  %lu  %lu", ra[0], ra[1], ra[2], ra[3], ra[4], ra[5]);
    correct.format("Six arg: %lu  %lu  %lu  %lu  %lu  %lu", ra[0], ra[1], ra[2], ra[3], ra[4], ra[5]);
    truth.check(correct.toChar());
    truth.reset();
    
    Fw::Logger::log("Seven arg: %lu  %lu  %lu  %lu  %lu  %lu  %lu", ra[0], ra[1], ra[2], ra[3], ra[4], ra[5],
                    ra[6]);
    correct.format("Seven arg: %lu  %lu  %lu  %lu  %lu  %lu  %lu", ra[0], ra[1], ra[2], ra[3], ra[4], ra[5],
                    ra[6]);
    truth.check(correct.toChar());
    truth.reset();
    
    Fw::Logger::log("Eight arg: %lu  %lu  %lu  %lu  %lu  %lu  %lu  %lu", ra[0], ra[1], ra[2], ra[3], ra[4],
                    ra[5], ra[6], ra[7]);
    correct.format("Eight arg: %lu  %lu  %lu  %lu  %lu  %lu  %lu  %lu", ra[0], ra[1], ra[2], ra[3], ra[4],
                    ra[5], ra[6], ra[7]);
    truth.check(correct.toChar());
    truth.reset();
    
    Fw::Logger::log("Nine arg: %lu  %lu  %lu  %lu  %lu  %lu  %lu  %lu  %lu", ra[0], ra[1], ra[2], ra[3], ra[4],
                    ra[5], ra[6], ra[7], ra[8]);
    correct.format("Nine arg: %lu  %lu  %lu  %lu  %lu  %lu  %lu  %lu  %lu", ra[0], ra[1], ra[2], ra[3], ra[4],
                    ra[5], ra[6], ra[7], ra[8]);
    truth.check(correct.toChar());
    truth.reset();

    Fw::Logger::log("Ten arg: %lu  %lu  %lu  %lu  %lu  %lu  %lu  %lu  %lu  %lu", ra[0], ra[1], ra[2], ra[3],
                    ra[4], ra[5], ra[6], ra[7], ra[8], ra[9]);
    correct.format("Ten arg: %lu  %lu  %lu  %lu  %lu  %lu  %lu  %lu  %lu  %lu", ra[0], ra[1], ra[2], ra[3],
                    ra[4], ra[5], ra[6], ra[7], ra[8], ra[9]);
    truth.check(correct.toChar());
    truth.reset();
}

Which produces the same disagreement in the printouts for arguments 7 & 8 (different switchover points of variadic args to the stack?)

[ RUN      ] LoggerTests.SixtyFourTest
sizeof(unsigned long long) = 8;
sizeof(unsigned long) = 8;
sizeof(U32) = 4;
/home/wmac/fprime/Fw/Logger/test/ut/FakeLogger.cpp:22: Failure
Expected equality of these values:
  m_last
    Which is: "Seven arg: 66415486  2395077953  2686479289  2919437883  803690036  4158329107  1451939808"
  std::string(message)
    Which is: "Seven arg: 66415486  2395077953  2686479289  2919437883  803690036  4158329107  281472133683168"
/home/wmac/fprime/Fw/Logger/test/ut/FakeLogger.cpp:22: Failure
Expected equality of these values:
  m_last
    Which is: "Eight arg: 66415486  2395077953  2686479289  2919437883  803690036  4158329107  1451939808  281471151300818"
  std::string(message)
    Which is: "Eight arg: 66415486  2395077953  2686479289  2919437883  803690036  4158329107  281472133683168  469557458"
/home/wmac/fprime/Fw/Logger/test/ut/FakeLogger.cpp:22: Failure
Expected equality of these values:
  m_last
    Which is: "Nine arg: 66415486  2395077953  2686479289  2919437883  803690036  4158329107  1451939808  281471151300818  1383106162"
  std::string(message)
    Which is: "Nine arg: 66415486  2395077953  2686479289  2919437883  803690036  4158329107  281472133683168  469557458  1383106162"
/home/wmac/fprime/Fw/Logger/test/ut/FakeLogger.cpp:22: Failure
Expected equality of these values:
  m_last
    Which is: "Ten arg: 66415486  2395077953  2686479289  2919437883  803690036  4158329107  1451939808  281471151300818  1383106162  2286821165"
  std::string(message)
    Which is: "Ten arg: 66415486  2395077953  2686479289  2919437883  803690036  4158329107  281472133683168  469557458  1383106162  2286821165"
[  FAILED  ] LoggerTests.SixtyFourTest (2 ms)

Simply switching the random array to U64 ra[10]; is enough for the unit test to pass on my system, but I suspect this might break the test on 32 bit wide unsigned long systems.

bocchino · 2025-10-04T00:07:11Z

Fw/Logger/test/ut/LoggerRules.cpp

        case 1:
-            Fw::Logger::log("One arg: %lu", ra[0]);
-            correct.format("One arg: %lu", ra[0]);
+            Fw::Logger::log("One arg: %llu", ra[0]);


Good catch! Here is a suggestion:

Suggested change

Fw::Logger::log("One arg: %llu", ra[0]);

Fw::Logger::log("One arg: %" PRI_U64 ", ra[0]);

The C format specifiers %u, %lu, and %llu mean unsigned, unsigned long, and unsigned long long. They should bind only to those exact C/C++ types and not to any other types such as U64, which in general have different representations on different platforms. For those other types, we should use the PRI macros, which are provided by the compiler and are correct for each platform. The original code also looks incorrect to me (it may be a holdover from before we had the PRI macros).

Willmac16 · 2025-10-04T00:36:34Z

Fw/Logger/test/ut/LoggerRules.cpp

        case 0:
            Fw::Logger::log("No args");
            break;
        case 1:
-            Fw::Logger::log("One arg: %lu", ra[0]);
+            Fw::Logger::log("One arg: %llu", ra[0]);
            break;
        case 2:
-            Fw::Logger::log("Two arg: %lu", ra[0], ra[1]);
+            Fw::Logger::log("Two arg: %llu", ra[0], ra[1]);
            break;
        case 3:
-            Fw::Logger::log("Three arg: %lu", ra[0], ra[1], ra[2]);
+            Fw::Logger::log("Three arg: %llu", ra[0], ra[1], ra[2]);
            break;
        case 4:
-            Fw::Logger::log("Four arg: %lu", ra[0], ra[1], ra[2], ra[3]);
+            Fw::Logger::log("Four arg: %llu", ra[0], ra[1], ra[2], ra[3]);
            break;
        case 5:
-            Fw::Logger::log("Five arg: %lu", ra[0], ra[1], ra[2], ra[3], ra[4]);
+            Fw::Logger::log("Five arg: %llu", ra[0], ra[1], ra[2], ra[3], ra[4]);
            break;
        case 6:
-            Fw::Logger::log("Six arg: %lu", ra[0], ra[1], ra[2], ra[3], ra[4], ra[5]);
+            Fw::Logger::log("Six arg: %llu", ra[0], ra[1], ra[2], ra[3], ra[4], ra[5]);
            break;
        case 7:
-            Fw::Logger::log("Seven arg: %lu", ra[0], ra[1], ra[2], ra[3], ra[4], ra[5], ra[6]);
+            Fw::Logger::log("Seven arg: %llu", ra[0], ra[1], ra[2], ra[3], ra[4], ra[5], ra[6]);
            break;
        case 8:
-            Fw::Logger::log("Eight arg: %lu", ra[0], ra[1], ra[2], ra[3], ra[4], ra[5], ra[6], ra[7]);
+            Fw::Logger::log("Eight arg: %llu", ra[0], ra[1], ra[2], ra[3], ra[4], ra[5], ra[6], ra[7]);
            break;
        case 9:
-            Fw::Logger::log("Nine arg: %lu", ra[0], ra[1], ra[2], ra[3], ra[4], ra[5], ra[6], ra[7], ra[8]);
+            Fw::Logger::log("Nine arg: %llu", ra[0], ra[1], ra[2], ra[3], ra[4], ra[5], ra[6], ra[7], ra[8]);
            break;
        case 10:
-            Fw::Logger::log("Ten arg: %lu", ra[0], ra[1], ra[2], ra[3], ra[4], ra[5], ra[6], ra[7], ra[8], ra[9]);
+            Fw::Logger::log("Ten arg: %llu", ra[0], ra[1], ra[2], ra[3], ra[4], ra[5], ra[6], ra[7], ra[8], ra[9]);


Is the intention that these all only have one arg specified in the format string?

This looks like a bug in the original code. If there are n arguments, there should be n format specifiers. @LeStarch can you comment on this?

I went ahead and corrected these to have a matching number of specifiers

bocchino · 2025-10-04T03:14:33Z

Fw/Logger/test/ut/LoggerRules.cpp

        case 1:
-            Fw::Logger::log("One arg: %llu", ra[0]);
-            correct.format("One arg: %llu", ra[0]);
+            Fw::Logger::log("One arg: " PRI_U64, ra[0]);


You need the percent sign before the closing quotation mark: "One arg: %" PRI_U64. ThePRI_U64 gets expanded to "lu" or "llu" as appropriate for the platform.

Willmac16 · 2025-10-06T17:57:46Z

Can we change the threshold on this guy:

[ RUN      ] Functionality.RandomizedTesting
/home/runner/work/fprime/fprime/Os/test/ut/rawtime/RulesHeaders.hpp:77: Failure
Value of: result < Fw::TimeInterval(0, INTERVAL_DIFF_THRESHOLD)
  Actual: false
Expected: true
Interval difference: (0s,38583us)
/home/runner/work/fprime/fprime/Os/test/ut/rawtime/RulesHeaders.hpp:87: Failure
Value of: result_diff < INTERVAL_DIFF_THRESHOLD
  Actual: false
Expected: true
Difference between results: 38583 microseconds
Ran 5000 steps for RawTime.
[  FAILED  ] Functionality.RandomizedTesting (603 ms)
[----------] 7 tests from Functionality (633 ms total)

[----------] Global test environment tear-down
[==========] 7 tests from 1 test suite ran. (635 ms total)
[  PASSED  ] 6 tests.
[  FAILED  ] 1 test, listed below:
[  FAILED  ] Functionality.RandomizedTesting

I believe I've seen this fail about 1/4 the time on some of my machines

LeStarch · 2025-10-06T18:25:32Z

@Willmac16 yes, I believe @thomas-bc is working on it.

Use U64 for LoggerTests

61e16ff

bocchino reviewed Oct 4, 2025

View reviewed changes

Willmac16 commented Oct 4, 2025

View reviewed changes

Switch %llu to PRI_U64

7b69d65

bocchino reviewed Oct 4, 2025

View reviewed changes

Add back the % before PRI_U64

4f74908

LeStarch previously approved these changes Oct 6, 2025

View reviewed changes

clang-format LoggerRules.cpp

a4026f8

Willmac16 dismissed LeStarch’s stale review via a4026f8 October 6, 2025 17:54

LeStarch approved these changes Oct 6, 2025

View reviewed changes

LeStarch merged commit 589ed5d into nasa:devel Oct 6, 2025
75 checks passed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Switch to U64 Logger Tests#4262

Switch to U64 Logger Tests#4262
LeStarch merged 4 commits intonasa:develfrom
Willmac16:u64-logger-tests

Willmac16 commented Oct 3, 2025

Uh oh!

Willmac16 commented Oct 3, 2025

Uh oh!

bocchino Oct 4, 2025 •

edited

Loading

Uh oh!

Willmac16 Oct 4, 2025

Uh oh!

bocchino Oct 4, 2025

Uh oh!

Willmac16 Oct 4, 2025

Uh oh!

bocchino Oct 4, 2025 •

edited

Loading

Uh oh!

Willmac16 Oct 4, 2025

Uh oh!

Willmac16 commented Oct 6, 2025

Uh oh!

LeStarch commented Oct 6, 2025

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

	Fw::Logger::log("One arg: %llu", ra[0]);
	Fw::Logger::log("One arg: %" PRI_U64 ", ra[0]);

Conversation

Willmac16 commented Oct 3, 2025

Change Description

Rationale

Testing/Review Recommendations

Uh oh!

Willmac16 commented Oct 3, 2025

Uh oh!

bocchino Oct 4, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Willmac16 Oct 4, 2025

Choose a reason for hiding this comment

Uh oh!

bocchino Oct 4, 2025

Choose a reason for hiding this comment

Uh oh!

Willmac16 Oct 4, 2025

Choose a reason for hiding this comment

Uh oh!

bocchino Oct 4, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Willmac16 Oct 4, 2025

Choose a reason for hiding this comment

Uh oh!

Willmac16 commented Oct 6, 2025

Uh oh!

LeStarch commented Oct 6, 2025

Uh oh!

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

bocchino Oct 4, 2025 •

edited

Loading

bocchino Oct 4, 2025 •

edited

Loading