Request logging for HTTP 2.x + fixed docs prefix stripping bug (#304)

**Request Logging**
As part of the HTTP 2.x upgrade I wanted to ensure we didn't drop support for request logs. I've carried over the exact same spec + small improvements so previous log formats should work as is. Any web framework needs to have some level of default logging in place, so I had to postpone the upgrade until something like this was in place

- `access_log` is still the main entry point for customizing the log format
-  The `logfmt` macro from 1.x of HTTP.jl is carried over
- The same log formatting is used and exposed as`oxygen_logfmt` (used by default)

**Docs Prefix Bug**
Fixed an issue where docs wouldn't render properly due to the absolute paths that were configured internally. When running oxygen behind a reverse-proxy, the docs pages weren't accessible. The solution was to make sure all docs links are relative links so they work with custom and global prefixes

Author: ndortega

Project.toml

@@ -5,10 +5,12 @@ authors = ["Nathan Ortega <nate.ortega95@gmail.com>"]
 repo = "https://github.com/OxygenFramework/Oxygen.jl.git"
 
 [deps]
+Base64 = "2a0f44e3-6c83-55bd-87e4-b1978d98bd5f"
 DataStructures = "864edb3b-99cc-5e75-8d2d-829cb0a9cfe8"
 Dates = "ade2ca70-3891-5945-98fb-dc099432e06a"
 HTTP = "cd3eb016-35fb-5094-929b-558a96fad6f3"
 JSON = "682c06a0-de6a-54ab-a142-c8b1cf79cde6"
+Logging = "56ddb016-857b-54e1-b83d-db4d58db5568"
 LRUCache = "8ac3fa9e-de4c-5943-b1dc-09c6b5f20637"
 MIMEs = "6c6e2e6c-3030-632d-7369-2d6c69616d65"
 Reexport = "189a3867-3050-52da-a836-e630ba90ab69"
@@ -37,6 +39,7 @@ TimeZonesExt = "TimeZones"
 WGLMakieExt = ["WGLMakie", "Bonito"]
 
 [compat]
+Base64 = "^1"
 Bonito = "^5"
 CairoMakie = "^0.13, 0.15"
 DataStructures = "^0.18.15, 0.19"

README.md

@@ -1055,10 +1055,34 @@ serve()
 ```
 ## Logging
 
-HTTP.jl 2.x no longer does per-request access logging in the server, so the `access_log` keyword
-(and the `logfmt"..."` format macro) from earlier Oxygen versions is gone. The `access_log` kwarg
-is still accepted by `serve()` and `serveparallel()` for backwards compatibility, but it is ignored.
-If you need request logging, add it yourself with a small [middleware](#middleware) function.
+Since HTTP.jl 2.x no longer performs per-request access logging in the server, 
+we reintroduced request-level logging through the built-in `AccessLog` middleware. It emits a log entry
+for each request through Julia's logging system (at `Info` level with `_group=:access`) using
+NGINX-style format strings defined with the `logfmt"..."` macro. 
+
+In practice, you'll rarely need to configure this middleware function yourself. The main entrypoint to configure the logging format is the `access_log` keyword in the `serve()` and `serverparallel()` function:
+
+```julia
+serve(access_log=logfmt"[$time_iso8601] \"$request\" $status $body_bytes_sent")
+```
+
+If you ever want to have additional request logging formats running alongside the default you can insert the middleware function like this:
+
+```julia
+using Oxygen
+
+# Oxygen Log Format (default)
+serve(middleware=[AccessLog()])
+
+# Combined Log Format
+serve(middleware=[AccessLog(format=combined_logfmt)])
+
+# Custom format
+serve(middleware=[AccessLog(format=logfmt"[$time_iso8601] \"$request\" $status $body_bytes_sent")])
+```
+
+Because entries go through the standard logging system, they can be captured, filtered or
+redirected to a file using the `Logging` / `LoggingExtras` APIs.
 
 ## Middleware
 

demo/Project.toml

@@ -10,6 +10,7 @@ Gtk = "4c0ca9eb-093a-5379-98c5-f87ac0bbbf44"
 HTTP = "cd3eb016-35fb-5094-929b-558a96fad6f3"
 JSON = "682c06a0-de6a-54ab-a142-c8b1cf79cde6"
 JSON3 = "0f8b85d8-7281-11e9-16c2-39a750bddbf1"
+LRUCache = "8ac3fa9e-de4c-5943-b1dc-09c6b5f20637"
 MIMEs = "6c6e2e6c-3030-632d-7369-2d6c69616d65"
 Mustache = "ffc61752-8dc7-55ee-8c37-f3e9cdd09e70"
 OteraEngine = "b2d7f28f-acd6-4007-8b26-bc27716e5513"
@@ -23,4 +24,5 @@ StructTypes = "856f2bd8-1eba-4b0a-8007-ebc267875bd4"
 Suppressor = "fd094767-a336-5f1f-9728-57cf17d0bbfb"
 SwaggerMarkdown = "1b6eb727-ad4b-44eb-9669-b9596a6e760f"
 TimeZones = "f269a46b-ccf7-5d73-abea-4c690281aa53"
+URIs = "5c2747f8-b7ea-4ff2-ba2e-563bfd36b1d4"
 WGLMakie = "276b4fcb-3e11-5398-bf8b-a0c2d153d008"

demo/ergonomicsdemo.jl

@@ -2,7 +2,6 @@ module ErgonomicsDemo
 
 using Oxygen
 using Dates
-using HTTP
 using JSON
 using Base: @kwdef
 using BenchmarkTools

docs/src/index.md

@@ -1055,10 +1055,34 @@ serve()
 ```
 ## Logging
 
-HTTP.jl 2.x no longer does per-request access logging in the server, so the `access_log` keyword
-(and the `logfmt"..."` format macro) from earlier Oxygen versions is gone. The `access_log` kwarg
-is still accepted by `serve()` and `serveparallel()` for backwards compatibility, but it is ignored.
-If you need request logging, add it yourself with a small [middleware](#middleware) function.
+Since HTTP.jl 2.x no longer performs per-request access logging in the server, 
+we reintroduced request-level logging through the built-in `AccessLog` middleware. It emits a log entry
+for each request through Julia's logging system (at `Info` level with `_group=:access`) using
+NGINX-style format strings defined with the `logfmt"..."` macro. 
+
+In practice, you'll rarely need to configure this middleware function yourself. The main entrypoint to configure the logging format is the `access_log` keyword in the `serve()` and `serverparallel()` function:
+
+```julia
+serve(access_log=logfmt"[$time_iso8601] \"$request\" $status $body_bytes_sent")
+```
+
+If you ever want to have additional request logging formats running alongside the default you can insert the middleware function like this:
+
+```julia
+using Oxygen
+
+# Oxygen Log Format (default)
+serve(middleware=[AccessLog()])
+
+# Combined Log Format
+serve(middleware=[AccessLog(format=combined_logfmt)])
+
+# Custom format
+serve(middleware=[AccessLog(format=logfmt"[$time_iso8601] \"$request\" $status $body_bytes_sent")])
+```
+
+Because entries go through the standard logging system, they can be captured, filtered or
+redirected to a file using the `Logging` / `LoggingExtras` APIs.
 
 ## Middleware
 
@@ -1089,7 +1113,7 @@ function CorsMiddleware(handler)
     return function(req::HTTP.Request)
         println("CORS middleware")
         # determine if this is a pre-flight request from the browser
-        if req.method=="OPTIONS"
+        if HTTP.method(req)=="OPTIONS"
             return HTTP.Response(200, CORS_HEADERS)  
         else 
             return handler(req) # passes the request to the AuthMiddleware

src/Oxygen.jl

@@ -48,6 +48,7 @@ export  @oxidize, @oxidise, @get, @post, @put, @patch, @delete, @route,
         Path, Query, Header, Json, JsonFragment, Form, Body, extract, validate,
         # Middleware
         BearerAuth, Cors, RateLimiter, ExtractIP,
+        AccessLog, common_logfmt, combined_logfmt, oxygen_logfmt, @logfmt_str,
         # Docs
         configdocs, mergeschema, setschema, getschema, router,
         enabledocs, disabledocs, isdocsenabled, 

src/autodoc.jl

@@ -801,7 +801,7 @@ function readstaticfile(filepath::String)::String
 end
 
 
-function redochtml(schemapath::String, docspath::String) :: HTTP.Response
+function redochtml(schemapath::String) :: HTTP.Response
     redocjs = readstaticfile("$REDOC_VERSION/redoc.standalone.js")
 
     html("""
@@ -813,7 +813,7 @@ function redochtml(schemapath::String, docspath::String) :: HTTP.Response
             <meta charset="utf-8"/>
             <meta name="description" content="Docs" />
             <meta name="viewport" content="width=device-width, initial-scale=1">
-            <link rel="icon" type="image/x-icon" href="$docspath/metrics/favicon.ico">
+            <link rel="icon" type="image/x-icon" href="metrics/favicon.ico">
         </head>
         
         <body>
@@ -829,7 +829,7 @@ end
 """
 Return HTML page to render the autogenerated docs
 """
-function swaggerhtml(schemapath::String, docspath::String) :: HTTP.Response
+function swaggerhtml(schemapath::String) :: HTTP.Response
 
     # load static content files
     swaggerjs = readstaticfile("$SWAGGER_VERSION/swagger-ui-bundle.js")
@@ -845,7 +845,7 @@ function swaggerhtml(schemapath::String, docspath::String) :: HTTP.Response
             <meta name="viewport" content="width=device-width, initial-scale=1" />
             <meta name="description" content="Docs" />
             <style>$swaggerstyles</style>
-            <link rel="icon" type="image/x-icon" href="$docspath/metrics/favicon.ico">
+            <link rel="icon" type="image/x-icon" href="metrics/favicon.ico">
         </head>
         
         <body>

src/core.jl

@@ -26,9 +26,14 @@ include("repeattasks.jl");  @reexport using .RepeatTasks
 include("metrics.jl");      @reexport using .Metrics
 include("reflection.jl");   @reexport using .Reflection
 include("extractors.jl");   @reexport using .Extractors
-using .Extractors: Form  # Prefer over HTTP.Form
 include("autodoc.jl");      @reexport using .AutoDoc
 
+# Both HTTP and our Extractors module export a type named `Form`, which makes the
+# name ambiguous (and thus unbound) after `using HTTP` + `@reexport using .Extractors`.
+# The explicit import below resolves the ambiguity so `Oxygen.Form` is actually defined,
+# preferring our own extractor over HTTP.Form.
+using .Extractors: Form
+
 export start, serve, serveparallel, terminate,
     internalrequest, staticfiles, dynamicfiles
 
@@ -84,7 +89,7 @@ function ReviseHandler()
 end
 
 """
-    serve(; middleware::Vector=[], handler=stream_handler, host="127.0.0.1", port=8080, async=false, parallel=false, serialize=true, catch_errors=true, docs=true, metrics=true, show_errors=true, show_banner=true, docs_path="/docs", schema_path="/schema", external_url=nothing, revise, kwargs...)
+    serve(; middleware::Vector=[], handler=stream_handler, host="127.0.0.1", port=8080, async=false, parallel=false, serialize=true, catch_errors=true, docs=true, metrics=true, show_errors=true, show_banner=true, docs_path="/docs", schema_path="/schema", external_url=nothing, access_log=oxygen_logfmt, revise, kwargs...)
 
 Start the webserver with your own custom request handler
 """
@@ -107,6 +112,7 @@ function serve(ctx::ServerContext;
     prefix      = nothing,
     context     = missing,
     revise      = :none, # :none, :lazy, :eager
+    access_log  = oxygen_logfmt, # (io::IO, req::HTTP.Request) -> nothing formatter
     kwargs...) :: Server
 
     if !ismissing(context)
@@ -143,7 +149,7 @@ function serve(ctx::ServerContext;
     end
 
     # compose our middleware ahead of time (so it only has to be built up once)
-    configured_middelware = setupmiddleware(ctx; middleware, serialize, catch_errors, docs, metrics, show_errors)
+    configured_middelware = setupmiddleware(ctx; middleware, serialize, catch_errors, docs, metrics, show_errors, access_log)
 
     # setup the primary stream handler function (can be customized by the caller)
     handle_stream = handler(configured_middelware)
@@ -319,11 +325,11 @@ Compose the user & internally defined middleware functions together. Practically
 users to 'chain' middleware functions like `serve(handler1, handler2, handler3)` when starting their 
 application and have them execute in the order they were passed (left to right) for each incoming request
 """
-function setupmiddleware(ctx::ServerContext; middleware::Vector=[], docs::Bool=true, metrics::Bool=true, serialize::Bool=true, catch_errors::Bool=true, show_errors=true)::Function
+function setupmiddleware(ctx::ServerContext; middleware::Vector=[], docs::Bool=true, metrics::Bool=true, serialize::Bool=true, catch_errors::Bool=true, show_errors=true, access_log=nothing)::Function
 
     # determine if we have any special router or route-specific middleware
     raw_middleware = reverse(middleware)
-    
+
     processed_middleware = process_middleware(ctx, raw_middleware)
 
     custom_middleware = if !isempty(ctx.service.custommiddleware)
@@ -344,13 +350,22 @@ function setupmiddleware(ctx::ServerContext; middleware::Vector=[], docs::Bool=t
     # check if we need to track metrics
     collect_metrics = metrics ? [MetricsMiddleware(ctx.service, metrics)] : []
 
+    # check if access logging was requested
+    access_loggers = if access_log !== nothing
+        access_log isa Function || throw(ArgumentError("access_log must be a formatter function `(io::IO, req::HTTP.Request) -> nothing`, e.g. a logfmt\"...\" value"))
+        [AccessLog(format=access_log)]
+    else
+        []
+    end
+
     # combine all our middleware functions
     return reduce(|>, [
         ctx.service.router,
         serializer...,
         custom_middleware...,
         collect_metrics...,
         docs_middleware...,
+        access_loggers...,
         global_prefix_middleware...
     ])
 end
@@ -395,12 +410,11 @@ end
 
 
 """
-Removes deprecated keys from incoming keyword arguments, currently: :stream, :access_log, and :queuesize.
+Removes deprecated keys from incoming keyword arguments, currently: :stream and :queuesize.
 """
 function preprocesskwargs(kwargs)
     kwargs_dict = Dict{Symbol,Any}(kwargs)
     delete!(kwargs_dict, :stream)
-    delete!(kwargs_dict, :access_log)
     delete!(kwargs_dict, :queuesize)
     return kwargs_dict
 end
@@ -802,16 +816,20 @@ end
 function setupdocs(ctx::ServerContext, router::Router, schema::Dict, docspath::String, schemapath::String)
     full_schema = "$docspath$schemapath"
 
-    # If a global prefix is assigned, then we need to make sure we inject the prefixes into the source url as well.
-    prefixed_schema = join_url_path(ctx.service.prefix[], full_schema)
-    prefixed_docspath = join_url_path(ctx.service.prefix[], docspath)
+    # Emit the schema URL relative (no leading slash) so it resolves regardless of
+    # prefix-stripping reverse proxies. Nested pages (/docs/swagger, /docs/redoc) resolve
+    # a bare "schema" against <docspath>/, but the bare /docs page needs the docspath
+    # segment ("docs/schema") since its base directory is "/".
+    schema_url = String(lstrip(schemapath, '/'))
+    bare_schema_url = String(lstrip("$docspath$schemapath", '/'))
 
-    # Need to update the "path" in our open-api schema to include the global prefix
+    # If a global prefix is assigned, then we need to make sure we inject it into the
+    # "paths" of the open-api schema.
     prefixed_openapi_schema = prefix_schema_paths(schema, ctx.service.prefix[])
 
-    register_internal(ctx, router, "GET", "$docspath", () -> swaggerhtml(prefixed_schema, prefixed_docspath))
-    register_internal(ctx, router, "GET", "$docspath/swagger", () -> swaggerhtml(prefixed_schema, prefixed_docspath))
-    register_internal(ctx, router, "GET", "$docspath/redoc", () -> redochtml(prefixed_schema, prefixed_docspath))
+    register_internal(ctx, router, "GET", "$docspath", () -> swaggerhtml(bare_schema_url))
+    register_internal(ctx, router, "GET", "$docspath/swagger", () -> swaggerhtml(schema_url))
+    register_internal(ctx, router, "GET", "$docspath/redoc", () -> redochtml(schema_url))
     register_internal(ctx, router, "GET", full_schema, () -> prefixed_openapi_schema)
 end
 

src/middleware.jl

@@ -5,5 +5,6 @@ include("middleware/extract_ip.jl"); @reexport using .ExtractIPMiddleware
 include("middleware/rate_limiter.jl"); @reexport using .RateLimiterMiddleware
 include("middleware/auth_middleware.jl"); @reexport using .AuthMiddleware
 include("middleware/cors_middleware.jl"); @reexport using .CORSMiddleware
+include("middleware/access_log.jl"); @reexport using .AccessLogMiddleware
 
 end