cmake: modules: dts: print stderr on failure #79236

M1cha · 2024-10-01T03:21:18Z

059aae7 actually hid error messages completely instead of making them more visible.
db7a390 restored that for some processes, but not for dtc itself.

Without this patch, a device tree error like a missing reg property
failed the build without showing the reason:

CMake Error at zephyr/cmake/modules/dts.cmake:401 (message):
  dtc failed with return code: 2
Call Stack (most recent call first):
  zephyr/cmake/modules/zephyr_default.cmake:133 (include)
  zephyr/share/zephyr-package/cmake/ZephyrConfig.cmake:66 (include)
  zephyr/share/zephyr-package/cmake/ZephyrConfig.cmake:97 (include_boilerplate)
  CMakeLists.txt:5 (find_package)

With it, you can see the cause of the failure like before:

CMake Error at zephyr/cmake/modules/dts.cmake:401 (message):
  dtc failed with return code: 2

  build/zephyr/zephyr.dts:42.20-44.6:
  ERROR (unit_address_vs_reg): /soc/flash-controller@40020000/flash@0: node
  has a unit name, but no reg property

  ERROR: Input tree has errors, aborting (use -f to force output)

Call Stack (most recent call first):
  zephyr/cmake/modules/zephyr_default.cmake:133 (include)
  zephyr/share/zephyr-package/cmake/ZephyrConfig.cmake:66 (include)
  zephyr/share/zephyr-package/cmake/ZephyrConfig.cmake:92 (include_boilerplate)
  CMakeLists.txt:5 (find_package)

ycsin · 2024-10-01T03:32:32Z

Commit body is too long

 15: UC4 Commit message body line exceeds max length (79>75): "  zephyr/share/zephyr-package/cmake/ZephyrConfig.cmake:97 (include_boilerplate)"
33: UC4 Commit message body line exceeds max length (79>75): "  zephyr/share/zephyr-package/cmake/ZephyrConfig.cmake:92 (include_boilerplate)"

059aae7 actually hid error messages completely instead of making them more visible. db7a390 restored that for some processes, but not for dtc itself. Without this patch, a device tree error like a missing `reg` property failed the build without showing the reason. Signed-off-by: Michael Zimmermann <[email protected]>

M1cha · 2024-10-01T07:36:56Z

Commit body is too long

 15: UC4 Commit message body line exceeds max length (79>75): "  zephyr/share/zephyr-package/cmake/ZephyrConfig.cmake:97 (include_boilerplate)"
33: UC4 Commit message body line exceeds max length (79>75): "  zephyr/share/zephyr-package/cmake/ZephyrConfig.cmake:92 (include_boilerplate)"

How can I fix that, given that those are log messages?

nordicjm · 2024-10-01T07:40:17Z

Don't put the log messages in, a description of what this is fixing is sufficient

ycsin · 2024-10-01T09:10:35Z

How can I fix that, given that those are log messages?

I'd put the log msg in the PR (first post)

M1cha · 2024-10-01T09:31:55Z

Fixed, CI passes now.

M1cha · 2024-10-01T09:37:58Z

How can I fix that, given that those are log messages?

I'd put the log msg in the PR (first post)

good idea, thx. done.

tejlmand

not blocking as this does fix the issue at hand, but I would actually prefer that code is cleaned up.

tejlmand · 2024-10-01T13:41:27Z

cmake/modules/dts.cmake


 if(NOT "${ret}" STREQUAL "0")
-  message(FATAL_ERROR "dtc failed with return code: ${ret}")
+  message(FATAL_ERROR "dtc failed with return code: ${ret}\n${stderr}")


better to remove all this complex code and instead simply do:

