[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 <[email protected]>

Author: ghaskins

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 {

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
 

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`