2020-03-26

カーネルの観点から見たLinuxKit

はじめに

Docker社はDockerCon2017において、Dockerコンテナの実行にフォーカスした軽量Linuxである、LinuxKitをリリースしました。

以下関連URLです。

本記事はLinuxKitについて網羅的な説明をすることではなくて、LinuxKitに同梱されているカーネルがどのようなものかをざっと眺めることです。なぜカーネルだけなのかというと、単に私がカーネル屋さんなのでカーネルに興味があっただけです。

本記事のLinuxKitの対象バージョンは、本記事執筆時点(2017年4月19日)で最新のcommit:f2d6752751318477ec86e4677514d5a4890249c1です。

カーネルは独自実装かどうか

LinuxKitに同梱されているカーネルは、独自実装したようなものではなく、みなさんがお使いのlinux kernelと同じものにいくつかのパッチを当てたものです。カーネルバージョンは自分で選択もできるようですが、本書執筆現在で最新のv4.10 stable kernelもサポートしているようです。

カーネルに組み込まれている、モジュール化されている機能の数

通常のlinux distributionはなるべく多くの機能、デバイスをサポートするために、多くの機能を組み込んでいる、あるいはモジュール化していますが、LinuxKitに同梱されているカーネルはかなり思い切った作りになっており、ほとんどの機能を無効化しています。Ubuntu 16.04のカーネルの設定ファイルと、LinuxKitのデフォルトの設定ファイルのそれを比較してみます。

	Ubuntu 16.04のカーネル	LinuxKitのカーネル
有効化	2177	1540
モジュール化	4592	1

UbuntuのカーネルよりもLinuxKitのそれのほうがはるかに軽量であることがわかります。モジュールに至っては1つしかありません。これがLinuxKitの軽量化、起動の高速化に一役買っていると考えられます。

どのような設定が組み込まれている、あるいはモジュール化されているのか。

CPU関連

CONFIG_NR_CPUS=128
...
# CONFIG_SCHED_SMT is not set
CONFIG_SCHED_MC=y

最多で128のコアまでサポートしているようです。この数が多ければ多いほど、CPUごとに存在するデータの数が増えますので、無暗に多くのCPUをサポートしない方針だと考えられます。Ubuntuの場合は512です。

マルチコアはサポートしているものの、ハイパースレッドはサポートしていないようです。

ファイルシステム関連

#
# File systems
#
CONFIG_DCACHE_WORD_ACCESS=y
# CONFIG_EXT2_FS is not set
# CONFIG_EXT3_FS is not set
CONFIG_EXT4_FS=y
CONFIG_EXT4_USE_FOR_EXT2=y
CONFIG_EXT4_FS_POSIX_ACL=y
CONFIG_EXT4_FS_SECURITY=y
# CONFIG_EXT4_ENCRYPTION is not set
# CONFIG_EXT4_DEBUG is not set
CONFIG_JBD2=y
# CONFIG_JBD2_DEBUG is not set
CONFIG_FS_MBCACHE=y
# CONFIG_REISERFS_FS is not set
# CONFIG_JFS_FS is not set
# CONFIG_XFS_FS is not set
# CONFIG_GFS2_FS is not set
# CONFIG_BTRFS_FS is not set
# CONFIG_NILFS2_FS is not set
# CONFIG_F2FS_FS is not set
# CONFIG_FS_DAX is not set
CONFIG_FS_POSIX_ACL=y
CONFIG_EXPORTFS=y
...
# CONFIG_QUOTA is not set
# CONFIG_QUOTACTL is not set
# CONFIG_AUTOFS4_FS is not set
CONFIG_FUSE_FS=y
CONFIG_CUSE=y
CONFIG_OVERLAY_FS=y
...

ローカルファイルシステムはext4だけが有効化されています。XFSやBtrfsなどの、その他よく使われるファイルシステムは使わないようです。

Dockerのストレージドライバとしてよく使われるoverlayfsは有効化されています。

セキュリティ

#
# Security options
#
CONFIG_KEYS=y
CONFIG_PERSISTENT_KEYRINGS=y
CONFIG_BIG_KEYS=y
CONFIG_ENCRYPTED_KEYS=y
CONFIG_KEY_DH_OPERATIONS=y
CONFIG_SECURITY_DMESG_RESTRICT=y
CONFIG_SECURITY=y
CONFIG_SECURITYFS=y
CONFIG_SECURITY_NETWORK=y
CONFIG_SECURITY_NETWORK_XFRM=y
CONFIG_SECURITY_PATH=y
CONFIG_HAVE_HARDENED_USERCOPY_ALLOCATOR=y
CONFIG_HAVE_ARCH_HARDENED_USERCOPY=y
CONFIG_HARDENED_USERCOPY=y
# CONFIG_HARDENED_USERCOPY_PAGESPAN is not set
# CONFIG_SECURITY_SELINUX is not set
# CONFIG_SECURITY_SMACK is not set
# CONFIG_SECURITY_TOMOYO is not set
# CONFIG_SECURITY_APPARMOR is not set
# CONFIG_SECURITY_LOADPIN is not set
CONFIG_SECURITY_YAMA=y
CONFIG_INTEGRITY=y
# CONFIG_INTEGRITY_SIGNATURE is not set
CONFIG_INTEGRITY_AUDIT=y
# CONFIG_IMA is not set
# CONFIG_EVM is not set
CONFIG_DEFAULT_SECURITY_DAC=y
CONFIG_DEFAULT_SECURITY=""
CONFIG_CRYPTO=y

セキュリティモジュールは、なんと一番使われているSELinuxが無効化されています。そのかわり(?)、なぜかマイナーなYAMAが有効化されています。SELinuxのサポートについては今後の課題のようです。

namespaceとcgroup

コンテナ実装の肝であるnamespaceについてはひととおり有効化されているようです。

CONFIG_CGROUPS=y
CONFIG_PAGE_COUNTER=y
CONFIG_MEMCG=y
CONFIG_MEMCG_SWAP=y
CONFIG_MEMCG_SWAP_ENABLED=y
CONFIG_BLK_CGROUP=y
# CONFIG_DEBUG_BLK_CGROUP is not set
CONFIG_CGROUP_WRITEBACK=y
CONFIG_CGROUP_SCHED=y
CONFIG_FAIR_GROUP_SCHED=y
CONFIG_CFS_BANDWIDTH=y
CONFIG_RT_GROUP_SCHED=y
CONFIG_CGROUP_PIDS=y
CONFIG_CGROUP_FREEZER=y
CONFIG_CGROUP_HUGETLB=y
CONFIG_CPUSETS=y
CONFIG_PROC_PID_CPUSET=y
CONFIG_CGROUP_DEVICE=y
CONFIG_CGROUP_CPUACCT=y
CONFIG_CGROUP_PERF=y

コンテナのリソース制御をするcgroupについても多くが有効化されています。

CONFIG_NAMESPACES=y
CONFIG_UTS_NS=y
CONFIG_IPC_NS=y
CONFIG_USER_NS=y
CONFIG_PID_NS=y

仮想化

CONFIG_XEN=y
...
CONFIG_KVM_GUEST=y
...
CONFIG_HYPERV=y
...

Xen, KVM, Hyper-Vなどの主要なハイパーバイザのguestとして動くように設定されています。Widnows上や各種IaaS上で動かしたりする場合を考えれば当然必要でしょう。VIRTIOデバイスも用意されています。

おわりに

興味のある設定項目だけを適当に書き散らしたので、重要なところが漏れてことが多々あるかと思いますが、ご容赦ください。

2020-03-26

壊れたパッチと、その対処方法

はじめに

本記事は、何らかの理由によってパッチの内容が壊れてしまう理由と、その対処方法について述べます。IT系に限っても「パッチ」という言葉には様々な意味がありますが、本記事で言うパッチとは、diffコマンドやgit format-patchなどによって作成した、2つのテキストファイルの差分を表現するテキストファイルのことを指します。「パッチの内容が壊れる」とは、後述する様々な理由によって、パッチが、作成時とは異なる正しく適用できない状態になってしまっていることを言います。具体的にはタブが1つまたは複数のスペースに誤変換されることを指します。これ以降、単にこのような誤変換のことを「壊れる」と記載します。

本記事は、どちらかというとメーリングリスト(以下ML)ベースで開発をしている(せざるを得ない)旧来型の開発者向けです。「開発は全部githubとgitを使ってやるからパッチを直接扱うことなんて無いよ」とか「patchコマンドとかgit {apply,am}ってそもそも何?」という次世代開発者は本記事を見なくても問題無いです。

パッチが壊れる理由

「パッチが壊れる理由なんて知っとるわ、どう対処すればいいかだけ教えろ」というかたは、この節を飛ばして下さい。

