Timestamped logging macro for elapsed physical time #546

adi-65-ray · 2025-09-21T01:56:47Z

This PR is a fix for #395.

I have implemented a macro which prepends the physical lapsed time to debug messages
LF_TIMESTAMP_PRINT_DEBUG in logging_macros.h
I have also included a test code to test the functionality of the macro to check its expected output.
Example output:
DEBUG: [12345678]Hello World

hokeun

This is a great start. Thanks! I left some suggestions.

logging/api/logging_macros.h

test/general/logging_test.c

hokeun · 2025-09-22T17:58:15Z

Just to provide the context @adi-65-ray (Aditya Ray) is an M.S. student at ASU, and he kindly volunteered to fix this issue. This PR will be his very first contribution.

edwardalee

This is a nice feature to have, but there remain some subtleties. If we can resolve these, it might be nice to have this be part of the LF_PRINT_DEBUB macro rather than being a whole new macro.

logging/api/logging_macros.h

edwardalee

LGTM!
(Modulo getting the tests to pass)

hokeun

👍

test/general/logging_test.c

hokeun

Awesome!

edwardalee · 2025-10-31T07:38:10Z

.github/workflows/ci.yml

Do we really want to set LOG_LEVEL globally for all tests? What are the consequences of this? Can it be set within your one test that needs it?

I tried redefining LOG_LEVEL locally in the test file but it gave waring for redeclaration and -Werror is set so it gets stuck.

I looked into this and I came up with two solutions:

I can create a separate test command which uses the global debug flag. so it would be unit-tests and unit-tests-debug with the LOG_LEVEL =4.

I create a separate executable of reactor-c with LOG_LEVEL=4, link that to my test file and run the test within unit-tests.
I wanted to take the 2nd option but the CMakeLists.txt file of core has lot of conditional dependencies and I don't know should include all or is it fine if I link only a few of them.

@adi-65-ray It will be great if you can use LOG_LEVEL=4 only for the unit tests involving debug-level logging.

Why isn't sufficient to just set logging: DEBUG as a target parameter in the relevant tests?

Hello Prof. Lee, @edwardalee

I think maybe you are confused.
This PR is adding a unit test, which is just run as make unit-tests right in reactor-c/.
There is no .lf file, so there are no target properties (e.g., logging: DEBUG). So adding this flag does not affect most tests, such as the long tests like lf-default.

The CI for this part, which is the unit-tests-single such as here, only takes 9 to 15 seconds to finish, so I don't think adding this will increase the CI test's time.

If we still really want to separate this Aditya suggested two ways.

Create another unit-test in the Makefile.

unit-tests: clean # In case NUMBER_OF_WORKERS has been set, unset it. cmake -B build -UNUMBER_OF_WORKERS cmake --build build cd build && make test ## CREATE THIS PART unit-tests-debug: clean # In case NUMBER_OF_WORKERS has been set, unset it. cmake -B build -UNUMBER_OF_WORKERS -DLOG_LEVEL=4 cmake --build build cd build && make test

However, I say this is not the right way to do, and complicate things more.

Override the log level in the test/general/logging_test.c
We can override the log level using #define LOG_LEVEL 4, but it shows a warning, and warnings are set as errors due to -Werror flag.

Do you still suggest fixing this problem? I say this is too trivial, and fixing this will complicate the CMake.

I’m open to your guidance if you think this should still be addressed or if there is a cleaner solution I may have missed.

We just talked with @Hokuen and he suggested us to create separate binaries on the test such as I mentioned as method 1.
@adi-65-ray will work on it.

I see. But why does this need to be a unit test rather than a regular LF test? It seems the same trick of redirecting stdout could work in a startup reaction and the check could be performed in a shutdown reaction.

I also think that makes sense. Would you like to create a LF test @adi-65-ray?

edwardalee · 2025-10-31T07:39:31Z

This PR is a fix for #395.

I have implemented a macro which prepends the physical lapsed time to debug messages LF_TIMESTAMP_PRINT_DEBUG in logging_macros.h I have also included a test code to test the functionality of the macro to check its expected output.

expected output: DEBUG: Start time: -9223372036854775808 DEBUG: [-7464962496372149757] [Test case: 0]testing timed debug prints DEBUG: [-7464962491372064629] [Test case: 1]testing timed debug prints DEBUG: [-7464962486371771465] [Test case: 2]testing timed debug prints DEBUG: [-7464962481371438023] [Test case: 3]testing timed debug prints DEBUG: [-7464962476371116940] [Test case: 4]testing timed debug prints DEBUG: [-7464962471370813344] [Test case: 5]testing timed debug prints DEBUG: [-7464962466370645568] [Test case: 6]testing timed debug prints DEBUG: [-7464962461370410362] [Test case: 7]testing timed debug prints DEBUG: [-7464962456370065744] [Test case: 8]testing timed debug prints DEBUG: [-7464962451369754731] [Test case: 9]testing timed debug prints

Why are these numbers negative?

adi-65-ray · 2025-10-31T08:09:22Z