execute_process( COMMAND ${DTC} ... ${ZEPHYR_DTS} OUTPUT_QUIET # Discard stdout WORKING_DIRECTORY ${PROJECT_BINARY_DIR} COMMAND_ERROR_IS_FATAL ANY )

and then remove the

if(NOT "${ret}" STREQUAL "0") ...

logic below.

See also this comment for details: #78250 (comment)

So with COMMAND_ERROR_IS_FATAL, cmake only prints the output on failure? Or will will always prints the output no matter what with your proposed change?

It will print any output on standard error regardless of the error code.

Basically:

COMMAND_ERROR_IS_FATAL: Will fail CMake if return code is different from zero.
Flag has no relation / impact on standard out or standard error.

No ERROR_OUTPUT, will print any message from standard error in the normal CMake output.
Just like we are doing with message(... "... ${stderr}").

See: https://cmake.org/cmake/help/latest/command/execute_process.html

If no OUTPUT_* or ERROR_* options are given the output will be shared with the corresponding pipes of the CMake process itself.

Note: OUTPUT_QUIET discard only standard out, not standard error.

mathieuchopstm · 2024-10-14T12:01:42Z

While I fully acknowledge that #76472 was flawed, I don't really agree with completely reverting it as is being done with this PR + #78250.

(The reason why I didn't bother printing dtc's stderr on failure is that I assumed gen_defines.py would always catch faulty DTS, and die before dtc was ever invoked - it seems I was wrong)

I must admit that the current state is slightly improved compared to pre-76472... merely because we no longer print the faulty command 😅. The CMake error message is however more confusing, in my opinion:

   Found BOARD.dts: ~/zephyrproject/zephyr/boards/st/nucleo_f401re/nucleo_f401re.dts
devicetree error: 'reg' appears in /soc/custom-controller@80/child-device@0 in ~/zephyrproject/build/zephyr/zephyr.dts.pre, but is not declared in 'properties:' in ~/zephyrproject/zephyr/dts/bindings/acpi/test_binding_1.yaml
- CMake Error at ~/zephyrproject/zephyr/cmake/modules/dts.cmake:301 (execute_process):
-  execute_process failed command indexes:
-
-    1: "Child return code: 1"
-
-Call Stack (most recent call first):
-  ~/zephyrproject/zephyr/cmake/modules/zephyr_default.cmake:133 (include)
-  ~/zephyrproject/zephyr/share/zephyr-package/cmake/ZephyrConfig.cmake:66 (include)
-  ~/zephyrproject/zephyr/share/zephyr-package/cmake/ZephyrConfig.cmake:97 (include_boilerplate)
-  CMakeLists.txt:5 (find_package)


   Configuring incomplete, errors occurred!

For reference, a similar failure would look like this previously:

Error message pre-76472

   Found BOARD.dts: ~/zephyrproject/zephyr/boards/st/nucleo_f401re/nucleo_f401re.dts
devicetree error: ~/zephyrproject/zephyr/boards/st/nucleo_f401re/nucleo_f401re.dts:27 (column 2): parse error: expected ';', not 'leds'
   In: ~/zephyrproject/zephyr/build/zephyr, command: ~/zephyrproject/.venv/bin/python3;~/zephyrproject/zephyr/scripts/dts/gen_defines.py;--dts;~/zephyrproject/zephyr/build/zephyr/zephyr.dts.pre;--dtc-flags;'';--bindings-dirs;~/zephyrproject/zephyr/dts/bindings;--header-out;~/zephyrproject/zephyr/build/zephyr/include/generated/zephyr/devicetree_generated.h.new;--dts-out;~/zephyrproject/zephyr/build/zephyr/zephyr.dts.new;--edt-pickle-out;~/zephyrproject/zephyr/build/zephyr/edt.pickle;--vendor-prefixes;~/zephyrproject/zephyr/dts/bindings/vendor-prefixes.txt
-CMake Error at ~/zephyrproject/zephyr/cmake/modules/dts.cmake:301 (message):
-   gen_defines.py failed with return code: 1
- Call Stack (most recent call first):
-   ~/zephyrproject/zephyr/cmake/modules/zephyr_default.cmake:132 (include)
-   ~/zephyrproject/zephyr/share/zephyr-package/cmake/ZephyrConfig.cmake:66 (include)
-   ~/zephyrproject/zephyr/share/zephyr-package/cmake/ZephyrConfig.cmake:97 (include_boilerplate)
-   CMakeLists.txt:5 (find_package)


   Configuring incomplete, errors occurred!

While I understand @tejlmand's point of using COMMAND_ERROR_IS_FATAL, I don't find it suitable here - I think we really want the stderr contents in the CMake error message, and we can't have that by just using COMMAND_ERROR_IS_FATAL.

I'm not -1'ing because this works, but I think keeping the behavior I tried to introduce with #76472 would be better - maybe a function wrapping execute_process and doing this should be introduced and used?

Proposal concept

# just a toy proposal, so WORKING_DIRECTORY etc not handled...
function(zephyr_execute_process command)
  execute_process(COMMAND ${command}
     RESULT_VARIABLE status
     OUTPUT_QUIET
     ERROR_VARIABLE stderr
  )

  if (NOT "${status}" STREQUAL "0")
    # Program failed -> FATAL_ERROR. Print stderr if present, or indicate it was empty.
    if (NOT stderr)
      set(stderr "<empty stderr>")
    endif()
    message(FATAL_ERROR "${command} failed with status code ${status}\n${stderr}")
  elif(stderr)
    message(WARNING "${command} succeeded with non-empty stderr:\n${stderr}")
  endif()
endfunction()

mmahadevan108 · 2024-11-08T20:16:30Z

@M1cha , can you take a look at the comments from @tejlmand and help update this PR.

tejlmand · 2024-11-11T10:40:29Z

While I understand @tejlmand's point of using COMMAND_ERROR_IS_FATAL, I don't find it suitable here - I think we really want the stderr contents in the CMake error message, and we can't have that by just using COMMAND_ERROR_IS_FATAL.

and this to me exactly show why we should keep things simple and let CMake handle stuff in most case because people often fail to realize exactly how those output and error variables work.

From CMake docs:

If no OUTPUT_* or ERROR_* options are given the output will be shared with the corresponding pipes of the CMake process itself.

So if you don't specify ERROR_OUTPUT then any error messages are printed directly to the users, regardless of the error code.
Which is exactly what you seem to want: I think we really want the stderr contents in the CMake error message

and is also what you have in your own comment here: #79236 (comment)

devicetree error: 'reg' appears in /soc/custom-controller@80/child-device@0 in ~/zephyrproject/build/zephyr/zephyr.dts.pre, but is not declared in 'properties:' in ~/zephyrproject/zephyr/dts/bindings/acpi/test_binding_1.yaml

@mathieuchopstm The part where I do believe CMake can improve is this part:

1: "Child return code: 1"

But for that I'm not convinced that it's better for us to have our own wrapper function.
This is something which should be addressed by CMake itself, so feel free to make comment or up-vote this issue: https://gitlab.kitware.com/cmake/cmake/-/issues/24815

mathieuchopstm · 2025-01-03T09:28:49Z

So if you don't specify ERROR_OUTPUT then any error messages are printed directly to the users, regardless of the error code. Which is exactly what you seem to want: I think we really want the stderr contents in the CMake error message
and is also what you have in your own comment here: #79236 (comment)

Not exactly. When ERROR_OUTPUT is not specified, CMake redirects the process' stderr to its own. This has three consequences (which I attempted to demonstrate in my comment):

redirected stderr is logged in the terminal before CMake's error message
redirected stderr is not color-highlighted like CMake's error message
- I guess this can vary depending on which OS/terminal/etc is used though
CMake's error message becomes pure noise
- we don't care about where execute_process failed, nor the call stack
- we (usually) don't care about which command has failed (gen_defines/dtc)
  - ...this information is no longer displayed anyways!

Since CMake's error message is ~10 lines while gen_defines' can be a single one, the resulting signal-to-noise ratio is poor. I must admit it is less important in the error case because the build halts (c.f. next point), and I can admit it may boil down to personal preferences, but I don't see any downsides to the proposal.

It may be a weak argument, but I find support for my point in #77266, filed merely two weeks after #76472, which reported a dtc warning that had existed for more than a year but never been reported 🙂 (presumably because the warning, lost in a sea of build log noise, suddenly became visible thanks to the yellow highlighting applied to warnings)

But for that I'm not convinced that it's better for us to have our own wrapper function. This is something which should be addressed by CMake itself, so feel free to make comment or up-vote this issue: https://gitlab.kitware.com/cmake/cmake/-/issues/24815

While I agree in principle, this sounds more like wishful thinking that a true solution: the issue is 1 year old and has no activity... and even if we assumed the feature was implemented right now, Zephyr's documentation says that the minimum CMake version is 3.20.5 (~3 years old) - would bumping this requirement to $LATEST be a sound idea (or even feasible)?

tejlmand · 2025-01-08T09:41:23Z

redirected stderr is logged in the terminal before CMake's error message

I agree that this is not ideal, but I'm also in favor of two other things, simplicity and consistency.
Sticking with COMMAND_ERROR_IS_FATAL follows both of these as it at least will make use of execute_process() simpler (no need for manual if() check) and thereby minimize mistakes, and consistency as any messages from stderr is always printed at same location.

This PR will mean that stderr in sometimes printed before CMake's own message and stack trace, and sometimes as part of the warning / error code from CMake's message(...).

Perhaps in this case a solution could be to introduce a zephyr_execute_process() which support similar arguments as regular execute_process() but where we adjust how the message is printed.

That will ensure the two points, simplicity and consistency.
Updating existing code can then be a simple matter of adjusting execute_process() --> zephyr_execute_process().
Of course some code, especially in Zephyr modules might still use execute_process(), but we can try to align the messages to minimize the difference in output while still achieving the improved highlight of stderr from the sub-process.

Thoughts ?

mathieuchopstm · 2025-01-08T14:50:41Z

Perhaps in this case a solution could be to introduce a zephyr_execute_process() which support similar arguments as regular execute_process() but where we adjust how the message is printed.

That will ensure the two points, simplicity and consistency. Updating existing code can then be a simple matter of adjusting execute_process() --> zephyr_execute_process(). Of course some code, especially in Zephyr modules might still use execute_process(), but we can try to align the messages to minimize the difference in output while still achieving the improved highlight of stderr from the sub-process.

Thoughts ?

This is the idea I had in mind, and suggested at the end of #79236 (comment), so +1 from me.

This PR will mean that stderr in sometimes printed before CMake's own message and stack trace, and sometimes as part of the warning / error code from CMake's message(...).

Since this point has been open for a while, I'm fine with using your proposal (execute_process(COMMAND_ERROR_IS_FATAL ANY)) in this PR to reduce inconsistencies and have something we can merge "quick". We could then "fix" everything in a follow-up PR implementing zephyr_execute_process().

tejlmand · 2025-03-19T08:24:56Z

@M1cha any update on this ?

kartben · 2025-03-24T18:33:59Z

Superseded by #87303 I believe

tejlmand · 2025-03-26T13:48:47Z

Superseded by #87303 I believe

yes

zephyrbot added size: XS A PR changing only a single line of code area: Build System labels Oct 1, 2024

zephyrbot requested review from 57300, jeremybettis, nashif, nordicjm and tejlmand October 1, 2024 03:22

zephyrbot assigned tejlmand Oct 1, 2024

M1cha force-pushed the restore-dtc-errors branch from a1894df to c1fa610 Compare October 1, 2024 07:47

pdgendt approved these changes Oct 1, 2024

View reviewed changes

tejlmand reviewed Oct 1, 2024

View reviewed changes

ycsin approved these changes Oct 1, 2024

View reviewed changes

fabiobaltieri added this to the v4.1.0 milestone Feb 17, 2025

fabiobaltieri modified the milestones: v4.1.0, v4.2.0 Mar 3, 2025

tejlmand mentioned this pull request Mar 19, 2025

cmake: modules: dts: print error message if DTC fails #87303

Merged

tejlmand closed this Mar 26, 2025

cmake: modules: dts: print stderr on failure #79236

cmake: modules: dts: print stderr on failure #79236

Uh oh!

Conversation

M1cha commented Oct 1, 2024 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

ycsin commented Oct 1, 2024

Uh oh!

M1cha commented Oct 1, 2024

Uh oh!

nordicjm commented Oct 1, 2024

Uh oh!

ycsin commented Oct 1, 2024

Uh oh!

M1cha commented Oct 1, 2024

Uh oh!

M1cha commented Oct 1, 2024

Uh oh!

tejlmand left a comment

Choose a reason for hiding this comment

Uh oh!

tejlmand Oct 1, 2024

Choose a reason for hiding this comment

Uh oh!

M1cha Nov 11, 2024

Choose a reason for hiding this comment

Uh oh!

tejlmand Nov 11, 2024 • 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!

mathieuchopstm commented Oct 14, 2024

Uh oh!

mmahadevan108 commented Nov 8, 2024

Uh oh!

tejlmand commented Nov 11, 2024

Uh oh!

mathieuchopstm commented Jan 3, 2025

Uh oh!

tejlmand commented Jan 8, 2025

Uh oh!

mathieuchopstm commented Jan 8, 2025

Uh oh!

tejlmand commented Mar 19, 2025

Uh oh!

kartben commented Mar 24, 2025

Uh oh!

tejlmand commented Mar 26, 2025

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

10 participants

M1cha commented Oct 1, 2024 •

edited

Loading

tejlmand Nov 11, 2024 •

edited

Loading