qlogのプロトコルに依存しないメインスキーマの紹介

本記事ではIETFで標準化が行われている、QUICなどのロギングを行うフォーマットであるqlogの、プロトコルに依存しないメインスキーマについて紹介します。

ドラフトの構成について

現在qlogでは3つのドラフトが提案されています。

一つ目が、プロトコルに依存しないハイレベルのスキーマを定義する、「Main logging schema for qlog draft-ietf-quic-qlog-main-schema-00」です。本記事で紹介する内容はこれになります。

QUICに関連する定義は「QUIC event definitions for qlog draft-ietf-quic-qlog-quic-events-00」、HTTP/3とQPACKに関連する定義は「HTTP/3 and QPACK event definitions for qlog draft-ietf-quic-qlog-h3-events-00」にそれぞれかかてれいます。

フォーマット設計のゴール

qlogの設計の方針として、以下のようなものが挙げられています。

• ストリーム可能なイベントベースのロギング
• 柔軟なフォーマット、ツールで複雑なことを可能とする(意訳です)
• 拡張性と実用があること
• 集約と変換がやりやすい
• メタデータとイベントデータを一緒に保存する

qlogの例

実際のログの例です。この例は、qlogの可視化を行うツールであるqvisのサイトにあるサンプルから取得しました。

{
  "qlog_version": "draft-02",
  "qlog_format": "JSON",
  "title": "",
  "description": "",
  "summary": {},
  "traces": [
    {
      "vantage_point": {
        "name": "TODO",
        "type": "network",
        "flow": "client"
      },
      "title": "Connection 1",
      "description": "",
      "configuration": {
        "time_offset": "0",
        "time_units": "ms",
        "original_uris": [
          "file:///srv/pcap2qlog/examples/draft-01/new_cid.json"
        ]
      },
      "common_fields": {
        "group_id": "7e37e4dcc6682da8",
        "protocol_type": "QUIC",
        "reference_time": "1564658098.991056",
        "time_format": "relative"
      },
      "events": [
        {
          "time": "0",
          "name": "connectivity:connection_started",
          "data": {
            "ip_version": "4",
            "src_ip": "130.104.228.79",
            "dst_ip": "52.58.13.57",
            "transport_protocol": "UDP",
            "src_port": "40618",
            "dst_port": "4433",
            "quic_version": "0xff000016",
            "src_cid": "7e37e4dcc6682da8",
            "dst_cid": "36ce104eee50101c",
            "trigger": "line"
          }
        },
        {
          "time": "0",
          "name": "transport:packet_sent",
          "data": {
            "header": {
              "version": "0xff000016",
              "scid": "7e37e4dcc6682da8",
              "dcid": "36ce104eee50101c",
              "scil": "8",
              "dcil": "8",
              "packet_number": "0",
              "packet_type": "initial"
            },
            "frames": [
              {
                "frame_type": "crypto",
                "offset": "0",
                "length": "284",
                "frame_size": 604,
                "header_size": 320,
                "payload_size": 284
              },
              {
                "frame_type": "padding",
                "frame_size": 604,
                "header_size": 604,
                "payload_size": 0
              }
            ],
            "raw": {
              "length": 1251,
              "payload_length": 1224
            },
            "trigger": "line"
          }
        },
      ...
      ]
    }
  ]
}

qlog_version、qlog_format、title、description、summaryのフィールドにはqlogファイル全体に関わるメタデータ情報が入ります。

tracesにはtraceというトレースしたログが入ります。

events が、時系列にログ情報が入ります。

フォーマットの定義

トップレベルのフォーマット

一つのqlogファイルは、複数の独立したトレースや、複数のvantage point (クライアントやサーバーなどの観測点)を含むことが可能です。

トップレベルの定義は以下のようになっています。

   class QlogFile {
       qlog_version:string,
       qlog_format?:string,
       title?:string,
       description?:string,
       summary?: Summary,
       traces: array<Trace|TraceError>
   }

参考までに、? が末尾についているものはオプションなので省略可能なようです。

