From 99ab7805e6ef0a14568d8a100eec03bb2cb03631 Mon Sep 17 00:00:00 2001 From: Mike Bland Date: Mon, 2 Jan 2017 16:17:29 -0500 Subject: [PATCH] log: Set `local IFS=','` to fix Travis Linux build This definitively fixes the failing `log/log-command` tests for the Travis Linux build. The breakage was due to a bug in Bash 4.2.25, and not fixed until 4.2.41, in which process substitutions did not have access to the temporary environment for a command. Moving `IFS=','` to a `local` declaration in `_@go.log_level_file_descriptors` solves the problem, but emphasizes the need for a `@go.split` function as described in #62. I'll implement it and replace all `IFS='...' read -ra` invocations with it shortly to protect against the same bug. Details: ------- Several `log/log-command` test cases failed for the Travis Linux build for #81 prior to this commit: - https://travis-ci.org/mbland/go-script-bash/builds/188272967 - https://travis-ci.org/mbland/go-script-bash/builds/188273548 These builds ran with Bash 4.2.25(1)-release, and I could not reproduce the failures using 3.2.57(1)-release or 4.4.5(1)-release. To reproduce the error, I downloaded the Bash 4.2 sources and patches from: - https://mirrors.ocf.berkeley.edu/gnu/bash/ - https://mirrors.ocf.berkeley.edu/gnu/bash/bash-4.2-patches/ To make life easier, I downloaded the patches via: ```bash mkdir bash-source cd bash-source BASEURL='https://mirrors.ocf.berkeley.edu/gnu/bash/bash-4.2-patches/bash42-0' for i in {1..9}; do curl -O "${BASEURL}0${i}" done for i in {10..53}; do curl -O "${BASEURL}${i}" done ``` I then proceeded to build version 4.2.25 via: ```bash gzip -dc bash-4.2.tar.gz | tar xf - mv bash-4.2 bash-4.2.25 cd bash-4.2.25 for p in ../bash42-00* ../bash42-0{10..25}; do patch -p0 <"$p"; done ./configure --prefix=/usr/local/bash-builds/4.2.25 && make install ``` Then I returned to the go-script-bash project and ran: ```bash PATH="/usr/local/bash-builds/4.2.25/bin:$PATH" ./go test log/log-command ``` This recreated the failure as seen on Travis. The relevant change appeared to be the update to `_@go.log_level_file_descriptors` to use `IFS=',' read -ra`. To debug, I instrumented the function like so (which inspired me to file #82): ```bash _@go.log_level_file_descriptors() { IFS=',' read -ra __go_log_level_file_descriptors \ <<< "${__GO_LOG_LEVELS_FILE_DESCRIPTORS[$1]}" if [[ -n "$TEST_DEBUG" && ${#__go_log_level_file_descriptors[@]} -eq '1' ]]; then echo "FDS: '${__go_log_level_file_descriptors[@]}'" >&2 @go.print_stack_trace >&2 fi } ``` and then updated the first failing test suite thus: ``` @test "$SUITE: logging to a file doesn't repeat lines or skip other log files" { local info_log="$TEST_GO_ROOTDIR/info.log" TEST_DEBUG='true' run_log_script \ ``` The test would then fail for 3.2.57 and 4.4.5, with the following as the final `FDS: '...'` line: ``` FDS: '1 4 5' ``` But for 4.2.25: ``` FDS: '1,4,5' ``` This reflected the invocation taking place in `function_that_logs_info`, which was executed within a process substitution via `@go.log_command` and `_@go.log_command_invoke`. I built 4.2.53 (the last 4.2 patch level) and ran the test, and it passed. After building intervening versions in a `git bisect`-like fashion, I finally pinpointed the problem and the fix in patch 41. From https://mirrors.ocf.berkeley.edu/gnu/bash/bash-4.2-patches/bash42-041: ``` Process substitution incorrectly inherited a flag that inhibited using the (local) temporary environment for variable lookups if it was providing the filename to a redirection. The intent the flag is to enforce the Posix command expansion ordering rules. ``` From https://tiswww.case.edu/php/chet/bash/CHANGES: ``` This document details the changes between this version, bash-4.3-alpha, and the previous version, bash-4.2-release. iii. Fixed a bug that caused commands in process substitutions to not look in the local temporary environment when performing word expansions. ``` And from bash-4.3/ChangeLog: ``` 12/2 ---- subst.c - process_substitute: turn off the `expanding_redir' flag, which controls whether or not variables.c:find_variable_internal uses the temporary environment to find variables. We want to use the temp environment, since we don't have to worry about order of evaluation in a subshell. Fixes bug reported by Andrey Borzenkov ``` Moving `IFS=','` to a local declaration fixed all test cases for 4.2.25, and the full build passed as well. However, I allowed all the other `IFS='...' read` invocations to stand for now, even though they're technically all just as vulnerable as the one from `_@go.log_level_file_descriptors`. I'll implement `@go.split` and then replace all instances with a call to that function in a follow-up PR. --- lib/log | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/lib/log b/lib/log index a6ae846..230fd9a 100644 --- a/lib/log +++ b/lib/log @@ -657,7 +657,8 @@ _@go.log_format_level_labels() { # Arguments: # log_level_index: A log level index returned from _@go.log_level_index _@go.log_level_file_descriptors() { - IFS=',' read -ra __go_log_level_file_descriptors \ + local IFS=',' + read -ra __go_log_level_file_descriptors \ <<< "${__GO_LOG_LEVELS_FILE_DESCRIPTORS[$1]}" }