diff --git a/daemon.ml b/daemon.ml index c70c601..568e0fc 100644 --- a/daemon.ml +++ b/daemon.ml @@ -62,6 +62,12 @@ let unless_exit x = Lwt.pick [wait_exit (); x] let get_args () = [ ("-loglevel", Arg.String Log.set_loglevels, " ([=]debug|info|warn|error[,])+"); + ("-logformat", + Arg.Symbol (["plain"; "default"; "logfmt"], (function + | "plain" | "default" -> Log.State.set_plaintext () + | "logfmt" -> Log.State.set_logfmt () + | s -> failwith (Printf.sprintf "unknown log format %S" s))), + " Log output format (default: plain)"); ExtArg.may_str "logfile" logfile " Log file"; ExtArg.may_str "pidfile" pidfile " PID file"; "-runas", diff --git a/httpev.ml b/httpev.ml index 96c78fe..f352ac4 100644 --- a/httpev.ml +++ b/httpev.ml @@ -284,7 +284,7 @@ let finish ?(shutdown=true) c = | Ready req -> Hashtbl.remove c.server.reqs req.id; if c.server.config.debug then - log #info "finished %s" (show_request req) + log #info "finished" ~pairs:(pairs_of_request req) let write_f c (data,ack) ev fd _flags = let finish () = finish c; Ev.del ev in @@ -324,7 +324,7 @@ let log_access_apache ch code size ?(background=false) req = (header_safe req "x-request-id") (if background then " (BG)" else "") with exn -> - log #warn ~exn "access log : %s" @@ show_request req + log #warn ~exn "access log" ~pairs:(pairs_of_request req) let log_status_apache ch status size req = match status with @@ -498,10 +498,10 @@ let handle_request c body answer = | `Ok -> answer c.server req k end | _ -> - log #info "version %u.%u not supported from %s" (fst req.version) (snd req.version) (show_request req); + log #info "version %u.%u not supported" (fst req.version) (snd req.version) ~pairs:(pairs_of_request req); send_reply_async c Identity (`Version_not_supported,[],"HTTP/1.0 is supported") with exn -> - log #error ~exn "answer %s" @@ show_request req; + log #error ~exn "answer" ~pairs:(pairs_of_request req); match req.blocking with | None -> send_reply_async c Identity (`Not_found,[],"Not found") | Some _ -> Exn.suppress teardown c.fd @@ -639,7 +639,7 @@ let check_hung_requests server = let now = Time.now () in server.reqs |> Hashtbl.iter begin fun _ req -> if req.recv -. now > Time.minutes 30 then - log #warn "request takes too much time to process : %s" (show_request req) + log #warn "request takes too much time to process" ~pairs:(pairs_of_request req) end let check_waiting_requests srv = @@ -845,7 +845,7 @@ let answer_blocking ?(debug=false) srv req answer k = | Continue continue -> 200, Some continue | exn -> let saved_backtrace = Exn.get_backtrace () in - log #warn ~exn ~backtrace:debug ~saved_backtrace "answer forked %s" (show_request req); + log #warn ~exn ~backtrace:debug ~saved_backtrace "answer forked" ~pairs:(pairs_of_request req); -1, None in if srv.config.access_log_enabled then @@ -861,7 +861,7 @@ let nr_rejected = stats#count "rejected" let answer_forked ?debug srv req answer k = let do_fork () = match check_req req with - | `Error err -> Exn.fail "pre fork %s : %s" (show_request req) (Unix.error_message err) + | `Error err -> Exn.fail "pre fork : %s" (show_request req) (Unix.error_message err) | `Ok -> begin match Nix.fork () with | `Child -> @@ -873,7 +873,7 @@ let answer_forked ?debug srv req answer k = end; U.sys_exit 0 | `Forked pid -> - log #info "forked %d : %s" pid (show_request req); + log #info "forked %d" pid ~pairs:(pairs_of_request req); k (`No_reply,[],""); (* close socket in parent immediately *) Hashtbl.add srv.h_childs pid () end @@ -883,7 +883,7 @@ let answer_forked ?debug srv req answer k = do_fork () with exn -> - log #warn ~exn "answer fork failed %s" (show_request req); + log #warn ~exn "answer fork failed" ~pairs:(pairs_of_request req); k (`Internal_server_error,[],"") in if Hashtbl.length srv.h_childs < srv.config.max_data_childs then @@ -899,7 +899,7 @@ let answer_forked ?debug srv req answer k = else begin incr nr_rejected; - log #info "rejecting, overloaded : %s" (show_request req); + log #info "rejecting, overloaded" ~pairs:(pairs_of_request req); k (`Service_unavailable, ["Content-Type", "text/plain"], "overloaded") end @@ -989,11 +989,11 @@ let handle_request_lwt c req answer = try%lwt answer c.server req with exn -> - log #error ~exn "answer %s" @@ show_request req; + log #error ~exn "answer" ~pairs:(pairs_of_request req); return (`Not_found,[],"Not found") end | _ -> - log #info "version %u.%u not supported from %s" (fst req.version) (snd req.version) (show_request req); + log #info "version %u.%u not supported" (fst req.version) (snd req.version) ~pairs:(pairs_of_request req); return (`Version_not_supported,[],"HTTP/1.0 is supported") let read_buf ic buf = @@ -1163,7 +1163,7 @@ let rest ~show_exn req answer = | Arg.Bad s -> bad_request @@ sprintf "bad parameter %s in %s" s req.url | exn -> let ref = random_ref () in - log#warn ~exn "failed ref:%Ld %s" ref (show_request req); + log#warn ~exn "failed ref:%Ld" ref ~pairs:(pairs_of_request req); if show_exn then internal_error @@ sprintf "internal error ref:%Ld : %s" ref (match exn with Failure s -> s | _ -> Exn.str exn) else diff --git a/httpev_common.ml b/httpev_common.ml index 90364d4..90ebdb9 100644 --- a/httpev_common.ml +++ b/httpev_common.ml @@ -106,6 +106,17 @@ let show_request req = (header_safe req "user-agent") (header_safe req "x-request-id") +let pairs_of_request req : Logger.Pairs.t = + [ "req_id", string_of_int req.id; + "client_addr", show_client_addr req; + "http_duration", sprintf "%.4f" (Time.get () -. req.conn); + "http_recv_duration", sprintf "%.4f" (req.recv -. req.conn); + "http_host", header_safe req "host"; + "url", req.url; + "http_user_agent", header_safe req "user-agent"; + "http_req_id", header_safe req "x-request-id" + ] + let status_code : reply_status -> int = function | `Ok -> 200 | `Created -> 201 diff --git a/log.ml b/log.ml index 4ab2bc2..09c5998 100644 --- a/log.ml +++ b/log.ml @@ -77,30 +77,62 @@ module State = struct let output_ch ch = fun str -> try output_string ch str; flush ch with _ -> () (* logging never fails, most probably ENOSPC *) - let format_simple level facil msg = + let format_simple_full level facil ts pairs msg = let pid = Unix.getpid () in let tid = U.gettid () in let pinfo = if pid = tid then sprintf "%5u:" pid else sprintf "%5u:%u" pid tid in - sprintf "[%s] %s [%s:%s] %s\n" - (Time.to_string ~gmt:!utc_timezone ~ms:true (Unix.gettimeofday ())) + let pairs_str = match pairs with [] -> "" | _ -> " " ^ Logfmt.to_string pairs in + sprintf "[%s] %s [%s:%s] %s%s\n" + (Time.to_string ~gmt:!utc_timezone ~ms:true ts) pinfo facil.Logger.name (Logger.string_level level) msg + pairs_str + + let format_logfmt level facil ts pairs msg = + let pairs = ("msg", msg) :: pairs in + let pid = Unix.getpid () in + let tid = U.gettid () in + let pairs = + if pid = tid then ("pid", string_of_int pid) :: pairs + else ("pid", string_of_int pid) :: ("tid", string_of_int tid) :: pairs + in + let pairs = + ("time", Time.to_string ~gmt:!utc_timezone ~ms:true ts) :: + ("level", Logger.string_level level) :: + ("facil", facil.Logger.name) :: + pairs + in + let buf = Buffer.create 32 in + Logfmt.add_to_buffer buf pairs; + Buffer.add_char buf '\n'; + Buffer.contents buf + + let cur_format = Atomic.make format_simple_full + let set_cur_format f = Atomic.set cur_format f + let set_plaintext () = set_cur_format format_simple_full + let set_logfmt () = set_cur_format format_logfmt + + let format level facil ts pairs msg = + (Atomic.get cur_format) level facil ts pairs msg + + let format_simple level facil msg = + format level facil (Unix.gettimeofday()) [] msg let log_ch = stderr let () = assert (Unix.descr_of_out_channel stderr = Unix.stderr) let base_name = ref "" - let hook = ref (fun _ _ _ -> ()) + let output_simple level facil s = !hook level facil s; output_ch log_ch s - module Put = Logger.PutSimple( - struct - let format = format_simple - let output = fun level facil s -> let () = !hook level facil s in output_ch log_ch s - end) + let put = Logger.put_simple { + format; + output = output_simple; + } - module M = Logger.Make(Put) + (** Main logger, writes into [put] *) + let logger = Logger.make put let self = "lib" @@ -117,11 +149,21 @@ module State = struct (fun () -> Unix.dup2 (Unix.descr_of_out_channel ch) Unix.stderr) () with - e -> M.warn (facility self) "reopen_log_ch(%s) failed : %s" file (Printexc.to_string e) + e -> + let now = (Unix.gettimeofday ()) in + logger.warn (facility self) now [] "reopen_log_ch(%s) failed : %s" file (Printexc.to_string e) end -include State.M +let debug_s = State.logger.debug_s +let info_s = State.logger.info_s +let warn_s = State.logger.warn_s +let error_s = State.logger.error_s +let put_s = State.logger.put_s +let debug = State.logger.debug +let info = State.logger.info +let warn = State.logger.warn +let error = State.logger.error let facility = State.facility let set_filter = State.set_filter @@ -146,39 +188,39 @@ let read_env_config = State.read_env_config param [saved_backtrace]: supply backtrace to show instead of using [Printexc.get_backtrace] *) -type 'a pr = ?exn:exn -> ?lines:bool -> ?backtrace:bool -> ?saved_backtrace:string list -> ('a, unit, string, unit) format4 -> 'a +type 'a pr = ?exn:exn -> ?lines:bool -> ?backtrace:bool -> ?saved_backtrace:string list -> ?ts:Time.t -> ?pairs:Logger.Pairs.t -> ('a, unit, string, unit) format4 -> 'a class logger facil = -let make_s output_line = + let make_s (output_line:Logger.facil -> Time.t -> Logger.Pairs.t -> string -> unit) = let output = function | true -> - fun facil s -> + fun facil ts pairs s -> if String.contains s '\n' then - List.iter (output_line facil) @@ String.nsplit s "\n" + List.iter (output_line facil ts pairs) @@ String.nsplit s "\n" else - output_line facil s + output_line facil ts pairs s | false -> output_line in - let print_bt lines exn bt s = - output lines facil (s ^ " : exn " ^ Exn.str exn ^ (if bt = [] then " (no backtrace)" else "")); - List.iter (fun line -> output_line facil (" " ^ line)) bt + let print_bt lines exn bt ts pairs s = + output lines facil ts pairs (s ^ " : exn " ^ Exn.str exn ^ (if bt = [] then " (no backtrace)" else "")); + List.iter (fun line -> output_line facil ts pairs (" " ^ line)) bt in - fun ?exn ?(lines=true) ?(backtrace=false) ?saved_backtrace s -> + fun ?exn ?(lines=true) ?(backtrace=false) ?saved_backtrace ?(ts=Unix.gettimeofday()) ?(pairs=[]) s -> try match exn with - | None -> output lines facil s + | None -> output lines facil ts pairs s | Some exn -> match saved_backtrace with - | Some bt -> print_bt lines exn bt s + | Some bt -> print_bt lines exn bt ts pairs s | None -> match backtrace with - | true -> print_bt lines exn (Exn.get_backtrace ()) s - | false -> output lines facil (s ^ " : exn " ^ Exn.str exn) + | true -> print_bt lines exn (Exn.get_backtrace ()) ts pairs s + | false -> output lines facil ts pairs (s ^ " : exn " ^ Exn.str exn) with exn -> - output_line facil (sprintf "LOG FAILED : %S with message %S" (Exn.str exn) s) + output_line facil ts pairs (sprintf "LOG FAILED : %S with message %S" (Exn.str exn) s) in -let make output ?exn ?lines ?backtrace ?saved_backtrace fmt = - ksprintf (fun s -> output ?exn ?lines ?backtrace ?saved_backtrace s) fmt +let make : _ -> _ pr = fun output ?exn ?lines ?backtrace ?saved_backtrace ?ts ?pairs fmt -> + ksprintf (fun s -> output ?exn ?lines ?backtrace ?saved_backtrace ?ts ?pairs s) fmt in let debug_s = make_s debug_s in let warn_s = make_s warn_s in diff --git a/logfmt.ml b/logfmt.ml new file mode 100644 index 0000000..5079426 --- /dev/null +++ b/logfmt.ml @@ -0,0 +1,41 @@ + +let[@inline] needs_escape c = + Char.code c < 0x20 || c = '"' || c = '\\' + +let[@inline] needs_quotes c = + c = ' ' || Char.code c >= 0x80 + +type cat = Safe | Has_space | Needs_escape + +let categorize s : cat = + let quote = ref false in + + try + for i=0 to String.length s-1 do + let c = String.unsafe_get s i in + if needs_escape c then raise_notrace Exit; + if needs_quotes c then quote := true + done; + if !quote then Has_space else Safe + with Exit -> Needs_escape + +let add_pair buf k v = + Buffer.add_string buf k; + Buffer.add_char buf '='; + match categorize v with + | Safe -> Buffer.add_string buf v + | Has_space -> Printf.bprintf buf {|"%s"|} v + | Needs_escape -> Printf.bprintf buf "%S" v + +let rec add_to_buffer buf (pairs:Logger.Pairs.t) : unit = + match pairs with + | [] -> () + | [k,v] -> add_pair buf k v + | (k,v) :: pairs -> add_pair buf k v; Buffer.add_char buf ' '; add_to_buffer buf pairs + +let to_string pairs = match pairs with + | [] -> "" + | _ -> + let buf = Buffer.create 32 in + add_to_buffer buf pairs; + Buffer.contents buf diff --git a/logfmt.mli b/logfmt.mli new file mode 100644 index 0000000..a139910 --- /dev/null +++ b/logfmt.mli @@ -0,0 +1,3 @@ + +val add_to_buffer : Buffer.t -> Logger.Pairs.t -> unit +val to_string : Logger.Pairs.t -> string diff --git a/logger.ml b/logger.ml index 91184fb..2d91bbf 100644 --- a/logger.ml +++ b/logger.ml @@ -33,64 +33,72 @@ let level = function | "nothing" -> `Nothing | s -> Exn.fail "unrecognized level %s" s -module type Target = -sig - val format : level -> facil -> string -> string - val output : level -> facil -> string -> unit +module Pairs = struct + type pair = string*string + type t = pair list end -module type Put = sig -val put : level -> facil -> string -> unit -end +type target = { + format : level -> facil -> Time.t -> Pairs.t -> string -> string; + output : level -> facil -> string -> unit; +} -module PutSimple(T : Target) : Put = -struct +type put = { + put : level -> facil -> Time.t -> Pairs.t -> string -> unit +} [@@unboxed] - let put level facil str = +let put_simple (t:target) : put = { + put = fun level facil ts pairs str -> if allowed facil level then - T.output level facil (T.format level facil str) - -end + t.output level facil (t.format level facil ts pairs str) +} -module PutLimited(T : Target) : Put = -struct +let put_limited (t:target) : put = + let last = ref (`Debug,"") in + let n = ref 0 in - let last = ref (`Debug,"") - let n = ref 0 - - (** FIXME not thread safe *) - let put level facil str = + (* FIXME not thread safe *) + let put level facil ts pairs str = match allowed facil level with | false -> () | true -> let this = (level,str) in if !last = this then - incr n + n := !n + 1 else begin if !n <> 0 then begin - T.output level facil (sprintf + t.output level facil (sprintf "last message repeated %u times, suppressed\n" !n); n := 0 end; last := this; - T.output level facil (T.format level facil str); + t.output level facil (t.format level facil ts pairs str); end - -end - -module Make(T : Put) = struct - - let debug_s = T.put `Debug - let info_s = T.put `Info - let warn_s = T.put `Warn - let error_s = T.put `Error - let put_s = T.put - - let debug f fmt = ksprintf (debug_s f) fmt - let info f fmt = ksprintf (info_s f) fmt - let warn f fmt = ksprintf (warn_s f) fmt - let error f fmt = ksprintf (error_s f) fmt - -end + in { put } + +(** A logger *) +type t = { + debug_s: facil -> Time.t -> Pairs.t -> string -> unit; + info_s: facil -> Time.t -> Pairs.t -> string -> unit; + warn_s: facil -> Time.t -> Pairs.t -> string -> unit; + error_s: facil -> Time.t -> Pairs.t -> string -> unit; + put_s: level -> facil -> Time.t -> Pairs.t -> string -> unit; + debug: 'a. facil -> Time.t -> Pairs.t -> ('a, unit, string, unit) format4 -> 'a; + info: 'a. facil -> Time.t -> Pairs.t -> ('a, unit, string, unit) format4 -> 'a; + warn: 'a. facil -> Time.t -> Pairs.t -> ('a, unit, string, unit) format4 -> 'a; + error: 'a. facil -> Time.t -> Pairs.t -> ('a, unit, string, unit) format4 -> 'a; +} + +let make (t:put) : t = + let debug_s = t.put `Debug in + let info_s = t.put `Info in + let warn_s = t.put `Warn in + let error_s = t.put `Error in + let put_s = t.put in + let debug f ts pairs fmt = ksprintf (debug_s f ts pairs) fmt in + let info f ts pairs fmt = ksprintf (info_s f ts pairs) fmt in + let warn f ts pairs fmt = ksprintf (warn_s f ts pairs) fmt in + let error f ts pairs fmt = ksprintf (error_s f ts pairs) fmt in + { debug_s; info_s; warn_s; error_s; put_s; debug; info; warn; error } diff --git a/test.ml b/test.ml index e578035..c9af39f 100644 --- a/test.ml +++ b/test.ml @@ -595,6 +595,69 @@ let () = assert_equal !accumulator 4; () +let () = test "Logfmt" begin fun () -> + let eq name expected got = + assert_equal ~msg:name ~printer:(fun s -> sprintf "%S" s) expected got + in + eq "empty" "" (Logfmt.to_string []); + eq "safe" "k=v" (Logfmt.to_string ["k","v"]); + eq "multiple" "a=1 b=2" (Logfmt.to_string [("a","1");("b","2")]); + eq "empty value" "k=" (Logfmt.to_string ["k",""]); + eq "space" {|k="hello world"|} (Logfmt.to_string ["k","hello world"]); + eq "newline" {|k="a\nb"|} (Logfmt.to_string ["k","a\nb"]); + eq "quote" {|k="a\"b"|} (Logfmt.to_string ["k","a\"b"]); + eq "backslash" {|k="a\\b"|} (Logfmt.to_string ["k","a\\b"]); + eq "utf8" {|k="é"|} (Logfmt.to_string ["k","é"]); +end + +let with_log_hook f = + let buf = Buffer.create 128 in + let prev = !Log.State.hook in + Log.State.hook := (fun _ _ s -> Buffer.add_string buf s); + Std.finally (fun () -> Log.State.hook := prev) f (); + buf + +let () = test "Log.pairs" begin fun () -> + let prev_utc = !Log.State.utc_timezone in + Log.State.utc_timezone := true; + Std.finally (fun () -> Log.State.utc_timezone := prev_utc) (fun () -> + let ts = 1700000000. in (* 2023-11-14 22:13:20 UTC *) + let log = Log.from "logtest" in + let check ~msg ~suffix out = + assert_bool (sprintf "%s: expected suffix %S, got %S" msg suffix out) + (Stre.ends_with out suffix) + in + let run action = + let out = Buffer.contents (with_log_hook action) in + assert_bool ("facility in output: " ^ out) (Stre.exists out "[logtest:"); + assert_bool ("ts in output: " ^ out) (Stre.exists out "2023-11-14"); + out + in + let out = run (fun () -> log#info ~ts ~pairs:["k","v"] "hello %d" 42) in + check ~msg:"pairs suffix" ~suffix:" hello 42 k=v\n" out; + let out = run (fun () -> log#info ~ts "plain") in + check ~msg:"no pairs" ~suffix:" plain\n" out; + let out = run (fun () -> log#warn ~ts ~pairs:[("a","1");("quoted","he said \"hi\"")] "m") in + check ~msg:"escape+multi" ~suffix:({| m a=1 quoted="he said \"hi\""|} ^ "\n") out; + assert_bool ("warn level: " ^ out) (Stre.exists out "[logtest:warn]") + ) () +end + +let () = test "Log.filter" begin fun () -> + let log = Log.from "filtertest" in + let prev_level = log#level in + log#allow `Warn; + Std.finally (fun () -> log#allow prev_level) (fun () -> + let buf = with_log_hook (fun () -> + log#info "suppressed"; + log#warn "kept" + ) in + let out = Buffer.contents buf in + assert_bool ("only warn survives: " ^ out) (not (Stre.exists out "suppressed")); + assert_bool ("warn kept: " ^ out) (Stre.exists out "kept") + ) () +end + let tests () = let (_:test_results) = run_test_tt_main ("devkit" >::: List.rev !tests) in () diff --git a/web.ml b/web.ml index 806dbbd..bffd7e4 100644 --- a/web.ml +++ b/web.ml @@ -238,28 +238,36 @@ module Http (IO : IO_TYPE) (Curl_IO : CURL with type 'a t = 'a IO.t) : HTTP with let verbose_curl_result nr_http action t h code = let open Curl in - let b = Buffer.create 10 in - bprintf b "%s #%d %s ⇓%s ⇑%s %s " - (string_of_http_action action) nr_http (Time.compact_duration t#get) - (Action.bytes_string_f @@ get_sizedownload h) - (Action.bytes_string_f @@ get_sizeupload h) - (get_primaryip h) - ; - begin match code with + let size_down = get_sizedownload h in + let size_up = get_sizeupload h in + let base = [ + "method", string_of_http_action action; + "http_seq", string_of_int nr_http; + "duration", sprintf "%.3f" t#get; + "size_down", Action.bytes_string_f size_down; + "size_down_raw", sprintf "%.0f" size_down; + "size_up", Action.bytes_string_f size_up; + "size_up_raw", sprintf "%.0f" size_up; + "ip", get_primaryip h; + ] in + let base = match get_httpcode h with + | 0 -> base + | n -> ("http_status", string_of_int n) :: base + in + match code with | CURLE_OK -> - bprintf b "HTTP %d %s" (get_httpcode h) (get_effectiveurl h); - begin match get_redirecturl h with - | "" -> () - | s -> bprintf b " -> %s" s - end; - begin match get_redirectcount h with - | 0 -> () - | n -> bprintf b " after %d redirects" n - end + let pairs = ("url", get_effectiveurl h) :: base in + let pairs = match get_redirecturl h with "" -> pairs | s -> ("redirect", s) :: pairs in + let pairs = match get_redirectcount h with 0 -> pairs | n -> ("redirect_count", string_of_int n) :: pairs in + log #info ~pairs "http done" | _ -> - bprintf b "error (%d) %s (errno %d)" (errno code) (strerror code) (Curl.get_oserrno h) - end; - log #info_s (Buffer.contents b) + let pairs = + ("err", strerror code) :: + ("errno", string_of_int (errno code)) :: + ("oserrno", string_of_int (get_oserrno h)) :: + base + in + log #info ~pairs "http error" (* Given a list of strings, check pre-existing entry starting with `~name`; and adds the concatenation of `~name` and `~value` if not. *) let add_if_absent ~name ~value strs = @@ -320,7 +328,13 @@ module Http (IO : IO_TYPE) (Curl_IO : CURL with type 'a t = 'a IO.t) : HTTP with | Some (`Raw (ct,body)) -> sprintf "%s \"%s\"" ct (Stre.shorten ~escape:true 64 body) | Some (`Chunked (ct,_f)) -> sprintf "%s chunked" ct in - log #info "%s #%d %s %s" action_name nr_http url body + let pairs = [ + "method", action_name; + "http_seq", string_of_int nr_http; + "url", url; + ] in + let pairs = if body = "" then pairs else ("body", body) :: pairs in + log #info ~pairs "http start" end; let describe () =