SystemTapを学習します

Google Cloudが技術的な問題をどのように解決していったかということを「DNS パケット欠落のケース: Google Cloud サポート ストーリー」として記事にして公開してくれていましたので
それを題材にSystemTapを勉強してみました。
こちらの記事では net.core.rmem_default の整数オーバーフローが原因でDNS パケットが欠落する問題を解決するために収集した情報やどのように解決に至ったかについて
詳しく説明されています。 cloud.google.com

あらかじめ v5.4のカーネルとdropwatchを用意しておきます。
v5.4のkernelで起動した直後のUDPの統計情報です。

# netstat -su
Udp:
    0 packets received
    0 packets to unknown port received
    0 packet receive errors
    0 packets sent
    0 receive buffer errors
    0 send buffer errors
    IgnoredMulti: 1
UdpLite:
IpExt:
    InBcastPkts: 1
    InOctets: 18613
    OutOctets: 16002
    InBcastOctets: 272
    InNoECTPkts: 98
    InECT0Pkts: 82
# nstat -a |grep -i udp
UdpInDatagrams                  3                  0.0
UdpOutDatagrams                 3                  0.0
UdpIgnoredMulti                 1                  0.0 

sysctl -w net.core.rmem_default=$((2**31-1))を設定し
DNS パケットが欠落する状況を用意してからdig www.google.comしたdropwatchの結果です。

# dropwatch -lkas
Initializing kallsyms db
dropwatch> start
Enabling monitoring...
Kernel monitoring activated.
Issue Ctrl-C to stop monitoring
16 drops at netlink_broadcast_filtered+257 (0xffffffffadd8e7c7) [software]
1 drops at udp_queue_rcv_one_skb+391 (0xffffffffaddd7061) [software]
1 drops at udpv6_queue_rcv_one_skb+138 (0xffffffffade4f718) [software]
8 drops at netlink_broadcast_filtered+257 (0xffffffffadd8e7c7) [software]
1 drops at udp_queue_rcv_one_skb+391 (0xffffffffaddd7061) [software]
8 drops at netlink_broadcast_filtered+257 (0xffffffffadd8e7c7) [software]
2 drops at udp_queue_rcv_one_skb+391 (0xffffffffaddd7061) [software]
1 drops at udp_queue_rcv_one_skb+391 (0xffffffffaddd7061) [software]
1 drops at __udp4_lib_rcv+ae5 (0xffffffffaddd9185) [software]

^CGot a stop message
dropwatch> exit
Shutting down ...

receive buffer errorsとpacket receive errorsが増加しているのが分かります。

# netstat -su
Udp:
    3 packets received
    0 packets to unknown port received
    6 packet receive errors
    9 packets sent
    6 receive buffer errors
    0 send buffer errors
    IgnoredMulti: 3
UdpLite:
IpExt:
    InBcastPkts: 3
    InOctets: 34027
    OutOctets: 27396
    InBcastOctets: 816
    InNoECTPkts: 223
    InECT0Pkts: 175
# nstat -a |grep -i udp
UdpInDatagrams                  3                  0.0
UdpInErrors                     6                  0.0
UdpOutDatagrams                 9                  0.0
UdpRcvbufErrors                 6                  0.0
UdpIgnoredMulti                 4                  0.0
Udp6InErrors                    1                  0.0
Udp6OutDatagrams                1                  0.0
Udp6RcvbufErrors                1                  0.0

dropwatchの結果から udp_queue_rcv_one_skb() を見てみることにします。https://elixir.bootlin.com/linux/v5.4/source/net/ipv4/udp.c#L1993
udp_queue_rcv_one_skb() の実行結果を確認するために __udp_queue_rcv_skb() 及びラベル csum_error と drop にプローブポイントを設定して
別ターミナルでdig www.google.comしてみます。

$ cat stp0.stp 
#!/usr/bin/stap

probe kernel.statement("udp_queue_rcv_one_skb@net/ipv4/udp.c:2085")
{
  printf ("TIME=%s,ProbePoint=%s,func=%s\n",tz_ctime(gettimeofday_s()), pp(),probefunc())
}

probe kernel.statement("udp_queue_rcv_one_skb@net/ipv4/udp.c:2088")
{
  printf ("TIME=%s,ProbePoint=%s,func=%s\n",tz_ctime(gettimeofday_s()), pp(),probefunc())
}

probe kernel.statement("udp_queue_rcv_one_skb@net/ipv4/udp.c:2090")
{
  printf ("TIME=%s,ProbePoint=%s,func=%s\n",tz_ctime(gettimeofday_s()), pp(),probefunc())
}
$ sudo stap -v ./stp0.stp 
Pass 1: parsed user script and 476 library scripts using 104260virt/90828res/7396shr/83300data kb, in 130usr/30sys/170real ms.
Pass 2: analyzed script: 3 probes, 13 functions, 1 embed, 0 globals using 247624virt/226380res/8432shr/226664data kb, in 1120usr/150sys/1268real ms.
Pass 3: translated to C into "/tmp/stapfN7K19/stap_91e495a5ab0883939c22b5dffb5db63b_8460_src.c" using 247624virt/226716res/8688shr/226664data kb, in 130usr/90sys/214real ms.
Pass 4: compiled C into "stap_91e495a5ab0883939c22b5dffb5db63b_8460.ko" in 4030usr/430sys/4412real ms.
Pass 5: starting run.
TIME=Thu Dec 10 15:18:44 2020 JST,ProbePoint=kernel.statement("udp_queue_rcv_one_skb@/usr/src/linux-stable/net/ipv4/udp.c:2085"),func=udp_queue_rcv_one_skb
TIME=Thu Dec 10 15:18:44 2020 JST,ProbePoint=kernel.statement("udp_queue_rcv_one_skb@/usr/src/linux-stable/net/ipv4/udp.c:2085"),func=udp_queue_rcv_one_skb
TIME=Thu Dec 10 15:18:49 2020 JST,ProbePoint=kernel.statement("udp_queue_rcv_one_skb@/usr/src/linux-stable/net/ipv4/udp.c:2085"),func=udp_queue_rcv_one_skb
TIME=Thu Dec 10 15:18:54 2020 JST,ProbePoint=kernel.statement("udp_queue_rcv_one_skb@/usr/src/linux-stable/net/ipv4/udp.c:2085"),func=udp_queue_rcv_one_skb
^CPass 5: run completed in 10usr/60sys/27537real ms.