JSONでシリアライズされた例は以下のようになっています。

   {
       "qlog_version": "draft-03-WIP",
       "qlog_format": "JSON",
       "title": "Name of this particular qlog file (short)",
       "description": "Description for this group of traces (long)",
       "summary": {
           ...
       },
       "traces": [...]
   }

トップレベルでは、qlog_version、qlog_format、title、description、summaryといったメタデータと、traces という実際のログを含む配列が定義されています。

qlog_version はqlogのバージョンを定義します。現時点でのドラフトではqlog-03-WIPというバージョンを定義しています。

qlog_formatは、JSONなどのフォーマットをシリアライズした方法を記述しています。

title、descriptionについては特に説明はありませんでした。おそらく名前通りの使い方が想定できると思います。

summaryは、ログの長さ、パケットロス率、その他いろいろな情報をもとに、ソートやフィルタリングをするために仕えるようです。ただし、デプロイの仕方に依存するので、ドラフトでは書き方については定義されていません。

summary の以下のような例がドラフトに書かれていました。

   class Summary {
       "trace_count":uint32, // amount of traces in this file
       "max_duration":uint64, // time duration of the longest trace in ms
       "max_outgoing_loss_rate":float, // highest loss rate for outgoing packets over all traces
       "total_event_count":uint64, // total number of events across all traces,
       "error_count":uint64 // total number of error events in this trace
   }

JSONでシリアライズされた例は以下のようになります。

   {
       "trace_count": 1,
       "max_duration": 5006,
       "max_outgoing_loss_rate": 0.013,
       "total_event_count": 568,
       "error_count": 2
   }

traces

tracesは関連したログを一つのファイルに格納するために使います。例えばクライアントとサーバーで収集したログを一つのqlogファイルに入れたい場合があります。

tracesは複数のログを入れるために、配列として定義されています。

また、tracesには、traceだけではなく、errorというエントリーも格納できます。これは複数のqlogファイルを集約したときにエラーが起きたことを明示的に記録するために使いうことができます。エラーが起きた結果その部分のデータがなくなっていることに気がつかないという事態を避けるための設計のようです。

TraceErrroは以下のように定義されています。

   class TraceError {
       error_description: string, // A description of the error
       uri?: string, // the original URI at which we attempted to find the file
       vantage_point?: VantagePoint // see {{vantage_point}}: the vantage point we were expecting to include here
   }

JSONでシリアライズした例は以下のようになります。

   {
       "error_description": "File could not be found",
       "uri": "/srv/traces/today/latest.qlog",
       "vantage_point": { type: "server" }
   }

trace

trace は単一の接続でのすべてのイベントを表します。通常のユースケースでは、一つの場所で集められたログを指します。例えば、QUICの場合はクライアントまたはサーバーの論理的な一つの接続のログを含みます。

定義は以下のようになっています。

   class Trace {
       title?: string,
       description?: string,
       configuration?: Configuration,
       common_fields?: CommonFields,
       vantage_point: VantagePoint,
       events: array<Event>
   }

JSONでシリアライズされた例は以下のようになります。

   {
       "title": "Name of this particular trace (short)",
       "description": "Description for this trace (long)",
       "configuration": {
           "time_offset": 150
       },
       "common_fields": {
           "ODCID": "abcde1234",
           "time_format": "absolute"
       },
       "vantage_point": {
           "name": "backend-67",
           "type": "server"
       },
       "events": [...]
   }

configuration

qlogは単体ではなく様々なツールから使用されることが想定されます。configurationは、ツールベースの設定をqlog内部に保存したいときに、使うことができます。

ドキュメントではツールに依存しない、time_offsetとoriginal_uris の2つを定義しています。それ以外のフィールドは任意に設定可能です。

   class Configuration {
       time_offset:double, // in ms,
       original_uris: array<string>,

       // list of fields with any type
   }

JSONでシリアライズした例は以下のようになります。

   {
       "time_offset": 150, // starts 150ms after the first timestamp indicates
       "original_uris": [
           "https://example.org/trace1.qlog",
           "https://example.org/trace2.qlog"
       ]
   }

