Skip to content
This repository has been archived by the owner on Mar 22, 2023. It is now read-only.

Commit

Permalink
logs backend response status and headers when debug is enabled
Browse files Browse the repository at this point in the history 
cleans up unused imports
makes logs consistently start with lower-case characters
  • Loading branch information
@shamsimam
shamsimam committed Jun 26, 2019
1 parent 70826a8 commit d31bd90
Showing 1 changed file with 30 additions and 23 deletions.
53 changes: 30 additions & 23 deletions waiter/src/waiter/process_request.clj
View file
Original file line number Diff line number Diff line change
Expand Up @@ -43,7 +43,7 @@
(:import (java.io ByteArrayOutputStream InputStream IOException)
(java.nio ByteBuffer)
(java.util.concurrent LinkedBlockingQueue ThreadPoolExecutor TimeoutException TimeUnit)
(javax.servlet ReadListener ServletInputStream ServletOutputStream)
(javax.servlet ServletOutputStream)
(org.eclipse.jetty.client HttpClient)
(org.eclipse.jetty.io EofException)
(org.eclipse.jetty.server HttpChannel HttpOutput Response)))
Expand Down Expand Up @@ -120,10 +120,10 @@
(fn [old-value header-value display-name]
(let [parsed-value (when header-value
(try
(log/info "Request wants to configure" display-name "to" header-value)
(log/info "request wants to configure" display-name "to" header-value)
(Integer/parseInt (str header-value))
(catch Exception _
(log/warn "Cannot convert header for" display-name "to an int:" header-value)
(log/warn "cannot convert header for" display-name "to an int:" header-value)
nil)))]
(if (and parsed-value (pos? parsed-value)) parsed-value old-value)))]
(-> instance-request-properties
Expand Down Expand Up @@ -154,21 +154,26 @@
instance-rpc-chan service-id reason-map start-new-service-fn queue-timeout-ms metric-group))]
(au/on-chan-close request-state-chan
(fn on-request-state-chan-close []
(cid/cdebug correlation-id "request-state-chan closed")
; assume request did not process successfully if no value in promise
(deliver reservation-status-promise :generic-error)
(let [status @reservation-status-promise]
(cid/cinfo correlation-id "done processing request" status)
(when (= :success status)
(counters/inc! (metrics/service-counter service-id "request-counts" "successful")))
(when (= :generic-error status)
(cid/cerror correlation-id "there was a generic error in processing the request;"
"if this is a client or server related issue, the code needs to be updated."))
(when (not= :success-async status)
(counters/dec! (metrics/service-counter service-id "request-counts" "outstanding"))
(statsd/gauge-delta! metric-group "request_outstanding" -1))
(service/release-instance-go instance-rpc-chan instance {:status status, :cid correlation-id, :request-id request-id})))
(fn [e] (log/error e "error releasing instance!")))
(cid/with-correlation-id
correlation-id
(log/debug "request-state-chan closed")
; assume request did not process successfully if no value in promise
(deliver reservation-status-promise :generic-error)
(let [status @reservation-status-promise]
(log/info "done processing request" status)
(when (= :success status)
(counters/inc! (metrics/service-counter service-id "request-counts" "successful")))
(when (= :generic-error status)
(log/error "there was a generic error in processing the request;"
"if this is a client or server related issue, the code needs to be updated."))
(when (not= :success-async status)
(counters/dec! (metrics/service-counter service-id "request-counts" "outstanding"))
(statsd/gauge-delta! metric-group "request_outstanding" -1))
(service/release-instance-go instance-rpc-chan instance {:status status, :cid correlation-id, :request-id request-id}))))
(fn [e]
(cid/with-correlation-id
correlation-id
(log/error e "error releasing instance!"))))
instance)))

(defn- handle-response-error
Expand Down Expand Up @@ -364,7 +369,7 @@
(histograms/update! (metrics/service-histogram service-id "request-content-length") content-length)
(statsd/inc! metric-group "request_content_length" content-length)))
(catch Exception e
(log/error e "Unable to track content-length on request")))
(log/error e "unable to track content-length on request")))
(when waiter-debug-enabled?
(log/info "connecting to" instance-endpoint "using" proto-version))
(let [auth-user-map (handler/make-auth-user-map request)
Expand Down Expand Up @@ -449,7 +454,7 @@
[bytes-streamed false])))
(catch Exception e
(histograms/update! (metrics/service-histogram service-id "response-size") bytes-streamed)
(log/error "Error occurred after streaming" bytes-streamed "bytes in response.")
(log/error "error occurred after streaming" bytes-streamed "bytes in response.")
; Handle lower down
(throw e)))]
(let [bytes-reported-to-statsd'
Expand All @@ -472,7 +477,7 @@
(when-let [output-stream @output-stream-atom]
(log/info "invoking poison pill directly on output stream")
(poison-pill-function output-stream))))
(log/error e "Exception occurred while streaming response for" service-id))
(log/error e "exception occurred while streaming response for" service-id))
(finally
(async/close! resp-chan)
(async/close! body)
Expand Down Expand Up @@ -507,6 +512,8 @@
[post-process-async-request-response-fn _ instance-request-properties descriptor instance
{:keys [uri] :as request} reason-map reservation-status-promise confirm-live-connection-with-abort
request-state-chan {:keys [status] :as response}]
(when (utils/request->debug-enabled? request)
(log/info "backend response status:" (:status response)"and headers:" (:headers response)))
(let [{:keys [service-description service-id]} descriptor
{:strs [backend-proto blacklist-on-503 metric-group]} service-description
waiter-debug-enabled? (utils/request->debug-enabled? request)
Expand Down Expand Up @@ -666,7 +673,7 @@
response-map (cond-> {:service-id service-id}
time (assoc :suspended-at (du/date-to-str time))
(not (str/blank? last-updated-by)) (assoc :last-updated-by last-updated-by))]
(log/info "Service has been suspended" response-map)
(log/info "service has been suspended" response-map)
(meters/mark! (metrics/service-meter service-id "response-rate" "error" "suspended"))
(-> {:details response-map, :message "Service has been suspended", :status 503}
(utils/data->error-response request)))
Expand All @@ -684,7 +691,7 @@
:max-queue-length max-queue-length
:outstanding-requests outstanding-requests
:service-id service-id}]
(log/info "Max queue length exceeded" response-map)
(log/info "max queue length exceeded" response-map)
(meters/mark! (metrics/service-meter service-id "response-rate" "error" "queue-length"))
(-> {:details response-map, :message "Max queue length exceeded", :status 503}
(utils/data->error-response request)))
Expand Down

0 comments on commit d31bd90

Please sign in to comment.