こちらの出力から2085行目 : return __udp_queue_rcv_skb() してることがわかりました。
次に1956行目 : __udp_queue_rcv_skb() を確認してみます。https://elixir.bootlin.com/linux/v5.4/source/net/ipv4/udp.c#L1956

確認すると __udp_queue_rcv_skb() は __udp_enqueue_schedule_skb() を呼び出して結果をrcに代入していますので
1446行目 : __udp_enqueue_schedule_skb() のreturnを確認してみます。https://elixir.bootlin.com/linux/v5.4/source/net/ipv4/udp.c#L1446

$ sudo stap -v -e 'probe kernel.function("__udp_enqueue_schedule_skb").return { printf("%s\n", $$return) }'
Pass 1: parsed user script and 476 library scripts using 104260virt/90888res/7456shr/83300data kb, in 150usr/30sys/171real ms.
Pass 2: analyzed script: 1 probe, 1 function, 0 embeds, 0 globals using 172580virt/159936res/8580shr/151620data kb, in 830usr/210sys/1092real ms.
Pass 3: translated to C into "/tmp/stapsiCjUW/stap_460d03025583944fff84ca26db9eda2b_1217_src.c" using 172580virt/160064res/8708shr/151620data kb, in 30usr/70sys/99real ms.
Pass 4: compiled C into "stap_460d03025583944fff84ca26db9eda2b_1217.ko" in 2090usr/500sys/2536real ms.
Pass 5: starting run.
return=0xfffffffffffffff4
return=0xfffffffffffffff4
return=0xfffffffffffffff4
return=0xfffffffffffffff4
return=0xfffffffffffffff4

0xfffffffffffffff4を返しているので-ENOMEMのようです。

1446行目 : __udp_enqueue_schedule_skb() を詳しくみて行きます。
この関数にはラベル drop と uncharge_drop がありますので関数を使ってプローブポイントをセットしてみます。

$ sudo stap -L 'kernel.function("__udp_enqueue_schedule_skb").label("*")'
kernel.function("__udp_enqueue_schedule_skb@/usr/src/linux-stable/net/ipv4/udp.c:1510").label("uncharge_drop") $sk:struct sock* $skb:struct sk_buff* $delta:int $err:int $busy:spinlock_t* $size:int
kernel.function("__udp_enqueue_schedule_skb@/usr/src/linux-stable/net/ipv4/udp.c:1513").label("drop") $sk:struct sock* $skb:struct sk_buff* $delta:int $err:int $busy:spinlock_t* $size:int 
$ cat stp1.stp 
#!/usr/bin/env stap

probe kernel.function("__udp_enqueue_schedule_skb").label("drop")
{
  printf("drop: TIME=%s\n", tz_ctime(gettimeofday_s()))
}

probe kernel.function("__udp_enqueue_schedule_skb").label("uncharge_drop")
{
  printf("uncharge_drop: TIME=%s\n", tz_ctime(gettimeofday_s()))
}
$ sudo stap -v ./stp1.stp 
Pass 1: parsed user script and 476 library scripts using 104256virt/90892res/7464shr/83296data kb, in 180usr/20sys/209real ms.
Pass 2: analyzed script: 2 probes, 6 functions, 1 embed, 0 globals using 172576virt/159780res/8388shr/151616data kb, in 860usr/160sys/1013real ms.
Pass 3: translated to C into "/tmp/stapJJI9Hg/stap_279afa261f7ee3edcfb4050fbc405982_5786_src.c" using 172576virt/160100res/8708shr/151616data kb, in 50usr/60sys/115real ms.
Pass 4: compiled C into "stap_279afa261f7ee3edcfb4050fbc405982_5786.ko" in 2160usr/380sys/2493real ms.
Pass 5: starting run.
uncharge_drop: TIME=Tue Dec 15 17:57:38 2020 JST
drop: TIME=Tue Dec 15 17:57:38 2020 JST
uncharge_drop: TIME=Tue Dec 15 17:57:38 2020 JST
drop: TIME=Tue Dec 15 17:57:38 2020 JST
uncharge_drop: TIME=Tue Dec 15 17:57:38 2020 JST
drop: TIME=Tue Dec 15 17:57:38 2020 JST
uncharge_drop: TIME=Tue Dec 15 17:57:43 2020 JST
drop: TIME=Tue Dec 15 17:57:43 2020 JST
uncharge_drop: TIME=Tue Dec 15 17:57:48 2020 JST
drop: TIME=Tue Dec 15 17:57:48 2020 JST

uncharge_drop -> drop の順に実行されているのが分かりました。

uncharge_drop にジャンプする条件は以下になります。

1456 rmem = atomic_add_return(size, &sk->sk_rmem_alloc);
1457 if (rmem > (size + sk->sk_rcvbuf))
1458         goto uncharge_drop;

rmem の値と (size + sk->sk_rcvbuf) の値を確認します。

$ cat stp2.stp 
%{
#include <net/sock.h>
#include <asm/atomic.h>
%}

function get_rmem:long(sk:long, skb:long)
%{
    int rmem, size;
    struct sock *sk = (struct sock *)((long)STAP_ARG_sk);
    struct sk_buff *skb = (struct sk_buff *)((long)STAP_ARG_skb);
    size = skb->truesize; 
    rmem = atomic_add_return(size, &sk->sk_rmem_alloc);
    STAP_RETVALUE = rmem;
%}

function calc:long(sk:long, skb:long)
%{
    int size, total;
    struct sock *sk = (struct sock *)((long)STAP_ARG_sk);
    struct sk_buff *skb = (struct sk_buff *)((long)STAP_ARG_skb);
    size = skb->truesize;
    STAP_RETVALUE = size + sk->sk_rcvbuf;
%}