ある人がパッチを作ったとします。それを誰か別の人と共有するには

パッチファイルを直接コピーして渡す
パッチの内容をwebページ(ブログなど)に貼り付ける
パッチを貼り付けたメールを個人ないしMLに送信する

などの方法があります。直接コピーなら大丈夫なのですが、それ以外の場合は、例えば次のような時にパッチが壊れます。

Webページの表示時: htmlソースには正しいパッチが挿入されていても、webブラウザ上では任意長のタブないしスペースから成る列(POSIX 正規表現で言うと/:space:+/)は全て1つのスペースに変換されてしまう
メールの送信時: 送信時にタブをスペースに自動変換する(パッチという観点から見ると)邪悪なメールクライアント(参考)がある
端末からwebページへのコピペ時: タブが、その文字幅に応じたスペースの列に変換されることがある

こうなると、誰かがせっかく書いて公開してくれた便利なパッチをみなさんが使いたくても使えないという問題が発生します(逆のパターンもあり)。パッチを書いた人に連絡して正しいパッチを貰えればいいのですが、連絡するのに気が引けたり、連絡が取れなかったり、はたまた投稿者本人もそのパッチをもう持っていないなどということもありえます。

壊れたパッチの具体例

linuxの開発MLに投稿されたカーネルパッチを題材として壊れたパッチの具体例を示しましょう。これは、ML投稿時には正しかったものの、MLアーカイブサイトの誤整形によって壊れてしまったパッチです。

linux カーネルソースのコーディングスタイルでは、インデントは8文字幅のタブです。しかし、この壊れたパッチ内のインデントはすべてタブではなくスペースになってしまっています。これではpatchコマンドやgit {apply,am}コマンドなどにとっては、パッチ内の各断片をソース中のどこに適用してよいのかわからないため、適用に失敗します。

対処方法

本節では壊れたパッチに遭遇した場合の様々な対処方法について述べます。

別サイトを探す

あるMLアーカイブサイト上にあるパッチが壊れているからといって、別のサイトでもそうであるとは限りません。問題が発生していない別のサイトがあれば、そちらを見ればいいのです。例えばこれはさきほどのパッチ(が挿入されたメール)を別のサイト上で見たものです。こちらは、タブはタブとして正しく整形されています。

linux開発について言えば、主な開発MLに投稿されたパッチがpatchwork.kernel.orgに正しく適用可能な形式でまとめられています。例に挙げた述べたパッチについてはここにあります。

直接 html をダウンロードする

パッチの著者が何も考えずにパッチをそのままhtmlにベタコピーしているような場合は、curlなどを使ってhtmlファイルを直接ダウンロードして、そこからパッチ部分を抽出することによって正しく適用可能なパッチが得られます。

パッチ適用時にマッチングのルールを緩くする

patchコマンドやgit {am,apply-patch}コマンドの--ignore-whitespaceオプションを使えば(patchコマンドの場合は-lでも可)、パッチ適用時にタブとスペースに関するマッチングのルールを緩めてくれるため、壊れたパッチも適用可能になります。

ただしこれには注意が必要です。パッチ適用後には"+"で始まる行のコンテンツがそのまま元のテキストに追加されます。このため、タブやスペースに特別な意味を持たせている場合に問題が発生します。例えばタブがスペースに変換されているパッチを、タブにが特別な意味を持つMakefileに対して適用すると、その後正しく動作しないことがあります。また、このような問題が無いケースでも、パッチ適用後のコードがプロジェクトのコーディングスタイルに違反してしまうこともあるので、パッチ適用後にフォーマッティングツールを適用するとよいかもしれません。

壊れたパッチを手元で修復する

次のようなスクリプトを適用すると、ある程度修復作業が自動化できます。

#!/bin/bash                                                                                                                                                                                                                                