This PR is a fix for #395.
I have implemented a macro which prepends the physical lapsed time to debug messages LF_TIMESTAMP_PRINT_DEBUG in logging_macros.h I have also included a test code to test the functionality of the macro to check its expected output.
expected output: DEBUG: Start time: -9223372036854775808 DEBUG: [-7464962496372149757] [Test case: 0]testing timed debug prints DEBUG: [-7464962491372064629] [Test case: 1]testing timed debug prints DEBUG: [-7464962486371771465] [Test case: 2]testing timed debug prints DEBUG: [-7464962481371438023] [Test case: 3]testing timed debug prints DEBUG: [-7464962476371116940] [Test case: 4]testing timed debug prints DEBUG: [-7464962471370813344] [Test case: 5]testing timed debug prints DEBUG: [-7464962466370645568] [Test case: 6]testing timed debug prints DEBUG: [-7464962461370410362] [Test case: 7]testing timed debug prints DEBUG: [-7464962456370065744] [Test case: 8]testing timed debug prints DEBUG: [-7464962451369754731] [Test case: 9]testing timed debug prints

Why are these numbers negative?

initially my test was wrong I wasn't using assertions and just printing it. I'll update the description so that others don't get confused.

adi-65-ray · 2025-12-23T21:15:56Z

Hello,
I need some help in resolving one CI error which is recurring error in lf-python(windows) build. The integration test fails after running some tests and gives a java instrumentation error. I have ran it once again to get more logs to compare and investigate.

Timestamped logging macro

4f51612

hokeun marked this pull request as ready for review September 22, 2025 17:50

hokeun self-requested a review September 22, 2025 17:50

hokeun reviewed Sep 22, 2025

View reviewed changes

logging/api/logging_macros.h Outdated Show resolved Hide resolved

test/general/logging_test.c Outdated Show resolved Hide resolved

test/general/logging_test.c Outdated Show resolved Hide resolved

hokeun requested a review from edwardalee September 22, 2025 17:57

edwardalee requested changes Sep 25, 2025

View reviewed changes

logging/api/logging_macros.h Outdated Show resolved Hide resolved

logging/api/logging_macros.h Outdated Show resolved Hide resolved

Added unit test

2e60dc9

adi-65-ray requested review from edwardalee and hokeun September 26, 2025 07:36

edwardalee approved these changes Sep 28, 2025

View reviewed changes

hokeun changed the title ~~Timestamped logging macro~~ Timestamped logging macro for elapsed physical time Sep 28, 2025

hokeun linked an issue Sep 28, 2025 that may be closed by this pull request

Prepend logging prints with the current/elapsed physical time #395

Open

hokeun added the enhancement Enhancement of existing feature label Sep 28, 2025

hokeun requested a review from Jakio815 October 14, 2025 19:18

adi-65-ray added 2 commits October 14, 2025 12:39

unit test for logging clang-format fix

7aa0ff7

logging_macros format fix

995e05e

hokeun approved these changes Oct 21, 2025

View reviewed changes

test/general/logging_test.c Outdated Show resolved Hide resolved

hokeun added 2 commits October 21, 2025 11:57

Update test/general/logging_test.c

9564112

Merge branch 'main' into logging-timestamped

e5ccae5

hokeun enabled auto-merge October 21, 2025 18:58

hokeun mentioned this pull request Oct 21, 2025

Prepend logging prints with the current/elapsed physical time #395

Open

hokeun disabled auto-merge October 22, 2025 16:06

hokeun and others added 2 commits October 22, 2025 09:14

Remove inclusion of tag.h

eb05623

Enable LOG_LEVEL_DEBUG for log UT

578111d

adi-65-ray requested a review from hokeun October 22, 2025 18:56

adi-65-ray and others added 3 commits October 28, 2025 22:35

CI fix

948a758

trace low-level-platform dependency

dba5062

Revert unnecessary change to CMakeLists

9ca2499

hokeun approved these changes Oct 30, 2025

View reviewed changes

hokeun enabled auto-merge October 30, 2025 19:07

edwardalee reviewed Oct 31, 2025

View reviewed changes

adi-65-ray closed this Oct 31, 2025

auto-merge was automatically disabled October 31, 2025 07:59
Pull request was closed

adi-65-ray reopened this Oct 31, 2025

adi-65-ray added 2 commits December 20, 2025 23:52

Merge branch 'main' into logging-timestamped

ba37edb

added unit-tests-debug for running test/debug_tests

8782543

Timestamped logging macro for elapsed physical time #546

Are you sure you want to change the base?

Timestamped logging macro for elapsed physical time #546

Uh oh!

Conversation

adi-65-ray commented Sep 21, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

hokeun left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

hokeun commented Sep 22, 2025

Uh oh!

edwardalee left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

edwardalee left a comment • 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!

hokeun left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

hokeun left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

edwardalee commented Oct 31, 2025

Uh oh!

adi-65-ray commented Oct 31, 2025

Uh oh!

adi-65-ray commented Dec 23, 2025

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

adi-65-ray commented Sep 21, 2025 •

edited

Loading

edwardalee left a comment •

edited

Loading