probe kernel.statement("__udp_enqueue_schedule_skb")
{
    printf("rmem=%d total=%d\n", get_rmem($sk, $skb), calc($sk, $skb))
}
$ sudo stap -v -g ./stp2.stp 
Pass 1: parsed user script and 476 library scripts using 104260virt/90880res/7448shr/83300data kb, in 130usr/40sys/178real ms.
Pass 2: analyzed script: 1 probe, 4 functions, 1 embed, 0 globals using 176940virt/164372res/8624shr/155980data kb, in 890usr/100sys/985real ms.
Pass 3: translated to C into "/tmp/stap0FmEiy/stap_424f4d030d8e4bcc70ca1d070427c068_2061_src.c" using 176940virt/164500res/8752shr/155980data kb, in 30usr/70sys/107real ms.
Pass 4: compiled C into "stap_424f4d030d8e4bcc70ca1d070427c068_2061.ko" in 2210usr/360sys/2513real ms.
Pass 5: starting run.
rmem=768 total=-2147482881
rmem=768 total=-2147482881
rmem=768 total=-2147482881
rmem=1536 total=-2147482881
rmem=2304 total=-2147482881
^CPass 5: run completed in 30usr/60sys/45548real ms.

size + sk->sk_rcvbufの計算結果が-2147482881となっているのでオーバーフローしていそうです。
sizeとsk->sk_rcvbufの値をそれぞれ確認してみます。

$ cat stp3.stp 
%{
#include <net/sock.h>
#include <asm/atomic.h>
%}

function get_rmem:long(sk:long, skb:long)
%{
    int rmem, size;
    struct sock *sk = (struct sock *)((long)STAP_ARG_sk);
    struct sk_buff *skb = (struct sk_buff *)((long)STAP_ARG_skb);
    size = skb->truesize; 
    rmem = atomic_add_return(size, &sk->sk_rmem_alloc);
    STAP_RETVALUE = rmem;
%}

function calc:long(sk:long, skb:long)
%{
    int size, total;
    struct sock *sk = (struct sock *)((long)STAP_ARG_sk);
    struct sk_buff *skb = (struct sk_buff *)((long)STAP_ARG_skb);
    size = skb->truesize;;
    STAP_RETVALUE = size + sk->sk_rcvbuf;
%}

function get_size:long(sk:long, skb:long)
%{
    struct sock *sk = (struct sock *)((long)STAP_ARG_sk);
    struct sk_buff *skb = (struct sk_buff *)((long)STAP_ARG_skb);
    STAP_RETVALUE = skb->truesize;
%}

probe kernel.statement("__udp_enqueue_schedule_skb")
{
    printf("rmem=%d %d=%d+%d\n", get_rmem($sk, $skb), calc($sk, $skb), get_size($sk, $skb), $sk->sk_rcvbuf)
}
$ sudo stap -g -v ./stp3.stp 
Pass 1: parsed user script and 476 library scripts using 104264virt/90936res/7504shr/83304data kb, in 170usr/20sys/185real ms.
Pass 2: analyzed script: 1 probe, 6 functions, 1 embed, 0 globals using 176948virt/164364res/8608shr/155988data kb, in 870usr/130sys/999real ms.
Pass 3: using cached /root/.systemtap/cache/2b/stap_2b032db9bfd3b47319c8ecdca4d96dda_2476.c
Pass 4: using cached /root/.systemtap/cache/2b/stap_2b032db9bfd3b47319c8ecdca4d96dda_2476.ko
Pass 5: starting run.
rmem=768 -2147482881=768+2147483647
rmem=768 -2147482881=768+2147483647
rmem=768 -2147482881=768+2147483647
rmem=1536 -2147482881=768+2147483647
rmem=2304 -2147482881=768+2147483647
^CPass 5: run completed in 20usr/50sys/22017real ms.

sizeとsk->sk_rcvbuf は int なので整数オーバーフローが起き計算結果が -2147482881 となりDNS パケット欠落の原因がオーバーフローによるものであることが確認できました。

まとめ

SystemTapの学習のためGoogle Cloudのサポートブログを参考にスクリプトを作成しながら カーネルの動作を追ってみました。

  • ソースコードを変更しなくても良いので敷居は低そうです。
  • printkデバッグのようにカーネルを再構築をする必要がないので時間の節減になります。
  • 大変有益な記事を公開してくれたGoogle Cloudさんありがとう。

参考にさせてもらいました。

Linuxカーネルのデバッグでprintk(9)デバッグを卒業したいっ! - φ(・・*)ゞ ウーン カーネルとか弄ったりのメモ

第585回 SystemTapを活用してネットワークの動作を確認する:Ubuntu Weekly Recipe|gihyo.jp … 技術評論社

SystemTapの使い方 - Qiita

linuxのrootをSSHの証明書認証を使って共有し CERT IDで個々のユーザーを識別する

Linuxのユーザーの管理で何かより良い方法がないかと検索していたら Scalable and secure access with SSH - Facebook CodeSSHの証明書認証を使った方法が紹介されていたので検証してみました。


上記の記事をざっくりまとめると
  1. rootを共通アカウントとして使用する
  2. 証明書認証のCERT IDを使用し個々のユーザーを識別する
  3. ログは全て集約しているので簡単に分析できる
  4. AuthorizedPrincipalsFileを使ってアクセス制御を行う
    といった感じでしょうか。

証明書認証には以下の理由からHashicorpのVaultを使ってみることにしました。
  1. 署名に必要な秘密鍵を公開しなくて済むので、ユーザーに公開鍵への署名を任せられます。
  2. ldap auth methodを使いActive Directoryに認証を任せると、token_display_name(今回の場合はldap-usernameという形式)がCERT IDにセットされるようになり、ユーザーがCERT IDを変更することが出来なくなります。
  3. Policyで証明書発行時に必要なroleへのアクセスを制限可能になります。

以下を参考に環境を構築しておきます。

Signed SSH Certificates - SSH - Secrets Engines - Vault by HashiCorp

LDAP - Auth Methods - Vault by HashiCorp


ttlの変更

tokenのttlが長すぎなので短くしておきます。

