crownstone / bluenet

Bluenet is the in-house firmware on Crownstone hardware. Functions: switching, dimming, energy monitoring, presence detection, indoor localization, switchcraft.
https://crownstone.rocks
91 stars 62 forks source link

Bug: a process executed through EXECUTE_PROCESS shows a delay #110

Closed mrquincle closed 3 years ago

mrquincle commented 3 years ago

As described by @vliedel when connecting with a phone and writing a value, the result is shown several seconds later if it is displayed through a process that is started through EXECUTE_PROCESS.

Check for example the https://github.com/crownstone/bluenet/blob/master/source/conf/cmake/modules/uart_tool.cmake file.

It starts a script log-client.py:

execute_process(
        COMMAND ${DEFAULT_MODULES_PATH}/../../../../scripts/log-client.py -d ${UART_DEVICE}
        )

Note how it does not capture the result or output variables, these should be mapped to stdout. As you might or might not know, those commands COMMAND are executed concurrently as a pipeline, with the standard output of each process piped to the standard input of the next. A single standard error pipe is used for all processes. Here we have only a single COMMAND so it should be immediately piped to stdout, however, there's apparently a buffer.

For completeness, the above is called like this:

        add_custom_target(uart_binary_client
            COMMAND ${CMAKE_COMMAND} ${DEFAULT_TOOL_PARAM} "-DINSTRUCTION=START_BINARY_CLIENT" -P ${DEFAULT_MODULES_PATH}/uart_tool.cmake
            )

Suggestion 1

We might try to run it explicitly as a bash script, but I would be surprised if this would fix the delay. There's still some pipe buffer issues, but now with the shell involved, I guess. Worth a try though.

execute_process(
        COMMAND bash "-c" "${DEFAULT_MODULES_PATH}/../../../../scripts/log-client.py -d ${UART_DEVICE}"
        )

Suggestion 2

It might be the case that the older, deprecated exec_program command is doing something less fancy. Worth a try too.

exec_program(${DEFAULT_MODULES_PATH}/../../../../scripts/log-client.py
        ARGS -d ${UART_DEVICE}
        )

Suggestion 3

If this all isn't working, we will have to back to finding a way in which we can pass runtime variables directly into our COMMAND lines in our custom targets:

        add_custom_target(uart_binary_client
            COMMAND ${SCRIPT_PATH}/log-client.py -d $$(${SCRIPT_PATH}/get_config.sh UART_DEVICE)
            )

Something like this. Here we feed the COMMAND an argument by executing a script get_config.sh which outputs the value for UART_DEVICE. Of course, this is not cross-platform, but tsja. It can be be also a python script of course. Anyway, this will allow us to set our variables at runtime as well and very likely it is running directly in the shell where make or ninja is called, not wrapped by cmake.

vliedel commented 3 years ago

Tried suggestion 1 and 2, both show the same behaviour.

vliedel commented 3 years ago

I get the same behaviour if i run ./log-client.py | grep "". So maybe it has nothing to do with cmake.

mrquincle commented 3 years ago

In that case you pipe it into grep. This might do something similar indeed to cmake. You can check with strace. I think grep uses by default block buffering while you want it to do line buffering. For grep you can use the flag --line-buffered for this.

Then we also have python itself, if might also detect if it is actually sending output to tty vs another process. In that case you'll have to use something like fflush or indicate in a different way that you don't want to buffer: https://stackoverflow.com/questions/107705/disable-output-buffering

That all being said, I think my suggestion 3 will very likely just run in the same shell without pipe redirections. I would predict that that solution works. You can test it first by hardcoding the UART_DEVICE value.

mrquincle commented 3 years ago

This solution uses cmake scripts to do this.

COMMAND bash -c "cmake ${DEFAULT_TOOL_PARAM} ${UART_CONFIG_PARAM} -P ${DEFAULT_MODULES_PATH}/get_config.cmake 2>&1 | xargs -I uart ${WORKSPACE_DIR}/scripts/log-client.py -d uart"

Given that we are using python anyway for binary logging, we can just as well consider this a dependency. Then the above command cmake ${DEFAULT_TOOL_PARAM} ${UART_CONFIG_PARAM} -P ${DEFAULT_MODULES_PATH}/get_config.cmake can be replaced by something like ${WORKSPACE_DIR}/scripts/get-config.py UART_DEVICE)

It is slightly cleaner perhaps, but not by much. The benefit of the current approach is that it just uses the cmake scripts again, just at runtime now.

mrquincle commented 3 years ago

Fixed in https://github.com/crownstone/bluenet/commit/ca120d5ec3d261a296e96668756179c575121258