time_offsetはtraceの開始時間へのオフセットです。複数のシステムから集めたログは時刻が同期されていないことが想定されます。そのような場合に、それらのログの時刻を合わせるために適切なオフセット値を後から追加するために使うらしいです。

origin_urisは、複数のqlogファイルを結合する場合に使います

これら以外のフィールドは任意に設定可能です。qvisの場合以下のような情報を入れていると例示がありました。

{
    "configuration" : {
        "qvis" : {
            // when loaded into the qvis toolsuite's congestion graph tool
            // zoom in on the period between 1s and 2s and select the 124th event defined in this trace
            "congestion_graph": {
                "startX": 1000,
                "endX": 2000,
                "focusOnEventIndex": 124
            }

            // when loaded into the qvis toolsuite's sequence diagram tool
            // automatically scroll down the timeline to the 555th event defined in this trace
            "sequence_diagram" : {
                "focusOnEventIndex": 555
            }
        }
    }
}

vantage_point

vantage_pointは、サーバー、クライアントなどのログを観測した場所を示す情報を定義します。
それぞれのtraceは単一のvantage_pointのイベントを含みます。
単一のqlogファイルに複数のtraceを持つことで、複数のvantage_pointからのログを持つことが可能になります。

定義は以下のようになっています。

   class VantagePoint {
       name?: string,
       type: VantagePointType,
       flow?: VantagePointType
   }

   class VantagePointType {
       server, // endpoint which initiates the connection.
       client, // endpoint which accepts the connection.
       network, // observer in between client and server.
       unknown
   }

JSONでシリアライズされた例は以下のようになります。

   {
       "name": "aioquic client",
       "type": "client",
   }

   {
       "name": "wireshark trace",
       "type": "network",
       "flow": "client"
   }

flowフィールドは、typeがnetworkの時だけに使います。これによって、packet sent、packet received の区別が可能になります。例えば、IPによるフローの向きを保存したくない場合に仕えるそうです。

event

event には、エンドポイントで発生したイベントのリストを保存します。ここに何を含むべきかはプロトコルに依存します。なので、QUICや、HTTP/3などにどのようなイベントを定義するのかについては別のドラフトで定義しています。

このドラフトでは、事前に定義されたものだけが説明されています。

   class Event {
       time: double,
       name: string,
       data: any,

       protocol_type?: Array<string>,
       group_id?: string|uint32,

       time_format?: "absolute"|"delta"|"relative",

       // list of fields with any type
   }

JSONでシリアライズした例は以下のようになります。

   {
       time: 1553986553572,

       name: "transport:packet_sent",
       data: { ... }

       protocol_type:  ["QUIC","HTTP3"],
       group_id: "127ecc830d98f9d54a42c4f0842aa87e181a",

       time_format: "absolute",

       ODCID: "127ecc830d98f9d54a42c4f0842aa87e181a", // QUIC specific
   }

最小限必要なのは、time、name、data です。
それ以外に、time_format、protocol_type、trigger、group_idといったフィールドがあります。
後者の4つのようにすべてのイベントに共通するものは、common_fieldsへの格納が可能です。

time にはイベントが起きたタイムスタンプを保存します。ファイルサイズ削減のために、絶対時刻、前のイベントからの差分、基準時刻からの相対値の3つの形式がサポートされます。

time_formatには、これら3つのうちどの方式を使用しているかを記述します。

name には、イベントの識別と、どのようにdataを解析するかを識別する情報を記載します。

これらの情報は、category、typeという二つに分けて書くことも、nameに一つにまとめて書くことも可能です。

QUICやHTTP/3には、transport、http、qpack、recoveryといったcategoryが規定されているようです。
また、eventには、packet_sent、packet_receivedというものがあるようです。

JSONでシリアライズした例は以下のようになります。

   JSON serialization using separate fields:
   {
       category: "transport",
       type: "packet_sent"
   }
