From 5848f67a392eda415622df3b25623d6712979319 Mon Sep 17 00:00:00 2001 From: Gregory Haskins Date: Tue, 24 Jan 2017 21:45:58 -0500 Subject: [PATCH] [FAB-1855] Capture chaincode stdout from docker This code captures all output from stdout/stderr originating from our peer-launched docker containers and stuffs it into a custom logger on a per-chaincode basis. It is enabled by the configuration knob "CORE_VM_DOCKER_ATTACHSTDOUT=true" and defaults to disabled. This should allow an admin or developer to enable this log at their discretion to assist with debugging container problems, while minimizing risk for malicious/faulty chaincodes to threaten the peer with unmitigated logging. Change-Id: I3f36958c41f14981e2e0f412b7e46589e6fa7110 Signed-off-by: Greg Haskins --- .../dockercontroller/dockercontroller.go | 80 ++++++++++++++++++- docs/Setup/logging-control.md | 8 +- peer/core.yaml | 4 + 3 files changed, 87 insertions(+), 5 deletions(-) diff --git a/core/container/dockercontroller/dockercontroller.go b/core/container/dockercontroller/dockercontroller.go index dd9fcf68c49..126161c2f56 100644 --- a/core/container/dockercontroller/dockercontroller.go +++ b/core/container/dockercontroller/dockercontroller.go @@ -21,6 +21,9 @@ import ( "fmt" "io" "strings" + "time" + + "bufio" "github.com/fsouza/go-dockerclient" "github.com/hyperledger/fabric/core/container/ccintf" @@ -100,8 +103,8 @@ func getDockerHostConfig() *docker.HostConfig { return hostConfig } -func (vm *DockerVM) createContainer(ctxt context.Context, client *docker.Client, imageID string, containerID string, args []string, env []string) error { - config := docker.Config{Cmd: args, Image: imageID, Env: env} +func (vm *DockerVM) createContainer(ctxt context.Context, client *docker.Client, imageID string, containerID string, args []string, env []string, attachStdout bool) error { + config := docker.Config{Cmd: args, Image: imageID, Env: env, AttachStdout: attachStdout, AttachStderr: attachStdout} copts := docker.CreateContainerOptions{Name: containerID, Config: &config, HostConfig: getDockerHostConfig()} dockerLogger.Debugf("Create container: %s", containerID) _, err := client.CreateContainer(copts) @@ -160,13 +163,14 @@ func (vm *DockerVM) Start(ctxt context.Context, ccid ccintf.CCID, args []string, } containerID := strings.Replace(imageID, ":", "_", -1) + attachStdout := viper.GetBool("vm.docker.attachStdout") //stop,force remove if necessary dockerLogger.Debugf("Cleanup container %s", containerID) vm.stopInternal(ctxt, client, containerID, 0, false, false) dockerLogger.Debugf("Start container %s", containerID) - err = vm.createContainer(ctxt, client, imageID, containerID, args, env) + err = vm.createContainer(ctxt, client, imageID, containerID, args, env, attachStdout) if err != nil { //if image not found try to create image and retry if err == docker.ErrNoSuchImage { @@ -177,7 +181,7 @@ func (vm *DockerVM) Start(ctxt context.Context, ccid ccintf.CCID, args []string, } dockerLogger.Debug("start-recreated image successfully") - if err = vm.createContainer(ctxt, client, imageID, containerID, args, env); err != nil { + if err = vm.createContainer(ctxt, client, imageID, containerID, args, env, attachStdout); err != nil { dockerLogger.Errorf("start-could not recreate container post recreate image: %s", err) return err } @@ -191,6 +195,74 @@ func (vm *DockerVM) Start(ctxt context.Context, ccid ccintf.CCID, args []string, } } + if attachStdout { + // Launch a few go-threads to manage output streams from the container. + // They will be automatically destroyed when the container exits + attached := make(chan struct{}) + r, w := io.Pipe() + + go func() { + // AttachToContainer will fire off a message on the "attached" channel once the + // attachment completes, and then block until the container is terminated. + err = client.AttachToContainer(docker.AttachToContainerOptions{ + Container: containerID, + OutputStream: w, + ErrorStream: w, + Logs: true, + Stdout: true, + Stderr: true, + Stream: true, + Success: attached, + }) + + // If we get here, the container has terminated. Send a signal on the pipe + // so that downstream may clean up appropriately + _ = w.CloseWithError(err) + }() + + go func() { + // Block here until the attachment completes or we timeout + select { + case <-attached: + // successful attach + case <-time.After(10 * time.Second): + dockerLogger.Errorf("Timeout while attaching to IO channel in container %s", containerID) + return + } + + // Acknowledge the attachment? This was included in the gist I followed + // (http://bit.ly/2jBrCtM). Not sure it's actually needed but it doesn't + // appear to hurt anything. + attached <- struct{}{} + + // Establish a buffer for our IO channel so that we may do readline-style + // ingestion of the IO, one log entry per line + is := bufio.NewReader(r) + + // Acquire a custom logger for our chaincode, inheriting the level from the peer + containerLogger := logging.MustGetLogger(containerID) + logging.SetLevel(logging.GetLevel("peer"), containerID) + + for { + // Loop forever dumping lines of text into the containerLogger + // until the pipe is closed + line, err := is.ReadString('\n') + if err != nil { + switch err { + case io.EOF: + dockerLogger.Infof("Container %s has closed its IO channel", containerID) + default: + dockerLogger.Errorf("Error reading container output: %s", err) + } + + return + } + + containerLogger.Info(line) + } + }() + } + // start container with HostConfig was deprecated since v1.10 and removed in v1.2 err = client.StartContainer(containerID, nil) if err != nil { diff --git a/docs/Setup/logging-control.md b/docs/Setup/logging-control.md index b0ad8d21816..1bde4f51501 100644 --- a/docs/Setup/logging-control.md +++ b/docs/Setup/logging-control.md @@ -60,7 +60,13 @@ settings): ## Go chaincodes -As independently executed programs, user-provided chaincodes can use any appropriate technique to create their private logs - from simple print statements to fully-annotated and level-controlled logs. The chaincode `shim` package provides APIs that allow a chaincode to create and manage logging objects whose logs will be formatted and interleaved consistently with the `shim` logs. +The standard mechanism to log within a chaincode application is to integrate with the logging transport exposed to each chaincode instance via the peer. The chaincode `shim` package provides APIs that allow a chaincode to create and manage logging objects whose logs will be formatted and interleaved consistently with the `shim` logs. + +As independently executed programs, user-provided chaincodes may technically also produce output on stdout/stderr. While naturally useful for "devmode", these channels are normally disabled on a production network to mitigate abuse from broken or malicious code. However, it is possible to enable this output even for peer-managed containers (e.g. "netmode") on a per-peer basis via the CORE_VM_DOCKER_ATTACHSTDOUT=true configuration option. + +Once enabled, each chaincode will receive its own logging channel keyed by its container-id. Any output written to either stdout or stderr will be integrated with the peer's log on a per-line basis. It is not recommended to enable this for production. + +### API `NewLogger(name string) *ChaincodeLogger` - Create a logging object for use by a chaincode diff --git a/peer/core.yaml b/peer/core.yaml index 41529546710..d7a10021fbe 100644 --- a/peer/core.yaml +++ b/peer/core.yaml @@ -180,6 +180,10 @@ vm: file: /path/to/ca.pem key: file: /path/to/server-key.pem + + # Enables/disables the standard out/err from chaincode containers for debugging purposes + attachStdout: false + # Parameters of docker container creating. For docker can created by custom parameters # If you have your own ipam & dns-server for cluster you can use them to create container efficient. # NetworkMode Sets the networking mode for the container. Supported standard values are: `host`(default),`bridge`,`ipvlan`,`none`