Added log line prefixes

README.md

@@ -15,16 +15,17 @@ This project is currently at the proof-of-concept stage. Current production Psip
 
 ### TODO (proof-of-concept)
 
-* log noise: "use of closed network connection"; "psiphon.relayPortForward: ...: i/o timeout"
+* prefilter entries by capability; don't log "server does not have sufficient capabilities"
+* log noise: "use of closed network connection"
 * use ContextError in more places
 * build/test on Android and iOS
 * integrate meek-client
 * disconnect all local proxy clients when tunnel disconnected
 * add connection and idle timeouts to proxied connections where appropriate
-* log levels
 
 ### TODO (future)
 
+* SOCKS5 support
 * SSH compression
 * preemptive reconnect functionality
 * implement page view stats

psiphon/dataStore.go

@@ -25,7 +25,6 @@ import (
 	"errors"
 	"fmt"
 	sqlite3 "github.com/mattn/go-sqlite3"
-	"log"
 	"sync"
 	"time"
 )
@@ -57,11 +56,11 @@ func initDataStore() {
 			"sqlite3",
 			fmt.Sprintf("file:%s?cache=private&mode=rwc", DATA_STORE_FILENAME))
 		if err != nil {
-			log.Fatal("initDataStore failed to open database: %s", err)
+			Fatal("initDataStore failed to open database: %s", err)
 		}
 		_, err = db.Exec(schema)
 		if err != nil {
-			log.Fatal("initDataStore failed to initialize schema: %s", err)
+			Fatal("initDataStore failed to initialize schema: %s", err)
 		}
 		singleton.db = db
 	})
@@ -151,9 +150,9 @@ func StoreServerEntry(serverEntry *ServerEntry, replaceIfExists bool) error {
 		if err != nil {
 			return err
 		}
-		// TODO: log after commit
+		// TODO: post notice after commit
 		if !serverEntryExists {
-			log.Printf("stored server %s", serverEntry.IpAddress)
+			Notice(NOTICE_INFO, "stored server %s", serverEntry.IpAddress)
 		}
 		return nil
 	})
@@ -281,13 +280,13 @@ func HasServerEntries(region string) bool {
 	if region == "" {
 		err = singleton.db.QueryRow("select count(*) from serverEntry;").Scan(&count)
 		if err == nil {
-			log.Printf("servers: %d", count)
+			Notice(NOTICE_INFO, "servers: %d", count)
 		}
 	} else {
 		err = singleton.db.QueryRow(
 			"select count(*) from serverEntry where region = ?;", region).Scan(&count)
 		if err == nil {
-			log.Printf("servers for region %s: %d", region, count)
+			Notice(NOTICE_INFO, "servers for region %s: %d", region, count)
 		}
 	}
 	return err == nil && count > 0

psiphon/httpProxy.go

@@ -22,7 +22,6 @@ package psiphon
 import (
 	"errors"
 	"io"
-	"log"
 	"net"
 	"net/http"
 	"sync"
@@ -62,7 +61,7 @@ func NewHttpProxy(tunnel *Tunnel, failureSignal chan bool) (proxy *HttpProxy, er
 	}
 	proxy.waitGroup.Add(1)
 	go proxy.serveHttpRequests()
-	log.Printf("local HTTP proxy running at address %s", proxy.listener.Addr().String())
+	Notice(NOTICE_HTTP_PROXY, "local HTTP proxy running at address %s", proxy.listener.Addr().String())
 	return proxy, nil
 }
 
@@ -93,20 +92,20 @@ func (proxy *HttpProxy) ServeHTTP(responseWriter http.ResponseWriter, request *h
 		hijacker, _ := responseWriter.(http.Hijacker)
 		conn, _, err := hijacker.Hijack()
 		if err != nil {
-			log.Print(ContextError(err))
+			Notice(NOTICE_ALERT, "%s", ContextError(err))
 			http.Error(responseWriter, "", http.StatusInternalServerError)
 			return
 		}
 		go func() {
 			err := httpConnectHandler(proxy.tunnel, conn, request.URL.Host)
 			if err != nil {
-				log.Printf("%s", err)
+				Notice(NOTICE_ALERT, "%s", ContextError(err))
 			}
 		}()
 		return
 	}
 	if !request.URL.IsAbs() {
-		log.Print(ContextError(errors.New("no domain in request URL")))
+		Notice(NOTICE_ALERT, "%s", ContextError(errors.New("no domain in request URL")))
 		http.Error(responseWriter, "", http.StatusInternalServerError)
 		return
 	}
@@ -119,7 +118,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 {
-		log.Print(ContextError(err))
+		Notice(NOTICE_ALERT, "%s", ContextError(err))
 		http.Error(responseWriter, "", http.StatusInternalServerError)
 		return
 	}
@@ -140,7 +139,7 @@ func (proxy *HttpProxy) ServeHTTP(responseWriter http.ResponseWriter, request *h
 	responseWriter.WriteHeader(response.StatusCode)
 	_, err = io.Copy(responseWriter, response.Body)
 	if err != nil {
-		log.Print(ContextError(err))
+		Notice(NOTICE_ALERT, "%s", ContextError(err))
 		http.Error(responseWriter, "", http.StatusInternalServerError)
 		return
 	}
@@ -187,8 +186,8 @@ func (proxy *HttpProxy) serveHttpRequests() {
 		case proxy.failureSignal <- true:
 		default:
 		}
-		log.Printf("HTTP proxy server error: %s", err)
+		Notice(NOTICE_ALERT, "%s", ContextError(err))
 		return
 	}
-	log.Printf("HTTP proxy stopped")
+	Notice(NOTICE_HTTP_PROXY, "HTTP proxy stopped")
 }

psiphon/remoteServerList.go

@@ -28,7 +28,6 @@ import (
 	"encoding/json"
 	"errors"
 	"io/ioutil"
-	"log"
 	"net/http"
 	"strings"
 )
@@ -47,7 +46,7 @@ type RemoteServerList struct {
 // public key config.RemoteServerListSignaturePublicKey; and parses the
 // data field into ServerEntry records.
 func FetchRemoteServerList(config *Config) (err error) {
-	log.Printf("fetching remote server list")
+	Notice(NOTICE_INFO, "fetching remote server list")
 	httpClient := http.Client{
 		Timeout: FETCH_REMOTE_SERVER_LIST_TIMEOUT,
 	}

psiphon/runTunnel.go

@@ -50,14 +50,13 @@ func establishTunnelWorker(
 		if IsSignalled(broadcastStopWorkers) {
 			return
 		}
-		log.Printf("connecting to %s in region %s",
-			serverEntry.IpAddress, serverEntry.Region)
+		Notice(NOTICE_INFO, "connecting to %s in region %s", serverEntry.IpAddress, serverEntry.Region)
 		tunnel, err := EstablishTunnel(serverEntry, pendingConns)
 		if err != nil {
 			// TODO: distingush case where conn is interrupted?
-			log.Printf("failed to connect to %s: %s", serverEntry.IpAddress, err)
+			Notice(NOTICE_INFO, "failed to connect to %s: %s", serverEntry.IpAddress, err)
 		} else {
-			log.Printf("successfully connected to %s", serverEntry.IpAddress)
+			Notice(NOTICE_INFO, "successfully connected to %s", serverEntry.IpAddress)
 			select {
 			case establishedTunnels <- tunnel:
 			default:
@@ -71,7 +70,7 @@ func establishTunnelWorker(
 // no longer required (another tunnel has already been selected). Since
 // the connection was successful, the server entry is still promoted.
 func discardTunnel(tunnel *Tunnel) {
-	log.Printf("discard connection to %s", tunnel.serverEntry.IpAddress)
+	Notice(NOTICE_INFO, "discard connection to %s", tunnel.serverEntry.IpAddress)
 	PromoteServerEntry(tunnel.serverEntry.IpAddress)
 	tunnel.Close()
 }
@@ -106,7 +105,7 @@ func establishTunnel(config *Config) (tunnel *Tunnel, err error) {
 		select {
 		case candidateServerEntries <- serverEntry:
 		case selectedTunnel = <-establishedTunnels:
-			log.Printf("selected connection to %s", selectedTunnel.serverEntry.IpAddress)
+			Notice(NOTICE_INFO, "selected connection to %s", selectedTunnel.serverEntry.IpAddress)
 		case <-timeout:
 			err = errors.New("timeout establishing tunnel")
 		}
@@ -144,39 +143,38 @@ func establishTunnel(config *Config) (tunnel *Tunnel, err error) {
 // that tunnel. The tunnel connection is monitored and this function returns an
 // error when the tunnel unexpectedly disconnects.
 func runTunnel(config *Config) error {
-	log.Printf("establishing tunnel")
+	Notice(NOTICE_INFO, "establishing tunnel")
 	tunnel, err := establishTunnel(config)
 	if err != nil {
 		return ContextError(err)
 	}
 	defer tunnel.Close()
 	// TODO: could start local proxies, etc., before synchronizing work group is establishTunnel
-	log.Printf("running tunnel")
 	stopTunnelSignal := make(chan bool)
 	err = tunnel.conn.SetClosedSignal(stopTunnelSignal)
 	if err != nil {
 		return fmt.Errorf("failed to set closed signal: %s", err)
 	}
-	log.Printf("starting local SOCKS proxy")
 	socksProxy, err := NewSocksProxy(tunnel, stopTunnelSignal)
 	if err != nil {
 		return fmt.Errorf("error initializing local SOCKS proxy: %s", err)
 	}
 	defer socksProxy.Close()
-	log.Printf("starting local HTTP proxy")
 	httpProxy, err := NewHttpProxy(tunnel, stopTunnelSignal)
 	if err != nil {
 		return fmt.Errorf("error initializing local HTTP proxy: %s", err)
 	}
 	defer httpProxy.Close()
-	log.Printf("starting session")
+	Notice(NOTICE_INFO, "starting session")
 	localHttpProxyAddress := httpProxy.listener.Addr().String()
 	_, err = NewSession(config, tunnel, localHttpProxyAddress)
 	if err != nil {
 		return fmt.Errorf("error starting session: %s", err)
 	}
-	log.Printf("monitoring tunnel")
+	Notice(NOTICE_TUNNEL, "tunnel started")
+	Notice(NOTICE_INFO, "monitoring tunnel")
 	<-stopTunnelSignal
+	Notice(NOTICE_TUNNEL, "tunnel stopped")
 	return nil
 }
 
@@ -188,7 +186,7 @@ func RunTunnelForever(config *Config) {
 	if config.LogFilename != "" {
 		logFile, err := os.OpenFile(config.LogFilename, os.O_CREATE|os.O_APPEND|os.O_WRONLY, 0600)
 		if err != nil {
-			log.Fatalf("error opening log file: %s", err)
+			Fatal("error opening log file: %s", err)
 		}
 		defer logFile.Close()
 		log.SetOutput(logFile)
@@ -202,7 +200,7 @@ func RunTunnelForever(config *Config) {
 		for {
 			err := FetchRemoteServerList(config)
 			if err != nil {
-				log.Printf("failed to fetch remote server list: %s", err)
+				Notice(NOTICE_ALERT, "failed to fetch remote server list: %s", err)
 				time.Sleep(FETCH_REMOTE_SERVER_LIST_RETRY_TIMEOUT)
 			} else {
 				time.Sleep(FETCH_REMOTE_SERVER_LIST_STALE_TIMEOUT)
@@ -213,7 +211,7 @@ func RunTunnelForever(config *Config) {
 		if HasServerEntries(config.EgressRegion) {
 			err := runTunnel(config)
 			if err != nil {
-				log.Printf("run tunnel error: %s", err)
+				Notice(NOTICE_ALERT, "run tunnel error: %s", err)
 			}
 		}
 		time.Sleep(1 * time.Second)

psiphon/serverApi.go

@@ -25,7 +25,6 @@ import (
 	"errors"
 	"fmt"
 	"io/ioutil"
-	"log"
 	"net"
 	"net/http"
 	"strconv"
@@ -138,20 +137,20 @@ 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 {
-		log.Printf("homepage: %s", homepage)
+		Notice(NOTICE_HOMEPAGE, homepage)
 	}
 	upgradeClientVersion, err := strconv.Atoi(handshakeConfig.UpgradeClientVersion)
 	if err != nil {
 		return ContextError(err)
 	}
 	if upgradeClientVersion > session.config.ClientVersion {
-		log.Printf("upgrade available to client version: %d", upgradeClientVersion)
+		Notice(NOTICE_UPGRADE, "%d", upgradeClientVersion)
 	}
 	for _, pageViewRegex := range handshakeConfig.PageViewRegexes {
-		log.Printf("page view regex: %s", pageViewRegex)
+		Notice(NOTICE_PAGE_VIEW_REGEX, "%s %s", pageViewRegex["regex"], pageViewRegex["replace"])
 	}
 	for _, httpsRequestRegex := range handshakeConfig.HttpsRequestRegexes {
-		log.Printf("HTTPS regex: %s", httpsRequestRegex)
+		Notice(NOTICE_HTTPS_REGEX, "%s %s", httpsRequestRegex["regex"], httpsRequestRegex["replace"])
 	}
 	return nil
 }

psiphon/socksProxy.go

@@ -22,7 +22,6 @@ package psiphon
 import (
 	socks "git.torproject.org/pluggable-transports/goptlib.git"
 	"io"
-	"log"
 	"net"
 	"sync"
 )
@@ -53,7 +52,7 @@ func NewSocksProxy(tunnel *Tunnel, failureSignal chan bool) (proxy *SocksProxy,
 		waitGroup:     new(sync.WaitGroup)}
 	proxy.waitGroup.Add(1)
 	go proxy.acceptSocksConnections()
-	log.Printf("local SOCKS proxy running at address %s", proxy.listener.Addr().String())
+	Notice(NOTICE_SOCKS_PROXY, "local SOCKS proxy running at address %s", proxy.listener.Addr().String())
 	return proxy, nil
 }
 
@@ -89,12 +88,12 @@ func relayPortForward(local, remote net.Conn) {
 		defer waitGroup.Done()
 		_, err := io.Copy(local, remote)
 		if err != nil {
-			log.Printf("%s", ContextError(err))
+			Notice(NOTICE_ALERT, "%s", ContextError(err))
 		}
 	}()
 	_, err := io.Copy(remote, local)
 	if err != nil {
-		log.Printf("%s", ContextError(err))
+		Notice(NOTICE_ALERT, "%s", ContextError(err))
 	}
 	waitGroup.Wait()
 }
@@ -106,7 +105,7 @@ func (proxy *SocksProxy) acceptSocksConnections() {
 		// Note: will be interrupted by listener.Close() call made by proxy.Close()
 		socksConnection, err := proxy.listener.AcceptSocks()
 		if err != nil {
-			log.Printf("SOCKS proxy accept error: %s", err)
+			Notice(NOTICE_ALERT, "SOCKS proxy accept error: %s", err)
 			if e, ok := err.(net.Error); ok && !e.Temporary() {
 				select {
 				case proxy.failureSignal <- true:
@@ -121,9 +120,9 @@ func (proxy *SocksProxy) acceptSocksConnections() {
 		go func() {
 			err := socksConnectionHandler(proxy.tunnel, socksConnection)
 			if err != nil {
-				log.Printf("%s", err)
+				Notice(NOTICE_ALERT, "%s", ContextError(err))
 			}
 		}()
 	}
-	log.Printf("SOCKS proxy stopped")
+	Notice(NOTICE_SOCKS_PROXY, "SOCKS proxy stopped")
 }

psiphon/tunnel.go

@@ -25,7 +25,6 @@ import (
 	"encoding/base64"
 	"errors"
 	"fmt"
-	"log"
 	"net"
 	"strconv"
 	"strings"
@@ -135,7 +134,7 @@ func EstablishTunnel(serverEntry *ServerEntry, pendingConns *PendingConns) (tunn
 			case <-sshKeepAliveTicker.C:
 				_, _, err := sshClient.SendRequest("keepalive@openssh.com", true, nil)
 				if err != nil {
-					log.Printf("ssh keep alive failed: %s", err)
+					Notice(NOTICE_ALERT, "ssh keep alive failed: %s", err)
 					// TODO: call Tunnel.Close()?
 					sshKeepAliveTicker.Stop()
 					conn.Close()