Skip to content

Commit

Permalink
log: Set local IFS=',' to fix Travis Linux build
Browse files Browse the repository at this point in the history
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.
  • Loading branch information
mbland committed Jan 2, 2017
1 parent c95d3bc commit 99ab780
Showing 1 changed file with 2 additions and 1 deletion.
3 changes: 2 additions & 1 deletion lib/log
Original file line number Diff line number Diff line change
Expand Up @@ -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]}"
}

Expand Down

0 comments on commit 99ab780

Please sign in to comment.