1885: Fix bug in not returning from the handler on failed authorization.

Improved logging (which uncovered the previous bug.)  Tweaked go.sh and tests.

diff --git a/sdk/go/go.sh b/sdk/go/go.sh
index 89f81fb910bd12bf20a110db731d0dc0bb26c283..5553567287388f8e83dbd4b3f5645156ea1b9920 100755 (executable)
--- a/sdk/go/go.sh
+++ b/sdk/go/go.sh
@@ -1,6 +1,11 @@
 #! /bin/sh
 
-rootdir=$(dirname $0)
+# Wraps the 'go' executable with some environment setup.  Sets GOPATH, creates
+# 'pkg' and 'bin' directories, automatically installs dependencies, then runs
+# the underlying 'go' executable with any command line parameters provided to
+# the script.
+
+rootdir=$(readlink -f $(dirname $0))
 GOPATH=$rootdir:$GOPATH
 export GOPATH
 

diff --git a/sdk/go/src/arvados.org/keepclient/keepclient.go b/sdk/go/src/arvados.org/keepclient/keepclient.go
index dadf8bf740f1f31857bbf9c388a816f652cb973f..5ba6257859f5437f5b2109a016d172e26e49a0d1 100644 (file)
--- a/sdk/go/src/arvados.org/keepclient/keepclient.go
+++ b/sdk/go/src/arvados.org/keepclient/keepclient.go
@@ -24,6 +24,9 @@ var BlockNotFound = errors.New("Block not found")
 var InsufficientReplicasError = errors.New("Could not write sufficient replicas")
 var OversizeBlockError = errors.New("Block too big")
 
+const X_Keep_Desired_Replicas = "X-Keep-Desired-Replicas"
+const X_Keep_Replicas_Stored = "X-Keep-Replicas-Stored"
+
 // Information about Arvados and Keep servers.
 type KeepClient struct {
        ApiServer     string

diff --git a/sdk/go/src/arvados.org/keepclient/keepclient_test.go b/sdk/go/src/arvados.org/keepclient/keepclient_test.go
index 395603d5ad3b5c3f92363763c2be719fd723d494..291d8f896c2aa5e19c5f3651c3c478ebe7d68152 100644 (file)
--- a/sdk/go/src/arvados.org/keepclient/keepclient_test.go
+++ b/sdk/go/src/arvados.org/keepclient/keepclient_test.go
@@ -44,8 +44,12 @@ func (s *ServerRequiredSuite) SetUpSuite(c *C) {
                c.Skip("Skipping tests that require server")
        } else {
                os.Chdir(pythonDir())
-               exec.Command("python", "run_test_server.py", "start").Run()
-               exec.Command("python", "run_test_server.py", "start_keep").Run()
+               if err := exec.Command("python", "run_test_server.py", "start").Run(); err != nil {
+                       panic("'python run_test_server.py start' returned error")
+               }
+               if err := exec.Command("python", "run_test_server.py", "start_keep").Run(); err != nil {
+                       panic("'python run_test_server.py start_keep' returned error")
+               }
        }
 }
 

