Merge pull request #291 from vania-pooh/master

Correctly proxying HTTPS

docs/log-files.adoc

@@ -12,61 +12,62 @@ Every line contains:
 
 .Log entry contents
 |===
-| Field | Example | Notes 
- 
-| Time | 2017/04/18 03:52:36 | - 
-| Request counter | [12413389] | So far as session ID is unknown when doing attempts this counter is used to find all session attempts for each new session request. 
-| Status | [SESSION_ATTEMPTED] | See table below for complete list of statuses. 
-| Quota name | [my_quota] | Extracted from basic HTTP auth headers. 
-| User IP | [192.168.2.3] | IPv4 or IPv6 address 
-| Browser | [firefox-42.0] | Name and version. Only present for new session requests. 
-| Hub host | [firefox42-1.example.com:4444] | Host from quota XML file 
-| Attempt number | [1] | For SESSION_ATTEMPTED entries means current attempt number. For SESSION_CREATED entries means total number of attempts to create this session. 
-| Session ID | [0c500a6f-98d2-4871-acb7-637d85e1416a] | As arrived from hub 
-| Session start time | [5.86s] | - 
+| Field | Example | Notes
+
+| Time | 2017/04/18 03:52:36 | -
+| Request counter | [12413389] | So far as session ID is unknown when doing attempts this counter is used to find all session attempts for each new session request.
+| Status | [SESSION_ATTEMPTED] | See table below for complete list of statuses.
+| Quota name | [my_quota] | Extracted from basic HTTP auth headers.
+| User IP | [192.168.2.3] | IPv4 or IPv6 address
+| Browser | [firefox-42.0] | Name and version. Only present for new session requests.
+| Hub host | [firefox42-1.example.com:4444] | Host from quota XML file
+| Attempt number | [1] | For SESSION_ATTEMPTED entries means current attempt number. For SESSION_CREATED entries means total number of attempts to create this session.
+| Session ID | [0c500a6f-98d2-4871-acb7-637d85e1416a] | As arrived from hub
+| Session start time | [5.86s] | -
 | Error | Error forwarding the new session Request timed out waiting for a node to become available. | Only present for SESSION_FAILED
 |===
 
 The following statuses are available:
 
 .Log entry statuses
 |===
