Use parent STDOUT for logging output #172
Conversation
agners
left a comment
agners
left a comment
There was a problem hiding this comment.
#169 causes lots of problems, because many bashio functions produce output (on stdout) that is meant to be captured by the caller, and log messages produced by those functions are now intermixed with that output and captured by the caller instead of being sent to an independent stream.
Nice catch!
I think this can be fixed by duplicating the original/parent stdout file handle to fd 3, then logging to fd 3 instead of stdout, as implemented in this PR. This works because each subshell/child gets its own fd 0/1/2 (overriding the parent's fd 0/1/2 but piping from/to the parent's fd 0/1/2 unless redirected) while inheriting all other fds from the parent (so in this case, the copy of the parent's stdout in fd 3 will be inherited by all subshells/children), effectively providing an independent log stream that can be used without affecting output capture for subshells/children.
Hm, I see that works as long as the only thing we rely on is output from child processes. E.g. if we were using echo something in some bashio script and parse that in parent, it still would mix with the log output. But I'd consider that unexpected use.
I guess another alternative would be to revert #169, and left things as they were. But I think this approach is worth a try. I'd guess this has a high chance to work in pretty much all cases. One suggestion though to improve the implementation, just in case fd 3 is used somewhere (which I think s6 is actually, iirc).
WalkthroughRedirects bashio logging in Changes
Sequence Diagram(s)sequenceDiagram
autonumber
participant Script
participant LogFn as bashio::log.*
participant Core as bashio::log.log
participant FD as LOG_FD\n(dup of original STDOUT)
participant Out as Terminal/Log Sink
Note over Script,Out: Logging flow using preserved original STDOUT (LOG_FD)
Script->>LogFn: call e.g. bashio::log.green("msg")
LogFn->>Core: format & delegate
Core-->>FD: printf '%b\n' "formatted" >&"$LOG_FD"
FD-->>Out: emit log line
Note over Script,FD: Subshell/stdout captures no longer intercept logging (logs go to LOG_FD)
Estimated code review effort🎯 2 (Simple) | ⏱️ ~10 minutes Possibly related PRs
Suggested labels
Suggested reviewers
Poem
Pre-merge checks and finishing touches✅ Passed checks (3 passed)
✨ Finishing touches
🧪 Generate unit tests
Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out. Comment |
![coderabbitai[bot]](https://avatars.githubusercontent.com/in/347564?s=60&v=4){kind=small}
There was a problem hiding this comment.
Actionable comments posted: 0
🧹 Nitpick comments (2)
lib/log.sh (2)
10-14: Solid approach preserving parent STDOUT; add an idempotency guard to avoid FD leaks on re-sourceIf this file is sourced multiple times, a new FD will be allocated each time. Guard the setup so it only runs if LOG_FD isn’t already a valid descriptor.
Apply this diff:
-# Preserve the original STDOUT on a free fd so that we can log to it without -# interfering with the STDOUT of subshells and child processes whose output we -# want to capture for other purposes. -exec {LOG_FD}>&1 +# Preserve the original STDOUT on a free fd so that we can log to it without +# interfering with the STDOUT of subshells and child processes whose output we +# want to capture for other purposes. +# Only allocate if not already a valid, open FD (prevents leaks on re-source). +if ! : >&"$LOG_FD" 2>/dev/null; then + exec {LOG_FD}>&1 +fi
23-23: Use printf instead of echo -e to avoid escape/portability pitfallsprintf is safer and avoids oddities with echo -e and messages starting with “-”.
Apply this diff:
- echo -e "${message}" >&"$LOG_FD" + printf '%s\n' "${message}" >&"$LOG_FD"- echo -e "${__BASHIO_COLORS_RED}${message}${__BASHIO_COLORS_RESET}" >&"$LOG_FD" + printf '%b\n' "${__BASHIO_COLORS_RED}${message}${__BASHIO_COLORS_RESET}" >&"$LOG_FD"- echo -e "${__BASHIO_COLORS_GREEN}${message}${__BASHIO_COLORS_RESET}" >&"$LOG_FD" + printf '%b\n' "${__BASHIO_COLORS_GREEN}${message}${__BASHIO_COLORS_RESET}" >&"$LOG_FD"- echo -e "${__BASHIO_COLORS_YELLOW}${message}${__BASHIO_COLORS_RESET}" >&"$LOG_FD" + printf '%b\n' "${__BASHIO_COLORS_YELLOW}${message}${__BASHIO_COLORS_RESET}" >&"$LOG_FD"- echo -e "${__BASHIO_COLORS_BLUE}${message}${__BASHIO_COLORS_RESET}" >&"$LOG_FD" + printf '%b\n' "${__BASHIO_COLORS_BLUE}${message}${__BASHIO_COLORS_RESET}" >&"$LOG_FD"- echo -e "${__BASHIO_COLORS_MAGENTA}${message}${__BASHIO_COLORS_RESET}" >&"$LOG_FD" + printf '%b\n' "${__BASHIO_COLORS_MAGENTA}${message}${__BASHIO_COLORS_RESET}" >&"$LOG_FD"- echo -e "${__BASHIO_COLORS_CYAN}${message}${__BASHIO_COLORS_RESET}" >&"$LOG_FD" + printf '%b\n' "${__BASHIO_COLORS_CYAN}${message}${__BASHIO_COLORS_RESET}" >&"$LOG_FD"- echo -e "${output}" >&"$LOG_FD" + printf '%b\n' "${output}" >&"$LOG_FD"Also applies to: 35-35, 47-47, 59-59, 71-71, 83-83, 95-95, 123-123
📜 Review details
Configuration used: CodeRabbit UI
Review profile: CHILL
Plan: Pro
📒 Files selected for processing (1)
lib/log.sh(9 hunks)
🔇 Additional comments (1)
lib/log.sh (1)
106-126: Core fix LGTM — log.log now writes to preserved STDOUT, preventing corruptionThis redirects structured log lines to LOG_FD, addressing the regression where logs mixed with function stdout.
|
Made a few updates for safety (defensive programming). |
There was a problem hiding this comment.
Actionable comments posted: 0
🧹 Nitpick comments (1)
lib/log.sh (1)
10-16: Harden LOG_FD validation and add a fallback if STDOUT is closedAvoid honoring 0/1/2 for LOG_FD and provide a safe fallback to STDERR if duplicating STDOUT fails (e.g., stdout closed). This reduces the risk of writes going to an unreadable FD.
-# Unless $LOG_FD is already set to a valid fd -if ! [[ "$LOG_FD" =~ ^[0-9]+$ ]] || ! { true >&"$LOG_FD" ; } 2>/dev/null ; then - # Preserve the original STDOUT on a free fd (stored in $LOG_FD) so that we can - # log to it without interfering with the STDOUT of subshells whose output we - # want to capture for other purposes. - exec {LOG_FD}>&1 -fi +# Unless $LOG_FD is already set to a valid fd (>=3) that we can duplicate to +if ! [[ "$LOG_FD" =~ ^[3-9][0-9]*$ ]] || ! { : >&"$LOG_FD"; } 2>/dev/null; then + # Preserve the original STDOUT on a free fd (stored in $LOG_FD) so that we can + # log to it without interfering with the STDOUT of subshells whose output we + # want to capture for other purposes. If STDOUT is not available, fall back to STDERR. + if ! exec {LOG_FD}>&1 2>/dev/null; then + exec {LOG_FD}>&2 + fi +fi
📜 Review details
Configuration used: CodeRabbit UI
Review profile: CHILL
Plan: Pro
📒 Files selected for processing (1)
lib/log.sh(9 hunks)
🔇 Additional comments (1)
lib/log.sh (1)
26-26: Good switch to printf to LOG_FD — approvedAll printf calls in lib/log.sh (lines 26, 38, 50, 62, 74, 86, 98, 126) are redirected with >&"$LOG_FD"; no echo -e or explicit >&1/>&2 matches found.
|
I was actually a bit confused as why this worked even without the guard introduced in d998311. I've tested the NUT case without guard, and it worked. We do command substitution So for one, a subshell inherits the environment variable even without exporting. But subshells are still separate processes. However, it seems that But the d998311 certainly don't hurt, e.g. if we were to actually call another, separate bashio script using subshell syntax |
|
There are several unintuitive things that are relevant to the behavior here: First, file handles/descriptors created in BASH are inherited by / exported to commands run by bash (unless overridden using bash redirects when running the command). For example: Note that Next, the simple case works fine without a guard. LOG_FD doesn't initially exist, so (with or without the guard) we create an fd and populate LOG_FD, then everything continues as expected after that. Finally, this statement is incorrect:
If you are looking at $$ then it might appear that $() doesn't create a subshell process if it is a function, but $BASHPID shows that it is a separate process. Does that help explain how/why this works? |
It is not that I just made these statements up. I tested it: diff --git a/lib/log.sh b/lib/log.sh
index 5f94701..9df3415 100644
--- a/lib/log.sh
+++ b/lib/log.sh
@@ -7,6 +7,8 @@
# to be included in add-on scripts to reduce code duplication across add-ons.
# ==============================================================================
+echo "Logging from PID $$"
+
# Unless $LOG_FD is already set to a valid fd
if ! [[ "${LOG_FD-}" =~ ^[0-9]+$ ]] || ! { : >&"${LOG_FD-2}"; } 2>/dev/null; then
# Preserve the original STDOUT on a free fd (stored in $LOG_FD) so that we can
As I said initially, the I've rebuilt the NUT add-on without guard and export and it worked. Can you explain why it worked if my statements are not true? |
|
@agners
From Test again using
While your statement about $() running in the same process is false, your other statements are true. So, the reason it works without the guard and export is a combination of:
|
$ git diff
diff --git a/lib/log.sh b/lib/log.sh
index 5f94701..c296537 100644
--- a/lib/log.sh
+++ b/lib/log.sh
@@ -7,6 +7,8 @@
# to be included in add-on scripts to reduce code duplication across add-ons.
# ==============================================================================
+echo "Logging from PID $BASHPID"
+
# Unless $LOG_FD is already set to a valid fd
if ! [[ "${LOG_FD-}" =~ ^[0-9]+$ ]] || ! { : >&"${LOG_FD-2}"; } 2>/dev/null; then
# Preserve the original STDOUT on a free fd (stored in $LOG_FD) so that we canI read up a bit, and it seems that bash does some optimizations for subshells, some of which avoid forking if not necessary (and execute the function still in a "subshell" with its own environment, e.g. from But yeah, with that in mind its maybe safer to not rely on that optimization, and pass down LOG_FD to bashio subshells just in case. |
|
Can someone please explain what shebang should we use in scripts in /usr/bin to make it work? Currently these scripts either see the log in the captured stdout of a bashio function, or can't see bashio functions at all. |
|
(I replied in #177) |
4 participants
#169 causes lots of problems, because many bashio functions produce output (on stdout) that is meant to be captured by the caller, and log messages produced by those functions are now intermixed with that output and captured by the caller instead of being sent to an independent stream for logging.
For example, configuring
log_level: traceon (almost) any HA add-on now causes the add-on to fail because thelog.tracemessage in bashio::addon.config() gets mixed with the returned config value (effectively corrupting the returned config value) and causes thejqcommand in bashio::config() to fail, effectively breaking config parsing entirely.Some reports of user issues related to this are here: hassio-addons/addon-nut#451
I think this can be fixed by duplicating the original/parent stdout file handle to fd 3, then logging to fd 3 instead of stdout, as implemented in this PR. This works because each subshell/child gets its own fd 0/1/2 (overriding the parent's fd 0/1/2 but piping from/to the parent's fd 0/1/2 unless redirected) while inheriting all other fds from the parent (so in this case, the copy of the parent's stdout in fd 3 will be inherited by all subshells/children), effectively providing an independent log stream that can be used without affecting output capture for subshells/children.
However, as I don't know all of the ways bashio is used, it is possible that this doesn't solve all of the problems caused by #169.
Note that any add-on images published since #169 was merged (09/11/2025 15:50 UTC) will need to be re-published after bashio is fixed.
Summary by CodeRabbit