Correct logging functionality (#59)

* Correct logging functionality

 * Consume ServiceLoggers such that go-java-launcher can retain it's expected
   behavior of always logging to standard out
 * Adds clarity to go-init intentionally only truncating log files once, and
   also correctly truncates all processes being restarted, not just the
   primary

* remove unused const file

* make file flags public

* go-java-launcher integration test

* fail immediately if cannot log, update README

README.md

@@ -106,8 +106,7 @@ The launcher is invoked as:
 go-java-launcher [<path to StaticLauncherConfig> [<path to CustomLauncherConfig>]]
 ```
 
-where the
-static configuration file defaults to `./launcher-static.yml` and the custom configuration file defaults to
+where the static configuration file defaults to `./launcher-static.yml` and the custom configuration file defaults to
 `./launcher-custom.yml`. It assembles the configuration options and executes the following command (where `<static.xyz>`
 and `<custom.xyz>` refer to the options from the two configuration files, respectively):
 
@@ -136,15 +135,19 @@ for `CUSTOM_PATH`. The following fixed expansions are supported:
 Expansions are only performed on the values. No expansions are performed on the keys. Note that the JAVA_HOME
 environment cannot be overwritten with this mechanism; use the `javaHome` mechanism in `StaticLauncherConfig` instead.
 
+All output from `go-java-launcher` itself, and from the launch of all processes themselves is directed to stdout.
+
 # go-init
 
 This repository also publishes a binary called `go-init` that supports the commands `start`, `status`, and `stop`, in
 adherence with the
 [Linux Standard Base](http://refspecs.linuxbase.org/LSB_3.1.1/LSB-Core-generic/LSB-Core-generic/iniscrptact.html)
 specification for init scripts. The binary reads configuration from (relative to its working directory)
-`service/bin/launcher-static.yml` and `var/conf/launcher-custom.yml` in the same vein as `go-java-launcher`, and outputs
-to `var/log/startup.log` and other `var/log/${SUB_PROCESS}-startup.log` files. `go-init` does not launch each
-`subProcess` as a child process of the primary process.
+`service/bin/launcher-static.yml` and `var/conf/launcher-custom.yml` in the same vein as `go-java-launcher`, but instead
+outputs its own logging and that of the primary process to `var/log/startup.log`.  Logs on the compilation of a
+command used to launch a specific subProcesses, and its subsequent stdout and stderr streams are directed to
+`var/log/${SUB_PROCESS}-startup.log` files. `go-init` does not launch each `subProcess` as a child process of the
+primary process.
 
 # License
 This repository is made available under the [Apache 2.0 License](http://www.apache.org/licenses/LICENSE-2.0).

init/cli/cli.go

@@ -16,9 +16,7 @@ package cli
 
 import (
 	"fmt"
-	"log"
 	"os"
-	"path/filepath"
 
 	"github.com/palantir/pkg/cli"
 	"github.com/pkg/errors"
@@ -35,33 +33,34 @@ func App() *cli.App {
 	return app
 }
 
-func executeWithContext(action func(cli.Context) error, fileFlag int) func(cli.Context) error {
+func executeWithLoggers(action func(cli.Context, launchlib.ServiceLoggers) error, flags FileFlags) func(cli.Context) error {
 	return func(ctx cli.Context) (rErr error) {
 		// Fall back to default stdout if error opening log file
-		outputParentDir := filepath.Dir(launchlib.PrimaryOutputFile)
-		if err := os.MkdirAll(outputParentDir, 0755); err != nil {
-			log.Printf("Encountered error during MkdirAll the output dir '%s': %v, falling back to stdout",
-				outputParentDir, err)
-			return action(ctx)
+		if err := os.MkdirAll(logDir, 0755); err != nil {
+			return logErrorAndReturnWithExitCode(
+				ctx, errors.Wrapf(err, "Error trying to make log directory '%s'", logDir), 4)
 		}
-		outputFile, err := os.OpenFile(launchlib.PrimaryOutputFile, fileFlag, outputFileMode)
+
+		loggers := &FileLoggers{
+			flags: flags,
+			mode:  outputFileMode,
+		}
+
+		outputFile, err := loggers.PrimaryLogger()
 		if err != nil {
-			log.Printf("Encountered error opening the primary output file '%s': %v, falling back to stdout",
-				launchlib.PrimaryOutputFile, err)
-			return action(ctx)
+			return logErrorAndReturnWithExitCode(ctx, errors.Wrap(err, "Error opening startup log file"), 4)
 		}
 		defer func() {
 			if cErr := outputFile.Close(); rErr == nil && cErr != nil {
 				/*
 				 * Exit 0 and communicate "success with errors" because although we failed to close the
 				 * output file, we're a cli and the OS will close it for us momentarily
 				 */
-				rErr = cli.WithExitCode(0, errors.Errorf("failed to close primary output file: %s",
-					launchlib.PrimaryOutputFile))
+				rErr = cli.WithExitCode(0, errors.Errorf("failed to close primary output file"))
 			}
 		}()
 		ctx.App.Stdout = outputFile
-		return action(ctx)
+		return action(ctx, loggers)
 	}
 }
 

init/cli/lib.go

@@ -17,6 +17,8 @@ package cli
 import (
 	"io/ioutil"
 	"os"
+	"os/exec"
+	"path/filepath"
 	"syscall"
 
 	"github.com/palantir/pkg/cli"
@@ -31,32 +33,44 @@ const (
 	truncOutputFileFlag  = outputFileFlag | os.O_TRUNC
 	appendOutputFileFlag = outputFileFlag | os.O_APPEND
 	outputFileMode       = 0644
+
+	outputLogFile = "startup.log"
 )
 
 var (
 	launcherStaticFile = "service/bin/launcher-static.yml"
 	launcherCustomFile = "var/conf/launcher-custom.yml"
 	pidfile            = "var/run/pids.yml"
+
+	logDir                     = "var/log"
+	PrimaryOutputFile          = filepath.Join(logDir, outputLogFile)
+	SubProcessOutputFileFormat = filepath.Join(logDir, "%s-"+outputLogFile)
 )
 
+type CommandContext struct {
+	Command *exec.Cmd
+	Logger  launchlib.CreateLogger
+	Dirs    []string
+}
+
 type servicePids map[string]int
 
 type serviceStatus struct {
-	notRunningCmds map[string]launchlib.CmdWithContext
+	notRunningCmds map[string]CommandContext
 	writtenPids    servicePids
 	runningProcs   map[string]*os.Process
 }
 
-func getServiceStatus(ctx cli.Context) (*serviceStatus, error) {
-	cmds, err := getConfiguredCommands(ctx)
+func getServiceStatus(ctx cli.Context, loggers launchlib.ServiceLoggers) (*serviceStatus, error) {
+	cmds, err := getConfiguredCommands(ctx, loggers)
 	if err != nil {
 		return nil, errors.Wrap(err, "failed to get commands from static and custom configuration files")
 	}
 	writtenPids, runningProcs, err := getPidfileInfo()
 	if err != nil {
 		return nil, errors.Wrap(err, "failed to determine running processes")
 	}
-	notRunningCmds := make(map[string]launchlib.CmdWithContext)
+	notRunningCmds := make(map[string]CommandContext)
 	for name, cmd := range cmds {
 		if _, ok := runningProcs[name]; !ok {
 			notRunningCmds[name] = cmd
@@ -86,20 +100,33 @@ func getPidfileInfo() (servicePids, map[string]*os.Process, error) {
 	return servicePids, runningProcs, nil
 }
 
-func getConfiguredCommands(ctx cli.Context) (map[string]launchlib.CmdWithContext, error) {
+func getConfiguredCommands(ctx cli.Context, loggers launchlib.ServiceLoggers) (map[string]CommandContext, error) {
 	staticConfig, customConfig, err := launchlib.GetConfigsFromFiles(launcherStaticFile, launcherCustomFile,
 		ctx.App.Stdout)
 	if err != nil {
 		return nil, errors.Wrap(err, "failed to read static and custom configuration files")
 	}
-	serviceCmds, err := launchlib.CompileCmdsFromConfig(&staticConfig, &customConfig, ctx.App.Stdout)
+	serviceCmds, err := launchlib.CompileCmdsFromConfig(&staticConfig, &customConfig, loggers)
 	if err != nil {
 		return nil, errors.Wrap(err, "failed to compile commands from static and custom configurations")
 	}
-	cmds := make(map[string]launchlib.CmdWithContext)
-	cmds[staticConfig.ServiceName] = serviceCmds.Primary
-	for name, subProc := range serviceCmds.SubProcs {
-		cmds[name] = subProc
+	cmds := make(map[string]CommandContext)
+	cmds[staticConfig.ServiceName] = CommandContext{
+		serviceCmds.Primary,
+		loggers.PrimaryLogger,
+		staticConfig.Dirs,
+	}
+	for name, subProc := range serviceCmds.SubProcesses {
+		subStatic, ok := staticConfig.SubProcesses[name]
+		if !ok {
+			return nil, errors.Errorf("command given for non-existent subProcess '%s'", name)
+		}
+
+		cmds[name] = CommandContext{
+			subProc,
+			loggers.SubProcessLogger(name),
+			subStatic.Dirs,
+		}
 	}
 	return cmds, nil
 }

init/cli/logging.go

@@ -0,0 +1,80 @@
+// Copyright 2016 Palantir Technologies, Inc.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+package cli
+
+import (
+	"fmt"
+	"io"
+	"os"
+
+	"github.com/pkg/errors"
+
+	"github.com/palantir/go-java-launcher/launchlib"
+)
+
+type FileFlags interface {
+	Get(path string) int
+}
+
+type truncatingFirst struct {
+	created map[string]struct{}
+}
+
+func (t *truncatingFirst) Get(name string) int {
+	if _, ok := t.created[name]; ok {
+		return appendOutputFileFlag
+	}
+	t.created[name] = struct{}{}
+	return truncOutputFileFlag
+}
+
+func NewTruncatingFirst() FileFlags {
+	return &truncatingFirst{
+		make(map[string]struct{}),
+	}
+}
+
+type alwaysAppending struct{}
+
+func (a *alwaysAppending) Get(path string) int {
+	return appendOutputFileFlag
+}
+
+func NewAlwaysAppending() FileFlags {
+	return &alwaysAppending{}
+}
+
+type FileLoggers struct {
+	flags FileFlags
+	mode  os.FileMode
+}
+
+func (f *FileLoggers) PrimaryLogger() (io.WriteCloser, error) {
+	return f.OpenFile(PrimaryOutputFile)
+}
+
+func (f *FileLoggers) SubProcessLogger(name string) launchlib.CreateLogger {
+	return func() (io.WriteCloser, error) {
+		return f.OpenFile(fmt.Sprintf(SubProcessOutputFileFormat, name))
+	}
+}
+
+func (f *FileLoggers) OpenFile(path string) (*os.File, error) {
+	file, err := os.OpenFile(path, f.flags.Get(path), f.mode)
+	if err != nil {
+		return file, errors.Wrapf(err, "could not open logging file '%s'", path)
+	}
+	return file, nil
+}

init/cli/start.go

@@ -34,11 +34,11 @@ Ensures the service defined by the static and custom configurations at service/b
 var/conf/launcher-custom.yml is running and its outputs are redirecting to var/log/startup.log and other
 var/log/${SUB_PROCESS}-startup.log files. If successful, exits 0, otherwise exits 1 and writes an error message to
 stderr and var/log/startup.log.`,
-	Action: executeWithContext(start, truncOutputFileFlag),
+	Action: executeWithLoggers(start, NewTruncatingFirst()),
 }
 