-| Status | Description 
-
-| BAD_CAPABILITY | User is passing non-string value for capability that should be string 
-| BAD_JSON | User request does not contain valid Selenium data 
-| BAD_RESPONSE | Upstream server returned data using unknown JSON protocol 
-| BROWSER_NOT_SET | Browser name is not present or empty string 
-| CLIENT_DISCONNECTED | User disconnected and doing session attempts was interrupted 
-| INIT | Server initialization messages 
-| INVALID_HOST_VNC_URL | Failed to parse VNC host URL specified in quota configuration 
-| INVALID_DOWNLOAD_REQUEST_URL | Download request URL do not contain enough information to determine upstream host 
-| INVALID_LOG_REQUEST_URL | Log request URL do not contain enough information to determine upstream host 
-| INVALID_VNC_REQUEST_URL | VNC request URL do not contain enough information to determine upstream host 
-| INVALID_VIDEO_REQUEST_URL | Video request URL do not contain enough information to determine upstream host 
-| INVALID_URL | Session ID does not contain information about host where it was created 
-| PROXYING | Proxying Selenium request (shown in verbose mode only) 
-| PROXYING_DOWNLOAD | Starting to proxy downloaded file from upstream host 
-| PROXYING_LOG | Starting to proxy log from upstream host 
-| PROXYING_TO_VNC | Starting to proxy VNC traffic 
-| PROXYING_VIDEO | Starting to proxy video from upstream host 
-| QUOTA_INFO_REQUESTED | Quota information request arrived 
-| ROUTE_NOT_FOUND | Trying to proxy session to unknown host. Usually means quota files inconsistency between multiple Ggr instances. 
-| SESSION_ATTEMPTED | New user request for session arrived 
-| SESSION_CREATED | A new session was created and returned to user 
-| SESSION_DELETED | Existing session was deleted by user request 
-| SESSION_FAILED | Session attempt on specified host failed 
-| SESSION_NOT_CREATED | Attempts to create a new session on all hosts failed. An error was returned to user. 
-| SHUTTING_DOWN | Server is shutting down and waiting graceful shutdown timeout for currently proxied requests to finish  
-| UNKNOWN_DEVTOOLS_HOST | Requested to proxy devtools to host not present in quota 
-| UNKNOWN_DOWNLOAD_HOST | Requested to proxy downloaded file to host not present in quota 
-| UNKNOWN_LOG_HOST | Requested to proxy log to host not present in quota 
-| UNKNOWN_VNC_HOST | Requested to proxy VNC to host not present in quota 
-| UNKNOWN_VIDEO_HOST | Requested to proxy video to host not present in quota 
-| UNSUPPORTED_BROWSER | Requested browser name and version is not present in quota 
-| UNSUPPORTED_HOST_VNC_SCHEME | Invalid URL protocol specified for host in quota VNC configuration (should be vnc:// or ws://) 
-| WS_CLIENT_DISCONNECTED | Client disconnected from websocket API 
-| WS_ERROR | An error occurred when trying to proxy websocket traffic 
+| Status | Description
+
+| BAD_CAPABILITY | User is passing non-string value for capability that should be string
+| BAD_JSON | User request does not contain valid Selenium data
+| BAD_RESPONSE | Upstream server returned data using unknown JSON protocol
+| BROWSER_NOT_SET | Browser name is not present or empty string
+| CLIENT_DISCONNECTED | User disconnected and doing session attempts was interrupted
+| INIT | Server initialization messages
+| INVALID_HOST_VNC_URL | Failed to parse VNC host URL specified in quota configuration
+| INVALID_DOWNLOAD_REQUEST_URL | Download request URL do not contain enough information to determine upstream host
+| INVALID_LOG_REQUEST_URL | Log request URL do not contain enough information to determine upstream host
+| INVALID_VNC_REQUEST_URL | VNC request URL do not contain enough information to determine upstream host
+| INVALID_VIDEO_REQUEST_URL | Video request URL do not contain enough information to determine upstream host
+| INVALID_URL | Session ID does not contain information about host where it was created
+| PROXY_ERROR | An error occurred while proxying request
+| PROXYING | Proxying Selenium request (shown in verbose mode only)
+| PROXYING_DOWNLOAD | Starting to proxy downloaded file from upstream host
+| PROXYING_LOG | Starting to proxy log from upstream host
+| PROXYING_TO_VNC | Starting to proxy VNC traffic
+| PROXYING_VIDEO | Starting to proxy video from upstream host
+| QUOTA_INFO_REQUESTED | Quota information request arrived
+| ROUTE_NOT_FOUND | Trying to proxy session to unknown host. Usually means quota files inconsistency between multiple Ggr instances.
+| SESSION_ATTEMPTED | New user request for session arrived
+| SESSION_CREATED | A new session was created and returned to user
+| SESSION_DELETED | Existing session was deleted by user request
+| SESSION_FAILED | Session attempt on specified host failed
+| SESSION_NOT_CREATED | Attempts to create a new session on all hosts failed. An error was returned to user.
+| SHUTTING_DOWN | Server is shutting down and waiting graceful shutdown timeout for currently proxied requests to finish
+| UNKNOWN_DEVTOOLS_HOST | Requested to proxy devtools to host not present in quota
+| UNKNOWN_DOWNLOAD_HOST | Requested to proxy downloaded file to host not present in quota
+| UNKNOWN_LOG_HOST | Requested to proxy log to host not present in quota
+| UNKNOWN_VNC_HOST | Requested to proxy VNC to host not present in quota
+| UNKNOWN_VIDEO_HOST | Requested to proxy video to host not present in quota
+| UNSUPPORTED_BROWSER | Requested browser name and version is not present in quota
+| UNSUPPORTED_HOST_VNC_SCHEME | Invalid URL protocol specified for host in quota VNC configuration (should be vnc:// or ws://)
+| WS_CLIENT_DISCONNECTED | Client disconnected from websocket API
+| WS_ERROR | An error occurred when trying to proxy websocket traffic
 | WS_SESSION_CLOSED | Client closed websocket session
 |===
 
@@ -82,4 +83,4 @@ With this capability browser column will look like this:
 ```
 [firefox-42.0 buildNumber=122 branch=feature-XXX]
 ```
-Such additional metadata in logs allows to better analyze respective Selenium sessions.
+Such additional metadata in logs allows to better analyze respective Selenium sessions.

proxy.go

@@ -375,53 +375,62 @@ func secondsSince(start time.Time) float64 {
 	return float64(time.Now().Sub(start).Seconds())
 }
 
-func proxy(r *http.Request) {
+func proxy(w http.ResponseWriter, r *http.Request) {
 	id := serial()
-	_, remote := info(r)
-	r.URL.Scheme = "http"
-	if len(r.URL.Path) > tail {
-		sum := r.URL.Path[head:tail]
-		proxyPath := r.URL.Path[:head] + r.URL.Path[tail:]
-		confLock.RLock()
-		h, ok := routes[sum]
-		confLock.RUnlock()
-		if ok {
-			if r.Body != nil {
-				if body, err := ioutil.ReadAll(r.Body); err == nil {
-					r.Body.Close()
-					var msg map[string]interface{}
-					if err := json.Unmarshal(body, &msg); err == nil {
-						delete(msg, "sessionId")
-						body, _ = json.Marshal(msg)
-						r.ContentLength = int64(len(body))
+	(&httputil.ReverseProxy{
+		Director: func(r *http.Request) {
+			_, remote := info(r)
+			r.URL.Scheme = "http"
+			if len(r.URL.Path) > tail {
+				sum := r.URL.Path[head:tail]
+				proxyPath := r.URL.Path[:head] + r.URL.Path[tail:]
+				confLock.RLock()
+				h, ok := routes[sum]
+				confLock.RUnlock()
+				if ok {
+					if r.Body != nil {
+						if body, err := ioutil.ReadAll(r.Body); err == nil {
+							r.Body.Close()
+							var msg map[string]interface{}
+							if err := json.Unmarshal(body, &msg); err == nil {
+								delete(msg, "sessionId")
+								body, _ = json.Marshal(msg)
+								r.ContentLength = int64(len(body))
+							}
+							r.Body = ioutil.NopCloser(bytes.NewReader(body))
+						}
+					}
+					if h.Scheme != "" {
+						r.URL.Scheme = h.Scheme
+					}
+					r.Host = h.Net()
+					r.URL.Host = h.Net()
+					r.URL.Path = proxyPath
+					fragments := strings.Split(proxyPath, "/")
+					sess := fragments[sessPart]
+					if verbose {
+						log.Printf("[%d] [-] [PROXYING] [-] [%s] [-] [%s] [%s] [-] [%s]\n", id, remote, h.Net(), sess, proxyPath)
 					}
-					r.Body = ioutil.NopCloser(bytes.NewReader(body))
+					if r.Method == http.MethodDelete && len(fragments) == sessPart+1 {
+						log.Printf("[%d] [-] [SESSION_DELETED] [-] [%s] [-] [%s] [%s] [-] [-]\n", id, remote, h.Net(), sess)
+					}
+					return
 				}
+				log.Printf("[%d] [-] [ROUTE_NOT_FOUND] [-] [%s] [%s] [-] [-] [-] [-]\n", id, remote, proxyPath)
+			} else {
+				log.Printf("[%d] [-] [INVALID_URL] [-] [%s] [%s] [-] [-] [-] [-]\n", id, remote, r.URL.Path)
 			}
-			r.Host = h.Net()
-			r.URL.Host = h.Net()
-			r.URL.Path = proxyPath
-			fragments := strings.Split(proxyPath, "/")
-			sess := fragments[sessPart]
-			if verbose {
-				log.Printf("[%d] [-] [PROXYING] [-] [%s] [-] [%s] [%s] [-] [%s]\n", id, remote, h.Net(), sess, proxyPath)
-			}
-			if r.Method == http.MethodDelete && len(fragments) == sessPart+1 {
-				log.Printf("[%d] [-] [SESSION_DELETED] [-] [%s] [-] [%s] [%s] [-] [-]\n", id, remote, h.Net(), sess)
-			}
-			return
-		}
-		log.Printf("[%d] [-] [ROUTE_NOT_FOUND] [-] [%s] [%s] [-] [-] [-] [-]\n", id, remote, proxyPath)
-	} else {
-		log.Printf("[%d] [-] [INVALID_URL] [-] [%s] [%s] [-] [-] [-] [-]\n", id, remote, r.URL.Path)
-	}
-	r.URL.Host = listen
-	r.URL.Path = paths.Err
+			r.URL.Host = listen
+			r.URL.Path = paths.Err
+		},
+		ErrorHandler: defaultErrorHandler(id),
+	}).ServeHTTP(w, r)
 }
 
 func ping(w http.ResponseWriter, _ *http.Request) {
 	confLock.RLock()
-	defer confLock.RUnlock()
+	lrt := lastReloadTime.Format(time.RFC3339)
+	confLock.RUnlock()
 	w.Header().Set("Content-Type", "application/json")
 	json.NewEncoder(w).Encode(struct {
 		Uptime         string `json:"uptime"`
@@ -431,7 +440,7 @@ func ping(w http.ResponseWriter, _ *http.Request) {
 		Version        string `json:"version"`
 	}{
 		time.Since(startTime).String(),
-		lastReloadTime.Format(time.RFC3339),
+		lrt,
 		atomic.LoadUint64(&numRequests),
 		atomic.LoadUint64(&numSessions),
 		gitRevision,
@@ -454,9 +463,6 @@ func err(w http.ResponseWriter, _ *http.Request) {
 }
 
 func host(w http.ResponseWriter, r *http.Request) {
-	confLock.RLock()
-	defer confLock.RUnlock()
-
 	id := serial()
 	user, remote := info(r)
 	head := len(paths.Host)
@@ -468,7 +474,9 @@ func host(w http.ResponseWriter, r *http.Request) {
 		return
 	}
 	sum := path[head:tail]
+	confLock.RLock()
 	h, ok := routes[sum]
+	confLock.RUnlock()
 	if !ok {
 		w.WriteHeader(http.StatusNotFound)
 		w.Write([]byte("unknown host"))
@@ -480,12 +488,12 @@ func host(w http.ResponseWriter, r *http.Request) {
 }
 
 func quotaInfo(w http.ResponseWriter, r *http.Request) {
-	confLock.RLock()
-	defer confLock.RUnlock()
 	id := serial()
 	user, remote := info(r)
 	log.Printf("[%d] [-] [QUOTA_INFO_REQUESTED] [%s] [%s] [-] [-] [-] [-] [-]\n", id, user, remote)
+	confLock.RLock()
 	browsers := quota[user]
+	confLock.RUnlock()
 	w.Header().Set("Content-Type", "application/json")
 	for i := 0; i < len(browsers.Browsers.Browsers); i++ {
 		browser := &browsers.Browsers.Browsers[i]
@@ -614,8 +622,6 @@ func WithSuitableAuthentication(authenticator *auth.BasicAuth, handler func(http
 
 func vnc(wsconn *websocket.Conn) {
 	defer wsconn.Close()
-	confLock.RLock()
-	defer confLock.RUnlock()
 
 	id := serial()
 	head := len(paths.VNC)
@@ -626,7 +632,9 @@ func vnc(wsconn *websocket.Conn) {
 		return
 	}
 	sum := path[head:tail]
+	confLock.RLock()
 	h, ok := routes[sum]
+	confLock.RUnlock()
 	if ok {
 		vncInfo := h.VncInfo
 		scheme := vncScheme
@@ -720,9 +728,6 @@ func clipboard(w http.ResponseWriter, r *http.Request) {
 }
 
 func proxyStatic(w http.ResponseWriter, r *http.Request, route string, invalidUrlMessage string, proxyingMessage string, unknownHostMessage string, pathProvider func(string) string) {
-	confLock.RLock()
-	defer confLock.RUnlock()
-
 	id := serial()
 	user, remote := info(r)
 	head := len(route)
@@ -734,21 +739,34 @@ func proxyStatic(w http.ResponseWriter, r *http.Request, route string, invalidUr
 		return
 	}
 	sum := path[head:tail]
-	remainder := path[tail:]
+	confLock.RLock()
 	h, ok := routes[sum]
+	confLock.RUnlock()
+	remainder := path[tail:]
 	if ok {
-		(&httputil.ReverseProxy{Director: func(r *http.Request) {
-			r.URL.Scheme = "http"
-			r.URL.Host = h.Net()
-			r.URL.Path = pathProvider(remainder)
-			log.Printf("[%d] [-] [%s] [%s] [%s] [%s] [-] [%s] [-] [-]\n", id, proxyingMessage, user, remote, r.URL, remainder)
-		}}).ServeHTTP(w, r)
+		(&httputil.ReverseProxy{
+			Director: func(r *http.Request) {
+				r.URL.Scheme = "http"
+				r.URL.Host = h.Net()
+				r.URL.Path = pathProvider(remainder)
+				log.Printf("[%d] [-] [%s] [%s] [%s] [%s] [-] [%s] [-] [-]\n", id, proxyingMessage, user, remote, r.URL, remainder)
+			},
+			ErrorHandler: defaultErrorHandler(id),
+		}).ServeHTTP(w, r)
 	} else {
 		log.Printf("[%d] [-] [%s] [%s] [%s] [-] [-] [%s] [-] [-]\n", id, unknownHostMessage, user, remote, sum)
 		reply(w, errMsg("unknown host"), http.StatusNotFound)
 	}
 }
 
+func defaultErrorHandler(requestId uint64) func(http.ResponseWriter, *http.Request, error) {
+	return func(w http.ResponseWriter, r *http.Request, err error) {
+		user, remote := info(r)
+		log.Printf("[%d] [-] [PROXY_ERROR] [%s] [%s] [%s] [-] [-] [-] [%v]", requestId, user, remote, r.URL, err)
+		w.WriteHeader(http.StatusBadGateway)
+	}
+}
+
 func mux() http.Handler {
 	mux := http.NewServeMux()
 	authenticator := auth.NewBasicAuthenticator(
@@ -761,7 +779,7 @@ func mux() http.Handler {
 	mux.HandleFunc(paths.Host, WithSuitableAuthentication(authenticator, host))
 	mux.HandleFunc(paths.Quota, WithSuitableAuthentication(authenticator, quotaInfo))
 	mux.HandleFunc(paths.Route, withCloseNotifier(WithSuitableAuthentication(authenticator, postOnly(route))))
-	mux.Handle(paths.Proxy, &httputil.ReverseProxy{Director: proxy})
+	mux.HandleFunc(paths.Proxy, proxy)
 	mux.Handle(paths.VNC, websocket.Handler(vnc))
 	mux.HandleFunc(paths.Video, WithSuitableAuthentication(authenticator, video))
 	mux.HandleFunc(paths.Logs, WithSuitableAuthentication(authenticator, logs))