Ensure InitLogging only initialized once

- Prevents race conditions against logging
  global variables in automated tests that
  repeatedly call RunServices
- Added comment pointing out that client
  handler goroutines may still be in the
  process of stopping after tunnel.Run()
  returns.
- Note: future automated tests that require
  different logging configuration will now
  fail; at that point, another solution
  will be required -- such as implementing
  fully synchronized shutdown in Run()

psiphon/server/log.go

@@ -26,6 +26,7 @@ import (
 	"io/ioutil"
 	go_log "log"
 	"os"
+	"sync"
 
 	"github.com/Psiphon-Inc/logrus"
 	"github.com/Psiphon-Inc/rotate-safe-writer"
@@ -171,44 +172,51 @@ func (f *CustomJSONFormatter) Format(entry *logrus.Entry) ([]byte, error) {
 }
 
 var log *ContextLogger
-
 var logHostID, logBuildRev string
+var initLogging sync.Once
 
 // InitLogging configures a logger according to the specified
 // config params. If not called, the default logger set by the
 // package init() is used.
-// Concurrenty note: should only be called from the main
-// goroutine.
-func InitLogging(config *Config) error {
-
-	logHostID = config.HostID
-	logBuildRev = common.GetBuildInfo().BuildRev
+// Concurrency notes: this should only be called from the main
+// goroutine; InitLogging only has effect on the first call, as
+// the logging facilities it initializes may be in use by other
+// goroutines after that point.
+func InitLogging(config *Config) (retErr error) {
 
-	level, err := logrus.ParseLevel(config.LogLevel)
-	if err != nil {
-		return common.ContextError(err)
-	}
+	initLogging.Do(func() {
 
-	var logWriter io.Writer
+		logHostID = config.HostID
+		logBuildRev = common.GetBuildInfo().BuildRev
 
-	if config.LogFilename != "" {
-		logWriter, err = rotate.NewRotatableFileWriter(config.LogFilename, 0666)
+		level, err := logrus.ParseLevel(config.LogLevel)
 		if err != nil {
-			return common.ContextError(err)
+			retErr = common.ContextError(err)
+			return
 		}
-	} else {
-		logWriter = os.Stderr
-	}
 
-	log = &ContextLogger{
-		&logrus.Logger{
-			Out:       logWriter,
-			Formatter: &CustomJSONFormatter{},
-			Level:     level,
-		},
-	}
+		var logWriter io.Writer
+
+		if config.LogFilename != "" {
+			logWriter, err = rotate.NewRotatableFileWriter(config.LogFilename, 0666)
+			if err != nil {
+				retErr = common.ContextError(err)
+				return
+			}
+		} else {
+			logWriter = os.Stderr
+		}
+
+		log = &ContextLogger{
+			&logrus.Logger{
+				Out:       logWriter,
+				Formatter: &CustomJSONFormatter{},
+				Level:     level,
+			},
+		}
+	})
 
-	return nil
+	return retErr
 }
 
 func init() {

psiphon/server/tunnelServer.go

@@ -98,6 +98,9 @@ func NewTunnelServer(
 // forward tracks its bytes transferred. Overall per-client stats for connection duration,
 // GeoIP, number of port forwards, and bytes transferred are tracked and logged when the
 // client shuts down.
+//
+// Note: client handler goroutines may still be shutting down after Run() returns. See
+// comment in sshClient.stop(). TODO: fully synchronized shutdown.
 func (server *TunnelServer) Run() error {
 
 	type sshListener struct {