-func start(ctx cli.Context) error {
-	serviceStatus, err := getServiceStatus(ctx)
+func start(ctx cli.Context, loggers launchlib.ServiceLoggers) error {
+	serviceStatus, err := getServiceStatus(ctx, loggers)
 	if err != nil {
 		return logErrorAndReturnWithExitCode(ctx,
 			errors.Wrap(err, "failed to determine service status to determine what commands to run"), 1)
@@ -57,33 +57,34 @@ func start(ctx cli.Context) error {
 	return nil
 }
 
-func startService(ctx cli.Context, notRunningCmds map[string]launchlib.CmdWithContext) (servicePids, error) {
+func startService(ctx cli.Context, notRunningCmds map[string]CommandContext) (servicePids, error) {
 	servicePids := servicePids{}
 	for name, cmd := range notRunningCmds {
 		if err := startCommand(ctx, cmd); err != nil {
 			return nil, errors.Wrapf(err, "failed to start command '%s'", name)
 		}
-		servicePids[name] = cmd.Cmd.Process.Pid
+		servicePids[name] = cmd.Command.Process.Pid
 	}
 	return servicePids, nil
 }
 
-func startCommand(ctx cli.Context, cmd launchlib.CmdWithContext) error {
-	if err := launchlib.MkDirs(cmd.Dirs, ctx.App.Stdout); err != nil {
+func startCommand(ctx cli.Context, cmdCtx CommandContext) error {
+	if err := launchlib.MkDirs(cmdCtx.Dirs, ctx.App.Stdout); err != nil {
 		return errors.Wrap(err, "failed to create directories")
 	}
-	stdout, err := os.OpenFile(cmd.OutputFileName, appendOutputFileFlag, outputFileMode)
+
+	logger, err := cmdCtx.Logger()
 	if err != nil {
-		return errors.Wrapf(err, "failed to open output file: %s", cmd.OutputFileName)
+		return err
 	}
 	defer func() {
-		if cErr := stdout.Close(); cErr != nil {
-			fmt.Fprintf(ctx.App.Stdout, "failed to close output file: %s", cmd.OutputFileName)
+		if cErr := logger.Close(); cErr != nil {
+			fmt.Fprintf(ctx.App.Stdout, "failed to close logger for command")
 		}
 	}()
-	cmd.Cmd.Stdout = stdout
-	cmd.Cmd.Stderr = stdout
-	if err := cmd.Cmd.Start(); err != nil {
+	cmdCtx.Command.Stdout = logger
+	cmdCtx.Command.Stderr = logger
+	if err := cmdCtx.Command.Start(); err != nil {
 		return errors.Wrap(err, "failed to start command")
 	}
 	return nil

init/cli/status.go

@@ -17,6 +17,8 @@ package cli
 import (
 	"github.com/palantir/pkg/cli"
 	"github.com/pkg/errors"
+
+	"github.com/palantir/go-java-launcher/launchlib"
 )
 
 var statusCliCommand = cli.Command{
@@ -30,11 +32,11 @@ Exits:
 - 3 if no processes are running and there is no record of processes having been started
 - 4 if the status cannot be determined
 If exit code is nonzero, writes an error message to stderr and var/log/startup.log.`,
-	Action: executeWithContext(status, appendOutputFileFlag),
+	Action: executeWithLoggers(status, NewAlwaysAppending()),
 }
 
-func status(ctx cli.Context) error {
-	serviceStatus, err := getServiceStatus(ctx)
+func status(ctx cli.Context, loggers launchlib.ServiceLoggers) error {
+	serviceStatus, err := getServiceStatus(ctx, loggers)
 	if err != nil {
 		return logErrorAndReturnWithExitCode(ctx, errors.Wrap(err, "failed to determine service status"), 4)
 	}

init/cli/stop.go

@@ -25,6 +25,7 @@ import (
 	"github.com/pkg/errors"
 
 	time2 "github.com/palantir/go-java-launcher/init/cli/time"
+	"github.com/palantir/go-java-launcher/launchlib"
 )
 
 var (
@@ -38,10 +39,10 @@ var stopCliCommand = cli.Command{
 Ensures the service defined by the static and custom configurations are service/bin/launcher-static.yml and
 var/conf/launcher-custom.yml is not running. If successful, exits 0, otherwise exits 1 and writes an error message to
 stderr and var/log/startup.log. Waits for at least 240 seconds for any processes to stop before sending a SIGKILL.`,
-	Action: executeWithContext(stop, appendOutputFileFlag),
+	Action: executeWithLoggers(stop, NewAlwaysAppending()),
 }
 
-func stop(ctx cli.Context) error {
+func stop(ctx cli.Context, loggers launchlib.ServiceLoggers) error {
 	_, runningProcs, err := getPidfileInfo()
 	if err != nil {
 		return logErrorAndReturnWithExitCode(ctx, errors.Wrap(err, "failed to stop service"), 1)