[root@localhost ~]# vault read sys/auth/ldap/tune
Key                  Value
---                  -----
default_lease_ttl    768h
force_no_cache       false
max_lease_ttl        768h
token_type           default-service
[root@localhost ~]# vault write sys/auth/ldap/tune default_lease_ttl=10m max_lease_ttl=30m
Success! Data written to: sys/auth/ldap/tune
[root@localhost ~]# vault read sys/auth/ldap/tune
Key                  Value
---                  -----
default_lease_ttl    10m
force_no_cache       false
max_lease_ttl        30m
token_type           default-service
[root@localhost ~]#

roleの作成

rootというロールを作成し登録します。allow_user_key_idsをtrueにするとCERT IDをユーザーが更新できてしまうのでfalseにしておきます。
allow_usersにはリモートログイン先のユーザー名を指定します。defaultのままだと"*"となりリモートからログイン可能なユーザー全てを指定出来てしまうので注意が必要です。
有効期限は1時間としました。

[root@localhost ~]# vault write ssh-client-signer/roles/root -<<"EOH"
  {
     "allow_user_certificates": true,
     "allow_user_key_ids": "false",
     "allowed_users": "root",
     "default_extensions": [
      {
         "permit-pty": ""
       }
     ],
     "key_type": "ca",
     "default_user": "root",
     "ttl": "1h"
   }
EOH
Success! Data written to: ssh-client-signer/roles/root
[root@localhost vault.d]# vault read ssh-client-signer/roles/root
Key                         Value
---                         -----
allow_bare_domains          false
allow_host_certificates     false
allow_subdomains            false
allow_user_certificates     true
allow_user_key_ids          false
allowed_critical_options    n/a
allowed_domains             n/a
allowed_extensions          n/a
allowed_users               root
default_critical_options    map[]
default_extensions          map[permit-pty:]
default_user                root
key_bits                    0
key_id_format               n/a
key_type                    ca
max_ttl                     0s
ttl                         1h
[root@localhost vault.d]# 

ポリシーの割り当て

上で作成したロールに対するポリシーを設定し、Active Directoryのmnishikizawaユーザーにポリシーを割り当てます。

[root@localhost ~]# vault policy write ssh-user-root -<<"EOH"
> path "ssh-client-signer/sign/root"
> {
>   capabilities = ["update"]
> }
> EOH
Success! Uploaded policy: ssh-user-root
[root@localhost vault.d]# vault policy read ssh-user-root
# Write ssh certificates
path "ssh-client-signer/sign/root"
{
  capabilities = ["update"]
}
[root@localhost vault.d]# vault write auth/ldap/users/mnishikizawa policies=ssh-user-root
Success! Data written to: auth/ldap/users/mnishikizawa
[root@localhost vault.d]# vault read auth/ldap/users/mnishikizawa
Key         Value
---         -----
groups      n/a
policies    [ssh-user-root]

証明書の発行

Active Directoryで認証を行い証明書を発行してからrootでSSHログインしてみます。

[vagrant@localhost ~]$ vault login -method=ldap username=mnishikizawa
Password (will be hidden):
Success! You are now authenticated. The token information displayed below
is already stored in the token helper. You do NOT need to run "vault login"
again. Future Vault requests will automatically use this token.

Key                    Value
---                    -----
token                  s.n0SrSqKIK5LxXyg3eGkCrxX6
token_accessor         WzMbzaSQGrD0MRjoKceF0fEO
token_duration         10m
token_renewable        true
token_policies         ["default" "ssh-user-root"]
identity_policies      []
policies               ["default" "ssh-user-root"]
token_meta_username    mnishikizawa
[vagrant@localhost ~]$ vault token lookup
Key                 Value
---                 -----
accessor            WzMbzaSQGrD0MRjoKceF0fEO
creation_time       1549593890
creation_ttl        10m
display_name        ldap-mnishikizawa
entity_id           935ade7e-d2f6-5cc1-9e27-6490a7f38441
expire_time         2019-02-08T02:54:50.066232798Z
explicit_max_ttl    0s
id                  s.n0SrSqKIK5LxXyg3eGkCrxX6
issue_time          2019-02-08T02:44:50.066232489Z
meta                map[username:mnishikizawa]
num_uses            0
orphan              true
path                auth/ldap/login/mnishikizawa
policies            [default ssh-user-root]
renewable           true
ttl                 9m58s
type                service
[vagrant@localhost ~]$ vault write -field=signed_key ssh-client-signer/sign/root public_key=@$HOME/.ssh/id_rsa.pub > ~/.ssh/id_rsa-cert.pub
[vagrant@localhost ~]$ ssh-keygen -Lf .ssh/id_rsa-cert.pub
.ssh/id_rsa-cert.pub:
        Type: ssh-rsa-cert-v01@openssh.com user certificate
        Public key: RSA-CERT SHA256:3c7XiI1ULfNbrCqk1icCG0KtuEeew4bBbi1I6gO5mSM
        Signing CA: RSA SHA256:4LJnUxaq/OiEIRd1TuEjEhyoV/J73Daep/VNVaQMmvc
        Key ID: "vault-ldap-mnishikizawa-ddced7888d542df35bac2aa4d627021b42adb8479ec386c16e2d48ea03b99923"
        Serial: 2420534201198412456
        Valid: from 2019-02-20T01:33:06 to 2019-02-20T02:33:36
        Principals:
                root
        Critical Options: (none)
        Extensions:
                permit-pty
[vagrant@localhost ~]$ ssh root@localhost
Last login: Wed Feb 20 01:34:35 2019
[root@localhost ~]# tail /var/log/secure
Feb 20 01:34:48 localhost sshd[9396]: Accepted publickey for root from ::1 port 47374 ssh2: RSA-CERT ID vault-ldap-mnishikizawa-ddced7888d542df35bac2aa4d627021b42adb8479ec386c16e2d48ea03b99923 (serial 2420534201198412456) CA RSA SHA256:4LJnUxaq/OiEIRd1TuEjEhyoV/J73Daep/VNVaQMmvc

secureログには
RSA-CERT ID vault-ldap-mnishikizawa-xxxxxx
が記録されrootを共有アカウントとしても個々のユーザーを識別できそうです。