diff --git a/sdk/go/src/arvados.org/keepclient/support.go b/sdk/go/src/arvados.org/keepclient/support.go
index 38669a11dbfbda40c32df35c7702b3c8458a4e2c..f924137567dcba59ebca806bdefbdbd14a406eb6 100644 (file)
--- a/sdk/go/src/arvados.org/keepclient/support.go
+++ b/sdk/go/src/arvados.org/keepclient/support.go
@@ -156,7 +156,7 @@ type uploadStatus struct {
 func (this KeepClient) uploadToKeepServer(host string, hash string, body io.ReadCloser,
        upload_status chan<- uploadStatus, expectedLength int64) {
 
-       log.Printf("Uploading to %s", host)
+       log.Printf("Uploading %s to %s", hash, host)
 
        var req *http.Request
        var err error
@@ -175,7 +175,7 @@ func (this KeepClient) uploadToKeepServer(host string, hash string, body io.Read
        req.Header.Add("Content-Type", "application/octet-stream")
 
        if this.Using_proxy {
-               req.Header.Add("X-Keep-Desired-Replicas", fmt.Sprint(this.Want_replicas))
+               req.Header.Add(X_Keep_Desired_Replicas, fmt.Sprint(this.Want_replicas))
        }
 
        req.Body = body
@@ -188,7 +188,7 @@ func (this KeepClient) uploadToKeepServer(host string, hash string, body io.Read
        }
 
        rep := 1
-       if xr := resp.Header.Get("X-Keep-Replicas-Stored"); xr != "" {
+       if xr := resp.Header.Get(X_Keep_Replicas_Stored); xr != "" {
                fmt.Sscanf(xr, "%d", &rep)
        }
 
@@ -248,7 +248,7 @@ func (this KeepClient) putReplicas(
                                status.url, status.err)
                }
                active -= 1
-               log.Printf("Upload status code: %v remaining replicas: %v active: %v", status.statusCode, remaining_replicas, active)
+               log.Printf("Upload to %v status code: %v remaining replicas: %v active: %v", status.url, status.statusCode, remaining_replicas, active)
        }
 
        return this.Want_replicas, nil

diff --git a/services/keep/go.sh b/services/keep/go.sh
index 177b27db03f58546fa8e59dba28ebe029023f244..156fe90df2a3dbc224a90c476a1b890a9d27faa5 100755 (executable)
--- a/services/keep/go.sh
+++ b/services/keep/go.sh
@@ -1,6 +1,11 @@
 #! /bin/sh
 
-rootdir=$(dirname $0)
+# Wraps the 'go' executable with some environment setup.  Sets GOPATH, creates
+# 'pkg' and 'bin' directories, automatically installs dependencies, then runs
+# the underlying 'go' executable with any command line parameters provided to
+# the script.
+
+rootdir=$(readlink -f $(dirname $0))
 GOPATH=$rootdir:$rootdir/../../sdk/go:$GOPATH
 export GOPATH
 

diff --git a/services/keep/src/arvados.org/keepproxy/keepproxy.go b/services/keep/src/arvados.org/keepproxy/keepproxy.go
index b914f47d5cd669ed805d12c28c4932cdc775881c..9e0b2ff90c29fe070ec30e3bd11f96f1038f9a87 100644 (file)
--- a/services/keep/src/arvados.org/keepproxy/keepproxy.go
+++ b/services/keep/src/arvados.org/keepproxy/keepproxy.go
@@ -63,15 +63,9 @@ func main() {
 
        flag.Parse()
 
-       /*if no_get == false {
-               log.Print("Must specify -no-get")
-               return
-       }*/
-
        kc, err := keepclient.MakeKeepClient()
        if err != nil {
-               log.Print(err)
-               return
+               log.Fatal(err)
        }
 
        if pidfile != "" {
@@ -88,8 +82,7 @@ func main() {
 
        listener, err = net.Listen("tcp", listen)
        if err != nil {
-               log.Printf("Could not listen on %v", listen)
-               return
+               log.Fatalf("Could not listen on %v", listen)
        }
 
        go RefreshServicesList(&kc)
@@ -143,13 +136,25 @@ func (this *ApiTokenCache) RecallToken(token string) bool {
        }
 }
 
+func GetRemoteAddress(req *http.Request) string {
+       if realip := req.Header.Get("X-Real-IP"); realip != "" {
+               if forwarded := req.Header.Get("X-Forwarded-For"); forwarded != realip {
+                       return fmt.Sprintf("%s (X-Forwarded-For %s)", realip, forwarded)
+               } else {
+                       return realip
+               }
+       }
+       return req.RemoteAddr
+}
+
 func CheckAuthorizationHeader(kc keepclient.KeepClient, cache *ApiTokenCache, req *http.Request) bool {
-       if req.Header.Get("Authorization") == "" {
+       var auth string
+       if auth = req.Header.Get("Authorization"); auth == "" {
                return false
        }
 
        var tok string
-       _, err := fmt.Sscanf(req.Header.Get("Authorization"), "OAuth2 %s", &tok)
+       _, err := fmt.Sscanf(auth, "OAuth2 %s", &tok)
        if err != nil {
                // Scanning error
                return false
@@ -164,7 +169,7 @@ func CheckAuthorizationHeader(kc keepclient.KeepClient, cache *ApiTokenCache, re
 
        if usersreq, err = http.NewRequest("GET", fmt.Sprintf("https://%s/arvados/v1/users/current", kc.ApiServer), nil); err != nil {
                // Can't construct the request
-               log.Print("CheckAuthorizationHeader error: %v", err)
+               log.Printf("%s: CheckAuthorizationHeader error: %v", GetRemoteAddress(req), err)
                return false
        }
 
@@ -175,12 +180,13 @@ func CheckAuthorizationHeader(kc keepclient.KeepClient, cache *ApiTokenCache, re
        var resp *http.Response
        if resp, err = kc.Client.Do(usersreq); err != nil {
                // Something else failed
-               log.Print("CheckAuthorizationHeader error: %v", err)
+               log.Printf("%s: CheckAuthorizationHeader error connecting to API server: %v", GetRemoteAddress(req), err.Error())
                return false
        }
 
        if resp.StatusCode != http.StatusOK {
                // Bad status
+               log.Printf("%s: CheckAuthorizationHeader API server responded: %v", GetRemoteAddress(req), resp.Status)
                return false
        }
 
@@ -234,14 +240,17 @@ func (this GetBlockHandler) ServeHTTP(resp http.ResponseWriter, req *http.Reques
 
        kc := *this.KeepClient
 
-       if !CheckAuthorizationHeader(kc, this.ApiTokenCache, req) {
-               http.Error(resp, "Missing or invalid Authorization header", http.StatusForbidden)
-       }
-
        hash := mux.Vars(req)["hash"]
        signature := mux.Vars(req)["signature"]
        timestamp := mux.Vars(req)["timestamp"]
 
+       log.Printf("%s: %s %s", GetRemoteAddress(req), req.Method, hash)
+
+       if !CheckAuthorizationHeader(kc, this.ApiTokenCache, req) {
+               http.Error(resp, "Missing or invalid Authorization header", http.StatusForbidden)
+               return
+       }
+
        var reader io.ReadCloser
        var err error
        var blocklen int64
@@ -258,25 +267,32 @@ func (this GetBlockHandler) ServeHTTP(resp http.ResponseWriter, req *http.Reques
        switch err {
        case nil:
                if reader != nil {
-                       io.Copy(resp, reader)
+                       n, err2 := io.Copy(resp, reader)
+                       if n != blocklen {
+                               log.Printf("%s: %s %s mismatched return %v with Content-Length %v error", GetRemoteAddress(req), req.Method, hash, n, blocklen, err.Error())
+                       } else if err2 == nil {
+                               log.Printf("%s: %s %s success returned %v bytes", GetRemoteAddress(req), req.Method, hash, n)
+                       } else {
+                               log.Printf("%s: %s %s returned %v bytes error %v", GetRemoteAddress(req), req.Method, hash, n, err.Error())
+                       }
+               } else {
+                       log.Printf("%s: %s %s success", GetRemoteAddress(req), req.Method, hash)
                }
        case keepclient.BlockNotFound:
                http.Error(resp, "Not found", http.StatusNotFound)
        default:
                http.Error(resp, err.Error(), http.StatusBadGateway)
        }
+
+       if err != nil {
+               log.Printf("%s: %s %s error %s", GetRemoteAddress(req), req.Method, hash, err.Error())
+       }
 }
 
 func (this PutBlockHandler) ServeHTTP(resp http.ResponseWriter, req *http.Request) {
 
-       log.Print("PutBlockHandler start")
-
        kc := *this.KeepClient
 
-       if !CheckAuthorizationHeader(kc, this.ApiTokenCache, req) {
-               http.Error(resp, "Missing or invalid Authorization header", http.StatusForbidden)
-       }
-
        hash := mux.Vars(req)["hash"]
 
        var contentLength int64 = -1
@@ -288,15 +304,22 @@ func (this PutBlockHandler) ServeHTTP(resp http.ResponseWriter, req *http.Reques
 
        }
 
+       log.Printf("%s: %s %s Content-Length %v", GetRemoteAddress(req), req.Method, hash, contentLength)
+
        if contentLength < 1 {
                http.Error(resp, "Must include Content-Length header", http.StatusLengthRequired)
                return
        }
 
+       if !CheckAuthorizationHeader(kc, this.ApiTokenCache, req) {
+               http.Error(resp, "Missing or invalid Authorization header", http.StatusForbidden)
+               return
+       }
+
        // Check if the client specified the number of replicas
        if req.Header.Get("X-Keep-Desired-Replicas") != "" {
                var r int
-               _, err := fmt.Sscanf(req.Header.Get("X-Keep-Desired-Replicas"), "%d", &r)
+               _, err := fmt.Sscanf(req.Header.Get(keepclient.X_Keep_Desired_Replicas), "%d", &r)
                if err != nil {
                        kc.Want_replicas = r
                }
@@ -305,14 +328,13 @@ func (this PutBlockHandler) ServeHTTP(resp http.ResponseWriter, req *http.Reques
        // Now try to put the block through
        replicas, err := kc.PutHR(hash, req.Body, contentLength)
 
-       log.Printf("Replicas stored: %v err: %v", replicas, err)
-
        // Tell the client how many successful PUTs we accomplished
-       resp.Header().Set("X-Keep-Replicas-Stored", fmt.Sprintf("%d", replicas))
+       resp.Header().Set(keepclient.X_Keep_Replicas_Stored, fmt.Sprintf("%d", replicas))
 
        switch err {
        case nil:
                // Default will return http.StatusOK
+               log.Printf("%s: %s %s finished, stored %v replicas (desired %v)", GetRemoteAddress(req), req.Method, hash, replicas, kc.Want_replicas)
 
        case keepclient.OversizeBlockError:
                // Too much data
@@ -332,4 +354,8 @@ func (this PutBlockHandler) ServeHTTP(resp http.ResponseWriter, req *http.Reques
                http.Error(resp, err.Error(), http.StatusBadGateway)
        }
 
+       if err != nil {
+               log.Printf("%s: %s %s stored %v replicas (desired %v) got error %v", GetRemoteAddress(req), req.Method, hash, replicas, kc.Want_replicas, err.Error())
+       }
+
 }

diff --git a/services/keep/src/arvados.org/keepproxy/keepproxy_test.go b/services/keep/src/arvados.org/keepproxy/keepproxy_test.go
index d8abda73965e77f88cf6cc054dd058b3f3fa2025..f03c94f88b9f380ca4dccc31a07b95feed50d28f 100644 (file)
--- a/services/keep/src/arvados.org/keepproxy/keepproxy_test.go
+++ b/services/keep/src/arvados.org/keepproxy/keepproxy_test.go
@@ -39,8 +39,13 @@ func (s *ServerRequiredSuite) SetUpSuite(c *C) {
        defer os.Chdir(cwd)
 
        os.Chdir(pythonDir())
-       exec.Command("python", "run_test_server.py", "start").Run()
-       exec.Command("python", "run_test_server.py", "start_keep").Run()
+
+       if err := exec.Command("python", "run_test_server.py", "start").Run(); err != nil {
+               panic("'python run_test_server.py start' returned error")
+       }
+       if err := exec.Command("python", "run_test_server.py", "start_keep").Run(); err != nil {
+               panic("'python run_test_server.py start_keep' returned error")
+       }
 
        os.Setenv("ARVADOS_API_HOST", "localhost:3001")
        os.Setenv("ARVADOS_API_TOKEN", "4axaw8zxe0qm22wa6urpp5nskcne8z88cvbupv653y1njyi05h")