if [ $# -ne 1 ] ; then
    echo "usage: $0 <broken-patch>" >&2
    exit 1
fi

PATCH=$1

unexpand -a $PATCH | sed -e 's/^\t/ \t/' -e 's/^$/ /'

単にunexpandコマンドを使うだけだと、patchファイルにおいて特別な意味を持つ行頭の1文字目をうまく扱えないため、sedで行頭を追加整形しています。このスクリプトは次のように壊れたパッチを引数として受け取り、修正後のそれを標準出力に出力します。

$ ./patch-unexpand bad.patch >good.patch

タブ幅が8ではない場合はman 1 unexpandを参照の上、スクリプトのソースを改変してください(-tオプションを使うことになると思います)。

タブからスペースへの誤変換については、これでだいたいのものは修正できます。このスクリプによって作成した新たなパッチが依然適用できない場合は、元から意図的に連続スペースだったものをスクリプトがタブに誤変換してしまっていることが考えられます。しかし、それを考慮しても手作業で全て修正するよりは、事前にこのスクリプトを適用しておくほうが遥かに作業効率が高いです。

さらに、ここまでは触れませんでしたが、1行に所定の文字数(例えば80文字)以上書くと自動的に改行する(パッチという観点から見ると)極悪非道なサイト、メールクライアントがあります。たとえば前記の例に挙げたパッチの中の"buf_start,"で始まる行が該当します。この文字列は、本来この直前の行の末尾に配置されているべきものなのですが、サイトの設定によって、このように表示されてしまっています。このような整形をされた場合は、上記スクリプトでは全く救えません。

後は(残念ながら)修正不完全なパッチを、適用前のソースと見比べながら、手動でなんとか適用可能な状態にします。辛く苦しい作業ですが、しょうがないです。

おわりに

上記のスクリプトに加えて、パッチ内の修正箇所の前後数行と対応する元ソースとを比較して、より高精度な復元をするスクリプトの実装も可能かと思いますが、まずはここまで。

なお、「何でこんなダサいことしてるの？このコマンド使えば簡単じゃん」というような便利コマンドをご存知のかたがいれば教えてください。なお、{patch,{git {apply,am}}の--ignore-whitespaceオプションについては優しい人に教えていただいたので、後から追記しました。

2020-03-26

linux kernelのコードネームは無視していい

Linux Kernelにはバージョン名(本記事執筆時点では4.x)に加えてコードネームが存在します。Linux 4.10-rc6 Released, Now Codenamed The "Fearless Coyote"のように、記事のタイトルにコードネームを持ってきたり、コードネームが記事の中に記載されたりすることがあります。

実はこのコードネームにはほとんど意味がありません。少なくともlinuxの主要開発メーリングリストでもこれまでほとんど見たことがありません。2,3ヶ月に一度新バージョンがリリースされる現在ではコードネームがついていても覚えきれるわけがないので、使われないのは無理からぬことです。

カーネルのバイナリであるvmlinuxにもこの情報は含まれません。

$ strings vmlinux | grep "Fearless Coyote" 
$

そもそもLinuxのコードネームはソースディレクトリ直下のMakefileにName = <codename>という形で定義されているだけで、他の用途に使われることは一切ありません。

$ head Makefile 
VERSION = 4
PATCHLEVEL = 10
SUBLEVEL = 0
EXTRAVERSION = -rc6
NAME = Fearless Coyote         # ←コードネーム
...
$ find | xargs grep -rnH '\$(NAME)'
$

バージョン名がいたるところで使われており、かつ、vmlinuxにも情報が含まれていることに比べると大きな違いです。

ついでに言うと、過去のコードネームの一覧を見ればわかる通り、この名前はリリース毎に更新されているわけではなく、数バージョンにわたって同じものが使いまわされたりしています*1。

このためOpenStackのバージョン名"Mitaka"や"Newton"のような感覚で「君、昨日リリースされたFearless Coyoteをもう動かしてみたかね?」とかいう奴がいたら、そいつは似非カーネル通だと思います。

筆者はLinuxを使い始めて高々十数年なこともあって、過去のLinuxの歴史については詳しくありません。このため、過去にこのコードネームがいつから何のためにつけられたのかは知りません。しかし、少なくとも今現在は大した意味を持っていないことは確かです。このあたりの事情に詳しいかたがおられましたら、教えていただけると嬉しいです。

*1:Linus氏はコードネームについては更新をルーチンワークにしておらず、思い出したときに適当に更新しているのではないかと私は推測しています。

2020-03-26

カーネルモジュール作成によるlinuxカーネル開発入門 - 第三回デバッグ用インターフェース

はじめに

本記事は第二回の続きです。前回までの記事を既に見ていることが前提です。

今回は、今後凝ったカーネルモジュールを作るにあたって必要になってくる、デバッグに有用なdebugfsというファイルシステムについて学びます。debugfsはカーネルとユーザとの間で簡単に情報をやりとりするためのファイルシステムです。linuxにはprocfs, sysfsという、このような使い方ができる他のファイルシステムもあります。しかし、前者は原則としてプロセスに関連する情報だけを扱うというルールがあること¹、および、後者は扱いかたが少々難しい上に1ファイルにつき1つの値しかやりとりできないという制限があることより、おいそれと使えません。

debugfsは通常/sys/kernel/debugというディレクトリ以下にマウントされています。その下のファイルを読み書きすることによって、カーネルの情報をユーザプロセスから参照したり、ユーザプロセスからカーネルに情報を渡したりできます。これまでに使ってきたprintk()とは、

ユーザの望むタイミングで情報をやりとりできる
カーネルから情報を受取るだけでなく、ユーザから情報を渡せる

という違いがあります。

今回は、前回作成したタイマー処理を拡張して、ユーザプロセスから

タイマーの残り時間を参照する
タイマーの残り時間を変更する

ということをやります。

タイマーの残り時間を変更する

以下のようなモジュールを作ります。

モジュールロードの1000秒後に1000秒経過したことを示すメッセージを表示する
/sys/kernel/debug/mytimer_remain_msecsというファイルの読み出しによって、タイマーの残り時間(ミリ秒単位)を表示する
タイマー動作後に当該ファイルを読み出すと0を表示する

ソースを示します。

#include <linux/module.h>
#include <linux/debugfs.h>

MODULE_LICENSE("GPL v2");
MODULE_AUTHOR("Satoru Takeuchi <satoru.takeuchi@gmail.com>");
MODULE_DESCRIPTION("A simple example of debugfs");

static struct dentry *testfile;
static char testbuf[128];

struct timer_list mytimer;

#define MYTIMER_TIMEOUT_SECS    ((unsigned long)1000)

static void mytimer_fn(unsigned long arg)
{
        printk(KERN_ALERT "%lu secs passed.\n", MYTIMER_TIMEOUT_SECS);
}

static ssize_t mytimer_remain_msecs_read(struct file *f, char __user *buf, size_t len, loff_t *ppos)
{
        unsigned long diff_msecs, now = jiffies;

        if (time_after(mytimer.expires, now))
                diff_msecs = (mytimer.expires - now) * 1000 / HZ;
        else
                diff_msecs = 0;

        snprintf(testbuf, sizeof(testbuf), "%lu\n", diff_msecs);
        return simple_read_from_buffer(buf, len, ppos, testbuf, strlen(testbuf));
}

static struct file_operations test_fops = {
        .owner = THIS_MODULE,
        .read = mytimer_remain_msecs_read,
};

static int mymodule_init(void)
{
        init_timer(&mytimer);
        mytimer.expires = jiffies + MYTIMER_TIMEOUT_SECS*HZ;
        mytimer.data = 0;
        mytimer.function = mytimer_fn;
        add_timer(&mytimer);

        testfile = debugfs_create_file("mytimer_remain_msecs", 0400, NULL, NULL, &test_fops);
        if (!testfile)
                return -ENOMEM;

        return 0;
}

static void mymodule_exit(void)
{
        debugfs_remove(testfile);
        del_timer(&mytimer);
}

module_init(mymodule_init);
module_exit(mymodule_exit);

注目すべき点は次の通りです。

mytimer_remain_msecs_read()によってタイマーの残り時間を読み出す
time_after(a,b)は、時刻aが時刻bより先であれば1を、そうでなければ0を返す。ここでの時刻はunsigned long型なので、単純に"a - b > 0"という比較をしても常に1を返してしまう
simple_read_from_buffer()によって、testbufの内容をユーザ空間のバッファであるbufに渡している²
test_fops.readが、/sys/kernel/debug/mytimer_remain_msecs読み出し時に呼ばれるハンドラ
debugfs_create_file()によって/sys/kernel/debug/mytimer_remain_msecsを作成する(パーミッションは0400)
debugfs_remove()によって/sys/kernel/debug/mytimer_remain_msecsを削除する

VM上でモジュールロード前後に/sys/kernel/debug以下のファイルをリストしてみましょう。

# ls /sys/kernel/debug
acpi  cleancache  dma_buf  dynamic_debug  fault_around_bytes  gpio     kprobes  pinctrl  pwm  regmap     sched_features  split_huge_pages  suspend_stats  usb           wakeup_sources  zswap
bdi   clk         dri      extfrag        frontswap           iosf_sb  mce      pm_qos   ras  regulator  sleep_time      sunrpc            tracing        virtio-ports  x86
# insmod /vagrant/debugfs1.ko 
# ls /sys/kernel/debug
acpi  cleancache  dma_buf  dynamic_debug  fault_around_bytes  gpio     kprobes  mytimer_remain_msecs  pm_qos  ras     regulator       sleep_time        sunrpc         tracing  virtio-ports    x86
bdi   clk         dri      extfrag        frontswap           iosf_sb  mce      pinctrl               pwm     regmap  sched_features  split_huge_pages  suspend_stats  usb      wakeup_sources  zswap
#

ロード前には存在しなかった/sys/kernel/debug/mytimer_remain_msecsがロード後にはできていることがわかります。

では、定期的に、たとえば一秒ごとにこのファイルを読み出してみましょう。

# for ((i=0;i<10;i++)) ; do cat /sys/kernel/debug/mytimer_remain_msecs ; sleep 1; done
839888
838888
837884
836884
835884
834880
833880
832880
831876
830876
#

一秒ごとに約一秒(1000ミリ秒)づつカウントダウンしていることがわかります。

モジュールアンロード時にファイルが消えるかを確認します。

# rmmod debugfs1
# ls /sys/kernel/debug 
acpi  cleancache  dma_buf  dynamic_debug  fault_around_bytes  gpio     kprobes  pinctrl  pwm  regmap     sched_features  split_huge_pages  suspend_stats  usb           wakeup_sources  zswap
bdi   clk         dri      extfrag        frontswap           iosf_sb  mce      pm_qos   ras  regulator  sleep_time      sunrpc            tracing        virtio-ports  x86
#

正しく消えたようです。

モジュール固有のディレクトリを作成する

さきほどは自作モジュール用のファイルを/sys/kernel/debug直下に作成しました。実はこれは新規ファイルを増やすに従って他のモジュール用のファイルと名前が重なる可能性が高まること、および、当該ディレクトリ以下にやたらとファイルが出来てしまって見通しが悪くなることによって、あまり褒められた方法ではありません。このようなことを避けるために、モジュールごとに/sys/kernel/debug以下に専用のディレクトリを作成するのが望ましいです。

さきほどのプログラムを一部変更して、タイマーの残り時間を/sys/kernel/debug/mytimer/remain_msecsから得るようにしましょう。

#include <linux/module.h>
#include <linux/debugfs.h>

MODULE_LICENSE("GPL v2");
MODULE_AUTHOR("Satoru Takeuchi <satoru.takeuchi@gmail.com>");
MODULE_DESCRIPTION("A simple example of debugfs");

static struct dentry *topdir;
static struct dentry *testfile;
static char testbuf[128];

struct timer_list mytimer;

#define MYTIMER_TIMEOUT_SECS    ((unsigned long)1000)

static void mytimer_fn(unsigned long arg)
{
        printk(KERN_ALERT "%lu secs passed.\n", MYTIMER_TIMEOUT_SECS);
}

static ssize_t mytimer_remain_msecs_read(struct file *f, char __user *buf, size_t len, loff_t *ppos)
{
        unsigned long diff_msecs, now = jiffies;

        if (time_after(mytimer.expires, now))
                diff_msecs = (mytimer.expires - now) * 1000 / HZ;
        else
                diff_msecs = 0;

        snprintf(testbuf, sizeof(testbuf), "%lu\n", diff_msecs);
        return simple_read_from_buffer(buf, len, ppos, testbuf, strlen(testbuf));
}

static struct file_operations test_fops = {
        .owner = THIS_MODULE,
        .read = mytimer_remain_msecs_read,
};

static int mymodule_init(void)
{
        init_timer(&mytimer);
        mytimer.expires = jiffies + MYTIMER_TIMEOUT_SECS*HZ;
        mytimer.data = 0;
        mytimer.function = mytimer_fn;
        add_timer(&mytimer);

        topdir = debugfs_create_dir("mytimer", NULL);
        if (!topdir)
                return -ENOMEM;
        testfile = debugfs_create_file("remain_msecs", 0400, topdir, NULL, &test_fops);
        if (!testfile)
                return -ENOMEM;

        return 0;
}

static void mymodule_exit(void)
{
        debugfs_remove_recursive(topdir);
        del_timer(&mytimer);
}

module_init(mymodule_init);
module_exit(mymodule_exit);

さきほどのソースとの差分で注目すべき点は次の通りです。

debugfs_create_dir()によって/sys/kernel/debug以下にmytimerというディレクトリを作成する
debugfs_create_file()の第3引数に、ディレクトリに対応するstruct dentry *型のデータを指定すると、当該ディレクトリ以下にファイルを作成する。この場合は/sys/kernel/debug/mytimer以下にremain_msecsというファイルを作成する
debugfs_remove_recursive()によって、指定したディレクトリ以下のファイルを再帰的に削除する

さきほどと同様、ロード後に所定のファイルができているかを確認します。

# insmod /vagrant/debugfs2.ko 
# ls /sys/kernel/debug 
acpi  cleancache  dma_buf  dynamic_debug  fault_around_bytes  gpio     kprobes  mytimer  pm_qos  ras     regulator       sleep_time        sunrpc         tracing  virtio-ports    x86
bdi   clk         dri      extfrag        frontswap           iosf_sb  mce      pinctrl  pwm     regmap  sched_features  split_huge_pages  suspend_stats  usb      wakeup_sources  zswap
# ls /sys/kernel/debug/mytimer 
remain_msecs
#

うまくいっているようです。

また一秒ごとにタイマーの残り時間を見てみましょう。

# for ((i=0;i<10;i++)) ; do cat /sys/kernel/debug/mytimer/remain_msecs ; sleep 1; done
639008
638004
637004
636004
635000
634000
633000
632000
630996
629996
#

成功です。

モジュールをアンロードして、このモジュールが作成したディレクトリが消えていることを確認します。

# rmmod debugfs2 
# ls /sys/kernel/debug
acpi  cleancache  dma_buf  dynamic_debug  fault_around_bytes  gpio     kprobes  pinctrl  pwm  regmap     sched_features  split_huge_pages  suspend_stats  usb           wakeup_sources  zswap
bdi   clk         dri      extfrag        frontswap           iosf_sb  mce      pm_qos   ras  regulator  sleep_time      sunrpc            tracing        virtio-ports  x86
#

これも成功です。

タイマーの残り時間を変更する

これまではdebugfsを読み取りだけに使ってきましたが、今度は書き込みも試してみましょう。タイマーの残り時間を/sys/kernel/debug/mytimer/remain_msecsに書き込んだ値に設定し直します。ソースは次の通りです。

#include <linux/module.h>
#include <linux/debugfs.h>

MODULE_LICENSE("GPL v2");
MODULE_AUTHOR("Satoru Takeuchi <satoru.takeuchi@gmail.com>");
MODULE_DESCRIPTION("A simple example of debugfs");

static struct dentry *topdir;
static struct dentry *testfile;
static char testbuf[128];

struct timer_list mytimer;

static unsigned long mytimer_timeout_msecs = 1000 * 1000;

static void mytimer_fn(unsigned long arg)
{
        printk(KERN_ALERT "%lu secs passed.\n", mytimer_timeout_msecs / 1000);
}

static ssize_t mytimer_remain_msecs_read(struct file *f, char __user *buf, size_t len, loff_t *ppos)
{
        unsigned long diff_msecs, now = jiffies;

        if (time_after(mytimer.expires, now))
                diff_msecs = (mytimer.expires - now) * 1000 / HZ;
        else
                diff_msecs = 0;

        snprintf(testbuf, sizeof(testbuf), "%lu\n", diff_msecs);
        return simple_read_from_buffer(buf, len, ppos, testbuf, strlen(testbuf));
}

static ssize_t mytimer_remain_msecs_write(struct file *f, const char __user *buf, size_t len, loff_t *ppos)
{
        ssize_t ret;

        ret = simple_write_to_buffer(testbuf, sizeof(testbuf), ppos, buf, len);
        if (ret < 0)
                return ret;
        sscanf(testbuf, "%20lu", &mytimer_timeout_msecs);
        mod_timer(&mytimer, jiffies + mytimer_timeout_msecs * HZ / 1000);
        return ret;
}

static struct file_operations test_fops = {
        .owner = THIS_MODULE,
        .read = mytimer_remain_msecs_read,
        .write = mytimer_remain_msecs_write,
};

static int mymodule_init(void)
{
        init_timer(&mytimer);
        mytimer.expires = jiffies + mytimer_timeout_msecs * HZ / 1000; 
        mytimer.data = 0;
        mytimer.function = mytimer_fn;
        add_timer(&mytimer);

        topdir = debugfs_create_dir("mytimer", NULL);
        if (!topdir)
                return -ENOMEM;
        testfile = debugfs_create_file("remain_msecs", 0600, topdir, NULL, &test_fops);
        if (!testfile)
                return -ENOMEM;

        return 0;
}

static void mymodule_exit(void)
{
        debugfs_remove_recursive(topdir);
        del_timer(&mytimer);
}

module_init(mymodule_init);
module_exit(mymodule_exit);

次の点に注目してください。

mytimer_timeout_msecsがタイマーの待ち時間を示す(ミリ秒単位)
mytimer_remain_msecs_write()によって、ユーザ空間のバッファであるbufから、カーネル空間のバッファtestbufにデータを書き込む
上記で書き込んだデータをもとにタイマーの待ち時間を再設定

排他制御という観点からは本当はこのコードは少しまずいのですが、ここでは気にしないことにします。排他制御については後の回で扱う予定です。

では動作確認です。ファイルができているかどうかの確認は省略して、定期的にタイマーの残り時間が減少しているかを見ます。

# for ((i=0;i<10;i++)) ; do cat /sys/kernel/debug/mytimer/remain_msecs ; sleep 1 ; done
975616
974616
973616
972612
971612
970612
969612
968608
967608
966608
#

ここまではOK。では、タイマーの残り時間を10秒に変更した上で、またカウントダウンの様子を眺めましょう。

# echo 10000 > /sys/kernel/debug/mytimer/remain_msecs 
# for ((i=0;i<10;i++)) ; do cat /sys/kernel/debug/mytimer/remain_msecs ; sleep 1 ; done
7832
6828
5828
4828
3828
2824
1824
824
0
0
#

うまくいったようです。10秒経過したことを示すメッセージが出力されたかも確認します。

# dmesg | tail -1
[39528.736116] 10 secs passed.
#

OKです。最後にモジュールをアンロードしておきましょう。実行例の表示は省略します。

ここまでで今回はおしまいです。

演習問題

タイマーを2つ作成して、それぞれの残り時間を/sys/kernel/debug/mytimer/{1,2}/remain_msecsによって読み書きできるようにする

おわりに

今回使ったソースはexample/module/debugfs以下に置いています。次回はカーネル内の代表的なデータ構造であるリストについて述べます。

参考資料

カーネルソースのinclude/linux/debugfs.h: debugfs_create_*によって様々な型の単一のデータを扱うファイルを簡単に作成できる
カーネルソースのDocumentation/filesystems/debugfs.txt: debugfsの登場背景、用途、および使い方などについて述べられている

歴史的な事情によりプロセスに関係ないファイルも一部存在します↩
単純にmemcpy()によってデータをコピーしてしまうと、bufの一部が物理メモリ上に存在しない場合に問題となる。これについての詳細は後の回で述べる予定↩

2020-03-26

bashの組込みコマンド自作によるスクリプトの高速化

はじめに

bashには次の2つの理由によって、組み込みコマンド(builtin command)というものが存在します。

スクリプトの高速化のため。組み込みコマンドであれば通常のコマンドを実行する場合に比べてプロセスの生成コスト(fork()/exec())が削減できる
bash自身の状態を変更させるため。例えばcdコマンドを/bin/cdとして用意してbashから当該コマンドを実行しても、当該コマンドのpwdが変更されるだけで、bashのそれは変更されないため、意味がない

今回は前者に焦点を合わせて、その効果と、組み込みコマンドの自作方法について述べます。

予備知識: 組込みコマンドによるスクリプト高速化の効果

組込みコマンドそのものの存在、及びその存在意義について既にご存知のかたは、この節を飛ばしてもらって構いません。

例えば皆さんがbash スクリプトからechoコマンドを実行した場合、通常は/bin/echoコマンドではなくbashの組込みコマンドechoを実行します。目的は前述の通り、高速化です。

組込みコマンドによる高速化の効果を体験してみましょう。改行のみを出力する/bin/echoコマンドを一万回実行したときの経過時間を計測した結果を示します。出力そのものは不要なので/dev/nullに捨てています。

$ time (for ((i=0;i<10000;i++)) ; do /bin/echo >/dev/null; done)

real    0m5.760s
user    0m1.744s
sys     0m1.084s
$

所要時間はおよそ5.8秒でした。

同じことをbash組み込みコマンドで、つまり通常みなさんがbashから実行するechoでやってみましょう。

$ time (for ((i=0;i<10000;i++)) ; do echo >/dev/null; done)

real    0m0.086s
user    0m0.072s
sys     0m0.012s
$

こちらの所要時間はおよそ0.086秒と、通常のコマンドを実行する場合に比べて約1.4%の時間で処理を終えられました。bashはこのようにして様々な頻出コマンドを組み込みコマンド化によって高速化しています。

次のようにすれば組み込みコマンドのリストを得られます。興味のあるかたはご確認ください。

$ enable 
enable .
enable :
enable [
...
enable unalias
enable unset
enable wait
$

それぞれ高速化のためのものか、あるいは組込みコマンドでなければ実現不可能な機能なのかを考えてみるのもおもしろいかもしれません。

コマンド作成の実行環境

本記事執筆時点でのdebian/testing(stretch)最新版

必要なパッケージ

bash-builtins

組み込みコマンドの作成

簡単のため、みなさんがbash スクリプトを書いたとして、その中で頻繁に呼ばれるhello worldプログラムが性能ボトルネックになっていると仮定しましょう。この問題を、同コマンドの組み込みコマンド自作によって解決します。

もとのコマンドのソースは次の通りです。

#include <stdio.h>

int main(void) {
    puts("Hello world!");
    return 0;
}

実行してみましょう。

$ ./hello 
Hello world!
$

これと同じことをする組み込みコマンドのソースは次の通りです。

#include <builtins.h>
#include <shell.h>
#include <stdio.h>

static int myhello(WORD_LIST *list) {
    puts("Hello world!");
    fflush(stdout);
    return EXECUTION_SUCCESS;
}

static char *desc[] = {
    "Show a greeting message.",
    "",
    "It's far faster than launching executable file",
    "because it't not necessary to call exec() and fork().",
    (char *)NULL
};

struct builtin myhello_struct = {
    "myhello",      // builtin command name
    myhello,        // function called when issueing this command
    BUILTIN_ENABLED,    // initial flag
    desc,           // long description
    "myhello",      // short description
    0,
};

組込みコマンドの処理に対応する関数myhello(), ドキュメントとなるdesc変数、および、この組み込みコマンドをbashに登録するために必要なmyhello_structを作成する必要があります。それぞれの意味についてはソース内のコメントや後述の参考資料をごらんください。

これをビルドするためのMakefileは次のようになります。

BINARIES := hello myhello

.PHONY: all clean

all: hello myhello

myhello: myhello.c
    cc -L $@ -I/usr/include/bash/ -I/usr/include/bash/include -fpic -shared -o myhello.so myhello.c

clean:
    rm -rf *.o *.so *~ $(BINARIES)

ビルドしましょう。

$ make
cc     hello.c   -o hello
cc -L myhello -I/usr/include/bash/ -I/usr/include/bash/include -fpic -shared -o\
 myhello.so myhello.c
$ ls
LICENSE  Makefile  README.md  benchmark  hello  hello.c  myhello.c  myhello.so

成功です。作成されたmyhello.soという共有ライブラリが組み込みコマンドの実体です。

作成したコマンドの組み込み

コマンドの組み込みは次のようにします。

$ enable -f ./myhello.so myhello
$

これは./myhello.soという共有ライブラリをmyhelloという名前で組み込むという意味です。共有ライブラリ名の前の"./"を省略するとコマンドが失敗するので注意してください。

成功したかどうかを確認しましょう。

$ enable | grep myhello
enable myhello
$

myhello組み込みコマンドが正しくbashに認識されています。

ドキュメントも表示できます。

$ help myhello
myhello: myhello
    Show a greeting message.

    It's far faster than launching executable file
    because it't not necessary to call exec() and fork().
$

実行してみましょう。

$ myhello
Hello world!
$

成功です。

効果の確認

それぞれ同じことをする実行ファイル(./hello)とmyhello組み込みコマンドを10000回連続実行した際の所要時間を計測してみましょう。

$ time (for ((i=0;i<10000;i++)) ; do ./hello >/dev/null ; done)

real    0m5.508s
user    0m1.932s
sys     0m0.848s
$ time (for ((i=0;i<10000;i++)) ; do myhello >/dev/null ; done)

real    0m0.087s
user    0m0.076s
sys     0m0.008s
$

組み込みコマンドは実行ファイルの場合に比べて1.5%の所要時間で処理を終えられました。

注意

組み込みコマンドの自作は技術的には面白く、かつ、うまく使った場合の効果は高いのですが、次の理由によって、実際に適用できる範囲は少ないです。

Cソースを書いてbash組み込みコマンド専用の共有ライブラリをビルドしなくてはいけないため、移植性が低い
組込みコマンド化によって削減できるのはfork()/exec()のコストだけなので、前述のような著しい高速化が期待できるのは実行時間が極めて短いコマンドが大量に呼ばれる場合のみ¹

この機能は乱用を避けて、特定環境で特定処理だけを高速化したいというような特殊な場合にのみ使用するのがよいと筆者は考えます。ちょうどRubyやPythonなどのスクリプト言語の一部をCで実装したり、Cプログラムの一部をアセンブリ言語で実装したりするのと似ています。

おわりに

本記事で使用したソースはgithub上にアップロードしていますので、参考にしてください。

参考資料

/usr/share/doc/bash-builtins以下
入門bash 第3版の付録C

例えばfork()/exec()のコストが0.1秒だとして、実行に10秒を要するCプログラムを組み込みコマンドに置き換えたとしても削減できる実行時間は1%程度↩

2020-03-26

他人の書いたソフトウェアのバグへの対処例

はじめに

本記事は、他人の書いたソフトウェアのバグに遭遇したときにどうするかという流れを、実例を基にして、ストーリー仕立てでなるべく具体的に書きました。このようなときの対処に不慣れな人に、実際のデバッグ、バグレポート、および修正案の提出までの流れを掴んでもらうことが目的です。

バグに遭遇

筆者も参加していたLinux Advent Calendar 2016に、ある日シェルスクリプト（Bash）で作るTwitterクライアントという記事が投稿されました。twitter APIの認証に使われているOAuth1.0aとshell芸に興味があったことより、この記事を読んでみることにしました。

そこで紹介されているtweet.shというbash製twitterクライアントを試そうとしたところ、出力は次のようになりました。

$ ./tweet.sh showme
�VMo�6�+��umZ_����b��4E
���F2�tH*�wHY�?�=�P֛7����>��<M� XE�<以下省略>$

いきなり何かがおかしいです。自分のtwitterアカウントに関するJSON形式のデータが返ってくるはずが、実際に返ってきたのは意味不明なバイナリデータでした。

その時、たまたま土地勘の無い分野の技術への関心が高かったのと¹、それなりに自由な時間があったことより、デバッグしてみることにしました。

再現性の確認

デバッグでは同じ問題を簡単に再現できるかどうかが非常に重要です。ひとくちにバグと言っても、いつでもどこでも簡単な手順によって必ず再現できるものもありますし、数年に一回だけ不定期に発生する悪魔のようなものもあります。

幸いなことに、今回遭遇した問題の再現性は100%でした。

問題箇所の絞り込み

続いて、具体的にスクリプトのどの箇所で何が起きたのかを絞り込みました。無策でソースをいきなり見たりするのは手間暇がかかりますし、効率も悪いのです。

bashには、実行ログを表示する-xというオプションがあるので、それを使って問題発生箇所を特定することにしました。

$ bash -x ./tweet.sh showme
<省略>
++ curl --get --header 'Authorization: OAuth <省略>' --data '' --silent https://api.twitter.com/1.1/account/verify_credentials.json 
^_<8B>^H^@^@^@^@^@^@^@<AC>VMo<E3>6^P<FD>+<82><AE>umZ_<96>^D<F4><D0><ED>b<8F><BD>4E<省略>$

curlコマンドでtwitter APIにリクエストを発行する際に問題が発生していることがわかりしました。

続いて、上記コマンドを単独で実行しても同じ問題が発生するかを確認しました。

$ curl --get --header 'Authorization: OAuth <省略>'  --data '' --silent https://api.twitter.com/1.1/account/verify_credentials.json
^_<8B>^H^@^@^@^@^@^@^@<AC>VMo<E3>6^P<FD>+<82><AE>umZ_<96>^D<F4><D0><ED>b<8F><BD>4E<省略>$

発生しました。これで再現プログラムをcurlの実行１つだけに絞り込めました。

続いてバイナリデータが何者かを、わかる範囲で調べました。こういう時に役立つのがfileコマンドです。

$ ../tmp/bin/curl --get --header 'Authorization: OAuth <省略>' --data '' --silent https://api.twitter.com/1.1/account/verify_credentials.json  | file -
/dev/stdin: gzip compressed data, from FAT filesystem (MS-DOS, OS/2, NT)

どうやら出力はgzipで圧縮されたデータのようでした。展開してみましょう。

$ curl --get --header 'Authorization: OAuth <省略>' --data '' --silent https://api.twitter.com/1.1/account/verify_credentials.json | gunzip
{"id":<略>}$

展開した結果はJSON形式のデータでした。これが本来得たかった出力です。なんとなくhttpの仕様にある、コンテンツボディの圧縮が関係していそうです。

別環境での再現性の確認

前節における確認と前後して、その時たまたまチャットをしていた同業者の友人に問題の再現依頼をしました。すると、友人の環境では問題が再現しないことがわかりました。これは問題の切り分けに非常に有用です。

次に、私と友人の環境の比較をするために、バージョンを確認しました。

私の環境(Debian testing(stretch))では次の通り。

$ curl --version
curl 7.50.1 (x86_64-pc-linux-gnu) libcurl/7.50.1 GnuTLS/3.5.7 zlib/1.2.8 libidn/1.33 libssh2/1.7.0 nghttp2/1.17.0 librtmp/2.3
Protocols: dict file ftp ftps gopher http https imap imaps ldap ldaps pop3 pop3s rtmp rtsp scp sftp smb smbs smtp smtps telnet tftp 
Features: AsynchDNS IDN IPv6 Largefile GSS-API Kerberos SPNEGO NTLM NTLM_WB SSL libz TLS-SRP HTTP2 UnixSockets
$

友人の環境(Ubuntu14.04)では次の通り。

$ curl --version
curl 7.35.0 (x86_64-pc-linux-gnu) libcurl/7.35.0 OpenSSL/1.0.1f zlib/1.2.8 libidn/1.28 librtmp/2.3
Protocols: dict file ftp ftps gopher http https imap imaps ldap ldaps pop3 pop3s rtmp rtsp smtp smtps telnet tftp
Features: AsynchDNS GSS-Negotiate IDN IPv6 Largefile NTLM NTLM_WB SSL libz TLS-SRP
$

細かい違いはありますが、ここではバージョン名がそもそも違っていることに注目しました。友人をデバッグに付き合わせ続けるのは悪いので、自分の環境でも同じことが起きるかを確認しました。その際、upstreamのバージョン7.35.0をビルドして使いました。ビルドやインストールの手順は本筋ではないので省きます。

$ ../tmp/curl --version | head -1
curl 7.34.1-DEV (x86_64-pc-linux-gnu) libcurl/7.50.1-DEV OpenSSL/1.1.0c zlib/1.2.8 libidn/1.33 libssh2/1.7.0 nghttp2/1.17.0 librtmp/2.3
$ ../tmp/bin/curl --get --header 'Authorization: OAuth <省略>' --data '' --silent https://api.twitter.com/1.1/account/verify_credentials.json
{"id":...}$

正しくJSON形式のデータが返ってきました。

続いてupstreamの最新版で同じ問題が発生するかどうかを確かめました。

$ ../tmp/bin/curl --version | head -1                                           
curl 7.52.2-DEV (x86_64-pc-linux-gnu) libcurl/7.52.2-DEV OpenSSL/1.1.0c zlib/1.2.8 libssh2/1.7.0 nghttp2/1.17.0 librtmp/2.3
$ ../tmp/bin/curl --get --header 'Authorization: OAuth <省略>' --data '' --silent https://api.twitter.com/1.1/account/verify_credentials.json
^_<8B>^H^@^@^@^@^@^@^@<AC>VMo<E3>6^P<FD>+<82><AE>umZ_<96>^D<F4><D0><ED>b<8F><BD>4E<省略>$

想定通り、問題が再現しました。

再現/非再現環境の差分を採取

再現/非再現環境が整ったので、両者の差分を比較しました。失敗時の出力はgzipで圧縮されていたことより、何となくhttpヘッダの違いが関係していそうという当たりがつけられました。curlには、リクエスト/レスポンスに付加されたhttpヘッダなどの詳細情報を出力できる-vというオプションがあるので、これを使うことにしました。

$ ../tmp/bin/curl --get --header 'Authorization: OAuth <省略>' --data '' --silent https://api.twitter.com/1.1/account/verify_credentials.json -v >/dev/null

両バージョンにおける上記コマンドを発行した際の出力を比較したものを示します。

$ diff -urNp ../out.{good,bad}
<省略>
+* Using HTTP2, server supports multi-use
+* Connection state changed (HTTP/2 confirmed)
+* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
<省略>
-> User-Agent: curl/7.34.1-DEV
+> User-Agent: curl/7.52.2-DEV
-< HTTP/1.1 200 OK
<省略>
+< HTTP/2 200 
<省略>
+< content-encoding: gzip

この差分を表にまとめると次のようになります。

バージョン	twitter APIへのアクセスプロトコル	curlが許容するエンコーディング形式(Accept-Encodingヘッダ)	レスポンスボディのエンコーディング形式(Content-Encodingヘッダ)
7.35.0	http1.1	未指定	未指定(生のJSON形式データであることを示す)
最新版	http2	未指定	gzip

これによって次のことがわかります。

curlは7.35.0より後のいつの時点からか、twitter APIに対してデフォルトではhttp1.1ではなくhttp2によってアクセスするようになった
twitter APIはhttp1.1によってAccept-Encodingヘッダ無しでアクセスされると無圧縮のレスポンスボディを返す
同http2によってAccept-Encodingヘッダ無しでアクセスされるとgzipで圧縮されたボディを返す

再現プログラムのさらなる簡略化

問題の再現に認証は関係無さそうなので、次のように認証なしで(Authorization タグ無しで)アクセスしても問題が再現するかを試しました。

以下7.35.0の場合。

$ ../tmp/bin/curl --get --silent https://api.twitter.com/1.1/account/verify_credentials.json | file -
/dev/stdin: ASCII text, with no line terminators
$

以下最新版の場合。

$ ../tmp/bin/curl --get --silent https://api.twitter.com/1.1/account/verify_credentials.json | file -
/dev/stdin: gzip compressed data, from FAT filesystem (MS-DOS, OS/2, NT)
$

これまでの再現プログラムの場合と同様、前者はテキスト形式、後者はgzip形式になりました。ここでは省略しますが、-vオプションを付加して得られるヘッダなどの出力の違いも、これまでの再現プログラムと同様です。また、前者の出力はJSON形式であり、後者の出力をgunzipにかけると前者と同じものが得られます。

仕様かバグか

httpヘッダの話に戻ります。Accept-Encodingヘッダを指定していないのにgzip圧縮されたデータを返すのは直感的には妙に思います。その直感が正しいのかどうかは仕様を読むことによって確認します。自分の思い込みをもとにして正否を判断してバグ報告したりすると会話にならずに撃沈必至です。

Accept-EncodingヘッダとContent-EncodingヘッダはそれぞれRFC7231 5.3.4とRFC7231 3.1.2.2において定義されています。

Accept-Encodingヘッダの項目には次のようなことが書かれています。

<省略>
A request without an Accept-Encoding header field implies
that the　user agent has no preferences regarding content-codings.
Although　this allows the server to use any content-coding in a response,
it　does not imply that the user agent will be
able to correctly process　all encodings.
<省略>

意訳すると「ユーザエージェントがAccept-Encodingヘッダを指定してなければサーバはボディをどんなふうにエンコーディングしてもいい。しかし、その場合ユーザエージェントは正しくデコード出来ないかもしれない」です。要するにAccept-Encodingヘッダを指定しなかった場合にgzipで圧縮されたボディを返すのは仕様違反ではないようです。

続いて、最新版を使って、下記のように圧縮を一切許さないようにリクエストを出すとどうなるかを確認しました。

$ curl --get --silent --header "Accept-Encoding: identity;q=1.0,*;q=0" https://api.twitter.com/1.1/account/verify_credentials.json | file -
/dev/stdin: gzip compressed data, from FAT filesystem (MS-DOS, OS/2, NT)

それでも出力は圧縮されていました。これは問題です。

バグレポートと修正

今回の問題のレポート先はtwitter developers forum²とtweet.shのgithubの2つです。

根本原因は１つなのですが、それぞれの場所に訴える内容は微妙に違います。これを間違えると、受け手にとっては「この場所でそんなこと言われても…」となるので注意が必要です。ではそれぞれについて具体的に何をしたのか見てみましょう。

twitter developers forumへの報告

ここには「twitter APIにhttp2で圧縮を許可せずにアクセスしても圧縮したレスポンスボディが返ってくることが問題である」と報告します。

報告前にはforumの過去ログを漁って、既存の問題かどうかを確認します。すると、vimやらGoやらで色々有名なmattn_jpさんがすでに報告していました。

自分の持っている情報に何も新規性が無ければここで撤退しますが、今回の場合は

Twitter API doesn't treat "Accept-Encoding: identity".
I'm guessing many twitter client that doesn't use browser may not work."

という記載があったので、curlで問題を再現できたことを追記しました。

このとき、どんな環境で何をしたら本来どうあるべきなのに、実際はこうなった、というのを簡潔に記載する必要があります。「なんだかわからないけどとにかくうまく動かなかった」とかいう報告では人は動かせません。

twitter APIについてはバグ報告者にこれ以上できることはありません。何らかの返信があるまで待ちです。ソースが公開されていないので、実装に踏み込んだ解析はできませんし、修正案の提示もできません。

2017年1月4日に公式スタッフの人から"I will share it with the team"という返信が来ていましたが、その後この問題はしばらく放置されることになります。続きは本記事の後のほうに書いています。

tweet.shのgithubへの報告

ここには「最近のcurlを使っているとtweet.shがうまく動作しないという問題がある」と報告します。twitter APIと異なりtweet.shはOSSなので、実装に踏み込んだ解析と修正案の提示ができます(提示した修正案を受け入れるかどうかは作者次第ですが)。今回はここまでやってみました。

まずは報告前に既存の報告および修正案があるかどうか、issueとpull requestの一覧を見ました。今回は該当無しでした。

修正については、やりかたは色々あるのですが、今回は、過去のcurlのようにhttp1.1を使ってtwitter APIにアクセスするという回避策を提案しました。以下がそのpull requestです。

https://github.com/piroor/tweet.sh/pull/3

このpull requestはなんと一時間以内にマージされました。それを知った時は、これこそOSSのダイナミズムだ、という思いがしました。OSSって本当にいいものですね(ステマ)。ここまでで、本筋はおしまいです。

余談ですが、このpull requestはバグの内容だけについて触れており、肝心の修正方法の説明が一切書いてません。これは書き忘れです。下書きには

Although this problem comes from twitter API's problem,
it wouldn't be fixed for a while (forever?).
Accessing to twitter API via http1.1 can be a workaround.

というような文言があったのですが、いつの間にか消えていました。大ポカですね、すいません。

twitterにようやく修正が入る

わたしがこの問題に気づいてから約1年後、元のmattn_jpさんの報告からさかのぼると約2年後の2018年1月3日に、この問題が修正されたとのアナウンスがtwitter社から、ようやく出ました。再現試験を実施したところ、たしかに修正されていました。

$ ./curl --get --http2 https://api.twitter.com/1.1/account/verify_credentials.json
{"errors":[{"code":215,"message":"Bad Authentication data."}]}

チケットも数日後にmattn_jpさんからの問い合わせをきっかけとして、closeされました。これにて根本原因であるtwitterの問題も解決しました。めでたしめでたし。

おわりに

本記事で述べたようなことを毎回やる必要はありません。やる気と時間を天秤にかけて、自分がどこまでやるのかを決めるとよいかと思います。飽きたら途中でやめてもいいんです。フィードバックは義務ではなく、あくまで任意であり、自分が楽しむことが最優先です。筆者も修正作成までは滅多にやりません。だいたいは、他にもっとやりたいことがあるからです。

もう一点。筆者が畑違いということもあり、上記のデバッグ方法は恐らく最適なものではありません³。それでも、そのような人が実際に問題に遭遇した際にどのような試行錯誤したのかというライブ感を大事にするために、あえて実際の手順をほぼそのまま記載しました。

筆者の本業はlinux カーネル屋です↩
twitterにまつわるソフト開発について議論する場所↩
例えば最初のバイナリ出力を見た瞬間に「これはgzipで圧縮されたデータで展開後のデータはJSONだなあ」とわかる変た^H^H優秀なエンジニアはけっこういます↩

2020-03-26

カーネルモジュール作成によるlinuxカーネル開発入門 - 第二回一定時間後に処理をする(タイマー)

はじめに

本記事は第一回の続きです。前回までの記事を既に見た上で開発環境ができていることを前提としています。

前回書いたコードはモジュールをロードした時とアンロードしたときだけ動いていました。今回は、ある時点から一定時間後に所定の処理をする方法を学びましょう。そのためにカーネル内のタイマー機能を使います。タイマー機能はカーネル内のいたるところで使われています。

今回書くソースはすべてelkdatのソースディレクトリ以下のdev/module/timer以下に配置するものとします。

一番簡単な例

モジュールロードから10秒後にメッセージを出してみましょう。次のようなソースになります。

#include <linux/module.h>
#include <linux/timer.h>

MODULE_LICENSE("GPL v2");
MODULE_AUTHOR("Satoru Takeuchi <satoru.takeuchi@gmail.com>");
MODULE_DESCRIPTION("timer kernel module: oneshot timer");
 
struct timer_list mytimer;
 
#define MYTIMER_TIMEOUT_SECS    10

static void mytimer_fn(unsigned long arg)
{ 
        printk(KERN_ALERT "10 secs passed.\n");
}

static int mymodule_init(void)
{
        init_timer(&mytimer);
        mytimer.expires = jiffies + MYTIMER_TIMEOUT_SECS*HZ;
        mytimer.data = 0;
        mytimer.function = mytimer_fn;
        add_timer(&mytimer);

        return 0;
}

static void mymodule_exit(void)
{ 
        del_timer(&mytimer);
}

module_init(mymodule_init);
module_exit(mymodule_exit);

まず覚えて欲しいのは次のことです。

タイマーを使いたいときはlinux/timer.hをインクルードする
struct timer_listという構造体が１つのタイマーを指す。各フィールドの意味は次の通り

フィールド名	意味
expires	タイマーが動作する時刻。設定した値の意味は後述
function	タイマーが動作したときに呼ばれる処理
data	functionが呼ばれたときの引数(後述)

init_timer()によってタイマーを初期化(ここではモジュールロード時)
add_timer()によってタイマーが動作するようにカーネルに登録
del_timer()によってタイマーが今後動作しないようにカーネルから登録解除(ここではモジュールアンロード時)

続いてstruct timer_list.expiresに設定した値の意味を説明します。まず、jiffiesはカーネル起動直後からの経過時間を指します。この値は一秒間にHZという数だけ増加します¹。つまり、mytimer.expires = jiffies + MYTIMER_TIMEOUT_SECS(=10)*HZは「mytimerというタイマーを現在時刻から10秒後に動作させる」という意味になります。

Makefileは次の通りです。

.PHONY: all clean

obj-m := timer1.o

all:
        make -C ../../../output M=$(PWD) modules

clean:
        make -C ../../../linux M=$(PWD) clean

カーネルモジュールをビルドした上で、VMに配置し、VMにログインしてrootになります。

$ make
...
$ make install
...
$ make login
...
vagrant@packer-qemu:~$ sudo su
root@packer-qemu:/home/vagrant#

作成したカーネルモジュールをロードし、直後にカーネルログを確認します。

root@packer-qemu:/home/vagrant# insmod /vagrant/timer1.ko && dmesg | tail
...
[  275.906429] random: crng init done

このカーネルモジュールからは何も出力されていません。続いて、10秒以上経過してから再度ログを確認してみましょう。

root@packer-qemu:/home/vagrant# dmesg | tail
...
[  275.906429] random: crng init done
[16480.610243] 10 secs passed.

(モジュールロード時から)10秒経過したことを示すメッセージが出力されました。うまく動いていたようです。

最後にモジュールをアンロードしてVMから抜けます。

root@packer-qemu:/home/vagrant# rmmod timer1
root@packer-qemu:/home/vagrant# exit
...
vagrant@packer-qemu:~$ exit
...
$

カーネルに登録したタイマーの処理が呼ばれるのは一度だけということに注意してください。モジュールのロードからどれだけの時間が経過してもカーネルログに出力されるメッセージは一行だけということからそれが確認できます。定期的に所定の処理をしたいような場合については後述します。

カーネルモジュールのビルド、VMへの配置、VMへのログイン、VM上でrootになる手順は毎回ほぼ同じなので、これ以降は省略します。Makefileの中身についても同じく省略します。

タイマーの登録を解除しなければどうなるか

前回はお行儀よく、ロード時にカーネルに登録したタイマーを必ずアンロード時に登録解除していました。では登録解除しなければ、アンロード時に何もしなければどうなるのでしょうか。ソースは次の通りです。

...
static void timer_module_exit(void)
{
        /* do nothing */
}
...

timer_module_exit()の内容以外はtimer1.cと同じです。

ロードしてみましょう。

root@packer-qemu:/home/vagrant# insmod /vagrant/timer2.ko
root@packer-qemu:/home/vagrant#

10秒後以降にカーネルログを見ます。

root@packer-qemu:/home/vagrant# dmesg | tail
...
[17595.694822] 10 secs passed.

メッセージが出ました。アンロードします。

root@packer-qemu:/home/vagrant# rmmod timer2

何も問題はありませんでした。では、次のようにカーネルモジュールをロードした直後にアンロードする場合はどうでしょうか。

root@packer-qemu:/home/vagrant# insmod /vagrant/timer2.ko && rmmod timer2
root@packer-qemu:/home/vagrant#

何も起きない…ように見えますが10秒待ってからVMを操作しようとしてください。何も反応が無いはずです。

それもそのはず、タイマーの登録解除処理を省いたおかげで(せいで?)みなさんがお使いのカーネルは無事パニックしました。おめでとうございます。カーネル内のコードでは１つのバグがシステム全体にとっての致命傷になることがこれでお分かりいただけたと思います。

さて、このままでは困るので、まずは復旧します。VMにsshで接続している端末はもう戻ってきませんので閉じてしまって、別の端末から次のコマンドを実行します。

$ cd elkdat/
$ vagrant reload 
...
$ vagrant ssh -c "sudo grub-reboot ktest"
...
$ vagrant reload
...
$

パニックが起きるまでの流れは次の通りです。

カーネルモジュールをロードしてカーネルにmytimerを登録
カーネルモジュールをアンロードして、当該モジュールのメモリをすべて開放
10秒後に、解放済みのアドレスに存在するデータ(タイマー)を操作しようとしたためパニック

このようなことを起こさないようにするために、add_timer()とdel_timer()は必ず組にして使いましょう。

定期的に処理を実行する

カーネルモジュールのロードから10秒後だけでなく、10秒毎にメッセージを出してみましょう。ソースは次の通りです。

#include <linux/module.h>
#include <linux/timer.h>

MODULE_LICENSE("GPL v2");
MODULE_AUTHOR("Satoru Takeuchi <satoru.takeuchi@gmail.com>");
MODULE_DESCRIPTION("timer kernel module: periodic timer");

struct timer_list mytimer;

#define MYTIMER_TIMEOUT_SECS    10

static void mytimer_fn(unsigned long arg)
{
        printk(KERN_ALERT "10 secs passed.\n");
        mod_timer(&mytimer, jiffies + MYTIMER_TIMEOUT_SECS*HZ);
}

static int mymodule_init(void)
{
        init_timer(&mytimer);
        mytimer.expires = jiffies + MYTIMER_TIMEOUT_SECS*HZ;
        mytimer.data = 0;
        mytimer.function = mytimer_fn;
        add_timer(&mytimer);

        return 0;
}

static void mymodule_exit(void)
{
        del_timer(&mytimer);
}

module_init(mymodule_init);
module_exit(mymodule_exit);

ほとんどtimer1.cと同じです。違いはタイマーの処理(mytimer_fn())においてメッセージを出力した直後にmod_timer()という関数を追加していることです。この関数は、第一引数で指定したタイマーを再度カーネルに登録します。

ここではタイマーの処理において、呼び出し時点から10秒後に再度タイマーを動作させるように登録しています。これによって、10秒毎にmytimer_fn()を呼び出しています。カーネル内で定期的に処理を実行したい場合はこのようにします。

ロードして、10秒後以降にカーネルログを見ます。

root@packer-qemu:/home/vagrant# insmod /vagrant/timer3.ko
root@packer-qemu:/home/vagrant# dmesg | tail
...
[   40.130824] 10 secs passed.

メッセージが出力されています。1分ほど経過してから再度ログを見ましょう。

root@packer-qemu:/home/vagrant# dmesg | tail
...
[   40.130824] 10 secs passed.
[   50.407771] 10 secs passed.
[   60.657174] 10 secs passed.
[   70.898123] 10 secs passed.
[   81.137445] 10 secs passed.
[   91.377037] 10 secs passed.
root@packer-qemu:/home/vagrant#

正しく10秒ごとにメッセージがメッセージが出力されていることがわかります。

モジュールをアンロードします。それから10秒以上経ってから再度ログを見ます。

root@packer-qemu:/home/vagrant# rmmod timer3
root@packer-qemu:/home/vagrant# dmesg
...
[   81.137445] 10 secs passed.
[   91.377037] 10 secs passed.
root@packer-qemu:/home/vagrant#

アンロード以降はメッセージが出力されていないことがわかります。タイマーの登録解除ができている証拠です。

複数のタイマーを動作させる

ここでは2つのタイマーを動作させる例を示します。2つとも動作時には同じ関数を呼び出します。このようなときに役に立つのがstruct timer_list.dataです。前述のように、このフィールドはタイマー動作時に呼ばれる関数(struct timer_list.function)の第一引数に渡されます。このフィールドには各タイマーに関係する構造体へのポインタを格納することが多いです。具体的にどのように利用するかはこれから述べます。

では、2つのタイマーを動作させる例を示します。仕様は次の通り。

一つ目のタイマー。名前は"foo"。2秒に1回動作し、動作するごとに自分の名前と呼び出し間隔を出力
二つ目のタイマー。名前は"bar"。3秒に1回動作し、動作するごとに自分の名前と呼び出し間隔を出力

ソースは次の通りです。今までの例に比べて若干長くて複雑です。

#include <linux/module.h>
#include <linux/timer.h>

MODULE_LICENSE("GPL v2");
MODULE_AUTHOR("Satoru Takeuchi <satoru.takeuchi@gmail.com>");
MODULE_DESCRIPTION("timer kernel module: pass arg");

struct mytimer_data { 
        char *name;
        int interval;
        struct timer_list timer;
};

struct mytimer_data data[2] = {
        {
                .name = "foo",
                .interval = 2,
        },
        {
                .name = "bar",
                .interval = 3,
        },
};
 
#define MYTIMER_TIMEOUT_SECS    10

static void mytimer_fn(unsigned long arg)
{
        struct mytimer_data *data = (struct mytimer_data *)arg;

        printk(KERN_ALERT "%s: %d secs passed.\n",
               data->name, data->interval);

        mod_timer(&data->timer, jiffies + data->interval*HZ);
}

static int mymodule_init(void)
{
        int i;

        for (i = 0; i < 2; i++) {
                struct mytimer_data *d = &data[i];
                init_timer(&d->timer);
                d->timer.function = mytimer_fn;
                d->timer.expires = jiffies + d->interval*HZ;
                d->timer.data = (unsigned long)d;
                add_timer(&d->timer);
        }

        return 0;
}

static void mymodule_exit(void)
{
        int i;

        for (i = 0; i < 2; i++) {
                del_timer(&data[i].timer);
        }
}

module_init(mymodule_init);
module_exit(mymodule_exit);

ソースのポイントは次の通りです。

それぞれのタイマーに関する情報をstruct timer_list.dataに格納
mytimer_fn()呼び出し時に上記の情報を取り出し、処理をする(当該関数を呼び出したタイマーによって挙動を変える)

動かしてみましょう。ロードして、しばらくしてからカーネルログを見ます。

root@packer-qemu:/home/vagrant# insmod /vagrant/timer4.ko
root@packer-qemu:/home/vagrant# dmesg | tail
[ 3916.676466] foo: 2 secs passed.
[ 3918.532436] bar: 3 secs passed.
[ 3918.692439] foo: 2 secs passed.
[ 3920.708419] foo: 2 secs passed.
[ 3921.604404] bar: 3 secs passed.
[ 3922.724395] foo: 2 secs passed.
[ 3924.676374] bar: 3 secs passed.
[ 3924.740372] foo: 2 secs passed.
[ 3926.756355] foo: 2 secs passed.
[ 3927.748342] bar: 3 secs passed.
root@packer-qemu:/home/vagrant#

タイマーfooが2秒ごとに、同barが3秒ごとに呼び出されていることがわかります。

最後に(コマンドログは示しませんが)、モジュールをアンロードして、その後にこのモジュールからのメッセージが出力されないことを確認しておきましょう。これにて今回はおしまい。

演習問題

タイマーを実行するたびに待ち時間を変える。たとえばモジュールロード時から10秒後、15秒後、25秒後、30秒後…など
timer4.cを変更して、それぞれのタイマーの呼び出し時に通算呼び出し回数を出力。呼び出し回数を示すカウンタは各タイマで独立させる

おわりに

今回使ったソースはexample/module/timer以下に置いています。必要があれば参照してください。次回はユーザプロセスとカーネルのインターフェイスについて扱います。

/boot/config-<カーネルバージョン>というファイルのCONFIG_HZという値に、当該カーネルにおけるHZの値が記載されています。筆者の環境では250なので、jiffiesは一秒間に250増加します。↩