principalsを使ったアクセス制限

AuthorizedPrincipalsFileを使って、設定されたprincipalのみアクセス可能なのか確認してみます。

SSH - Secrets Engines - HTTP API - Vault by HashiCorp

・ default_user (string: "")
For the CA type, if you wish this to be a valid principal, it must also be in allowed_users.

この説明通りdefault_userとallowed_usersに同じ値を設定します。

[root@localhost ~]# vault write ssh-client-signer/roles/root -<<"EOH"
> {
>      "allow_user_certificates": true,
>       "allow_user_key_ids": "false",
>       "allowed_users": "root,zone-webservers,zone-databases",
>       "default_extensions": [
>        {
>           "permit-pty": ""
>         }
>       ],
>       "key_type": "ca",
>       "default_user": "root,zone-webservers,zone-databases",
>       "ttl": "1h"
>     }
> EOH
Success! Data written to: ssh-client-signer/roles/root
[root@localhost ~]# vault read ssh-client-signer/roles/root
Key                         Value
---                         -----
allow_bare_domains          false
allow_host_certificates     false
allow_subdomains            false
allow_user_certificates     true
allow_user_key_ids          false
allowed_critical_options    n/a
allowed_domains             n/a
allowed_extensions          n/a
allowed_users               root,zone-webservers,zone-databases
default_critical_options    map[]
default_extensions          map[permit-pty:]
default_user                root,zone-webservers,zone-databases
key_bits                    0
key_id_format               n/a
key_type                    ca
max_ttl                     0s
ttl                         1h
[root@localhost ~]#

principalsがある場合とない場合
[vagrant@localhost ~]$ ssh-keygen -Lf .ssh/id_rsa-cert.pub
.ssh/id_rsa-cert.pub:
        Type: ssh-rsa-cert-v01@openssh.com user certificate
        Public key: RSA-CERT SHA256:3c7XiI1ULfNbrCqk1icCG0KtuEeew4bBbi1I6gO5mSM
        Signing CA: RSA SHA256:4LJnUxaq/OiEIRd1TuEjEhyoV/J73Daep/VNVaQMmvc
        Key ID: "vault-ldap-mnishikizawa-ddced7888d542df35bac2aa4d627021b42adb8479ec386c16e2d48ea03b99923"
        Serial: 13444262937296389838
        Valid: from 2019-02-20T05:16:42 to 2019-02-20T06:17:12
        Principals:
                root
                zone-databases
                zone-webservers
        Critical Options: (none)
        Extensions:
                permit-pty
[vagrant@localhost ~]$ sudo cat /etc/ssh/auth_principals/root
zone-webservers
zone-databases
[vagrant@localhost ~]$ ssh root@localhost
Last login: Wed Feb 20 05:31:38 2019 from ::1
[root@localhost ~]# tail /var/log/secure
Feb 20 05:32:33 localhost sshd[11072]: Accepted publickey for root from ::1 port 47498 
ssh2: RSA-CERT ID vault-ldap-mnishikizawa-ddced7888d542df35bac2aa4d627021b42adb8479ec386c16e2d48ea03b99923 (serial 13444262937296389838) CA RSA SHA256:4LJnUxaq/OiEIRd1TuEjEhyoV/J73Daep/VNVaQMmvc
[root@localhost ~]# logout
Connection to localhost closed.
[vagrant@localhost ~]$ sudo cat /etc/ssh/auth_principals/root
root-everywhere
[vagrant@localhost ~]$ ssh root@localhost
no such identity: /home/vagrant/.ssh/id_ed25519: No such file or directory
Permission denied (publickey,gssapi-keyex,gssapi-with-mic).
[vagrant@localhost ~]$ sudo tail /var/log/secure
Feb 20 05:33:38 localhost sshd[11135]: error: Certificate does not contain an authorized principal
Feb 20 05:33:38 localhost sshd[11135]: Connection closed by ::1 port 47500 [preauth]
[vagrant@localhost ~]$

期待通りの動作ですがzone-webservers,zone-databasesというユーザーが存在した場合、そのユーザーでログインできてしまうのが残念です。


まとめ
  • SSHアカウントを共有してもCERT IDで個々のユーザーを識別できる。
  • ユーザーをサーバー毎に個別に作成しなくてすむ。
  • secureログ、auditログの分析基盤があればアカウントを共有しても個々のユーザーのログイン情報を分析可能となり運用も楽になると思う。

参考

SSH - Secrets Engines - HTTP API - Vault by HashiCorp

OpenSSHの認証に証明書を使う方法|ConoHa VPSサポート

VaultのPolicyを使った運用 - Carpe Diem

listen()のbacklogの設定値、キューの数値を確認する

Apacheのポートベースのバーチャルホストで特定のホストだけ死活監視が失敗する事がありました。 ssコマンドで表示されるRecv-Qがbacklogのキューの数値だと思っていたのですが ss(8) - Linux manual pageを見ても不確かだったのでソースを確認したいと思います。

以下、対象サーバーの5秒間隔のss -intlコマンドの出力結果になります。

State      Recv-Q Send-Q        Local Address:Port          Peer Address:Port
LISTEN     0      128                       *:30443                    *:*
LISTEN     38     128                       *:10443                    *:*
LISTEN     0      128                       *:40443                    *:*
LISTEN     0      128                       *:20443                    *:*

State      Recv-Q Send-Q        Local Address:Port          Peer Address:Port
LISTEN     0      128                       *:30443                    *:*
LISTEN     127    128                       *:10443                    *:*
LISTEN     0      128                       *:40443                    *:*
LISTEN     0      128                       *:20443                    *:*

State      Recv-Q Send-Q        Local Address:Port          Peer Address:Port
LISTEN     0      128                       *:30443                    *:*
LISTEN     129    128                       *:10443                    *:*
LISTEN     0      128                       *:40443                    *:*
LISTEN     0      128                       *:20443                    *:*

State      Recv-Q Send-Q        Local Address:Port          Peer Address:Port
LISTEN     0      128                       *:30443                    *:*
LISTEN     129    128                       *:10443                    *:*
LISTEN     0      128                       *:40443                    *:*
LISTEN     0      128                       *:20443                    *:*

