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

openshift-install: log debug output to file #689

Merged
merged 2 commits into from
Nov 20, 2018
Merged

openshift-install: log debug output to file #689

merged 2 commits into from
Nov 20, 2018

Conversation

crawford
Copy link
Contributor

This changes the logging strategy so that it logs all output to a local
file in addition to logging at the desired level to the console.
Unfortunately, logrus doesn't have a facility for capturing all log
entries (the hooks are only fired for entries which are at or below the
specified level) so this disables the console output and sets up two
hooks: one for the console and one for the local file.

@openshift-ci-robot openshift-ci-robot added do-not-merge/work-in-progress Indicates that a PR should not merge because it is a work in progress. size/M Denotes a PR that changes 30-99 lines, ignoring generated files. approved Indicates a PR has been approved by an approver from all required OWNERS files. labels Nov 15, 2018
Copy link
Member

@wking wking left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

While I'm fine with this being on by default, it would be nice to have the option to turn this off.

cmd/openshift-install/main.go Outdated Show resolved Hide resolved
@openshift-ci-robot openshift-ci-robot added size/L Denotes a PR that changes 100-499 lines, ignoring generated files. and removed size/M Denotes a PR that changes 30-99 lines, ignoring generated files. labels Nov 16, 2018
@crawford crawford changed the title WIP: openshift-install: log debug output to file openshift-install: log debug output to file Nov 16, 2018
@openshift-ci-robot openshift-ci-robot removed the do-not-merge/work-in-progress Indicates that a PR should not merge because it is a work in progress. label Nov 16, 2018
@crawford
Copy link
Contributor Author

/hold

This isn't working as intended.

@openshift-ci-robot openshift-ci-robot added the do-not-merge/hold Indicates that a PR should not merge because someone has issued a /hold command. label Nov 16, 2018
@crawford
Copy link
Contributor Author

/hold cancel

@openshift-ci-robot openshift-ci-robot removed the do-not-merge/hold Indicates that a PR should not merge because someone has issued a /hold command. label Nov 16, 2018
@crawford
Copy link
Contributor Author

Error executing openshift-install: failed to setup logging hook: failed to open log file: open .openshift-install.log: permission denied

Dangit

}

func setupFileHook() (func(), error) {
logfile, err := os.OpenFile(".openshift-install.log", os.O_WRONLY|os.O_APPEND|os.O_CREATE, 0666)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is going to get big ;). Do we need to prompt folks to occasionally prune somewhere? That's one reason why putting this in the asset directory might be useful.

assetToStore = onDiskAsset
source = onDiskSource
// The asset is in the state file. The asset is sourced from state file.
case foundInStateFile:
logrus.Debugf("%sUsing %q loaded from state file", indent, asset.Name())
logrus.Tracef("%sUsing %q loaded from state file", indent, asset.Name())
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We have enough trouble with asset contamination that I'd rather keep these at the debug level. Can you talk through why you're demoting them to trace?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Oh, I didn't realize that was still a problem. I figured it was noise to the vast majority of users and felt like a deeper level of logging. I'll drop that commit.

@wking
Copy link
Member

wking commented Nov 17, 2018

Also add trace to this list?

@wking
Copy link
Member

wking commented Nov 17, 2018

Error executing openshift-install: failed to setup logging hook: failed to open log file: open .openshift-install.log: permission denied 

Put it in the asset directory :p

@crawford
Copy link
Contributor Author

@wking I moved that log file into the install directory.

1.2.0 or newer is required in order to get the "trace" log level.
This changes the logging strategy so that it logs all output to a local
file in addition to logging at the desired level to the console.
Unfortunately, logrus doesn't have a facility for capturing all log
entries (the hooks are only fired for entries which are at or below the
specified level) so this disables the console output and sets up two
hooks: one for the console and one for the local file.
@abhinavdahiya
Copy link
Contributor

Looks like you have the manual bump here but are missing the dep ensure changes?

it looks like we are already at 1.2.0 for logrus on master

installer/Gopkg.lock

Lines 432 to 438 in 30bb25a

[[projects]]
digest = "1:d848e2bdc690ea54c4b49894b67a05db318a97ee6561879b814c2c1f82f61406"
name = "github.com/sirupsen/logrus"
packages = ["."]
pruneopts = "NUT"
revision = "bcd833dfe83d3cebad139e4a29ed79cb2318bf95"
version = "v1.2.0"

We moved to the latest tag here d92442d

@abhinavdahiya
Copy link
Contributor

/approve

@abhinavdahiya
Copy link
Contributor

/retest

@wking
Copy link
Member

wking commented Nov 20, 2018

/lgtm

@openshift-ci-robot openshift-ci-robot added the lgtm Indicates that a PR is ready to be merged. label Nov 20, 2018
@openshift-ci-robot
Copy link
Contributor

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: abhinavdahiya, crawford, wking

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:
  • OWNERS [abhinavdahiya,crawford,wking]

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

@crawford
Copy link
Contributor Author

/retest

@openshift-merge-robot openshift-merge-robot merged commit b4faf68 into openshift:master Nov 20, 2018
@crawford crawford deleted the logs branch November 20, 2018 23:21
wking added a commit to wking/openshift-installer that referenced this pull request Nov 26, 2018
06c5fd3 (openshift-install: log debug output to file, 2018-11-15, openshift#689),
the global logrus level has been TraceLevel.  Decisions about logging
to a particular target are now made when adding the hook for that
target.  This broke our Terraform debug approach, which had been based
on the level for the global logger.  Since 06c5fd3, logrus.GetLevel()
== logrus.DebugLevel will never be true.

With this commit, I've replaced that switch and now just push all
Terraform stdout into the default logger at the debug level.  A new
LinePrinter provides a shim between Terraform's stdout stream and the
line-based log calls.

I've added a local buffer for stderr, because Run [1] doesn't collect
it automatically like Output does [2].

LinePrinter.Lock protects us from parallel writes, because [3]:

  The slice is valid for use only until the next buffer modification
  (that is, only until the next call to a method like Read, Write,
  Reset, or Truncate).

The docs aren't clear about whether that limitation applies to
ReadString or not [4], but the backing implementation has no internal
lock to protect from changes made before the internal reference is
copied into a new slice [5].  We're unlikely to actually have parallel
writes for our Terraform use-case, but I'd rather be conservative now
and not have to track down a race if someone decides to use
LinePrinter for something concurrent later.

[1]: https://golang.org/pkg/os/exec/#Cmd.Run
[2]: https://golang.org/pkg/os/exec/#Cmd.Output
[3]: https://golang.org/pkg/bytes/#Buffer.Bytes
[4]: https://golang.org/pkg/bytes/#Buffer.ReadString
[5]: https://github.com/golang/go/blob/go1.11.2/src/bytes/buffer.go#L416-L439
wking added a commit to wking/openshift-installer that referenced this pull request Nov 26, 2018
06c5fd3 (openshift-install: log debug output to file, 2018-11-15, openshift#689),
the global logrus level has been TraceLevel.  Decisions about logging
to a particular target are now made when adding the hook for that
target.  This broke our Terraform debug approach, which had been based
on the level for the global logger.  Since 06c5fd3, logrus.GetLevel()
== logrus.DebugLevel will never be true.

With this commit, I've replaced that switch and now just push all
Terraform stdout into the default logger at the debug level.  A new
LinePrinter provides a shim between Terraform's stdout stream and the
line-based log calls.

I've added a local buffer for stderr, because Run [1] doesn't collect
it automatically like Output does [2].

LinePrinter.Lock protects us from parallel writes, because [3]:

  The slice is valid for use only until the next buffer modification
  (that is, only until the next call to a method like Read, Write,
  Reset, or Truncate).

The docs aren't clear about whether that limitation applies to
ReadString or not [4], but the backing implementation has no internal
lock to protect from changes made before the internal reference is
copied into a new slice [5].  We're unlikely to actually have parallel
writes for our Terraform use-case, but I'd rather be conservative now
and not have to track down a race if someone decides to use
LinePrinter for something concurrent later.

[1]: https://golang.org/pkg/os/exec/#Cmd.Run
[2]: https://golang.org/pkg/os/exec/#Cmd.Output
[3]: https://golang.org/pkg/bytes/#Buffer.Bytes
[4]: https://golang.org/pkg/bytes/#Buffer.ReadString
[5]: https://github.com/golang/go/blob/go1.11.2/src/bytes/buffer.go#L416-L439
wking added a commit to wking/openshift-installer that referenced this pull request Nov 26, 2018
06c5fd3 (openshift-install: log debug output to file, 2018-11-15, openshift#689),
the global logrus level has been TraceLevel.  Decisions about logging
to a particular target are now made when adding the hook for that
target.  This broke our Terraform debug approach, which had been based
on the level for the global logger.  Since 06c5fd3, logrus.GetLevel()
== logrus.DebugLevel will never be true.

With this commit, I've replaced that switch and now just push all
Terraform stdout into the default logger at the debug level.  A new
LinePrinter provides a shim between Terraform's stdout stream and the
line-based log calls.

I've added a local buffer for stderr, because Run [1] doesn't collect
it automatically like Output does [2].

LinePrinter.Lock protects us from parallel writes, because [3]:

  The slice is valid for use only until the next buffer modification
  (that is, only until the next call to a method like Read, Write,
  Reset, or Truncate).

The docs aren't clear about whether that limitation applies to
ReadString or not [4], but the backing implementation has no internal
lock to protect from changes made before the internal reference is
copied into a new slice [5].  We're unlikely to actually have parallel
writes for our Terraform use-case, but I'd rather be conservative now
and not have to track down a race if someone decides to use
LinePrinter for something concurrent later.

[1]: https://golang.org/pkg/os/exec/#Cmd.Run
[2]: https://golang.org/pkg/os/exec/#Cmd.Output
[3]: https://golang.org/pkg/bytes/#Buffer.Bytes
[4]: https://golang.org/pkg/bytes/#Buffer.ReadString
[5]: https://github.com/golang/go/blob/go1.11.2/src/bytes/buffer.go#L416-L439
wking added a commit to wking/openshift-installer that referenced this pull request Nov 27, 2018
06c5fd3 (openshift-install: log debug output to file, 2018-11-15, openshift#689),
the global logrus level has been TraceLevel.  Decisions about logging
to a particular target are now made when adding the hook for that
target.  This broke our Terraform debug approach, which had been based
on the level for the global logger.  Since 06c5fd3, logrus.GetLevel()
== logrus.DebugLevel will never be true.

With this commit, I've replaced that switch and now just push all
Terraform stdout into the default logger at the debug level.  A new
LinePrinter provides a shim between Terraform's stdout stream and the
line-based log calls.

I've added a local buffer for stderr, because Run [1] doesn't collect
it automatically like Output does [2].

LinePrinter.Lock protects us from parallel writes, because [3]:

  The slice is valid for use only until the next buffer modification
  (that is, only until the next call to a method like Read, Write,
  Reset, or Truncate).

The docs aren't clear about whether that limitation applies to
ReadString or not [4], but the backing implementation has no internal
lock to protect from changes made before the internal reference is
copied into a new slice [5].  We're unlikely to actually have parallel
writes for our Terraform use-case, but I'd rather be conservative now
and not have to track down a race if someone decides to use
LinePrinter for something concurrent later.

[1]: https://golang.org/pkg/os/exec/#Cmd.Run
[2]: https://golang.org/pkg/os/exec/#Cmd.Output
[3]: https://golang.org/pkg/bytes/#Buffer.Bytes
[4]: https://golang.org/pkg/bytes/#Buffer.ReadString
[5]: https://github.com/golang/go/blob/go1.11.2/src/bytes/buffer.go#L416-L439
wking added a commit to wking/openshift-installer that referenced this pull request Nov 27, 2018
06c5fd3 (openshift-install: log debug output to file, 2018-11-15, openshift#689),
the global logrus level has been TraceLevel.  Decisions about logging
to a particular target are now made when adding the hook for that
target.  This broke our Terraform debug approach, which had been based
on the level for the global logger.  Since 06c5fd3, logrus.GetLevel()
== logrus.DebugLevel will never be true.

With this commit, I've replaced that switch and now just push all
Terraform stdout into the default logger at the debug level.  A new
LinePrinter provides a shim between Terraform's stdout stream and the
line-based log calls.

I've added a local buffer for stderr, because Run [1] doesn't collect
it automatically like Output does [2].

LinePrinter.Lock protects us from parallel writes, because [3]:

  The slice is valid for use only until the next buffer modification
  (that is, only until the next call to a method like Read, Write,
  Reset, or Truncate).

The docs aren't clear about whether that limitation applies to
ReadString or not [4], but the backing implementation has no internal
lock to protect from changes made before the internal reference is
copied into a new slice [5].  We're unlikely to actually have parallel
writes for our Terraform use-case, but I'd rather be conservative now
and not have to track down a race if someone decides to use
LinePrinter for something concurrent later.

[1]: https://golang.org/pkg/os/exec/#Cmd.Run
[2]: https://golang.org/pkg/os/exec/#Cmd.Output
[3]: https://golang.org/pkg/bytes/#Buffer.Bytes
[4]: https://golang.org/pkg/bytes/#Buffer.ReadString
[5]: https://github.com/golang/go/blob/go1.11.2/src/bytes/buffer.go#L416-L439
wking added a commit to wking/openshift-installer that referenced this pull request Nov 27, 2018
06c5fd3 (openshift-install: log debug output to file, 2018-11-15, openshift#689),
the global logrus level has been TraceLevel.  Decisions about logging
to a particular target are now made when adding the hook for that
target.  This broke our Terraform debug approach, which had been based
on the level for the global logger.  Since 06c5fd3, logrus.GetLevel()
== logrus.DebugLevel will never be true.

With this commit, I've replaced that switch and now just push all
Terraform stdout into the default logger at the debug level.  A new
LinePrinter provides a shim between Terraform's stdout stream and the
line-based log calls.

I've added a local buffer for stderr, because Run [1] doesn't collect
it automatically like Output does [2].

LinePrinter.Lock protects us from parallel writes, because [3]:

  The slice is valid for use only until the next buffer modification
  (that is, only until the next call to a method like Read, Write,
  Reset, or Truncate).

The docs aren't clear about whether that limitation applies to
ReadString or not [4], but the backing implementation has no internal
lock to protect from changes made before the internal reference is
copied into a new slice [5].  We're unlikely to actually have parallel
writes for our Terraform use-case, but I'd rather be conservative now
and not have to track down a race if someone decides to use
LinePrinter for something concurrent later.

[1]: https://golang.org/pkg/os/exec/#Cmd.Run
[2]: https://golang.org/pkg/os/exec/#Cmd.Output
[3]: https://golang.org/pkg/bytes/#Buffer.Bytes
[4]: https://golang.org/pkg/bytes/#Buffer.ReadString
[5]: https://github.com/golang/go/blob/go1.11.2/src/bytes/buffer.go#L416-L439
wking added a commit to wking/openshift-installer that referenced this pull request Nov 27, 2018
06c5fd3 (openshift-install: log debug output to file, 2018-11-15, openshift#689),
the global logrus level has been TraceLevel.  Decisions about logging
to a particular target are now made when adding the hook for that
target.  This broke our Terraform debug approach, which had been based
on the level for the global logger.  Since 06c5fd3, logrus.GetLevel()
== logrus.DebugLevel will never be true.

With this commit, I've replaced that switch and now just push all
Terraform stdout into the default logger at the debug level.  A new
LinePrinter provides a shim between Terraform's stdout stream and the
line-based log calls.

I've added a local buffer for stderr, because Run [1] doesn't collect
it automatically like Output does [2].

LinePrinter.Lock protects us from parallel writes, because [3]:

  The slice is valid for use only until the next buffer modification
  (that is, only until the next call to a method like Read, Write,
  Reset, or Truncate).

The docs aren't clear about whether that limitation applies to
ReadString or not [4], but the backing implementation has no internal
lock to protect from changes made before the internal reference is
copied into a new slice [5].  We're unlikely to actually have parallel
writes for our Terraform use-case, but I'd rather be conservative now
and not have to track down a race if someone decides to use
LinePrinter for something concurrent later.

[1]: https://golang.org/pkg/os/exec/#Cmd.Run
[2]: https://golang.org/pkg/os/exec/#Cmd.Output
[3]: https://golang.org/pkg/bytes/#Buffer.Bytes
[4]: https://golang.org/pkg/bytes/#Buffer.ReadString
[5]: https://github.com/golang/go/blob/go1.11.2/src/bytes/buffer.go#L416-L439
wking added a commit to wking/openshift-installer that referenced this pull request Nov 28, 2018
06c5fd3 (openshift-install: log debug output to file, 2018-11-15, openshift#689),
the global logrus level has been TraceLevel.  Decisions about logging
to a particular target are now made when adding the hook for that
target.  This broke our Terraform debug approach, which had been based
on the level for the global logger.  Since 06c5fd3, logrus.GetLevel()
== logrus.DebugLevel will never be true.

With this commit, I've replaced that switch and now just push all
Terraform stdout into the default logger at the debug level.  A new
LinePrinter provides a shim between Terraform's stdout stream and the
line-based log calls.

I've added a local buffer for stderr, because Run [1] doesn't collect
it automatically like Output does [2].

LinePrinter.Lock protects us from parallel writes, because [3]:

  The slice is valid for use only until the next buffer modification
  (that is, only until the next call to a method like Read, Write,
  Reset, or Truncate).

The docs aren't clear about whether that limitation applies to
ReadString or not [4], but the backing implementation has no internal
lock to protect from changes made before the internal reference is
copied into a new slice [5].  We're unlikely to actually have parallel
writes for our Terraform use-case, but I'd rather be conservative now
and not have to track down a race if someone decides to use
LinePrinter for something concurrent later.

The mutex is embedded at Alex's recommendation [6].

[1]: https://golang.org/pkg/os/exec/#Cmd.Run
[2]: https://golang.org/pkg/os/exec/#Cmd.Output
[3]: https://golang.org/pkg/bytes/#Buffer.Bytes
[4]: https://golang.org/pkg/bytes/#Buffer.ReadString
[5]: https://github.com/golang/go/blob/go1.11.2/src/bytes/buffer.go#L416-L439
[6]: openshift#730 (comment)
wking added a commit to wking/openshift-installer that referenced this pull request Dec 14, 2018
These were inconsistencies from 06c5fd3 (openshift-install: log debug
output to file, 2018-11-15, openshift#689).
wking added a commit to wking/openshift-release that referenced this pull request Dec 19, 2018
This makes it easier for folks who are less familiar with the debug
logs to find the actual error message.  For folks who *do* need access
to the debug logs, we still have those in the recovered artifacts
since openshift/installer@06c5fd36 (openshift-install: log debug
output to file, 2018-11-15, openshift/installer#689).

Generated with:

  $ sed -i 's/--log-level.debug //' $(git grep -l -- '--log-level.debug')
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
approved Indicates a PR has been approved by an approver from all required OWNERS files. lgtm Indicates that a PR is ready to be merged. size/L Denotes a PR that changes 100-499 lines, ignoring generated files.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

5 participants