Add $body_bytes_received to log number of (body) bytes read from client, fixes #892.

Author: fredrikekre

src/Streams.jl

@@ -13,7 +13,8 @@ mutable struct Stream{M <: Message, S <: IO} <: IO
     readchunked::Bool
     warn_not_to_read_one_byte_at_a_time::Bool
     ntoread::Int
-    nwritten::Int
+    nread::Int    # number of read body bytes
+    nwritten::Int # number of written body bytes
 end
 
 """
@@ -36,7 +37,7 @@ Creates a `HTTP.Stream` that wraps an existing `IO` stream.
     for reuse. If a complete response has not been received, `closeread` throws
     `EOFError`.
 """
-Stream(r::M, io::S) where {M, S} = Stream{M, S}(r, io, false, false, true, 0, 0)
+Stream(r::M, io::S) where {M, S} = Stream{M, S}(r, io, false, false, true, 0, 0, 0)
 
 Messages.header(http::Stream, a...) = header(http.message, a...)
 setstatus(http::Stream, status) = (http.message.response.status = status)
@@ -208,6 +209,9 @@ end
 
 @inline function update_ntoread(http::Stream, n)
 
+    # Record number of read bytes for logging
+    http.nread += n
+
     if http.ntoread != unknown_length
         http.ntoread -= n
     end

src/access_log.jl

@@ -20,6 +20,7 @@ The following variables are currently supported:
  - `$time_local`: local time in Common Log Format
  - `$status`: response status code
  - `$body_bytes_sent`: number of bytes in response body
+ - `$body_bytes_received`: number of bytes read from client
 
 ## Examples
 ```julia
@@ -34,7 +35,6 @@ end
 
 function logfmt_parser(s)
     s = String(s)
-    vars = Symbol[]
     ex = Expr(:call, :print, :io)
     i = 1
     while i <= lastindex(s)
@@ -101,6 +101,8 @@ function symbol_mapping(s::Symbol)
         :(http.message.response.status)
     elseif s === :body_bytes_sent
         return :(http.nwritten)
+    elseif s === :body_bytes_received
+        return :(http.nread)
     else
         error("unknown variable in logfmt: $s")
     end

test/server.jl

@@ -208,6 +208,12 @@ end # @testset
             close(http.stream)
             return
         end
+        if http.message.method == "POST" && http.message.target == "/post"
+            read(http, String)
+            HTTP.setstatus(http, 200)
+            HTTP.startwrite(http)
+            return
+        end
         HTTP.setstatus(http, 200)
         HTTP.setheader(http, "Content-Type" => "text/plain")
         msg = "hello, world"
@@ -270,19 +276,21 @@ end # @testset
     @test occursin(r"^127.0.0.1 - - \[(\d{2})/.*/(\d{4}):\d{2}:\d{2}:\d{2}.*\] \"HEAD / HTTP/1.1\" 200 0 \"-\" \"HTTP\.jl/.*\"$", logs[4].message)
 
     # Custom log format
-    fmt = logfmt"$http_accept $sent_http_content_type $request $request_method $request_uri $remote_addr $remote_port $remote_user $server_protocol $time_iso8601 $time_local $status $body_bytes_sent"
+    fmt = logfmt"$http_accept $sent_http_content_type $request $request_method $request_uri $remote_addr $remote_port $remote_user $server_protocol $time_iso8601 $time_local $status $body_bytes_sent $body_bytes_received"
     logs = with_testserver(fmt) do
         HTTP.get("http://localhost:32612", ["Accept" => "application/json"])
         HTTP.get("http://localhost:32612/index.html")
         HTTP.get("http://localhost:32612/index.html?a=b")
         HTTP.head("http://localhost:32612")
+        HTTP.post("http://localhost:32612/post", [], "hello, world")
     end
-    @test length(logs) == 4
+    @test length(logs) == 5
     @test all(x -> x.group === :access, logs)
-    @test occursin(r"^application/json text/plain GET / HTTP/1\.1 GET / 127\.0\.0\.1 \d+ - HTTP/1\.1 \d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}.* \d+/.*/\d{4}:\d{2}:\d{2}:\d{2}.* 200 12$", logs[1].message)
-    @test occursin(r"^\*/\* text/plain GET /index\.html HTTP/1\.1 GET /index\.html 127\.0\.0\.1 \d+ - HTTP/1\.1 \d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}.* \d+/.*/\d{4}:\d{2}:\d{2}:\d{2}.* 200 12$", logs[2].message)
-    @test occursin(r"^\*/\* text/plain GET /index\.html\?a=b HTTP/1\.1 GET /index\.html\?a=b 127\.0\.0\.1 \d+ - HTTP/1\.1 \d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}.* \d+/.*/\d{4}:\d{2}:\d{2}:\d{2}.* 200 12$", logs[3].message)
-    @test occursin(r"^\*/\* text/plain HEAD / HTTP/1\.1 HEAD / 127\.0\.0\.1 \d+ - HTTP/1\.1 \d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}.* \d+/.*/\d{4}:\d{2}:\d{2}:\d{2}.* 200 0$", logs[4].message)
+    @test occursin(r"^application/json text/plain GET / HTTP/1\.1 GET / 127\.0\.0\.1 \d+ - HTTP/1\.1 \d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}.* \d+/.*/\d{4}:\d{2}:\d{2}:\d{2}.* 200 12 0$", logs[1].message)
+    @test occursin(r"^\*/\* text/plain GET /index\.html HTTP/1\.1 GET /index\.html 127\.0\.0\.1 \d+ - HTTP/1\.1 \d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}.* \d+/.*/\d{4}:\d{2}:\d{2}:\d{2}.* 200 12 0$", logs[2].message)
+    @test occursin(r"^\*/\* text/plain GET /index\.html\?a=b HTTP/1\.1 GET /index\.html\?a=b 127\.0\.0\.1 \d+ - HTTP/1\.1 \d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}.* \d+/.*/\d{4}:\d{2}:\d{2}:\d{2}.* 200 12 0$", logs[3].message)
+    @test occursin(r"^\*/\* text/plain HEAD / HTTP/1\.1 HEAD / 127\.0\.0\.1 \d+ - HTTP/1\.1 \d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}.* \d+/.*/\d{4}:\d{2}:\d{2}:\d{2}.* 200 0 0$", logs[4].message)
+    @test occursin(r"^\*/\* - POST /post HTTP/1\.1 POST /post 127\.0\.0\.1 \d+ - HTTP/1\.1 \d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}.* \d+/.*/\d{4}:\d{2}:\d{2}:\d{2}.* 200 0 12$", logs[5].message)
 end
 
 end # module