Machine readable Notices

* JSON encoded notice objects with structured data payloads
* Easier for clients to consume and parse
* notices.go documents API for consumers
* Rewriter to retain basic, readable console output

ConsoleClient/psiphonClient.go

@@ -68,7 +68,9 @@ func main() {
 			log.Fatalf("error opening log file: %s", err)
 		}
 		defer logFile.Close()
-		log.SetOutput(logFile)
+		psiphon.SetNoticeOutput(logFile)
+	} else {
+		psiphon.SetNoticeOutput(psiphon.NewNoticeConsoleRewriter(os.Stderr))
 	}
 
 	// Handle optional profiling parameter
@@ -134,10 +136,10 @@ func main() {
 	signal.Notify(systemStopSignal, os.Interrupt, os.Kill)
 	select {
 	case <-systemStopSignal:
-		psiphon.Notice(psiphon.NOTICE_INFO, "shutdown by system")
+		psiphon.NoticeInfo("shutdown by system")
 		close(shutdownBroadcast)
 		controllerWaitGroup.Wait()
 	case <-controllerStopSignal:
-		psiphon.Notice(psiphon.NOTICE_INFO, "shutdown by controller")
+		psiphon.NoticeInfo("shutdown by controller")
 	}
 }

psiphon/conn.go

@@ -140,12 +140,12 @@ func Relay(localConn, remoteConn net.Conn) {
 		defer copyWaitGroup.Done()
 		_, err := io.Copy(localConn, remoteConn)
 		if err != nil {
-			Notice(NOTICE_ALERT, "Relay failed: %s", ContextError(err))
+			NoticeAlert("Relay failed: %s", ContextError(err))
 		}
 	}()
 	_, err := io.Copy(remoteConn, localConn)
 	if err != nil {
-		Notice(NOTICE_ALERT, "Relay failed: %s", ContextError(err))
+		NoticeAlert("Relay failed: %s", ContextError(err))
 	}
 	copyWaitGroup.Wait()
 }

psiphon/controller.go

@@ -94,20 +94,20 @@ func NewController(config *Config) (controller *Controller, err error) {
 // - a local SOCKS proxy that port forwards through the pool of tunnels
 // - a local HTTP proxy that port forwards through the pool of tunnels
 func (controller *Controller) Run(shutdownBroadcast <-chan struct{}) {
-	Notice(NOTICE_VERSION, VERSION)
+	NoticeCoreVersion(VERSION)
 
 	// Start components
 
 	socksProxy, err := NewSocksProxy(controller.config, controller)
 	if err != nil {
-		Notice(NOTICE_ALERT, "error initializing local SOCKS proxy: %s", err)
+		NoticeAlert("error initializing local SOCKS proxy: %s", err)
 		return
 	}
 	defer socksProxy.Close()
 
 	httpProxy, err := NewHttpProxy(controller.config, controller)
 	if err != nil {
-		Notice(NOTICE_ALERT, "error initializing local HTTP proxy: %s", err)
+		NoticeAlert("error initializing local HTTP proxy: %s", err)
 		return
 	}
 	defer httpProxy.Close()
@@ -130,9 +130,9 @@ func (controller *Controller) Run(shutdownBroadcast <-chan struct{}) {
 
 	select {
 	case <-shutdownBroadcast:
-		Notice(NOTICE_INFO, "controller shutdown by request")
+		NoticeInfo("controller shutdown by request")
 	case <-controller.componentFailureSignal:
-		Notice(NOTICE_ALERT, "controller shutdown due to component failure")
+		NoticeAlert("controller shutdown due to component failure")
 	}
 
 	close(controller.shutdownBroadcast)
@@ -140,7 +140,7 @@ func (controller *Controller) Run(shutdownBroadcast <-chan struct{}) {
 	controller.fetchRemotePendingConns.CloseAll()
 	controller.runWaitGroup.Wait()
 
-	Notice(NOTICE_INFO, "exiting controller")
+	NoticeInfo("exiting controller")
 }
 
 // SignalComponentFailure notifies the controller that an associated component has failed.
@@ -165,7 +165,7 @@ loop:
 
 		var duration time.Duration
 		if err != nil {
-			Notice(NOTICE_ALERT, "failed to fetch remote server list: %s", err)
+			NoticeAlert("failed to fetch remote server list: %s", err)
 			duration = FETCH_REMOTE_SERVER_LIST_RETRY_PERIOD
 		} else {
 			duration = FETCH_REMOTE_SERVER_LIST_STALE_PERIOD
@@ -179,7 +179,7 @@ loop:
 		}
 	}
 
-	Notice(NOTICE_INFO, "exiting remote server list fetcher")
+	NoticeInfo("exiting remote server list fetcher")
 }
 
 // connectedReporter sends periodic "connected" requests to the Psiphon API.
@@ -202,7 +202,7 @@ loop:
 			if err == nil {
 				reported = true
 			} else {
-				Notice(NOTICE_ALERT, "failed to make connected request: %s", err)
+				NoticeAlert("failed to make connected request: %s", err)
 			}
 		}
 
@@ -222,7 +222,7 @@ loop:
 		}
 	}
 
