Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add DEBUG log level and priority filter variables #50

Merged
merged 5 commits into from
Dec 21, 2016
Merged

Conversation

mbland
Copy link
Owner

@mbland mbland commented Dec 21, 2016

Closes #36.

Now the log levels are ordered by priority within _GO_LOG_LEVELS, with a new DEBUG level at the lowest priority. Some existing levels have been rearranged as well.

The _GO_LOG_LEVEL_FILTER variable sets the minimum priority for logged messages (defaulting to RUN), and the _GO_LOG_CONSOLE_FILTER variable allows users to set the minimum priority specific to console output without affecting the priority for file output.

These variables must be set before . "$_GO_IMPORT_MODULES" 'log', either within a file or on the command line. They cannot be changed once the module is imported.

That's just commit b764e89. All of the other commits are test helper fixes and improvements, and a Bash bug workaround.

With this change, Bash scripts executing as child processes (such as
code executing within Bats test cases) may use `.  "$_GO_USE_MODULES"`
to import modules in a safe and reliable fashion. Each child process
will create its own `_GO_IMPORTED_MODULES` array.

Background:

While writing a test case for the upcoming `_GO_LOG_CONSOLE_FILTER` and
`_GO_LOG_LEVEL_FILTER` behavior described in #36, trying to use the
`assert_log_equals` assertion multiple times in the same test case
caused an error that resulted in no output. This is usually a sign that
something is deeply broken in a way that caused the assertion function
to exit the process with an error, rather than return with an error.

I eventually realized it was because `assert_log_equals` as written was
sourcing `$_GO_CORE_DIR/lib/log`. But because that module contains
`readonly` variables, sourcing it more than once in the same process was
causing the function to exit the process with an error.

Rather than hack around the problem locally, or reproduce
`_GO_USE_MODULES` in `tests/environment.bash`, I realized there was no
harm in exporting `_GO_USE_MODULES` in the first place, and actually a
huge benefit. Now any test helper or assertion can safely import module
functionality as needed, without the risk of the script aborting with no
error output under Bats.
Now that `_GO_USE_MODULES` is available to Bats tests and helpers, every
instance of `. "$_GO_CORE_DIR/lib/log"` has been replaced with
`. "$_GO_USE_MODULES" 'log'`, solving the problem of Bats test cases
failing with no output when calling an assertion multiple times leads to
an error due to importing the `log` module multiple times (because it
contains `readonly` variables). For details, see commit
9c2ae73.

The `format_label` helper now will fail loudly in case it's invoked
after any other function or assertion that imports the `log` module.
This hasn't been an issue yet, but seemed worth future-proofing.

Also adds the new `assert_log_file_equals` assertion to make examining
log file output (as opposed to standard output/error logs) easier to
test.

In the process of making these changes, I developed a useful idiom for
writing Bats assertions composed of other Bats assertions:

  local result=0

  if ! assert_some_condition "${inputs[@]}"; then
    result=1
  fi
  set +o functrace

  return_from_bats_assertion "$BASH_SOURCE" "$result"

Following this idiom helps ensure `return_from_bats_assertion` is called
in both the failure and success cases. Relevant to #29 and #48.
Renamed `__GO_CRITICAL_SECTION` to `__GO_LOG_CRITICAL_SECTION` to
facilitate this.
Closes #36.

Now the log levels are ordered by priority within `_GO_LOG_LEVELS`, with
a new `DEBUG` level at the lowest priority. Some existing levels have
been rearranged as well.

The `_GO_LOG_LEVEL_FILTER` variable sets the minimum priority for logged
messages (defaulting to `RUN`), and the `_GO_LOG_CONSOLE_FILTER`
variable allows users to set the minimum priority specific to console
output without affecting the priority for file output.

These variables must be set before `. "$_GO_IMPORT_MODULES" 'log'`, either
within a file or on the command line. They cannot be changed once the
module is imported.
While running the tests for `_GO_LOG_CONSOLE_FILTER` in the previous
commit (part of #36), the tests would pass under Bash 4.4.5(1)-release,
but not under Bash 3.2.57(1)-release.

Eventually I traced down the fact that under 3.2.57(1)-release,
`_GO_LOG_LEVELS` was getting erased sometime after the call to
`assert_log_equals` and before the call to `assert_log_file_equals`
causing `_@go.log_level_index` to fail for what should've been valid log
level names. I reasoned that the `.  "$_GO_USE_MODULES" 'log'`
invocation in `assert_log_equals` was causing `_GO_LOG_LEVELS` (and
likely other variables) to go out of scope after it returned, and since
`$_GO_USE_MODULES` ensures a module is imported only once, that variable
wasn't redefined—and there would've been errors with re-importing the
module anyway due to `readonly` variables, as mentioned in commit
9c2ae73.

Bash 4.4.5(1)-release didn't have this problem, and it started to ring
familiar. After scanninng the repo history, I realized this is my second
encounter with this bug, the first being documented in commit
b421c73.

The bug is this: Declaring a global array and initializing it at the
same time triggers a bug in some versions of bash 4.x prior to ~4.25
whereby it won't be visible outside the function in which it's declared
after all. See:

- https://lists.gnu.org/archive/html/bug-bash/2012-06/msg00068.html
- ftp://ftp.gnu.org/gnu/bash/bash-4.2-patches/bash42-025
- http://lists.gnu.org/archive/html/help-bash/2012-03/msg00078.html

Though the above links mention `declare -g`, as did my original commit,
it appears that `export` effectively triggers the same condition.

This is not a bug Apple has fixed in their shipping 3.2.57(1)-release
version of Bash. This is contrary to what I said in the earlier commit
message, as I think at that point I hadn't run the tests locally as
`PATH="/bin:$PATH" ./go test` (to avoid picking up the more recent
`/usr/local/bin/bash` from Homebrew), which is what I ran to hit the
problem locally again this time.

Fortunately working around the bug is straightforward and
forward-compatible: `export` the array name on the first line then
initialize it on the second. Annoying, but not bad as workarounds go.
@coveralls
Copy link

Coverage Status

Coverage decreased (-0.2%) to 94.292% when pulling c6bf1cf on log-filter into d921c4b on master.

@mbland mbland merged commit b04e952 into master Dec 21, 2016
@mbland mbland deleted the log-filter branch December 21, 2016 21:40
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Send log messages to multiple output files
2 participants