More server-side logging + client-side logging

backend/server/server.go

@@ -38,7 +38,6 @@ func apiESubmitHandler(w http.ResponseWriter, r *http.Request) {
 	if err != nil {
 		panic(fmt.Sprintf("body=%#v, err=%v", data, err))
 	}
-	GLOBAL_DB.Where("user_id = ?")
 	fmt.Printf("apiESubmitHandler: received request containg %d EncHistoryEntry\n", len(entries))
 	for _, entry := range entries {
 		tx := GLOBAL_DB.Where("user_id = ?", entry.UserId)
@@ -205,18 +204,55 @@ func attestationDownloadHandler(w http.ResponseWriter, r *http.Request) {
 	http.Redirect(w, r, fmt.Sprintf("https://github.com/ddworken/hishtory/releases/download/%s/hishtory-linux-amd64.intoto.jsonl", ReleaseVersion), http.StatusFound)
 }
 
-func withLogging(h func(rw http.ResponseWriter, r *http.Request)) http.Handler {
+type loggedResponseData struct {
+	size int
+}
+
+type loggingResponseWriter struct {
+	http.ResponseWriter
+	responseData *loggedResponseData
+}
+
+func (r *loggingResponseWriter) Write(b []byte) (int, error) {
+	size, err := r.ResponseWriter.Write(b)
+	r.responseData.size += size
+	return size, err
+}
+
+func (r *loggingResponseWriter) WriteHeader(statusCode int) {
+	r.ResponseWriter.WriteHeader(statusCode)
+}
+
+func withLogging(h func(http.ResponseWriter, *http.Request)) http.Handler {
 	logFn := func(rw http.ResponseWriter, r *http.Request) {
+		var responseData loggedResponseData
+		lrw := loggingResponseWriter{
+			ResponseWriter: rw,
+			responseData:   &responseData,
+		}
 		start := time.Now()
 
-		h(rw, r)
+		h(&lrw, r)
 
 		duration := time.Since(start)
-		fmt.Printf("%s %s %#v %s\n", r.RemoteAddr, r.Method, r.RequestURI, duration.String())
+		fmt.Printf("%s %s %#v %s %s\n", r.RemoteAddr, r.Method, r.RequestURI, duration.String(), byteCountToString(responseData.size))
 	}
 	return http.HandlerFunc(logFn)
 }
 
+func byteCountToString(b int) string {
+	const unit = 1000
+	if b < unit {
+		return fmt.Sprintf("%d B", b)
+	}
+	div, exp := int64(unit), 0
+	for n := b / unit; n >= unit; n /= unit {
+		div *= unit
+		exp++
+	}
+	return fmt.Sprintf("%.1f %cB", float64(b)/float64(div), "kMG"[exp])
+}
+
 func main() {
 	fmt.Println("Listening on localhost:8080")
 	http.Handle("/api/v1/esubmit", withLogging(apiESubmitHandler))

client/client_test.go

@@ -188,7 +188,7 @@ func testIntegration(t *testing.T) string {
 	// Test the banner
 	os.Setenv("FORCED_BANNER", "HELLO_FROM_SERVER")
 	out = hishtoryQuery(t, "")
-	if !strings.Contains(out, "HELLO_FROM_SERVER") {
+	if !strings.Contains(out, "HELLO_FROM_SERVER\nHostname") {
 		t.Fatalf("hishtory query didn't show the banner message! out=%#v", out)
 	}
 	os.Setenv("FORCED_BANNER", "")
@@ -546,8 +546,8 @@ hishtory enable`, i))
 
 	out := RunInteractiveBashCommands(t, "hishtory export")
 	expectedOutput := "set -emo pipefail\necho mycommand-0\nhishtory enable\nset -emo pipefail\nhishtory query mycommand-0\nset -emo pipefail\nhishtory query\nset -emo pipefail\necho mycommand-1\nhishtory enable\nset -emo pipefail\nhishtory query mycommand-1\nset -emo pipefail\nhishtory query\nset -emo pipefail\necho mycommand-2\nhishtory enable\nset -emo pipefail\nhishtory query mycommand-2\nset -emo pipefail\nhishtory query\nset -emo pipefail\necho mycommand-3\nhishtory enable\nset -emo pipefail\nhishtory query mycommand-3\nset -emo pipefail\nhishtory query\nset -emo pipefail\necho mycommand-4\nhishtory enable\nset -emo pipefail\nhishtory query mycommand-4\nset -emo pipefail\nhishtory query\nset -emo pipefail\necho mycommand-5\nhishtory enable\nset -emo pipefail\nhishtory query mycommand-5\nset -emo pipefail\nhishtory query\nset -emo pipefail\necho mycommand-6\nhishtory enable\nset -emo pipefail\nhishtory query mycommand-6\nset -emo pipefail\nhishtory query\nset -emo pipefail\necho mycommand-7\nhishtory enable\nset -emo pipefail\nhishtory query mycommand-7\nset -emo pipefail\nhishtory query\nset -emo pipefail\necho mycommand-8\nhishtory enable\nset -emo pipefail\nhishtory query mycommand-8\nset -emo pipefail\nhishtory query\nset -emo pipefail\necho mycommand-9\nhishtory enable\nset -emo pipefail\nhishtory query mycommand-9\nset -emo pipefail\nhishtory query\nset -emo pipefail\necho mycommand-10\nhishtory enable\nset -emo pipefail\nhishtory query mycommand-10\nset -emo pipefail\nhishtory query\nset -emo pipefail\necho mycommand-11\nhishtory enable\nset -emo pipefail\nhishtory query mycommand-11\nset -emo pipefail\nhishtory query\nset -emo pipefail\necho mycommand-12\nhishtory enable\nset -emo pipefail\nhishtory query mycommand-12\nset -emo pipefail\nhishtory query\nset -emo pipefail\necho mycommand-13\nhishtory enable\nset -emo pipefail\nhishtory query mycommand-13\nset -emo pipefail\nhishtory query\nset -emo pipefail\necho mycommand-14\nhishtory enable\nset -emo pipefail\nhishtory query mycommand-14\nset -emo pipefail\nhishtory query\nset -emo pipefail\necho mycommand-15\nhishtory enable\nset -emo pipefail\nhishtory query mycommand-15\nset -emo pipefail\nhishtory query\nset -emo pipefail\necho mycommand-16\nhishtory enable\nset -emo pipefail\nhishtory query mycommand-16\nset -emo pipefail\nhishtory query\nset -emo pipefail\necho mycommand-17\nhishtory enable\nset -emo pipefail\nhishtory query mycommand-17\nset -emo pipefail\nhishtory query\nset -emo pipefail\necho mycommand-18\nhishtory enable\nset -emo pipefail\nhishtory query mycommand-18\nset -emo pipefail\nhishtory query\nset -emo pipefail\necho mycommand-19\nhishtory enable\nset -emo pipefail\nhishtory query mycommand-19\nset -emo pipefail\nhishtory query\nset -emo pipefail\necho mycommand-20\nhishtory enable\nset -emo pipefail\nhishtory query mycommand-20\nset -emo pipefail\nhishtory query\nset -emo pipefail\necho mycommand-21\nhishtory enable\nset -emo pipefail\nhishtory query mycommand-21\nset -emo pipefail\nhishtory query\nset -emo pipefail\necho mycommand-22\nhishtory enable\nset -emo pipefail\nhishtory query mycommand-22\nset -emo pipefail\nhishtory query\nset -emo pipefail\necho mycommand-23\nhishtory enable\nset -emo pipefail\nhishtory query mycommand-23\nset -emo pipefail\nhishtory query\nset -emo pipefail\necho mycommand-24\nhishtory enable\nset -emo pipefail\nhishtory query mycommand-24\nset -emo pipefail\nhishtory query\nset -emo pipefail\n"
-	if out != expectedOutput {
+	if diff := cmp.Diff(expectedOutput, out); diff != "" {
-		t.Fatalf("hishtory export has unexpected output=%#v", out)
+		t.Fatalf("hishtory export mismatch (-expected +got):\n%s\nout=%#v", diff, out)
 	}
 }
 

client/lib/lib.go

@@ -16,6 +16,7 @@ import (
 	"runtime"
 	"strconv"
 	"strings"
+	"sync"
 	"syscall"
 	"time"
 
@@ -172,26 +173,15 @@ func Setup(args []string) error {
 	db.Exec("DELETE FROM history_entries")
 
 	// Bootstrap from remote date
-	resp, err := http.Get(GetServerHostname() + "/api/v1/eregister?user_id=" + data.UserId(userSecret) + "&device_id=" + config.DeviceId)
+	_, err = ApiGet("/api/v1/eregister?user_id=" + data.UserId(userSecret) + "&device_id=" + config.DeviceId)
 	if err != nil {
 		return fmt.Errorf("failed to register device with backend: %v", err)
 	}
-	if resp.StatusCode != 200 {
-		return fmt.Errorf("failed to register device with backend, status_code=%d", resp.StatusCode)
-	}
 
-	resp, err = http.Get(GetServerHostname() + "/api/v1/ebootstrap?user_id=" + data.UserId(userSecret) + "&device_id=" + config.DeviceId)
+	respBody, err := ApiGet("/api/v1/ebootstrap?user_id=" + data.UserId(userSecret) + "&device_id=" + config.DeviceId)
 	if err != nil {
 		return fmt.Errorf("failed to bootstrap device from the backend: %v", err)
 	}
-	defer resp.Body.Close()
-	if resp.StatusCode != 200 {
-		return fmt.Errorf("failed to bootstrap device with data from existing devices, status_code=%d", resp.StatusCode)
-	}
-	respBody, err := ioutil.ReadAll(resp.Body)
-	if err != nil {
-		return fmt.Errorf("failed to read bootstrap response body: %v", err)
-	}
 	var retrievedEntries []*shared.EncHistoryEntry
 	err = json.Unmarshal(respBody, &retrievedEntries)
 	if err != nil {
@@ -457,13 +447,34 @@ func Update(url string) error {
 	return nil
 }
 
-func GetServerHostname() string {
+func getServerHostname() string {
 	if server := os.Getenv("HISHTORY_SERVER"); server != "" {
 		return server
 	}
 	return "https://api.hishtory.dev"
 }
 
+var (
+	hishtoryLogger *log.Logger
+	getLoggerOnce  sync.Once
+)
+
+func getLogger() *log.Logger {
+	getLoggerOnce.Do(func() {
+		homedir, err := os.UserHomeDir()
+		if err != nil {
+			panic(fmt.Errorf("failed to get user's home directory: %v", err))
+		}
+		f, err := os.OpenFile(path.Join(homedir, shared.HISHTORY_PATH, "hishtory.log"), os.O_RDWR|os.O_CREATE|os.O_APPEND, 0o660)
+		if err != nil {
+			panic(fmt.Errorf("failed to open hishtory.log: %v", err))
+		}
+		// Purposefully not closing the file. Yes, this is a dangling file handle. But hishtory is short lived so this is okay.
+		hishtoryLogger = log.New(f, "\n", log.LstdFlags|log.Lshortfile)
+	})
+	return hishtoryLogger
+}
+
 func OpenLocalSqliteDb() (*gorm.DB, error) {
 	homedir, err := os.UserHomeDir()
 	if err != nil {
@@ -473,13 +484,13 @@ func OpenLocalSqliteDb() (*gorm.DB, error) {
 	if err != nil {
 		return nil, fmt.Errorf("failed to create ~/.hishtory dir: %v", err)
 	}
+	hishtoryLogger := getLogger()
 	newLogger := logger.New(
-		// TODO: change this back to warn, but have it go to a file?
+		hishtoryLogger,
-		log.New(os.Stdout, "\n", log.LstdFlags),
 		logger.Config{
-			SlowThreshold:             200 * time.Millisecond,
+			SlowThreshold:             100 * time.Millisecond,
-			LogLevel:                  logger.Silent,
+			LogLevel:                  logger.Warn,
-			IgnoreRecordNotFoundError: true,
+			IgnoreRecordNotFoundError: false,
 			Colorful:                  false,
 		},
 	)
@@ -498,3 +509,41 @@ func OpenLocalSqliteDb() (*gorm.DB, error) {
 	db.AutoMigrate(&data.HistoryEntry{})
 	return db, nil
 }
+
+func ApiGet(path string) ([]byte, error) {
+	start := time.Now()
+	resp, err := http.Get(getServerHostname() + path)
+	if err != nil {
+		return nil, fmt.Errorf("failed to GET %s: %v", path, err)
+	}
+	defer resp.Body.Close()
+	if resp.StatusCode != 200 {
+		return nil, fmt.Errorf("failed to GET %s: status_code=%d", path, resp.StatusCode)
+	}
+	respBody, err := ioutil.ReadAll(resp.Body)
+	if err != nil {
+		return nil, fmt.Errorf("failed to read response body from GET %s: %v", path, err)
+	}
+	duration := time.Since(start)
+	getLogger().Printf("ApiGet(%#v): %s\n", path, duration.String())
+	return respBody, nil
+}
+
+func ApiPost(path, contentType string, data []byte) ([]byte, error) {
+	start := time.Now()
+	resp, err := http.Post(getServerHostname()+path, contentType, bytes.NewBuffer(data))
+	if err != nil {
+		return nil, fmt.Errorf("failed to POST %s: %v", path, err)
+	}
+	defer resp.Body.Close()
+	if resp.StatusCode != 200 {
+		return nil, fmt.Errorf("failed to POST %s: status_code=%d", path, resp.StatusCode)
+	}
+	respBody, err := ioutil.ReadAll(resp.Body)
+	if err != nil {
+		return nil, fmt.Errorf("failed to read response body from POST %s: %v", path, err)
+	}
+	duration := time.Since(start)
+	getLogger().Printf("ApiPost(%#v): %s\n", path, duration.String())
+	return respBody, nil
+}

hishtory.go

@@ -1,12 +1,9 @@
 package main
 
 import (
-	"bytes"
 	"encoding/json"
 	"fmt"
-	"io/ioutil"
 	"log"
-	"net/http"
 	"os"
 	"strings"
 
@@ -66,17 +63,9 @@ func retrieveAdditionalEntriesFromRemote(db *gorm.DB) error {
 	if err != nil {
 		return err
 	}
-	resp, err := http.Get(lib.GetServerHostname() + "/api/v1/equery?device_id=" + config.DeviceId)
+	respBody, err := lib.ApiGet("/api/v1/equery?device_id=" + config.DeviceId)
 	if err != nil {
-		return fmt.Errorf("failed to pull latest history entries from the backend: %v", err)
+		return err
-	}
-	defer resp.Body.Close()
-	if resp.StatusCode != 200 {
-		return fmt.Errorf("failed to retrieve data from backend, status_code=%d", resp.StatusCode)
-	}
-	respBody, err := ioutil.ReadAll(resp.Body)
-	if err != nil {
-		return fmt.Errorf("failed to read latest history entries response body: %v", err)
 	}
 	var retrievedEntries []*shared.EncHistoryEntry
 	err = json.Unmarshal(respBody, &retrievedEntries)
@@ -108,20 +97,13 @@ func displayBannerIfSet() error {
 	if err != nil {
 		return fmt.Errorf("failed to get config: %v", err)
 	}
-	url := lib.GetServerHostname() + "/api/v1/banner?commit_hash=" + GitCommit + "&device_id=" + config.DeviceId + "&forced_banner=" + os.Getenv("FORCED_BANNER")
+	url := "/api/v1/banner?commit_hash=" + GitCommit + "&device_id=" + config.DeviceId + "&forced_banner=" + os.Getenv("FORCED_BANNER")
-	resp, err := http.Get(url)
+	respBody, err := lib.ApiGet(url)
 	if err != nil {
-		return fmt.Errorf("failed to call /api/v1/banner: %v", err)
+		return err
 	}
-	if resp.StatusCode != 200 {
+	if len(respBody) > 0 {
-		return fmt.Errorf("failed to call %s, status_code=%d", url, resp.StatusCode)
+		fmt.Println(string(respBody))
-	}
-	data, err := ioutil.ReadAll(resp.Body)
-	if err != nil {
-		return fmt.Errorf("failed to read /api/v1/banner response body: %v", err)
-	}
-	if len(data) > 0 {
-		fmt.Print(string(data))
 	}
 	return nil
 }
@@ -151,11 +133,8 @@ func saveHistoryEntry() {
 	lib.CheckFatalError(err)
 	jsonValue, err := json.Marshal([]shared.EncHistoryEntry{encEntry})
 	lib.CheckFatalError(err)
-	resp, err := http.Post(lib.GetServerHostname()+"/api/v1/esubmit", "application/json", bytes.NewBuffer(jsonValue))
+	_, err = lib.ApiPost("/api/v1/esubmit", "application/json", jsonValue)
 	lib.CheckFatalError(err)
-	if resp.StatusCode != 200 {
-		lib.CheckFatalError(fmt.Errorf("failed to submit result to backend, status_code=%d", resp.StatusCode))
-	}
 }
 
 func export() {

shared/testutils.go

@@ -99,7 +99,7 @@ func RunTestServer() func() {
 		if strings.Contains(stderr.String()+stdout.String(), "failed to") {
 			panic(fmt.Sprintf("server failed to do something: stderr=%#v, stdout=%#v", stderr.String(), stdout.String()))
 		}
-		fmt.Printf("stderr=%#v, stdout=%#v\n", stderr.String(), stdout.String())
+		// fmt.Printf("stderr=%#v, stdout=%#v\n", stderr.String(), stdout.String())
 	}
 }