quic-goを使った開発をするときのtips

go のQUICライブラリのquic-goを使った開発したときのtipsの備忘録です。

github.com

  1. Keylogファイルの書きだし方
  2. デバッグログの出力方法

についてメモしておきます。

Keylogファイルの書きだし方

↓で説明があるように、wiresharkでQUICの復号を行うためには、該当通信のKEYLOGファイルが必要になります。

asnokaze.hatenablog.com

quic-goでKeylogファイルを書きだすためには、quic.DialAddr を呼び出すときに、tls.Config に、KeylogWriterを持たせることで実現できます。

TLS ConfigにKeylogWriterを持たせる例は、goのdocumentから確認することができます

golang.org

例えば、以下のように実装すると、

   w, err := os.Create("./keylog.log")
    tlsConf := &tls.Config{
        InsecureSkipVerify: true,
        NextProtos:         []string{"hogehoge"},
        KeyLogWriter:       w,
    }

    config := &quic.Config{
        KeepAlive: true,
    }

    session, err := quic.DialAddr(addr, tlsConf, config)

keylog.logというファイルが生成されます。

中身は↓のようなフォーマットになっています。

CLIENT_HANDSHAKE_TRAFFIC_SECRET ... ...
SERVER_HANDSHAKE_TRAFFIC_SECRET ... ...
CLIENT_TRAFFIC_SECRET_0 ... ...
SERVER_TRAFFIC_SECRET_0 ... ...

logの出し方

github.com

環境変数 QUIC_GO_LOG_LEVEL=loglevel を設定して、プログラムを実行するとログの出力ができます。

例えば、QUIC_GO_LOG_LEVEL=debug と設定すると、QUICパケットの送信時に、QUICパケットとその内部に含まれるフレームのログが見たり

18:13:25.216025 client -> Sending packet 0x5 (26 bytes) for connection 0x39abd2c4bae665f6062f, 1-RTT
18:13:25.216028 client  Short Header{DestConnectionID: 0x0d76cf58, PacketNumber: 0x5, PacketNumberLen: 2, KeyPhase: 0}
18:13:25.216031 client  -> &wire.StreamFrame{StreamID: 6, FinBit: true, Offset: 0x15, Data length: 0x0, Offset + Data length: 0x15}

受信したQUICパケットを見たるすることが出来ます。

18:13:25.241739 client  Short Header{DestConnectionID: (empty), PacketNumber: 0x5, PacketNumberLen: 2, KeyPhase: 0}
18:13:25.241742 client  <- &wire.AckFrame{LargestAcked: 0x5, LowestAcked: 0x2, DelayTime: 25.504ms}

これ以外にも、接続シーケンスや切断したときの情報などを確認することが出来ます。

コードを動かして規格の中身を確認したいときに便利かもしれないです。

「LiteSpeed Beats Nginx in HTTP/3 Benchmarks」の紹介

blog.litespeedtech.com

OpenLiteSpeedとnginx の実装を比較している記事

163バイトのindex file、そこからリンクを張られている1MB、10MB、1GB のファイルのダウンロードを比較している。

index fileに対しては、同時に複数アクセスして毎秒どれくらいのリクエストをさばけるのかを確認しています。

1MB、10MB、1GBのファイルに対しては、ダウンロード時間を比較しています。

すべての結果でOpenLiteSpeedのほうが良い結果が出ていました。nginxはCPU使用率やメモリ使用量が多いらしいです。

主張したいのは

nginx’s HTTP/3 is not ready for production use. It delivers poor performance and, at the same time, uses too much CPU and memory.

のようです。

以下のツイッターのスレッドで議論が続いているようです。

「BBR Control in QUIC and HTTP/3」を読みました

blog.litespeedtech.com

LiteSpeedのLiteSpeed Web Server 5.4.2、Web ADC 2.6.0、OpenLiteSpeed 1.6.1でQUICの接続にBBRを使うようになったらしいです。

BBRは、Googleが開発した、Bottleneck Bandwidth and RTTという新しい輻輳制御のアルゴリズムです。BBRの解説は、こちら で読むことができます。ちなみに、BBRv2 もgoogleによって開発が進んでいるようです。

LiteSpeedの記事は、BBRの特徴、欠点、特徴を確認するためのテストを行った結果などが書かれている記事です。

特徴は、輻輳に起因しないロスに反応しにくいことと、レイテンシーが小さいことの2つです。

欠点は、shallow bufferの時に性能が低い点と、他のフローに対して公平ではない点が挙げられていました。

