diff --git a/backend/server/server.go b/backend/server/server.go index f08cb96..fd34ce2 100644 --- a/backend/server/server.go +++ b/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)) diff --git a/client/client_test.go b/client/client_test.go index 95a24cb..8861e73 100644 --- a/client/client_test.go +++ b/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 { - t.Fatalf("hishtory export has unexpected output=%#v", out) + if diff := cmp.Diff(expectedOutput, out); diff != "" { + t.Fatalf("hishtory export mismatch (-expected +got):\n%s\nout=%#v", diff, out) } } diff --git a/client/lib/lib.go b/client/lib/lib.go index 9008c15..30d02bb 100644 --- a/client/lib/lib.go +++ b/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? - log.New(os.Stdout, "\n", log.LstdFlags), + hishtoryLogger, logger.Config{ - SlowThreshold: 200 * time.Millisecond, - LogLevel: logger.Silent, - IgnoreRecordNotFoundError: true, + SlowThreshold: 100 * time.Millisecond, + LogLevel: logger.Warn, + 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 +} diff --git a/hishtory.go b/hishtory.go index a09cbdf..063f145 100644 --- a/hishtory.go +++ b/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) - } - 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) + return 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") - resp, err := http.Get(url) + url := "/api/v1/banner?commit_hash=" + GitCommit + "&device_id=" + config.DeviceId + "&forced_banner=" + os.Getenv("FORCED_BANNER") + 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 { - return fmt.Errorf("failed to call %s, status_code=%d", url, resp.StatusCode) - } - 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)) + if len(respBody) > 0 { + fmt.Println(string(respBody)) } 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() { diff --git a/shared/testutils.go b/shared/testutils.go index 8f65d5f..e8ebb59 100644 --- a/shared/testutils.go +++ b/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()) } }