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

Send log messages to multiple output files #36

Closed
mbland opened this issue Dec 18, 2016 · 3 comments · Fixed by #50
Closed

Send log messages to multiple output files #36

mbland opened this issue Dec 18, 2016 · 3 comments · Fixed by #50
Assignees
Milestone

Comments

@mbland
Copy link
Owner

mbland commented Dec 18, 2016

Per @JohnOmernik, it may prove convenient to print log messages both the console and a file.

A proof-of-concept of the approach is already implemented in the file module as @go.fds_printf. That function won't be directly applicable; the console will need to include format codes, and the file output should have them stripped by default. Also per #35, it may be desirable to convert the output to JSON for some output files.

@mbland mbland added this to the v1.3.0 milestone Dec 18, 2016
@mbland mbland self-assigned this Dec 18, 2016
@mbland
Copy link
Owner Author

mbland commented Dec 18, 2016

v1.3.0

@JohnOmernik
Copy link
Collaborator

With the logging to stdout, does it make sense to just treat it as an output, and set the logging level based on the logging configuration, or since it may be very interactive, could add a "CONSOLE_FILTER" level to conf make sense, so people could easily just override it if they were troubleshooting... Let's say the standard CONSOLE_FILTER was set to WARN, but I was having trouble, I could run a command like "CONSOLE_FILTER=DEBUG ./go runmycommand" to get enhanced output without changing a configuration...

This would not apply to the other variable outputs of log files... just console... You'd have the file descriptor output to console, then a CONSOLE_FILTER set in conf, and then the ENV variable, with each level taking precedence (logging set < CONSOLE_FILE in go.conf file < CONSOLE_FILTER set at run time in ENV....)

Just spitballing ideas here...

@mbland
Copy link
Owner Author

mbland commented Dec 19, 2016

Ah, I think I see what you mean. I dig it. But I think it's orthogonal to the multi-file descriptor output concept.

What I mean by that is, if there's an INFO log file, and _GO_LOG_CONSOLE_FILTER (keeping with the public env var naming convention) is set to WARN, there'd be a check to see if each file descriptor is a terminal ([[ -t $fd ]]). If so, the INFO message isn't printed. If not, it is.

Of course, now I'm wondering if there should be a _GO_LOG_LEVEL_FILTER that controls output globally, in case users want a single log file, but for error level WARN and up, say.

Implementation-wise, something like:

declare _GO_LOG_CONSOLE_FILTER="${_GO_LOG_CONSOLE_FILTER:-WARN}"
declare _GO_LOG_LEVEL_FILTER="${_GO_LOG_LEVEL_FILTER:-INFO}"
declare __GO_LOG_CONSOLE_PRIORITY
declare __GO_LOG_LEVEL_PRIORITY
...

@go.log() {
  ...
  local level_fds=()
  local level_fd
  local priority
  local log_msg
  ...
  local origIFS="$IFS"
  local IFS=','
  level_fds="${__GO_LOG_LEVELS_FILE_DESCRIPTORS[$__go_log_level_index]}"
  IFS="$origIFS"

  for level_fd in "${level_fds[@]}"; do
    if [[ ! -t "$level_fd" && -z "$_GO_LOG_FORMATTING" ]]; then
      ...
    fi

    log_msg="$(@go.timestamp) $formatted_log_level ${args[*]}$close_code\n"
    # Remove leading spaces if the timestamp is empty
    log_msg="${log_msg## }"

    if [[ -t "$level_fd" ]]; then
      if [[ "$__go_log_level_index" -ge "$__GO_LOG_CONSOLE_PRIORITY" ]]; then
        printf "$log_msg" >&"$level_fd"
      fi
    elif [[ "$__go_log_level_index" -ge "$__GO_LOG_LEVEL_PRIORITY" ]]; then
      printf "$log_msg" >&"$level_fd"
    fi
  done
}

...

_@go.log_init() {
  if [[ -z "$__GO_LOG_INIT" ]]; then
    _@go.log_format_level_labels
    # ...set __GO_LOG_{CONSOLE,LEVEL}_PRIORITY here...
    readonly __GO_LOG_INIT='done'
  fi
}

The above also implies that the priority is determined by the order of levels in _GO_LOG_LEVELS. That will have to be documented, and in the future, there may be a way to inject a new level to precede an existing level, but that'd be for a future release.

mbland added a commit that referenced this issue Dec 20, 2016
Preparation for #36. Existing behavior is maintained.

Note that a latent bug where `FATAL` output was always going to standard
error was fixed. Didn't add a test because future tests covering output
to multiple file descriptors will cover that case.
mbland added a commit that referenced this issue Dec 20, 2016
Preparation for #36. Existing behavior is maintained.

Note that a latent bug where `FATAL` output was always going to standard
error was fixed. Didn't add a test because future tests covering output
to multiple file descriptors will cover that case.
mbland added a commit that referenced this issue Dec 20, 2016
Implements #36, except for the priority filtering. That will come in a
future commit.

With `@go.log_add_output_file`, you can add an output file to:

- all existing log levels at once
- a new log level that this function will create for you
- a subset of log levels, existing or new

The infrastructure needed to support the multiple-destination log output
was added in #43 (commit b61556b).
mbland added a commit that referenced this issue Dec 21, 2016
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.
mbland added a commit that referenced this issue 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.
mbland added a commit that referenced this issue Dec 21, 2016
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.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants