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

pkg/lineprinter: Add a wrapper for Write -> Print #730

Merged
merged 1 commit into from
Dec 1, 2018

Conversation

wking
Copy link
Member

@wking wking commented Nov 26, 2018

06c5fd3 (#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 doesn't collect it automatically like Output does.

LinePrinter.Lock protects us from parallel writes, because:

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, but the backing implementation has no internal lock to protect from changes made before the internal reference is copied into a new slice. 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.

@openshift-ci-robot openshift-ci-robot added size/L Denotes a PR that changes 100-499 lines, ignoring generated files. approved Indicates a PR has been approved by an approver from all required OWNERS files. labels Nov 26, 2018
@abhinavdahiya
Copy link
Contributor

Whats the reasoning for impl io.WriterCloser vs io.Writer ? https://golang.org/pkg/os/exec/#Cmd Stdout is only io.Writer ?

@wking
Copy link
Member Author

wking commented Nov 26, 2018

What's the reasoning for impl io.WriterCloser vs io.Writer?

I wanted to be able to ensure any final subprocess output was logged, even if the subprocess died mid-line without having printed a trailing newline. A Close method seemed like a reasonable trigger for "and flush any remaining output from the buffer".

@abhinavdahiya
Copy link
Contributor

What's the reasoning for impl io.WriterCloser vs io.Writer?

I wanted to be able to ensure any final subprocess output was logged, even if the subprocess died mid-line without having printed a trailing newline. A Close method seemed like a reasonable trigger for "and flush any remaining output from the buffer".

I wanted to be able to ensure any final subprocess output was logged, even if the subprocess died mid-line without having printed a trailing newline.

hmm 😕 , it is preventing the installer from dying mid-priniting not subprocess right?

@wking
Copy link
Member Author

wking commented Nov 26, 2018

I wanted to be able to ensure any final subprocess output was logged, even if the subprocess died mid-line without having printed a trailing newline.

hmm, it is preventing the installer from dying mid-priniting not subprocess right?

It's not keeping anything from dying. It's ensuring that, if the Terraform subprocess happens to die mid-line, that we still get that partial line in the logs. There's nothing we can do about the installer dying mid-line (collecting that would be up to whoever was calling the installer).

@wking
Copy link
Member Author

wking commented Nov 27, 2018

The e2e-aws errors included:

fail [github.com/openshift/origin/test/extended/util/cli.go:193]: Expected error:
    <*errors.StatusError | 0xc422726630>: {
        ErrStatus: {
            TypeMeta: {Kind: "", APIVersion: ""},
            ListMeta: {SelfLink: "", ResourceVersion: "", Continue: ""},
            Status: "Failure",
            Message: "projectrequests.project.openshift.io is forbidden: User \"e2e-test-router-stress-dvrq5-user\" cannot create projectrequests.project.openshift.io at the cluster scope: RBAC: clusterrole.rbac.authorization.k8s.io \"self-provisioner\" not found",
            Reason: "Forbidden",
            Details: {
                Name: "",
                Group: "project.openshift.io",
                Kind: "projectrequests",
                UID: "",
                Causes: nil,
                RetryAfterSeconds: 0,
            },
            Code: 403,
        },
    }
    projectrequests.project.openshift.io is forbidden: User "e2e-test-router-stress-dvrq5-user" cannot create projectrequests.project.openshift.io at the cluster scope: RBAC: clusterrole.rbac.authorization.k8s.io "self-provisioner" not found
not to have occurred

failed: (23s) "[Conformance][Area:Networking][Feature:Router] The HAProxy router converges when multiple routers are writing status [Suite:openshift/conformance/parallel/minimal] [Suite:openshift/smoke-4]"

which would be orthogonal to this change. You can see that the Terraform logs are being captured again.

/retest

@abhinavdahiya
Copy link
Contributor

from https://storage.googleapis.com/origin-ci-test/pr-logs/pull/openshift_installer/730/pull-ci-openshift-installer-master-e2e-aws/1614/artifacts/e2e-aws/installer/.openshift_install.log

"module.vpc.aws_security_group_rule.console_ingress_https: Creation complete after 1s (ID: sgrule-2100279484)\n"

There is trailing \n do we want to remove that?

@wking
Copy link
Member Author

wking commented Nov 27, 2018

There is trailing \n do we want to remove that?

Ah, yes. Should be fixed with debabb6 -> c4c3c63 aa7162a (edit: I'd forgotten to add/commit the new trimmer Go ;).

@wking
Copy link
Member Author

wking commented Nov 27, 2018

No newlines now.

/retest

@@ -0,0 +1,27 @@
package lineprinter
Copy link
Contributor

Choose a reason for hiding this comment

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

lineprinters is splitting on \n it should be the one trimming it. Why add something new?

Copy link
Member Author

Choose a reason for hiding this comment

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

lineprinters is splitting on \n it should be the one trimming it. Why add something new?

If you hook LinePrinter up to fmt.Print, you do want the trailing newlines:

$ cat test.go
package main

import (
	"fmt"

	"github.com/openshift/installer/pkg/lineprinter"
)

func main() {
	linePrinter := &lineprinter.LinePrinter{
		Print: func (args ...interface{}) {
			fmt.Print(args...)
		},
	}
	linePrinter.Write([]byte("1\n2\n3\n4"))
	linePrinter.Close()
}
$ go run test.go 
1
2
3
4

Copy link
Contributor

Choose a reason for hiding this comment

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

lineprinters is splitting on \n it should be the one trimming it. Why add something new?

If you hook LinePrinter up to fmt.Print, you do want the trailing newlines:

$ cat test.go
package main

import (
	"fmt"

	"github.com/openshift/installer/pkg/lineprinter"
)

func main() {
	linePrinter := &lineprinter.LinePrinter{
		Print: func (args ...interface{}) {
			fmt.Print(args...)
		},
	}
	linePrinter.Write([]byte("1\n2\n3\n4"))
	linePrinter.Close()
}
$ go run test.go 
1
2
3
4

This example makes it seems like lineprinter is not named correctly then.

Copy link
Member Author

Choose a reason for hiding this comment

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

This example makes it seems like lineprinter is not named correctly then.

It reads in a stream and calls the wrapped print on each line. What would you call it instead?

@wking wking force-pushed the terraform-to-logger branch 2 times, most recently from 77f0380 to d94db67 Compare November 27, 2018 18:27
@wking
Copy link
Member Author

wking commented Nov 27, 2018

Dunno what these failures are about, looks like they are maybe all artifact-upload failures?

/retest

// any remaining partial line.
type LinePrinter struct {
buf bytes.Buffer
lock sync.Mutex
Copy link
Contributor

Choose a reason for hiding this comment

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

Mutexes are usually embedded so you can "lock" the struct directly.

Copy link
Member Author

Choose a reason for hiding this comment

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

Mutexes are usually embedded so you can "lock" the struct directly.

Done with d94db67 -> 2dd9230.

@crawford
Copy link
Contributor

This looks good to me. Sorry for breaking it in the first place and writing that conditional before that!

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)
@crawford
Copy link
Contributor

/lgtm
/retest

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

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: 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:

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

/retest

1 similar comment
@smarterclayton
Copy link
Contributor

/retest

@wking
Copy link
Member Author

wking commented Nov 30, 2018

/retest

@wking
Copy link
Member Author

wking commented Nov 30, 2018

e2e-aws has lots of errors like:

E1130 04:12:20.659512     460 memcache.go:147] couldn't get resource list for route.openshift.io/v1: the server could not find the requested resource
E1130 04:12:20.707030     460 memcache.go:147] couldn't get resource list for user.openshift.io/v1: the server could not find the requested resource

But #724 went through recently, so maybe if we try again... 🤞

/retest

@wking
Copy link
Member Author

wking commented Nov 30, 2018

/retest

@wking
Copy link
Member Author

wking commented Nov 30, 2018

/retest

See if openshift/release#2269 helped.

@wking
Copy link
Member Author

wking commented Nov 30, 2018

$ oc project ci-op-s2mqkj8s
$ oc logs e2e-aws -c test
...
fail [k8s.io/kubernetes/test/e2e/scheduling/resource_quota.go:129]: Expected error:
    <*errors.errorString | 0xc420091570>: {
        s: "timed out waiting for the condition",
    }
    timed out waiting for the condition
not to have occurred

failed: (1m35s) "[sig-scheduling] ResourceQuota should create a ResourceQuota and capture the life of a secret. [Suite:openshift/conformance/parallel] [Suite:k8s] [Suite:openshift/smoke-4]"

started: (1/235/325) "[k8s.io] Pods should be updated [NodeConformance] [Conformance] [Suite:openshift/conformance/parallel/minimal] [Suite:k8s] [Suite:openshift/smoke-4]"
...

That's {failed}/{index}/{total}, so we got pretty far in, but are still going to fail :/.

@wking
Copy link
Member Author

wking commented Dec 1, 2018

/retest

1 similar comment
@wking
Copy link
Member Author

wking commented Dec 1, 2018

/retest

@openshift-bot
Copy link
Contributor

/retest

Please review the full test history for this PR and help us cut down flakes.

@openshift-ci-robot
Copy link
Contributor

@wking: The following test failed, say /retest to rerun them all:

Test name Commit Details Rerun command
ci/prow/e2e-libvirt 2dd9230 link /test e2e-libvirt

Full PR test history. Your PR dashboard. Please help us cut down on flakes by linking to an open issue when you hit one in your PR.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository. I understand the commands that are listed here.

@openshift-merge-robot openshift-merge-robot merged commit 6757fcd into openshift:master Dec 1, 2018
@wking wking deleted the terraform-to-logger branch December 2, 2018 04:36
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.

7 participants