記事ではcubicとBBRを比較しBBRの特徴を確認するために2つのテストを行っています。一つ目は、パケットロスの値を変化させた時の、10MByteのファイルのダウンロードスピードの変化を見ます。二つ目は、大きいファイルと小さいファイルを同時にダウンロードさせたときのBBRとcubicの振る舞いの違いを見ています。前者の実験ではパケットロス率を0, 0.5, 1, 2, 3 と上げていくごとにファイルのダウンロード時間が長くなっていくことが分かります。後者の実験では、BBRを使用したときはネットワーク上のバッファをちょうどよい使い方をするので小さいファイルのダウンロード時間がRTTとほぼ同じ時間で終わっていることを示しています。

特徴

Resistance to Loss

BBRの主なアイディアは、パケットロスが発生していることが、輻輳が起きていることを意味しないかもしれないと考えることです。例えば、パケットは、一時的な電波の干渉によって発生することも考えられます。 cubicや他の輻輳制御のアルゴリズムは、輻輳が原因ではないパケットロスと実際の輻輳を区別せずに、両方の場合に送信レートを下げます。

BBRは簡単にはその影響を受けません。結果、BBRはネットワークの状態が準最適の場合でもスループットを保つことができます。

Minimal Latency

BufferbloatがUXにとって良くないと何年も言われています。インフラでもbufferbloatを避けるために大量のデータをバッファリングすることを避けるように変更が進められていました。

それにもかかわらず、cubicは、ネットワークのパス上に存在するbottleneck bufferを埋めようとしてしまい、その結果接続のレイテンシーが増加してしまいます。

An in-depth study of LTE: effect of network protocol and application behavior on performanceでは、パケットロスをマスクするために、バッファーが広範囲に使用され、それによりRTTが増大することが明らかになりました。

BBRは、bottleneck bandwidthを追跡し、定期的に最小のRTTをテストします。これらの評価は送信者によって、bottleneck bufferを埋め尽くさないようにするために使われています。BBRを使うことで、ウェブアプリケーションはより、responsiveになる可能性が高いです。

Drawback

パス上にshallow-bufferがあるときや、他のフローに対して、使用できる帯域の多くを要求するため公平ではないという問題があります。これらの問題はBBRv2で、将来対処されるようです。

テスト結果

Throughput Under Loss

LiteSpeedのLiteSpeed Web Server 5.4.2 でのテスト結果です。まずは10Mbyteのファイルをダウンロードしたときの結果です。下の表から、cubicはパケットロスに激しく反応しているが、BBRはそうではないことが分かります。

Rate (MBit/sec) Delay (ms) Loss (%) Cubic (sec) BBR (sec)
20 25 0 4.5 4.5
20 25 0.5 6.7 4.6
20 25 1 8.6 4.6
20 25 2 14.3 4.7
20 25 3 17.6 4.7

Latency

HTMLページと、そのHTMLページからリンクをしている大きいファイル、小さいファイル、これら3つ含むシンプルなウェブサイトで、帯域を20Mbit/sec、遅延を25ms に設定した状態でダウンロードのレイテンシーを計測しています。

ユーザーが大きいファイルへのリンクをクリックするとダウンロードが始まります。ユーザーはそれから小さいファイルへのリンクをクリックします。

cubicを使った場合、小さいファイルのダウンロードに1~2秒かかります、これは、cubicが中間のbufferをいっぱいにしようとするからです。

f:id:neko--suki:20191124233204p:plain
cubic を使用した場合。https://blog.litespeedtech.com/2019/10/28/bbr-congestion-control-quic-http-3/からの引用

一方で、BBRは、bottleneck bufferをちょうどよい状態に保とうとします。なので、小さいファイルは、RTTのオーダーでダウンロードが完了します。

f:id:neko--suki:20191124233344p:plain
BBRを使用した場合。https://blog.litespeedtech.com/2019/10/28/bbr-congestion-control-quic-http-3/ からの引用

理解に役立ちそうなリンク

Perceiving QUIC: Do Users Notice or Even Care?

arxiv.org

QUICとTCPをQoEの観点で比較した論文。2つを使ってウェブページをロードしたときに速いほうを知覚できるかと、単体で見た時速いかどうかを知覚できるかを調べたらしい。

2つ並べているときは速いほうを知覚できる。 単体の時で、特にネットワークの帯域に余裕があるときは知覚はできないらしい。

ちゃんと読んだらちゃんと書くかも。

下のページで実際に体験できるらしい。 https://study.netray.io

Mahimahiのmm-onoff でネットワークの接続・切断を繰り返す状態のエミュレーション

紹介