State      Recv-Q Send-Q        Local Address:Port          Peer Address:Port
LISTEN     0      128                       *:30443                    *:*
LISTEN     126    128                       *:10443                    *:*
LISTEN     0      128                       *:40443                    *:*
LISTEN     0      128                       *:20443                    *:*

10443ポートでListenしているRecv-Qが最大で(Send-Q)+1まで増加しています。
このRecv-QとSend-Qの値が何を指しているのか確認します。
ss.cのsock_state_print()が出力しています。

  • iproute2-4.11.0/misc/ss.c
 793 static void sock_state_print(struct sockstat *s)
 794 {
 795   const char *sock_name;
 796   static const char * const sstate_name[] = {
 797     "UNKNOWN",
 798     [SS_ESTABLISHED] = "ESTAB",
 799     [SS_SYN_SENT] = "SYN-SENT",
 800     [SS_SYN_RECV] = "SYN-RECV",
 801     [SS_FIN_WAIT1] = "FIN-WAIT-1",
 802     [SS_FIN_WAIT2] = "FIN-WAIT-2",
 803     [SS_TIME_WAIT] = "TIME-WAIT",
 804     [SS_CLOSE] = "UNCONN",
 805     [SS_CLOSE_WAIT] = "CLOSE-WAIT",
 806     [SS_LAST_ACK] = "LAST-ACK",
 807     [SS_LISTEN] = "LISTEN",
 808     [SS_CLOSING] = "CLOSING",
 809   };
 810
 811   switch (s->local.family) {
 812   case AF_UNIX:
 813     sock_name = unix_netid_name(s->type);
 814     break;
 815   case AF_INET:
 816   case AF_INET6:
 817     sock_name = proto_name(s->type);
 818     break;
 819   case AF_PACKET:
 820     sock_name = s->type == SOCK_RAW ? "p_raw" : "p_dgr";
 821     break;
 822   case AF_NETLINK:
 823     sock_name = "nl";
 824     break;
 825   default:
 826     sock_name = "unknown";
 827   }
 828
 829   if (netid_width)
 830     printf("%-*s ", netid_width,
 831            is_sctp_assoc(s, sock_name) ? "" : sock_name);
 832   if (state_width) {
 833     if (is_sctp_assoc(s, sock_name))
 834       printf("`- %-*s ", state_width - 3,
 835              sctp_sstate_name[s->state]);
 836     else
 837       printf("%-*s ", state_width, sstate_name[s->state]);
 838   }
 839
 840   printf("%-6d %-6d ", s->rq, s->wq);
 841 }

s->rqとs->wqには、parse_diag_msg()によってidiag_rqueueとidiag_wqueueの値がそれぞれ入ります。

2343 static void parse_diag_msg(struct nlmsghdr *nlh, struct sockstat *s)
2344 {
2345   struct rtattr *tb[INET_DIAG_MAX+1];
2346   struct inet_diag_msg *r = NLMSG_DATA(nlh);
2347
2348   parse_rtattr(tb, INET_DIAG_MAX, (struct rtattr *)(r+1),
2349          nlh->nlmsg_len - NLMSG_LENGTH(sizeof(*r)));
2350
2351   s->state  = r->idiag_state;
2352   s->local.family = s->remote.family = r->idiag_family;
2353   s->lport  = ntohs(r->id.idiag_sport);
2354   s->rport  = ntohs(r->id.idiag_dport);
2355   s->wq   = r->idiag_wqueue;
2356   s->rq   = r->idiag_rqueue;
2357   s->ino    = r->idiag_inode;
2358   s->uid    = r->idiag_uid;
2359   s->iface  = r->id.idiag_if;
2360   s->sk   = cookie_sk_get(&r->id.idiag_cookie[0]);
2361
2362   s->mark = 0;
2363   if (tb[INET_DIAG_MARK])
2364     s->mark = rta_getattr_u32(tb[INET_DIAG_MARK]);
2365   if (tb[INET_DIAG_PROTOCOL])
2366     s->raw_prot = rta_getattr_u8(tb[INET_DIAG_PROTOCOL]);
2367   else
2368     s->raw_prot = 0;
2369
2370   if (s->local.family == AF_INET)
2371     s->local.bytelen = s->remote.bytelen = 4;
2372   else
2373     s->local.bytelen = s->remote.bytelen = 16;
2374
2375   memcpy(s->local.data, r->id.idiag_src, s->local.bytelen);
2376   memcpy(s->remote.data, r->id.idiag_dst, s->local.bytelen);
2377 }

それぞれの値の意味はman(7)sock_diagによると
http://man7.org/linux/man-pages/man7/sock_diag.7.html  

idiag_rqueue
For listening sockets: the number of pending connections.
For other sockets: the amount of data in the incoming queue.

idiag_wqueue
For listening sockets: the backlog length.
For other sockets: the amount of memory available for sending.

idiag_rqueue (Recv-Q)は、accept()を待っているキューの数
idiag_wqueue (Send-Q)は、backlogのサイズ
という事なので期待していた数値で間違いなさそうです。

backlogが溢れた時の動作については、How TCP backlog works in Linuxに詳しく解説されてますが
1. LINUX_MIB_LISTENOVERFLOWS, LINUX_MIB_LISTENDROPSのカウンタをインクリメントしtcp_abort_on_overflow = 0だった場合何もしない。
2. ACK, SYNをdropする
となります。

カウンタの値は以下のコマンドで確認できます。

$ nstat -s |grep -i listen
TcpExtListenOverflows           32449              0.0
TcpExtListenDrops               32449              0.0
$ nstat -s TcpExtListenOverflows
#kernel
TcpExtListenOverflows           32449              0.0
[mnishikizawa@web01 ~ RADIAN-MUSASHI]$ nstat -s TcpExtListenDrops
#kernel
TcpExtListenDrops               32449              0.0
[mnishikizawa@web01 ~ RADIAN-MUSASHI]$

死活監視の失敗原因は、backlog溢れによるtimeoutで間違いなさそうなので今回はsomaxconnを増やして対応することにしました。