`
   JSON serialization using ":" concatenated field:
   {
       name: "transport:packet_sent"
   }

data には、イベント毎のメタデータを含みます。このセマンティクスはイベントごとに異なります。また中身の定義はプロトコルに依存します。

一例として、以下のようにdataの中身を定義することができます。

   class TransportPacketSentEvent {
       packet_size?:uint32,
       header:PacketHeader,
       frames?:Array<QuicFrame>
   }

これをJSONでシリアライズした例は以下のようになります。QUICを扱う人には見慣れた情報が書かれていると思います。

   {
       packet_size: 1280,
       header: {
           packet_type: "1RTT",
           packet_number: 123
       },
       frames: [
           {
               frame_type: "stream",
               length: 1000,
               offset: 456
           },
           {
               frame_type: "padding"
           }
       ]
   }

protocol_typeは、使用しているプロトコルを指定します。これによってウェブサーバーがHTTP/2とHTTP/3の両方をサポートしている場合に、単一のqlgoファイルに異なるプロトコルのデータを集めることが可能になります。

triggersは、イベントが起きた理由を記述するためにあります。

QUICの場合packet_droppedのイベントは以下のように定義されていました。

   class QuicPacketDroppedEvent {
       packet_type?:PacketType,
       raw_length?:uint32,

       trigger?: "key_unavailable" | "unknown_connection_id" | "decrypt_error" | "unsupported_version"
   }

group_idは、一つのqlogファイルに、複数の接続情報などを含みたいときに識別するために使われます。

group_idに用いる値はプロトコルとコンテキストに依存します。例えば、QUICのサーバーは接続IDを使用しますが、ミドルボックスなどは4 tupleを使うかもしれないです。

group_id を含むJSONでシリアライズされた例は以下のようになります。

   events: [
       {
           time: 1553986553579,
           protocol_type: ["TCP", "TLS", "HTTP2"],
           group_id: "ip1=2001:67c:1232:144:9498:6df6:f450:110b,ip2=2001:67c:2b0:1c1::198,port1=59105,port2=80",
           name: "transport:packet_received",
           data: { ... },
       },
       {
           time: 1553986553581,
           protocol_type: ["QUIC","HTTP3"],
           group_id: "127ecc830d98f9d54a42c4f0842aa87e181a",
           name: "transport:packet_sent",
           data: { ... },
       }
   ]

すべてのイベントに共通する情報はcommon_field にまとめて書くことができます。典型的には、time_format、reference_time、protocol_type、group_idなどが考えられます。

common_fieldを使わない場合の例は以下のようになります

   {
       events: [{
               group_id: "127ecc830d98f9d54a42c4f0842aa87e181a",
               protocol_type: ["QUIC","HTTP3"],
               time_format: "relative",
               reference_time: "1553986553572",

               time: 2,
               name: "transport:packet_received",
               data: { ... }
           },{
               group_id: "127ecc830d98f9d54a42c4f0842aa87e181a",
               protocol_type: ["QUIC","HTTP3"],
               time_format: "relative",
               reference_time: "1553986553572",

               time: 7,
               name: "http:frame_parsed",
               data: { ... }
           }
       ]
   }

common_fieldを使わう場合の例は以下のようになります

   {
       common_fields: {
           group_id: "127ecc830d98f9d54a42c4f0842aa87e181a",
           protocol_type: ["QUIC","HTTP3"],
           time_format: "relative",
           reference_time: "1553986553572"
       },
       events: [
           {
               time: 2,
               name: "transport:packet_received",
               data: { ... }
           },{
               7,
               name: "http:frame_parsed",
               data: { ... }
           }
       ]
   }

イベントの重要度について

イベントの設計によっては、複数のイベントが似たような情報やオーバーラップする情報をログすることがあります。
例えば、QUICのconnection_startedというイベントとconnection_state_updated というイベントが考えられます。そのような場合、どのイベントをログとして書き込むのか、使うべきかがいつも明確とは限らないです。

そういった場合に、イベントにCore、Base、Extra の3つの重要度を持たせることが推奨されています。

core は、あるプロトコルに対してすべてのqlogファイルに含まれているべきイベントです。典型的には、基本的なパケットやフレームの解析・生成などの処理や、基本となる内部情報が該当します。

QUIC event definitions for qlog draft-ietf-quic-qlog-quic-events-00 では、packet_sentなどが該当しているようです。

{
    header:PacketHeader,

    frames?:Array<QuicFrame>, // see appendix for the definitions

    is_coalesced?:boolean, // default value is false

    retry_token?:Token, // only if header.packet_type === retry

    stateless_reset_token?:bytes, // only if header.packet_type === stateless_reset. Is always 128 bits in length.

    supported_versions:Array<bytes>, // only if header.packet_type === version_negotiation

    raw?:RawInfo,
    datagram_id?:uint32
}

Base はデバッグに仕える追加の情報です。多くの場合はCoreから推測できますが、明示的に描かれていた方が実装がどうふるまっているかが分かりやすくなります。例として、バッファにデータを渡すタイミングや、内部の状態が変わる時などがあるようです。

QUIC event definitions for qlog draft-ietf-quic-qlog-quic-events-00 では、packet_droppedなどが挙げられています。

{
    header?:PacketHeader, // primarily packet_type should be filled here, as other fields might not be parseable

    raw?:RawInfo,
    datagram_id?:uint32
}

Extra はより低レベルの実装のデバッグに使用されることを想定しています。
QUIC event definitions for qlog draft-ietf-quic-qlog-quic-events-00 では、frame_processedなどが挙げられています。

   Data:

   {
       frames:Array<QuicFrame>, // see appendix for the definitions

       packet_number?:uint64
   }

Generic events and data classes

ドラフトでは、eventの中で共通で使われるものを定義しています。

例えば、バイトレングスやバイト値などの低レベルのwire imageの情報については以下のように定義されています。

class RawInfo {
    length?:uint64; // the full byte length of the entity (e.g., packet or frame) including headers and trailers
    payload_length?:uint64; // the byte length of the entity's payload, without headers or trailers

    data?:bytes; // the contents of the full entity, including headers and trailers
}

他には、error、warning、info、debug、verboseなどのよく知られているログと互換性のあるものも定義されています。

これらは、categoryがgenericで、typeが、errorなどの文字列で表されます。nameを使う場合は、generic:errorとなります。

error、warningの定義

   {
       code?:uint32,
       message?:string
   }

info、debug、verboseの定義

   {
       message:string
   }

これら以外に、プロトコルの評価なので、連続した接続性のテストやベンチマークのテストを行うことがあると思います。
そのような場合、実行中に状況が変わります。
例えば、連続したテストの実行や、帯域や遅延が変わったりネットワークが切断されたりするようなテストを行うことがあると思います。そのような場合に、正確にどこでそれらが起きたのかをイベントとして記述することが可能です。

これらは、categoryがsimulation、typeが、scenario で表されます。

テストシナリオの記述は、トップレベルのsummaryやconfigurationに書くことも可能です。しかし、もし複数のシナリオの実行結果を1つのtraceに入れたい場合は、event この情報を書くことでどこからそのテストが始まったが分かるのだと思います。

   {
       name?:string,
       details?:any
   }

maker というのは、具体的なエミュレーションの条件を記述するのに使います。例えば、「3秒の地点で2%のロスが発生する」や「10秒の地点でNATの再割り当てが発生する」といった情報が記述できます。

   {
       type?:string,
       message?:string
   }

シリアライズのフォーマットについて

qlogではフォーマットについては規定していないので、好きなフォーマットについて選ぶことが可能です。

開発時のデバッグにはJSONが読みやすくて適しているかもしれませんが、プロダクションでの利用になるとサイズの効率という観点でバイナリフォーマットの方が適しているかもしれません。

ドラフトでは、JSONへのマッピングや圧縮、バイナリフォーマットについての言及などがあるので興味がある場合は、「6. Serializing qlog」 を読んでみるとよいと思います。

まとめ

qlogの共通部分である Main logging schema for qlog について紹介しました。拡張性の高い提案になっているため、将来的には、QUICやHTTP/3以外での活用もあり得るのかもしれないです。

次回は、具体的なQUICに依存する部分のログを扱う「QUIC event definitions for qlog
draft-ietf-quic-qlog-quic-events-00」を紹介しようと思います。