Mahimahiとはネットワークエミュレーターです。遅延、帯域設定、ロス設定などができます。特徴として、「より正確に、マルチサーバーの環境を再現できる」、「ネットワークトラフィックを独立した環境に閉じ込めることができるので、複数の異なるインスタンスを同時に走らせることができる」、「composable (構成可能)なシェル、使いやすく拡張性もある」といった特徴を持っています。

mahimahi.mit.edu

mm-onoff はMahimahiに含まれる、ネットワークが接続・切断を繰り返すような状態をエミュレーションするためのコマンドです。

mm-onoff コマンドの使い方は、manで確認すると以下のようになっています。

mm-onoff uplink|downlink mean-on-time mean-off-time [command...]

The uplink or downlink will be intermittent and will switch between connected and disconnected states according to a Poisson point process with specified average durations spent "on" and "off".

uplinkまたはdownlinkに対して、ポアソン分布に従ったon(接続されている状態)とoff(切断されている状態)の平均時間を指定できます。

使い方

さっそく使ってみます。以下のようにコマンドを打ちます。

$ mm-onoff uplink 10 5
[onoff (up) on=10s off=5s] $ 

Mahimahiの特徴として、シェルを起動する形になるため、コマンドを実行すると、[onoff (up) on=10s off=5s] というのが表示されます。これは、onの状態が平均10秒続いて、offの状態が平均5秒続くということを表しています。

この状態から、pingを1秒間隔で30秒間投げてみます。

[onoff (up) on=10s off=5s] $ ping 8.8.8.8 -i 1 -c 30
PING 8.8.8.8 (8.8.8.8) 56(84) bytes of data.
64 bytes from 8.8.8.8: icmp_seq=8 ttl=53 time=7.33 ms             
64 bytes from 8.8.8.8: icmp_seq=9 ttl=53 time=10.5 ms
64 bytes from 8.8.8.8: icmp_seq=10 ttl=53 time=7.83 ms
64 bytes from 8.8.8.8: icmp_seq=11 ttl=53 time=6.83 ms
64 bytes from 8.8.8.8: icmp_seq=12 ttl=53 time=17.9 ms
64 bytes from 8.8.8.8: icmp_seq=13 ttl=53 time=7.17 ms
64 bytes from 8.8.8.8: icmp_seq=14 ttl=53 time=8.14 ms
64 bytes from 8.8.8.8: icmp_seq=15 ttl=53 time=6.92 ms
64 bytes from 8.8.8.8: icmp_seq=16 ttl=53 time=6.73 ms
64 bytes from 8.8.8.8: icmp_seq=17 ttl=53 time=6.69 ms
64 bytes from 8.8.8.8: icmp_seq=18 ttl=53 time=7.85 ms
64 bytes from 8.8.8.8: icmp_seq=19 ttl=53 time=6.60 ms
64 bytes from 8.8.8.8: icmp_seq=20 ttl=53 time=5.96 ms
64 bytes from 8.8.8.8: icmp_seq=21 ttl=53 time=7.27 ms
64 bytes from 8.8.8.8: icmp_seq=22 ttl=53 time=7.19 ms
64 bytes from 8.8.8.8: icmp_seq=23 ttl=53 time=6.20 ms
64 bytes from 8.8.8.8: icmp_seq=24 ttl=53 time=6.33 ms
64 bytes from 8.8.8.8: icmp_seq=25 ttl=53 time=7.16 ms
64 bytes from 8.8.8.8: icmp_seq=26 ttl=53 time=7.10 ms

--- 8.8.8.8 ping statistics ---
30 packets transmitted, 19 received, 36% packet loss, time 29352ms
rtt min/avg/max/mdev = 5.963/7.782/17.923/2.577 ms

pingの結果から、0~7、24~30のパケットがロスしていることが分かります。このタイミングで切断状態になっていたことが分かります。

同様に、wiresharkを使ってpingを実行している状態をキャプチャしてみます。

mm-onoffを起動しているシェル内からwiresharkを立ち上げる場合は、ingressというインターフェースを選択します。

f:id:neko--suki:20191121225337p:plain

別のシェルからwiresharkを立ち上げる場合は、onoff-xxxx というインターフェースを選択します。mahimahiではコマンドを起動するとコマンドに応じたネットワークインターフェースが作られるようです。mm-onoffの場合は、onoff-xxxx という名前のインターフェースが生成されます。

f:id:neko--suki:20191121230832p:plain

まずは、内部で立ち上げたwiresharkの結果です。開始12秒から16秒の場所で、Echo requestへのresponseがないと表示されています。

f:id:neko--suki:20191121231102p:plain