linuxのtcp_rmemの変更は何に影響するのか調べたのでメモっておく

大容量なファイル送信にかかる時間を短縮する為に色々調べていたら sysctlで送受信用ウィンドウ・サイズの最大値を変更するようアドバイスするサイトが多かったので 変更によって何が影響するのか調べてみた。

tcp_select_initial_window()のif (wscale_ok)の辺りが関係しそう。

#define TCP_MAX_WSCALE          14U
 191 void tcp_select_initial_window(const struct sock *sk, int __space, __u32 mss,
 192              __u32 *rcv_wnd, __u32 *window_clamp,
 193              int wscale_ok, __u8 *rcv_wscale,
 194              __u32 init_rcv_wnd)
 195 {
 196   unsigned int space = (__space < 0 ? 0 : __space);
 197
 198   /* If no clamp set the clamp to the max possible scaled window */
 199   if (*window_clamp == 0)
 200     (*window_clamp) = (U16_MAX << TCP_MAX_WSCALE);
 201   space = min(*window_clamp, space);
 202
 203   /* Quantize space offering to a multiple of mss if possible. */
 204   if (space > mss)
 205     space = rounddown(space, mss);
 206
 207   /* NOTE: offering an initial window larger than 32767
 208    * will break some buggy TCP stacks. If the admin tells us
 209    * it is likely we could be speaking with such a buggy stack
 210    * we will truncate our initial window offering to 32K-1
 211    * unless the remote has sent us a window scaling option,
 212    * which we interpret as a sign the remote TCP is not
 213    * misinterpreting the window field as a signed quantity.
 214    */
 215   if (sock_net(sk)->ipv4.sysctl_tcp_workaround_signed_windows)
 216     (*rcv_wnd) = min(space, MAX_TCP_WINDOW);
 217   else
 218     (*rcv_wnd) = space;
 219
 220   (*rcv_wscale) = 0;
 221   if (wscale_ok) {
 222     /* Set window scaling on max possible window */
 223     space = max_t(u32, space, sock_net(sk)->ipv4.sysctl_tcp_rmem[2]);
 224     space = max_t(u32, space, sysctl_rmem_max);
 225     space = min_t(u32, space, *window_clamp);
 226     while (space > U16_MAX && (*rcv_wscale) < TCP_MAX_WSCALE) {
 227       space >>= 1;
 228       (*rcv_wscale)++;
 229     }
 230   }
 231
 232   if (mss > (1 << *rcv_wscale)) {
 233     if (!init_rcv_wnd) /* Use default unless specified otherwise */
 234       init_rcv_wnd = tcp_default_init_rwnd(mss);
 235     *rcv_wnd = min(*rcv_wnd, init_rcv_wnd * mss);
 236   }
 237
 238   /* Set the clamp no higher than max representable value */
 239   (*window_clamp) = min_t(__u32, U16_MAX << (*rcv_wscale), *window_clamp);
 240 }
 241 EXPORT_SYMBOL(tcp_select_initial_window);

TCP window scale オプションが有効だった場合、tcp_rmemの設定値に応じて 最大値14のTCP window scale の値が変更になる。

TCP window scale 値は3 Way ハンドシェイク時に通知され、Wireshark等で確認できる。
この画像ではWindow scale: 6
tcp_rmemの値を増やすと、このWindow scaleが最大14まで上昇する。 f:id:nishitki:20180921112833p:plain

ssコマンドなんかでも確認できて、下の画像の wscale:5,6がそれ。
tcp_rmemが3839488だった場合のWindow scale値は6で、通信相手のWindow scale値が5。 f:id:nishitki:20180921123328p:plain

tcp_rmemを増やすことによって、レイテンシーに影響する場合もあるようなので注意が必要ですね。 The story of one latency spike

dbus-daemonのCPU使用率が高いので調べました

dbus-daemonのCPU使用率が高いので調査依頼を受けました。
何はともあれトレースして見ます。
straceの出番です。

$ sudo strace -o dbus.log -ttf -s 512 -p `pidof dbus-daemon`
712   10:58:37.914418 fcntl(-1, F_GETFD) = -1 EBADF (Bad file descriptor)
712   10:58:37.914546 epoll_wait(4, [{EPOLLIN, {u32=3, u64=5298502605327040515}}], 64, -1) = 1
712   10:58:37.914623 accept4(3, 0x7ffd7c185110, 0x7ffd7c18510c, SOCK_CLOEXEC) = -1 EMFILE (Too many open files)
712   10:58:37.914693 fcntl(-1, F_GETFD) = -1 EBADF (Bad file descriptor)
712   10:58:37.914751 epoll_wait(4, [{EPOLLIN, {u32=3, u64=5298502605327040515}}], 64, -1) = 1
712   10:58:37.914812 accept4(3, 0x7ffd7c185110, 0x7ffd7c18510c, SOCK_CLOEXEC) = -1 EMFILE (Too many open files)
712   10:58:37.914871 fcntl(-1, F_GETFD) = -1 EBADF (Bad file descriptor)
712   10:58:37.914928 epoll_wait(4, [{EPOLLIN, {u32=3, u64=5298502605327040515}}], 64, -1) = 1
712   10:58:37.914987 accept4(3, 0x7ffd7c185110, 0x7ffd7c18510c, SOCK_CLOEXEC) = -1 EMFILE (Too many open files)
712   10:58:37.915046 fcntl(-1, F_GETFD) = -1 EBADF (Bad file descriptor)
712   10:58:37.915096 epoll_wait(4, [{EPOLLIN, {u32=3, u64=5298502605327040515}}], 64, -1) = 1
712   10:58:37.915156 accept4(3, 0x7ffd7c185110, 0x7ffd7c18510c, SOCK_CLOEXEC) = -1 EMFILE (Too many open files)
712   10:58:37.915217 fcntl(-1, F_GETFD) = -1 EBADF (Bad file descriptor)
712   10:58:37.915276 epoll_wait(4, [{EPOLLIN, {u32=3, u64=5298502605327040515}}], 64, -1) = 1
712   10:58:37.915338 accept4(3, 0x7ffd7c185110, 0x7ffd7c18510c, SOCK_CLOEXEC) = -1 EMFILE (Too many open files)
712   10:58:37.915399 fcntl(-1, F_GETFD) = -1 EBADF (Bad file descriptor)
712   10:58:37.915457 epoll_wait(4, [{EPOLLIN, {u32=3, u64=5298502605327040515}}], 64, -1) = 1
712   10:58:37.915518 accept4(3, 0x7ffd7c185110, 0x7ffd7c18510c, SOCK_CLOEXEC) = -1 EMFILE (Too many open files)
712   10:58:37.915578 fcntl(-1, F_GETFD) = -1 EBADF (Bad file descriptor)