-	Notice(NOTICE_INFO, "exiting connected reporter")
+	NoticeInfo("exiting connected reporter")
 }
 
 func (controller *Controller) startConnectedReporter() {
@@ -256,9 +256,6 @@ func (controller *Controller) startConnectedReporter() {
 func (controller *Controller) runTunnels() {
 	defer controller.runWaitGroup.Done()
 
-	// Note: calling Count for its logging side-effect.
-	_ = CountServerEntries(controller.config.EgressRegion, controller.config.TunnelProtocol)
-
 	// Start running
 
 	controller.startEstablishing()
@@ -266,7 +263,7 @@ loop:
 	for {
 		select {
 		case failedTunnel := <-controller.failedTunnels:
-			Notice(NOTICE_ALERT, "tunnel failed: %s", failedTunnel.serverEntry.IpAddress)
+			NoticeAlert("tunnel failed: %s", failedTunnel.serverEntry.IpAddress)
 			controller.terminateTunnel(failedTunnel)
 			// Concurrency note: only this goroutine may call startEstablishing/stopEstablishing
 			// and access isEstablishing.
@@ -277,9 +274,8 @@ loop:
 		// !TODO! design issue: might not be enough server entries with region/caps to ever fill tunnel slots
 		// solution(?) target MIN(CountServerEntries(region, protocol), TunnelPoolSize)
 		case establishedTunnel := <-controller.establishedTunnels:
-			Notice(NOTICE_INFO, "established tunnel: %s", establishedTunnel.serverEntry.IpAddress)
 			if controller.registerTunnel(establishedTunnel) {
-				Notice(NOTICE_INFO, "active tunnel: %s", establishedTunnel.serverEntry.IpAddress)
+				NoticeActiveTunnel(establishedTunnel.serverEntry.IpAddress)
 			} else {
 				controller.discardTunnel(establishedTunnel)
 			}
@@ -308,7 +304,7 @@ loop:
 		controller.discardTunnel(tunnel)
 	}
 
-	Notice(NOTICE_INFO, "exiting run tunnels")
+	NoticeInfo("exiting run tunnels")
 }
 
 // SignalTunnelFailure implements the TunnelOwner interface. This function
@@ -329,7 +325,7 @@ func (controller *Controller) SignalTunnelFailure(tunnel *Tunnel) {
 
 // discardTunnel disposes of a successful connection that is no longer required.
 func (controller *Controller) discardTunnel(tunnel *Tunnel) {
-	Notice(NOTICE_INFO, "discard tunnel: %s", tunnel.serverEntry.IpAddress)
+	NoticeInfo("discard tunnel: %s", tunnel.serverEntry.IpAddress)
 	// TODO: not calling PromoteServerEntry, since that would rank the
 	// discarded tunnel before fully active tunnels. Can a discarded tunnel
 	// be promoted (since it connects), but with lower rank than all active
@@ -350,12 +346,12 @@ func (controller *Controller) registerTunnel(tunnel *Tunnel) bool {
 	// a duplicate connection.
 	for _, activeTunnel := range controller.tunnels {
 		if activeTunnel.serverEntry.IpAddress == tunnel.serverEntry.IpAddress {
-			Notice(NOTICE_ALERT, "duplicate tunnel: %s", tunnel.serverEntry.IpAddress)
+			NoticeAlert("duplicate tunnel: %s", tunnel.serverEntry.IpAddress)
 			return false
 		}
 	}
 	controller.tunnels = append(controller.tunnels, tunnel)
-	Notice(NOTICE_TUNNELS, "%d", len(controller.tunnels))
+	NoticeTunnels(len(controller.tunnels))
 	return true
 }
 
@@ -383,7 +379,7 @@ func (controller *Controller) terminateTunnel(tunnel *Tunnel) {
 				controller.nextTunnel = 0
 			}
 			activeTunnel.Close()
-			Notice(NOTICE_TUNNELS, "%d", len(controller.tunnels))
+			NoticeTunnels(len(controller.tunnels))
 			break
 		}
 	}
@@ -399,7 +395,7 @@ func (controller *Controller) terminateAllTunnels() {
 	}
 	controller.tunnels = make([]*Tunnel, 0)
 	controller.nextTunnel = 0
-	Notice(NOTICE_TUNNELS, "%d", len(controller.tunnels))
+	NoticeTunnels(len(controller.tunnels))
 }
 
 // getNextActiveTunnel returns the next tunnel from the pool of active
@@ -453,7 +449,7 @@ func (controller *Controller) startEstablishing() {
 	if controller.isEstablishing {
 		return
 	}
-	Notice(NOTICE_INFO, "start establishing")
+	NoticeInfo("start establishing")
 	controller.isEstablishing = true
 	controller.establishWaitGroup = new(sync.WaitGroup)
 	controller.stopEstablishingBroadcast = make(chan struct{})
@@ -476,7 +472,7 @@ func (controller *Controller) stopEstablishing() {
 	if !controller.isEstablishing {
 		return
 	}
-	Notice(NOTICE_INFO, "stop establishing")
+	NoticeInfo("stop establishing")
 	close(controller.stopEstablishingBroadcast)
 	// Note: on Windows, interruptibleTCPClose doesn't really interrupt socket connects
 	// and may leave goroutines running for a time after the Wait call.
@@ -499,7 +495,7 @@ func (controller *Controller) establishCandidateGenerator() {
 
 	iterator, err := NewServerEntryIterator(controller.config)
 	if err != nil {
-		Notice(NOTICE_ALERT, "failed to iterate over candidates: %s", err)
+		NoticeAlert("failed to iterate over candidates: %s", err)
 		controller.SignalComponentFailure()
 		return
 	}
@@ -508,12 +504,11 @@ func (controller *Controller) establishCandidateGenerator() {
 loop:
 	// Repeat until stopped
 	for {
-
 		// Yield each server entry returned by the iterator
 		for {
 			serverEntry, err := iterator.Next()
 			if err != nil {
-				Notice(NOTICE_ALERT, "failed to get next candidate: %s", err)
+				NoticeAlert("failed to get next candidate: %s", err)
 				controller.SignalComponentFailure()
 				break loop
 			}
@@ -546,7 +541,7 @@ loop:
 	}
 
 	close(controller.candidateServerEntries)
-	Notice(NOTICE_INFO, "stopped candidate generator")
+	NoticeInfo("stopped candidate generator")
 }
 
 // establishTunnelWorker pulls candidates from the candidate queue, establishes
@@ -578,7 +573,7 @@ loop:
 			if controller.isStopEstablishingBroadcast() {
 				break loop
 			}
-			Notice(NOTICE_INFO, "failed to connect to %s: %s", serverEntry.IpAddress, err)
+			NoticeInfo("failed to connect to %s: %s", serverEntry.IpAddress, err)
 			continue
 		}
 
@@ -592,7 +587,7 @@ loop:
 			controller.discardTunnel(tunnel)
 		}
 	}
-	Notice(NOTICE_INFO, "stopped establish worker")
+	NoticeInfo("stopped establish worker")
 }
 
 func (controller *Controller) isStopEstablishingBroadcast() bool {

psiphon/dataStore.go

@@ -182,7 +182,7 @@ func StoreServerEntry(serverEntry *ServerEntry, replaceIfExists bool) error {
 			return ContextError(err)
 		}
 		if serverEntryExists && !replaceIfExists {
-			Notice(NOTICE_INFO, "ignored update for server %s", serverEntry.IpAddress)
+			NoticeInfo("ignored update for server %s", serverEntry.IpAddress)
 			return nil
 		}
 		_, err = transaction.Exec(`
@@ -226,7 +226,7 @@ func StoreServerEntry(serverEntry *ServerEntry, replaceIfExists bool) error {
 		}
 		// TODO: post notice after commit
 		if !serverEntryExists {
-			Notice(NOTICE_INFO, "updated server %s", serverEntry.IpAddress)
+			NoticeInfo("updated server %s", serverEntry.IpAddress)
 		}
 		return nil
 	})
@@ -325,7 +325,7 @@ func newTargetServerEntryIterator(config *Config) (iterator *ServerEntryIterator
 		hasNextTargetServerEntry:    true,
 		targetServerEntry:           serverEntry,
 	}
-	Notice(NOTICE_INFO, "using TargetServerEntry: %s", serverEntry.IpAddress)
+	NoticeInfo("using TargetServerEntry: %s", serverEntry.IpAddress)
 	return iterator, nil
 }
 
@@ -339,6 +339,9 @@ func (iterator *ServerEntryIterator) Reset() error {
 		return nil
 	}
 
+	count := CountServerEntries(iterator.region, iterator.protocol)
+	NoticeCandidateServers(iterator.region, iterator.protocol, count)
+
 	transaction, err := singleton.db.Begin()
 	if err != nil {
 		return ContextError(err)
@@ -475,7 +478,7 @@ func CountServerEntries(region, protocol string) int {
 	err := singleton.db.QueryRow(query, whereParams...).Scan(&count)
 
 	if err != nil {
-		Notice(NOTICE_ALERT, "CountServerEntries failed: %s", err)
+		NoticeAlert("CountServerEntries failed: %s", err)
 		return 0
 	}
 
@@ -485,7 +488,7 @@ func CountServerEntries(region, protocol string) int {
 	if protocol == "" {
 		protocol = "(any)"
 	}
-	Notice(NOTICE_INFO, "servers for region %s and protocol %s: %d",
+	NoticeInfo("servers for region %s and protocol %s: %d",
 		region, protocol, count)
 
 	return count

psiphon/defaults.go

@@ -24,7 +24,7 @@ import (
 )
 
 const (
-	VERSION                                    = "0.0.5"
+	VERSION                                    = "0.0.6"
 	DATA_STORE_FILENAME                        = "psiphon.db"
 	CONNECTION_WORKER_POOL_SIZE                = 10
 	TUNNEL_POOL_SIZE                           = 1

psiphon/httpProxy.go

@@ -44,6 +44,9 @@ func NewHttpProxy(config *Config, tunneler Tunneler) (proxy *HttpProxy, err erro
 	listener, err := net.Listen(
 		"tcp", fmt.Sprintf("127.0.0.1:%d", config.LocalHttpProxyPort))
 	if err != nil {
+		if IsNetworkBindError(err) {
+			NoticeHttpProxyPortInUse(config.LocalSocksProxyPort)
+		}
 		return nil, ContextError(err)
 	}
 	tunneledDialer := func(_, addr string) (conn net.Conn, err error) {
@@ -66,7 +69,7 @@ func NewHttpProxy(config *Config, tunneler Tunneler) (proxy *HttpProxy, err erro
 	}
 	proxy.serveWaitGroup.Add(1)
 	go proxy.serve()
-	Notice(NOTICE_HTTP_PROXY_PORT, "%d", proxy.listener.Addr().(*net.TCPAddr).Port)
+	NoticeListeningHttpProxyPort(proxy.listener.Addr().(*net.TCPAddr).Port)
 	return proxy, nil
 }
 
@@ -103,20 +106,20 @@ func (proxy *HttpProxy) ServeHTTP(responseWriter http.ResponseWriter, request *h
 		hijacker, _ := responseWriter.(http.Hijacker)
 		conn, _, err := hijacker.Hijack()
 		if err != nil {
-			Notice(NOTICE_ALERT, "%s", ContextError(err))
+			NoticeAlert("%s", ContextError(err))
 			http.Error(responseWriter, "", http.StatusInternalServerError)
 			return
 		}
 		go func() {
 			err := proxy.httpConnectHandler(conn, request.URL.Host)
 			if err != nil {
-				Notice(NOTICE_ALERT, "%s", ContextError(err))
+				NoticeAlert("%s", ContextError(err))
 			}
 		}()
 		return
 	}
 	if !request.URL.IsAbs() {
-		Notice(NOTICE_ALERT, "%s", ContextError(errors.New("no domain in request URL")))
+		NoticeAlert("%s", ContextError(errors.New("no domain in request URL")))
 		http.Error(responseWriter, "", http.StatusInternalServerError)
 		return
 	}
@@ -131,7 +134,7 @@ func (proxy *HttpProxy) ServeHTTP(responseWriter http.ResponseWriter, request *h
 	// Relay the HTTP request and get the response
 	response, err := proxy.httpRelay.RoundTrip(request)
 	if err != nil {
-		Notice(NOTICE_ALERT, "%s", ContextError(err))
+		NoticeAlert("%s", ContextError(err))
 		forceClose(responseWriter)
 		return
 	}
@@ -154,7 +157,7 @@ func (proxy *HttpProxy) ServeHTTP(responseWriter http.ResponseWriter, request *h
 	responseWriter.WriteHeader(response.StatusCode)
 	_, err = io.Copy(responseWriter, response.Body)
 	if err != nil {
-		Notice(NOTICE_ALERT, "%s", ContextError(err))
+		NoticeAlert("%s", ContextError(err))
 		forceClose(responseWriter)
 		return
 	}
@@ -237,8 +240,8 @@ func (proxy *HttpProxy) serve() {
 	default:
 		if err != nil {
 			proxy.tunneler.SignalComponentFailure()
-			Notice(NOTICE_ALERT, "%s", ContextError(err))
+			NoticeAlert("%s", ContextError(err))
 		}
 	}
-	Notice(NOTICE_INFO, "HTTP proxy stopped")
+	NoticeInfo("HTTP proxy stopped")
 }

psiphon/meekConn.go

@@ -364,14 +364,14 @@ func (meek *MeekConn) relay() {
 			sendPayloadSize, err = sendBuffer.Read(sendPayload)
 			meek.replaceSendBuffer(sendBuffer)
 			if err != nil {
-				Notice(NOTICE_ALERT, "%s", ContextError(err))
+				NoticeAlert("%s", ContextError(err))
 				go meek.Close()
 				return
 			}
 		}
 		receivedPayload, err := meek.roundTrip(sendPayload[:sendPayloadSize])
 		if err != nil {
-			Notice(NOTICE_ALERT, "%s", ContextError(err))
+			NoticeAlert("%s", ContextError(err))
 			go meek.Close()
 			return
 		}
@@ -381,7 +381,7 @@ func (meek *MeekConn) relay() {
 		}
 		receivedPayloadSize, err := meek.readPayload(receivedPayload)
 		if err != nil {
-			Notice(NOTICE_ALERT, "%s", ContextError(err))
+			NoticeAlert("%s", ContextError(err))
 			go meek.Close()
 			return
 		}

psiphon/notice.go

@@ -20,23 +20,140 @@
 package psiphon
 
 import (
+	"encoding/json"
 	"fmt"
+	"io"
 	"log"
+	"os"
+	"sync"
+	"time"
 )
 
-const (
-	NOTICE_INFO             = "INFO"
-	NOTICE_ALERT            = "ALERT"
-	NOTICE_VERSION          = "VERSION"
-	NOTICE_TUNNELS          = "TUNNELS"
-	NOTICE_SOCKS_PROXY_PORT = "SOCKS-PROXY-PORT"
-	NOTICE_HTTP_PROXY_PORT  = "HTTP-PROXY-PORT"
-	NOTICE_UPGRADE          = "UPGRADE"
-	NOTICE_HOMEPAGE         = "HOMEPAGE"
-	NOTICE_PAGE_VIEW_REGEX  = "PAGE-VIEW-REGEX"
-	NOTICE_HTTPS_REGEX      = "HTTPS-REGEX"
-)
+var noticeLoggerMutex sync.Mutex
+var noticeLogger = log.New(os.Stderr, "", 0)
+
+// SetNoticeOutput sets a target writer to receive notices. By default,
+// notices are written to stderr.
+//
+// Notices are encoded in JSON. Here's an example:
+//
+// {"data":{"message":"shutdown operate tunnel"},"noticeType":"Info","showUser":false,"timestamp":"2015-01-28T17:35:13Z"}
+//
+// All notices have the following fields:
+// - "noticeType": the type of notice, which indicates the meaning of the notice along with what's in the data payload.
+// - "data": additional structured data payload. For example, the "ListeningSocksProxyPort" notice type has a "port" integer
+// data in its payload.
+// - "showUser": whether the information should be displayed to the user. For example, this flag is set for "SocksProxyPortInUse"
+// as the user should be informed that their configured choice of listening port could not be used. Core clients should
+// anticipate that the core will add additional "showUser"=true notices in the future and emit at least the raw notice.
+// - "timestamp": UTC timezone, RFC3339 format timestamp for notice event
+//
+// See the Notice* functions for details on each notice meaning and payload.
+//
+func SetNoticeOutput(output io.Writer) {
+	noticeLoggerMutex.Lock()
+	defer noticeLoggerMutex.Unlock()
+	noticeLogger = log.New(output, "", 0)
+}
+
+// outputNotice encodes a notice in JSON and writes it to the output writer.
+func outputNotice(noticeType string, showUser bool, args ...interface{}) {
+	obj := make(map[string]interface{})
+	noticeData := make(map[string]interface{})
+	obj["noticeType"] = noticeType
+	obj["showUser"] = showUser
+	obj["data"] = noticeData
+	obj["timestamp"] = time.Now().UTC().Format(time.RFC3339)
+	for i := 0; i < len(args)/2; i++ {
+		name, ok := args[i].(string)
+		value := args[i+1]
+		if ok {
+			noticeData[name] = value
+		}
+	}
+	encodedJson, err := json.Marshal(obj)
+	var output string
+	if err == nil {
+		output = string(encodedJson)
+	} else {
+		output = fmt.Sprintf("{\"Alert\":{\"message\":\"%s\"}}", ContextError(err))
+	}
+	noticeLoggerMutex.Lock()
+	defer noticeLoggerMutex.Unlock()
+	noticeLogger.Print(output)
+}
+
+// NoticeInfo is an informational message
+func NoticeInfo(format string, args ...interface{}) {
+	outputNotice("Info", false, "message", fmt.Sprintf(format, args...))
+}
+
+// NoticeInfo is an alert message; typically a recoverable error condition
+func NoticeAlert(format string, args ...interface{}) {
+	outputNotice("Alert", false, "message", fmt.Sprintf(format, args...))
+}
+
+// NoticeInfo is an error message; typically an unrecoverable error condition
+func NoticeError(format string, args ...interface{}) {
+	outputNotice("Error", true, "message", fmt.Sprintf(format, args...))
+}
+
+// NoticeCoreVersion is the version string of the core
+func NoticeCoreVersion(version string) {
+	outputNotice("CoreVersion", false, "version", version)
+}
+
+// NoticeCandidateServers is how many possible servers are available for the selected region and protocol
+func NoticeCandidateServers(region, protocol string, count int) {
+	outputNotice("CandidateServers", false, "region", region, "protocol", protocol, "count", count)
+}
+
+// NoticeConnectingServer is details on a connection attempt
+func NoticeConnectingServer(ipAddress, region, protocol, frontingDomain string) {
+	outputNotice("ConnectingServer", false, "ipAddress", ipAddress, "region",
+		region, "protocol", protocol, "frontingDomain", frontingDomain)
+}
+
+// NoticeActiveTunnel is a successful connection that is used as an active tunnel for port forwarding
+func NoticeActiveTunnel(ipAddress string) {
+	outputNotice("ActiveTunnel", false, "ipAddress", ipAddress)
+}
+
+// NoticeSocksProxyPortInUse is a failure to use the configured LocalSocksProxyPort
+func NoticeSocksProxyPortInUse(port int) {
+	outputNotice("SocksProxyPortInUse", true, "port", port)
+}
+
+// NoticeListeningSocksProxyPort is the selected port for the listening local SOCKS proxy
+func NoticeListeningSocksProxyPort(port int) {
+	outputNotice("ListeningSocksProxyPort", false, "port", port)
+}
+
+// NoticeSocksProxyPortInUse is a failure to use the configured LocalHttpProxyPort
+func NoticeHttpProxyPortInUse(port int) {
+	outputNotice("HttpProxyPortInUse", true, "port", port)
+}
+
+// NoticeListeningSocksProxyPort is the selected port for the listening local HTTP proxy
+func NoticeListeningHttpProxyPort(port int) {
+	outputNotice("ListeningHttpProxyPort", false, "port", port)
+}
+
+// NoticeClientUpgradeAvailable is an available client upgrade, as per the handshake. The
+// client should download and install an upgrade.
+func NoticeClientUpgradeAvailable(version string) {
+	outputNotice("ClientUgradeAvailable", false, "version", version)
+}
+
+// NoticeClientUpgradeAvailable is a sponsor homepage, as per the handshake. The client
+// should display the sponsor's homepage.
+func NoticeHomepage(url string) {
+	outputNotice("Homepage", false, "url", url)
+}
 
-func Notice(prefix, format string, args ...interface{}) {
-	log.Printf("%s %s", prefix, fmt.Sprintf(format, args...))
+// NoticeTunnels is how many active tunnels are available. The client should use this to
+// determine connecting/unexpected disconnect state transitions. When count is 0, the core is
+// disconnected; when count > 1, the core is connected.
+func NoticeTunnels(count int) {
+	outputNotice("Tunnels", false, "count", count)
 }

psiphon/remoteServerList.go

@@ -45,7 +45,7 @@ type RemoteServerList struct {
 // public key config.RemoteServerListSignaturePublicKey; and parses the
 // data field into ServerEntry records.
 func FetchRemoteServerList(config *Config, pendingConns *Conns) (err error) {
-	Notice(NOTICE_INFO, "fetching remote server list")
+	NoticeInfo("fetching remote server list")
 
 	// Note: pendingConns may be used to interrupt the fetch remote server list
 	// request. BindToDevice may be used to exclude requests from VPN routing.

psiphon/serverApi.go

@@ -142,7 +142,7 @@ func NextStatusRequestPeriod() (duration time.Duration) {
 
 	// In case of error we're just going to use zero jitter.
 	if err != nil {
-		Notice(NOTICE_ALERT, "NextStatusRequestPeriod: make jitter failed")
+		NoticeAlert("NextStatusRequestPeriod: make jitter failed")
 	}
 
 	duration = PSIPHON_API_STATUS_REQUEST_PERIOD_MIN + time.Duration(jitter)
@@ -239,10 +239,10 @@ func (session *Session) doHandshakeRequest() error {
 	// TODO: formally communicate the sponsor and upgrade info to an
 	// outer client via some control interface.
 	for _, homepage := range handshakeConfig.Homepages {
-		Notice(NOTICE_HOMEPAGE, homepage)
+		NoticeHomepage(homepage)
 	}
 	if handshakeConfig.UpgradeClientVersion != "" {
-		Notice(NOTICE_UPGRADE, "%s", handshakeConfig.UpgradeClientVersion)
+		NoticeClientUpgradeAvailable(handshakeConfig.UpgradeClientVersion)
 	}
 
 	session.statsRegexps = MakeRegexps(

psiphon/serverEntry.go

@@ -84,7 +84,7 @@ func ValidateServerEntry(serverEntry *ServerEntry) error {
 		errMsg := fmt.Sprintf("server entry has invalid IpAddress: '%s'", serverEntry.IpAddress)
 		// Some callers skip invalid server entries without propagating
 		// the error mesage, so issue a notice.
-		Notice(NOTICE_ALERT, errMsg)
+		NoticeAlert(errMsg)
 		return ContextError(errors.New(errMsg))
 	}
 	return nil

psiphon/socksProxy.go

@@ -46,6 +46,9 @@ func NewSocksProxy(config *Config, tunneler Tunneler) (proxy *SocksProxy, err er
 	listener, err := socks.ListenSocks(
 		"tcp", fmt.Sprintf("127.0.0.1:%d", config.LocalSocksProxyPort))
 	if err != nil {
+		if IsNetworkBindError(err) {
+			NoticeSocksProxyPortInUse(config.LocalSocksProxyPort)
+		}
 		return nil, ContextError(err)
 	}
 	proxy = &SocksProxy{
@@ -57,7 +60,7 @@ func NewSocksProxy(config *Config, tunneler Tunneler) (proxy *SocksProxy, err er
 	}
 	proxy.serveWaitGroup.Add(1)
 	go proxy.serve()
-	Notice(NOTICE_SOCKS_PROXY_PORT, "%d", proxy.listener.Addr().(*net.TCPAddr).Port)
+	NoticeListeningSocksProxyPort(proxy.listener.Addr().(*net.TCPAddr).Port)
 	return proxy, nil
 }
 
@@ -103,7 +106,7 @@ loop:
 		default:
 		}
 		if err != nil {
-			Notice(NOTICE_ALERT, "SOCKS proxy accept error: %s", err)
+			NoticeAlert("SOCKS proxy accept error: %s", err)
 			if e, ok := err.(net.Error); ok && e.Temporary() {
 				// Temporary error, keep running
 				continue
@@ -115,9 +118,9 @@ loop:
 		go func() {
 			err := proxy.socksConnectionHandler(socksConnection)
 			if err != nil {
-				Notice(NOTICE_ALERT, "%s", ContextError(err))
+				NoticeAlert("%s", ContextError(err))
 			}
 		}()
 	}
-	Notice(NOTICE_INFO, "SOCKS proxy stopped")
+	NoticeInfo("SOCKS proxy stopped")
 }

psiphon/stats_collector.go

@@ -112,12 +112,12 @@ func (ss serverStats) MarshalJSON() ([]byte, error) {
 	// In case of randomness fail, we're going to proceed with zero padding.
 	// TODO: Is this okay?
 	if err != nil {
-		Notice(NOTICE_ALERT, "stats.serverStats.MarshalJSON: MakeSecureRandomInt failed")
+		NoticeAlert("stats.serverStats.MarshalJSON: MakeSecureRandomInt failed")
 		padding = make([]byte, 0)
 	} else {
 		padding, err = MakeSecureRandomBytes(paddingSize)
 		if err != nil {
-			Notice(NOTICE_ALERT, "stats.serverStats.MarshalJSON: MakeSecureRandomBytes failed")
+			NoticeAlert("stats.serverStats.MarshalJSON: MakeSecureRandomBytes failed")
 			padding = make([]byte, 0)
 		}
 	}
@@ -136,7 +136,7 @@ func (ss serverStats) MarshalJSON() ([]byte, error) {
 
 	// Print the notice before adding the padding, since it's not interesting
 	noticeJSON, _ := json.Marshal(out)
-	Notice(NOTICE_INFO, "sending stats: %s", noticeJSON)
+	NoticeInfo("sending stats: %s", noticeJSON)
 
 	out["padding"] = base64.StdEncoding.EncodeToString(padding)
 

psiphon/stats_regexp.go

@@ -39,19 +39,19 @@ func MakeRegexps(pageViewRegexes, httpsRequestRegexes []map[string]string) *Rege
 	for _, rr := range httpsRequestRegexes {
 		regexString := rr["regex"]
 		if regexString == "" {
-			Notice(NOTICE_ALERT, "MakeRegexps: empty regex")
+			NoticeAlert("MakeRegexps: empty regex")
 			continue
 		}
 
 		replace := rr["replace"]
 		if replace == "" {
-			Notice(NOTICE_ALERT, "MakeRegexps: empty replace")
+			NoticeAlert("MakeRegexps: empty replace")
 			continue
 		}
 
 		regex, err := regexp.Compile(regexString)
 		if err != nil {
-			Notice(NOTICE_ALERT, "MakeRegexps: failed to compile regex: %s: %s", regexString, err)
+			NoticeAlert("MakeRegexps: failed to compile regex: %s: %s", regexString, err)
 			continue
 		}
 

psiphon/tunnel.go

@@ -104,8 +104,6 @@ func EstablishTunnel(
 	if err != nil {
 		return nil, ContextError(err)
 	}
-	Notice(NOTICE_INFO, "connecting to %s in region %s using %s",
-		serverEntry.IpAddress, serverEntry.Region, selectedProtocol)
 
 	// Build transport layers and establish SSH connection
 	conn, closedSignal, sshClient, err := dialSsh(
@@ -143,7 +141,7 @@ func EstablishTunnel(
 	// proceed with this tunnel as long as at least one previous handhake succeeded?
 	//
 	if !config.DisableApi {
-		Notice(NOTICE_INFO, "starting session for %s", tunnel.serverEntry.IpAddress)
+		NoticeInfo("starting session for %s", tunnel.serverEntry.IpAddress)
 		tunnel.session, err = NewSession(config, tunnel, sessionId)
 		if err != nil {
 			return nil, ContextError(fmt.Errorf("error starting session for %s: %s", tunnel.serverEntry.IpAddress, err))
@@ -246,7 +244,7 @@ func (conn *TunneledConn) Write(buffer []byte) (n int, err error) {
 // SignalComponentFailure notifies the tunnel that an associated component has failed.
 // This will terminate the tunnel.
 func (tunnel *Tunnel) SignalComponentFailure() {
-	Notice(NOTICE_ALERT, "tunnel received component failure signal")
+	NoticeAlert("tunnel received component failure signal")
 	tunnel.Close()
 }
 
@@ -306,6 +304,16 @@ func dialSsh(
 		port = serverEntry.SshPort
 	}
 
+	frontingDomain := ""
+	if useFronting {
+		frontingDomain = serverEntry.MeekFrontingDomain
+	}
+	NoticeConnectingServer(
+		serverEntry.IpAddress,
+		serverEntry.Region,
+		selectedProtocol,
+		frontingDomain)
+
 	// Create the base transport: meek or direct connection
 	dialConfig := &DialConfig{
 		UpstreamHttpProxyAddress: config.UpstreamHttpProxyAddress,
@@ -451,8 +459,7 @@ func (tunnel *Tunnel) operateTunnel(config *Config, tunnelOwner TunnelOwner) {
 		case failures := <-tunnel.portForwardFailures:
 			// Note: no mutex on portForwardFailureTotal; only referenced here
 			tunnel.portForwardFailureTotal += failures
-			Notice(
-				NOTICE_INFO, "port forward failures for %s: %d",
+			NoticeInfo("port forward failures for %s: %d",
 				tunnel.serverEntry.IpAddress, tunnel.portForwardFailureTotal)
 			if tunnel.portForwardFailureTotal > config.PortForwardFailureThreshold {
 				err = errors.New("tunnel exceeded port forward failure threshold")
@@ -464,13 +471,13 @@ func (tunnel *Tunnel) operateTunnel(config *Config, tunnelOwner TunnelOwner) {
 		case <-tunnel.shutdownOperateBroadcast:
 			// Attempt to send any remaining stats
 			sendStats(tunnel)
-			Notice(NOTICE_INFO, "shutdown operate tunnel")
+			NoticeInfo("shutdown operate tunnel")
 			return
 		}
 	}
 
 	if err != nil {
-		Notice(NOTICE_ALERT, "operate tunnel error for %s: %s", tunnel.serverEntry.IpAddress, err)
+		NoticeAlert("operate tunnel error for %s: %s", tunnel.serverEntry.IpAddress, err)
 		tunnelOwner.SignalTunnelFailure(tunnel)
 	}
 }
@@ -487,7 +494,7 @@ func sendStats(tunnel *Tunnel) {
 	if payload != nil {
 		err := tunnel.session.DoStatusRequest(payload)
 		if err != nil {
-			Notice(NOTICE_ALERT, "DoStatusRequest failed for %s: %s", tunnel.serverEntry.IpAddress, err)
+			NoticeAlert("DoStatusRequest failed for %s: %s", tunnel.serverEntry.IpAddress, err)
 			PutBack(tunnel.serverEntry.IpAddress, payload)
 		}
 	}

psiphon/utils.go

@@ -20,13 +20,19 @@
 package psiphon
 
 import (
+	"bytes"
 	"crypto/rand"
 	"crypto/x509"
 	"encoding/base64"
+	"encoding/json"
 	"errors"
 	"fmt"
+	"io"
 	"math/big"
+	"os"
 	"runtime"
+	"strings"
+	"sync"
 )
 
 // Contains is a helper function that returns true
@@ -71,6 +77,18 @@ func MakeSecureRandomBytes(length int) ([]byte, error) {
 	return randomBytes, nil
 }
 
+func DecodeCertificate(encodedCertificate string) (certificate *x509.Certificate, err error) {
+	derEncodedCertificate, err := base64.StdEncoding.DecodeString(encodedCertificate)
+	if err != nil {
+		return nil, ContextError(err)
+	}
+	certificate, err = x509.ParseCertificate(derEncodedCertificate)
+	if err != nil {
+		return nil, ContextError(err)
+	}
+	return certificate, nil
+}
+
 // TrimError removes the middle of over-long error message strings
 func TrimError(err error) error {
 	const MAX_LEN = 100
@@ -88,17 +106,59 @@ func ContextError(err error) error {
 	}
 	pc, _, line, _ := runtime.Caller(1)
 	funcName := runtime.FuncForPC(pc).Name()
+	index := strings.LastIndex(funcName, "/")
+	if index != -1 {
+		funcName = funcName[index+1:]
+	}
 	return fmt.Errorf("%s#%d: %s", funcName, line, err)
 }
 
-func DecodeCertificate(encodedCertificate string) (certificate *x509.Certificate, err error) {
-	derEncodedCertificate, err := base64.StdEncoding.DecodeString(encodedCertificate)
-	if err != nil {
-		return nil, ContextError(err)
+// IsNetworkBindError returns true when the err is due to EADDRINUSE.
+func IsNetworkBindError(err error) bool {
+	return strings.Contains(err.Error(), "bind: address already in use")
+}
+
+// NoticeConsoleRewriter consumes JOSN-format notice input and parses each
+// notice and rewrites in a more human-readable format more suitable for
+// console output. The data payload field is left as JSON.
+type NoticeConsoleRewriter struct {
+	mutex  sync.Mutex
+	writer io.Writer
+	buffer []byte
+}
+
+// NewNoticeConsoleRewriter initializes a new NoticeConsoleRewriter
+func NewNoticeConsoleRewriter(writer io.Writer) *NoticeConsoleRewriter {
+	return &NoticeConsoleRewriter{writer: writer}
+}
+
+// Write implements io.Writer.
+func (rewriter *NoticeConsoleRewriter) Write(p []byte) (n int, err error) {
+	rewriter.mutex.Lock()
+	defer rewriter.mutex.Unlock()
+
+	rewriter.buffer = append(rewriter.buffer, p...)
+
+	index := bytes.Index(rewriter.buffer, []byte("\n"))
+	if index == -1 {
+		return len(p), nil
 	}
-	certificate, err = x509.ParseCertificate(derEncodedCertificate)
-	if err != nil {
-		return nil, ContextError(err)
+	line := rewriter.buffer[:index]
+	rewriter.buffer = rewriter.buffer[index+1:]
+
+	type NoticeObject struct {
+		NoticeType string          `json:"noticeType"`
+		Data       json.RawMessage `json:"data"`
+		Timestamp  string          `json:"timestamp"`
 	}
-	return certificate, nil
+
+	var noticeObject NoticeObject
+	_ = json.Unmarshal(line, &noticeObject)
+	fmt.Fprintf(os.Stderr,
+		"%s %s %s\n",
+		noticeObject.Timestamp,
+		noticeObject.NoticeType,
+		string(noticeObject.Data))
+
+	return len(p), nil
 }