外部で立ち上げたwiresharkだと、12秒から16秒のところはecho requestも存在していません。

f:id:neko--suki:20191121231140p:plain

ちなみに、$ mm-onoff uplink 10 5 ping -c 30 8.8.8.8 のようにコマンドを実行することもできます。

以上紹介したようにmm-onoff を使うと、ネットワークが接続・切断状態を繰り返す状態をエミュレーションできました。on/offの時間はランダムなので完全に再現できるわけではないのが少し使いにくいかもしれません。

JAPAN Mobile Network Experience Report October 2019 を読みました

モバイルネットワークの評価についてのレポート情報があったので読んでみました。

www.opensignal.com

日本国内で、DocomoSoftBankauの3キャリアに対して、合計358,228デバイス、856,239,500計測、これを2019/6/1 ~ 2019/8/29 の間に行ったデータがまとめられています。

4G Availability、Video Experience、Voice App Experience、Download Speed Experience、Upload Speed Experience、Latency Experience、の7項目で評価しています

4G Availability

4G Availabilityは、ユーザーが4Gのネットワークに接続している時間の割合のようです(おそらく3Gと比較した割合です)。結果は、Docomo96.2%、SoftBank 94.6%、au 96.8%となっています。auが一番高い値ですがほぼ同じ値で、どのキャリアでもほぼ4Gが使えるようです。

Video Experience

ITUで定義した、ロード時間、ビデオストリーミングが停止する時間、ビデオの解像度などの定量化するための因子を使用して評価しているようです。それをもとに、0から100でスコアを付けています。

結果は、Docomoが63.4、SoftBankが71.1、auが67.2 となっています。SoftBankが一番高くなっていますが、全体的に改善の余地があると報告されています。

Voice App Experience

WhatsApp, Skype, Facebook MessengerのようなOTTのボイスサービスのexperienceの品質を評価しています。評価モデルは、ITUで定義されているものをもとにして、すべての通話品質と一連のキャリブレーションされてた技術パラメータ(具体的に何を指しているかはわかりませんでした)を使用しています。こちらも、0から100でスコアを付けています

結果は、Docomo 81.3、SoftBank 81.6、au 81.4 となっています。ちなみに、80~87の評価の定義が「80-87 Good - Many users satisfied」となっています。

英文の意味を正確につかめなかったのですが、評価は高そうです。Video Experienceと同様に、音声のコミュニケーションはスピードテストではなく直接アプリを使って計ったほうがよい特徴があるようです。

Download Speed Experience

Peak Download Speedを評価しているようです。理論値ではなく、98パーセンタイルの値を使っているようです。

結果は、Docomo 27.4Mbps、SoftBank 32.2Mbps、au 33.6Mbps でした。Softbankとの差は1.4 Mbpsととても小さいです。ただし、Download Speedではauが上回っていますが、Video ExperienceではSoftBankが上回っているので、Download Speed ExperienceをVideo Experienceに落とし込めていない可能性があります。

Upload Speed Experience

Upload ExperienceもDownloadと同様に、Peak upload Speedを評価しているようです。こちらも98%の値を使用しています。

結果は、Docomo 8.1Mbps、SoftBank 8.9Mbps、au 6.6Mbps でした。4G AvailabilityやDownload Speed Experienceでは一番だったauがここでは一番低い結果になっています。

Latency Experience

RTTで測っているようです。

結果は、Docomo 49.3ms、SoftBank 37.4ms、au 44.4msでした。

その他の情報

メトリクスの詳細は以下に記述されています。

www.opensignal.com

OpenSignalsイギリスの会社らしいです。88か国で調査を行っているらしく、おそらく他の国のレポートもあるのだと思います。

en.wikipedia.org

opensignals 国名 mobile network report で検索すると、他の国の情報も出てきそうです。例えば、アメリカの7月のレポートは https://www.opensignal.com/reports/2019/07/usa/mobile-network-experience で見ることができました。

Goでpanic(string) すると recover()で取り出せるのがstringになる

panic()が返すのは空interfaceなので、panic(string)したらrecover()で取り出せるのはstringになる。

ググってみても、panic(string)してる例は結構たくさんあった。

package main

import (
    "fmt"
    "reflect"
)

func main() {
    f()
}

func f() {
    defer func() {
        if err := recover(); err != nil {
            fmt.Println("type of err ", reflect.TypeOf(err))
            a, b := err.(error)
            fmt.Println(a) // nil
            fmt.Println(b) // false
        }
    }()

    panic("aaa")
    //    panic(errors.New("aaa"))
}

実行結果 play.golang.org