%%%------------------------------------------------------------------- %%% @doc QLOG Tracing for QUIC (draft-ietf-quic-qlog-quic-events) %%% %%% Provides JSON-SEQ format trace files for debug visibility with %%% Wireshark/qvis compatibility. %%% %%% Usage: pass `qlog' option to `quic:connect/4': %%% `#{qlog => #{enabled => true, dir => "/tmp/qlog"}}' %%% @end %%%------------------------------------------------------------------- -module(quic_qlog). -include("quic_qlog.hrl"). %% API -export([ new/3, close/1, is_enabled/1 ]). %% Event emission -export([ packet_sent/2, packet_received/2, frames_processed/2, connection_started/1, connection_state_updated/3, connection_closed/3, packets_acked/3, packet_lost/2, metrics_updated/2 ]). %% Writer process -export([ start_writer/2, writer_loop/1 ]). %%==================================================================== %% Types %%==================================================================== -type qlog_opts() :: #{ enabled => boolean(), dir => file:filename(), events => all | [atom()] }. -export_type([qlog_opts/0]). %%==================================================================== %% Writer State Record %%==================================================================== -record(writer_state, { fd :: file:io_device(), buffer = [] :: [iodata()], buffer_size = 0 :: non_neg_integer(), flush_timer :: reference() | undefined }). %%==================================================================== %% API %%==================================================================== %% @doc Create a new QLOG context from connection options. %% Returns undefined if qlog is disabled. -spec new(Opts :: map(), ODCID :: binary(), VantagePoint :: client | server) -> #qlog_ctx{} | undefined. new(Opts, ODCID, VantagePoint) -> %% Check connection options first, then application env QlogOpts = get_qlog_opts(Opts), case maps:get(enabled, QlogOpts, false) of false -> undefined; true -> Dir = maps:get(dir, QlogOpts, "/tmp/qlog"), Events = maps:get(events, QlogOpts, all), RefTime = erlang:system_time(millisecond), %% Create directory if it doesn't exist ok = filelib:ensure_dir(filename:join(Dir, "dummy")), %% Generate filename: {odcid_hex}_{vantage}_{timestamp}.qlog Filename = generate_filename(Dir, ODCID, VantagePoint, RefTime), %% Create JSON-SEQ header Header = encode_header(ODCID, VantagePoint, RefTime), %% Start writer process {ok, WriterPid} = start_writer(Filename, Header), #qlog_ctx{ enabled = true, writer = WriterPid, odcid = ODCID, reference_time = RefTime, vantage_point = VantagePoint, events = Events, dir = Dir } end. %% @doc Close the QLOG context and flush remaining data. -spec close(#qlog_ctx{} | undefined) -> ok. close(undefined) -> ok; close(#qlog_ctx{enabled = false}) -> ok; close(#qlog_ctx{writer = WriterPid}) when is_pid(WriterPid) -> WriterPid ! {close, self()}, receive {closed, WriterPid} -> ok after 5000 -> %% Force kill if writer doesn't respond exit(WriterPid, kill), ok end; close(_) -> ok. %% @doc Check if QLOG is enabled for this context. -spec is_enabled(#qlog_ctx{} | undefined) -> boolean(). is_enabled(undefined) -> false; is_enabled(#qlog_ctx{enabled = Enabled}) -> Enabled. %%==================================================================== %% Event Emission %%==================================================================== %% @doc Log a packet_sent event. -spec packet_sent(#qlog_ctx{} | undefined, map()) -> ok. packet_sent(undefined, _) -> ok; packet_sent(#qlog_ctx{enabled = false}, _) -> ok; packet_sent(Ctx, Info) -> case event_enabled(Ctx, ?QLOG_PACKET_SENT) of false -> ok; true -> Event = #{ name => <<"quic:packet_sent">>, data => encode_packet_info(Info) }, emit_event(Ctx, Event) end. %% @doc Log a packet_received event. -spec packet_received(#qlog_ctx{} | undefined, map()) -> ok. packet_received(undefined, _) -> ok; packet_received(#qlog_ctx{enabled = false}, _) -> ok; packet_received(Ctx, Info) -> case event_enabled(Ctx, ?QLOG_PACKET_RECEIVED) of false -> ok; true -> Event = #{ name => <<"quic:packet_received">>, data => encode_packet_info(Info) }, emit_event(Ctx, Event) end. %% @doc Log frames_processed event. -spec frames_processed(#qlog_ctx{} | undefined, [term()]) -> ok. frames_processed(undefined, _) -> ok; frames_processed(#qlog_ctx{enabled = false}, _) -> ok; frames_processed(Ctx, Frames) -> case event_enabled(Ctx, ?QLOG_FRAMES_PROCESSED) of false -> ok; true -> Event = #{ name => <<"quic:frames_processed">>, data => #{frames => encode_frames(Frames)} }, emit_event(Ctx, Event) end. %% @doc Log connection_started event. -spec connection_started(#qlog_ctx{} | undefined) -> ok. connection_started(undefined) -> ok; connection_started(#qlog_ctx{enabled = false}) -> ok; connection_started(#qlog_ctx{odcid = ODCID, vantage_point = VP} = Ctx) -> case event_enabled(Ctx, ?QLOG_CONNECTION_STARTED) of false -> ok; true -> Event = #{ name => <<"quic:connection_started">>, data => #{ odcid => hex_encode(ODCID), vantage_point => VP } }, emit_event(Ctx, Event) end. %% @doc Log connection_state_updated event. -spec connection_state_updated(#qlog_ctx{} | undefined, atom(), atom()) -> ok. connection_state_updated(undefined, _, _) -> ok; connection_state_updated(#qlog_ctx{enabled = false}, _, _) -> ok; connection_state_updated(Ctx, OldState, NewState) -> case event_enabled(Ctx, ?QLOG_CONNECTION_STATE_UPDATED) of false -> ok; true -> Event = #{ name => <<"quic:connection_state_updated">>, data => #{ old => OldState, new => NewState } }, emit_event(Ctx, Event) end. %% @doc Log connection_closed event. -spec connection_closed(#qlog_ctx{} | undefined, integer() | atom(), binary() | undefined) -> ok. connection_closed(undefined, _, _) -> ok; connection_closed(#qlog_ctx{enabled = false}, _, _) -> ok; connection_closed(Ctx, ErrorCode, Reason) -> case event_enabled(Ctx, ?QLOG_CONNECTION_CLOSED) of false -> ok; true -> Data = #{error_code => ErrorCode}, Data1 = case Reason of undefined -> Data; <<>> -> Data; _ -> Data#{reason => Reason} end, Event = #{ name => <<"quic:connection_closed">>, data => Data1 }, emit_event(Ctx, Event) end. %% @doc Log packets_acked event. -spec packets_acked(#qlog_ctx{} | undefined, [non_neg_integer()], map()) -> ok. packets_acked(undefined, _, _) -> ok; packets_acked(#qlog_ctx{enabled = false}, _, _) -> ok; packets_acked(Ctx, PacketNumbers, Info) -> case event_enabled(Ctx, ?QLOG_PACKETS_ACKED) of false -> ok; true -> Data = #{ packet_numbers => PacketNumbers }, Data1 = case maps:get(rtt_sample, Info, undefined) of undefined -> Data; RTT -> Data#{rtt_sample => RTT} end, Event = #{ name => <<"quic:packets_acked">>, data => Data1 }, emit_event(Ctx, Event) end. %% @doc Log packet_lost event. -spec packet_lost(#qlog_ctx{} | undefined, map()) -> ok. packet_lost(undefined, _) -> ok; packet_lost(#qlog_ctx{enabled = false}, _) -> ok; packet_lost(Ctx, Info) -> case event_enabled(Ctx, ?QLOG_PACKET_LOST) of false -> ok; true -> Event = #{ name => <<"quic:packet_lost">>, data => #{ packet_number => maps:get(packet_number, Info), reason => maps:get(reason, Info, unknown) } }, emit_event(Ctx, Event) end. %% @doc Log metrics_updated event. -spec metrics_updated(#qlog_ctx{} | undefined, map()) -> ok. metrics_updated(undefined, _) -> ok; metrics_updated(#qlog_ctx{enabled = false}, _) -> ok; metrics_updated(Ctx, Metrics) -> case event_enabled(Ctx, ?QLOG_METRICS_UPDATED) of false -> ok; true -> Event = #{ name => <<"quic:metrics_updated">>, data => Metrics }, emit_event(Ctx, Event) end. %%==================================================================== %% Internal Functions %%==================================================================== %% @private Get qlog options from connection opts or application env. get_qlog_opts(Opts) -> case maps:get(qlog, Opts, undefined) of undefined -> %% Check application environment application:get_env(quic, qlog, #{enabled => false}); QlogOpts when is_map(QlogOpts) -> QlogOpts end. %% @private Check if an event type should be logged. event_enabled(#qlog_ctx{events = all}, _Event) -> true; event_enabled(#qlog_ctx{events = Events}, Event) -> lists:member(Event, Events). %% @private Generate the qlog filename. generate_filename(Dir, ODCID, VantagePoint, Timestamp) -> ODCIDHex = hex_encode(ODCID), VP = atom_to_binary(VantagePoint), Filename = <>, filename:join(Dir, binary_to_list(Filename)). %% @private Encode the JSON-SEQ header. encode_header(ODCID, VantagePoint, RefTime) -> Header = #{ qlog_format => ?QLOG_FORMAT, qlog_version => ?QLOG_VERSION, title => <<"erlang_quic">>, trace => #{ vantage_point => #{type => VantagePoint}, common_fields => #{ protocol_type => [<<"QUIC">>], group_id => hex_encode(ODCID), reference_time => RefTime } } }, encode_json(Header). %% @private Emit an event to the writer process. emit_event(#qlog_ctx{writer = WriterPid, reference_time = RefTime}, Event) -> Now = erlang:system_time(millisecond), RelTime = Now - RefTime, EventWithTime = Event#{time => RelTime}, Json = encode_json(EventWithTime), WriterPid ! {event, Json}, ok. %% @private Encode a packet info map for qlog. encode_packet_info(Info) -> Base = #{}, Base1 = case maps:get(packet_type, Info, undefined) of undefined -> Base; Type -> Base#{packet_type => Type} end, Base2 = case maps:get(packet_number, Info, undefined) of undefined -> Base1; PN -> Base1#{packet_number => PN} end, Base3 = case maps:get(length, Info, undefined) of undefined -> Base2; Len -> Base2#{length => Len} end, case maps:get(frames, Info, undefined) of undefined -> Base3; Frames -> Base3#{frames => encode_frames(Frames)} end. %% @private Encode a list of frames for qlog. encode_frames(Frames) -> [encode_frame(F) || F <- Frames]. %% @private Encode a single frame for qlog. encode_frame(padding) -> #{frame_type => <<"padding">>}; encode_frame(ping) -> #{frame_type => <<"ping">>}; encode_frame({crypto, Offset, Data}) -> #{frame_type => <<"crypto">>, offset => Offset, length => byte_size(Data)}; encode_frame({ack, Ranges, AckDelay, _ECN}) -> #{frame_type => <<"ack">>, ack_ranges => encode_ack_ranges(Ranges), ack_delay => AckDelay}; encode_frame({stream, StreamId, Offset, Data, Fin}) -> #{ frame_type => <<"stream">>, stream_id => StreamId, offset => Offset, length => iolist_size(Data), fin => Fin }; encode_frame({max_data, MaxData}) -> #{frame_type => <<"max_data">>, maximum => MaxData}; encode_frame({max_stream_data, StreamId, MaxData}) -> #{frame_type => <<"max_stream_data">>, stream_id => StreamId, maximum => MaxData}; encode_frame({max_streams, bidi, Max}) -> #{frame_type => <<"max_streams">>, stream_type => <<"bidirectional">>, maximum => Max}; encode_frame({max_streams, uni, Max}) -> #{frame_type => <<"max_streams">>, stream_type => <<"unidirectional">>, maximum => Max}; encode_frame({reset_stream, StreamId, ErrorCode, FinalSize}) -> #{ frame_type => <<"reset_stream">>, stream_id => StreamId, error_code => ErrorCode, final_size => FinalSize }; encode_frame({stop_sending, StreamId, ErrorCode}) -> #{frame_type => <<"stop_sending">>, stream_id => StreamId, error_code => ErrorCode}; encode_frame({connection_close, ErrorCode, FrameType, Reason}) -> #{ frame_type => <<"connection_close">>, error_code => ErrorCode, trigger_frame_type => FrameType, reason_phrase => Reason }; encode_frame({new_connection_id, SeqNum, RetirePrior, CID, _Token}) -> #{ frame_type => <<"new_connection_id">>, sequence_number => SeqNum, retire_prior_to => RetirePrior, connection_id => hex_encode(CID) }; encode_frame({retire_connection_id, SeqNum}) -> #{frame_type => <<"retire_connection_id">>, sequence_number => SeqNum}; encode_frame({path_challenge, Data}) -> #{frame_type => <<"path_challenge">>, data => hex_encode(Data)}; encode_frame({path_response, Data}) -> #{frame_type => <<"path_response">>, data => hex_encode(Data)}; encode_frame(handshake_done) -> #{frame_type => <<"handshake_done">>}; encode_frame({new_token, Token}) -> #{frame_type => <<"new_token">>, length => byte_size(Token)}; encode_frame({datagram, Data}) -> #{frame_type => <<"datagram">>, length => iolist_size(Data)}; encode_frame(Frame) when is_tuple(Frame) -> #{frame_type => <<"unknown">>, raw => element(1, Frame)}; encode_frame(_) -> #{frame_type => <<"unknown">>}. %% @private Encode ACK ranges for qlog. encode_ack_ranges(Ranges) -> [[Start, End] || {Start, End} <- Ranges]. %% @private Hex encode a binary. hex_encode(Bin) when is_binary(Bin) -> <<<<(hex_digit(N div 16)), (hex_digit(N rem 16))>> || <> <= Bin>>. hex_digit(N) when N < 10 -> $0 + N; hex_digit(N) -> $a + N - 10. %% @private Simple JSON encoder (no external dependencies). encode_json(Map) when is_map(Map) -> Pairs = maps:to_list(Map), ["{", lists:join(",", [encode_json_pair(K, V) || {K, V} <- Pairs]), "}"]; encode_json(List) when is_list(List) -> ["[", lists:join(",", [encode_json(E) || E <- List]), "]"]; encode_json(Bin) when is_binary(Bin) -> ["\"", escape_json_string(Bin), "\""]; encode_json(Atom) when is_atom(Atom) -> ["\"", atom_to_binary(Atom), "\""]; encode_json(Int) when is_integer(Int) -> integer_to_binary(Int); encode_json(Float) when is_float(Float) -> float_to_binary(Float, [{decimals, 3}, compact]); encode_json(true) -> <<"true">>; encode_json(false) -> <<"false">>; encode_json(null) -> <<"null">>. encode_json_pair(Key, Value) -> [encode_json(Key), ":", encode_json(Value)]. %% @private Escape special JSON characters in a string. escape_json_string(Bin) -> escape_json_string(Bin, <<>>). escape_json_string(<<>>, Acc) -> Acc; escape_json_string(<<$", Rest/binary>>, Acc) -> escape_json_string(Rest, <>); escape_json_string(<<$\\, Rest/binary>>, Acc) -> escape_json_string(Rest, <>); escape_json_string(<<$\n, Rest/binary>>, Acc) -> escape_json_string(Rest, <>); escape_json_string(<<$\r, Rest/binary>>, Acc) -> escape_json_string(Rest, <>); escape_json_string(<<$\t, Rest/binary>>, Acc) -> escape_json_string(Rest, <>); escape_json_string(<>, Acc) when C < 32 -> %% Control characters as \uXXXX Hex = io_lib:format("\\u~4.16.0B", [C]), escape_json_string(Rest, <>); escape_json_string(<>, Acc) -> escape_json_string(Rest, <>). %%==================================================================== %% Writer Process %%==================================================================== %% @doc Start the async writer process. -spec start_writer(file:filename(), iodata()) -> {ok, pid()}. start_writer(Filename, Header) -> Parent = self(), Pid = spawn_link(fun() -> case file:open(Filename, [write, raw, delayed_write]) of {ok, Fd} -> %% Write header as first line ok = file:write(Fd, [Header, "\n"]), Parent ! {writer_ready, self()}, writer_loop(#writer_state{fd = Fd}); {error, Reason} -> Parent ! {writer_error, self(), Reason}, exit(Reason) end end), receive {writer_ready, Pid} -> {ok, Pid}; {writer_error, Pid, Reason} -> {error, Reason} after 5000 -> exit(Pid, kill), {error, timeout} end. %% @doc Writer process main loop. writer_loop(#writer_state{fd = Fd, buffer = Buffer, buffer_size = Size} = State) -> receive {event, Json} -> NewBuffer = [Buffer, Json, "\n"], NewSize = Size + iolist_size(Json) + 1, NewState = State#writer_state{buffer = NewBuffer, buffer_size = NewSize}, %% Check if we should flush case NewSize >= ?QLOG_MAX_BUFFER_SIZE of true -> flush_buffer(NewState); false -> %% Start flush timer if not already running NewState2 = maybe_start_flush_timer(NewState), writer_loop(NewState2) end; flush -> flush_buffer(State); {close, From} -> %% Flush remaining data and close case Buffer of [] -> ok; _ -> file:write(Fd, Buffer) end, file:close(Fd), From ! {closed, self()}, ok after ?QLOG_FLUSH_INTERVAL_MS -> %% Periodic flush flush_buffer(State) end. %% @private Flush the buffer to disk. flush_buffer(#writer_state{buffer = [], flush_timer = TimerRef} = State) -> cancel_timer(TimerRef), writer_loop(State#writer_state{flush_timer = undefined}); flush_buffer(#writer_state{fd = Fd, buffer = Buffer, flush_timer = TimerRef} = State) -> cancel_timer(TimerRef), file:write(Fd, Buffer), writer_loop(State#writer_state{buffer = [], buffer_size = 0, flush_timer = undefined}). %% @private Start flush timer if not already running. maybe_start_flush_timer(#writer_state{flush_timer = undefined} = State) -> TimerRef = erlang:send_after(?QLOG_FLUSH_INTERVAL_MS, self(), flush), State#writer_state{flush_timer = TimerRef}; maybe_start_flush_timer(State) -> State. %% @private Cancel a timer if set. cancel_timer(undefined) -> ok; cancel_timer(Ref) -> erlang:cancel_timer(Ref).