結果はこれ。ディスクリプタリークっぽいような気がします。
ググったら以下がヒット。
[https://bugzilla.redhat.com/show_bug.cgi?id=1325870]
もうすでに修正が入っているみたいでバージョンを上げれば直りそうです。
修正内容を確認してみます。

dbus/dbus - a lightweight ipc mechanism

diff --git a/dbus/dbus-sysdeps-util-unix.c b/dbus/dbus-sysdeps-util-unix.c
index 6cff3fe..bbc3f34 100644
--- a/dbus/dbus-sysdeps-util-unix.c
+++ b/dbus/dbus-sysdeps-util-unix.c
@@ -1144,6 +1144,7 @@ _dbus_command_for_pid (unsigned long  pid,
                       "Failed to read from \"%s\": %s",
                       _dbus_string_get_const_data (&path),
                       _dbus_strerror (errno));      
+      _dbus_close (fd, NULL);
       goto fail;
     }

定期的にアップデートはしないといけませんね。
気をつけます。

kworkerのCPU使用率が高すぎるのでなんとかした

題名の通りkworkerのCPU使用率が高いのをなんとかした記録。OSはCentOS 7.2

ぐぐってみたところ

Linuxで一つのコアのCPU利用率が異様に高いのを何とかする - Qiita

ubuntuでkworkerのcpu使用率がやたら高い - Qiita

ヒットするが、こちらの環境とはマッチしないみたい。

覚えたてのperfを使ってみます。

Samples: 44K of event 'cycles', Event count (approx.): 40358935514
  Children      Self  Command         Shared Object             Symbol
+   70.47%     0.00%  kworker/2:2     [kernel.kallsyms]         [k] kthread
+   70.47%     0.00%  kworker/2:2     [kernel.kallsyms]         [k] ret_from_fork
+   70.47%     0.00%  kworker/2:2     [kernel.kallsyms]         [k] worker_thread
+   70.44%     0.07%  kworker/2:2     [kernel.kallsyms]         [k] process_one_work
+   69.37%     0.05%  kworker/2:2     [kernel.kallsyms]         [k] rpm_idle
+   69.09%     0.08%  kworker/2:2     [kernel.kallsyms]         [k] rpm_suspend
+   68.98%     0.03%  kworker/2:2     [kernel.kallsyms]         [k] pm_runtime_work
+   68.83%     0.04%  kworker/2:2     [kernel.kallsyms]         [k] __rpm_callback
+   68.78%     0.01%  kworker/2:2     [kernel.kallsyms]         [k] usb_runtime_idle
+   68.74%     0.01%  kworker/2:2     [kernel.kallsyms]         [k] __pm_runtime_suspend
+   68.54%     0.00%  kworker/2:2     [kernel.kallsyms]         [k] rpm_callback
+   68.49%     0.01%  kworker/2:2     [kernel.kallsyms]         [k] usb_runtime_suspend
+   68.46%     0.03%  kworker/2:2     [kernel.kallsyms]         [k] usb_suspend_both
+   66.53%     0.01%  kworker/2:2     [kernel.kallsyms]         [k] usb_resume_interface.isra.5
+   66.53%     0.01%  kworker/2:2     [kernel.kallsyms]         [k] hub_resume
+   66.49%     0.42%  kworker/2:2     [kernel.kallsyms]         [k] hub_activate
+   65.50%     0.28%  kworker/2:2     [kernel.kallsyms]         [k] hub_port_status
+   64.32%     0.28%  kworker/2:2     [kernel.kallsyms]         [k] usb_control_msg
+   61.81%     0.22%  kworker/2:2     [kernel.kallsyms]         [k] usb_start_wait_urb
+   56.04%     0.07%  kworker/2:2     [kernel.kallsyms]         [k] usb_submit_urb
+   55.97%     0.54%  kworker/2:2     [kernel.kallsyms]         [k] usb_submit_urb.part.5
+   54.46%     1.71%  kworker/2:2     [kernel.kallsyms]         [k] usb_hcd_submit_urb
+   40.82%    39.99%  kworker/2:2     [kernel.kallsyms]         [k] xhci_hub_control
+   16.33%     0.00%  ksoftirqd/2     [kernel.kallsyms]         [k] kthread
+   16.33%     0.00%  ksoftirqd/2     [kernel.kallsyms]         [k] ret_from_fork
+   15.88%     1.32%  ksoftirqd/2     [kernel.kallsyms]         [k] smpboot_thread_fn

xHCIが悪さをしているようです。

USBをリセットしてみます。

[Reset USB 2.0 (ehci) & USB 3.0 (xhci) Without Reboot in Linux Kernel] (http://www.ubuntubuzz.com/2016/06/reset-usb-20-ehci-usb-30-xhci-without-reboot-linux.html)

使用率が低くなりました。よかったね。

標準入力からの入力に対応していないコマンドを何とかしたいんだ

  • 例えばssh-keygen -lf ~/.ssh/authorized_keysでフィンガープリントを確認したいんだけど ssh-keygen -lfは、標準入力からの入力に対応してない。 /dev/stdinを使えば何とかなるらしい。

  • Serverspecでこんなことしたかったけど/dev/stdin使ったらできた。

describe command(%|ssh-keygen -lf /dev/stdin <<<"$(grep hogehoge /home/hogehoge/.ssh/authorized_keys)"|) do
  its(:stdout) { should contain('1a:2b:3c:4d:5e:6f:7g:8h:9i:10:11:12:13:14:15:16').after(/2048/) }
end