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 … 技術評論社
linuxのrootをSSHの証明書認証を使って共有し CERT IDで個々のユーザーを識別する
Linuxのユーザーの管理で何かより良い方法がないかと検索していたら Scalable and secure access with SSH - Facebook CodeでSSHの証明書認証を使った方法が紹介されていたので検証してみました。
上記の記事をざっくりまとめると
- rootを共通アカウントとして使用する
- 証明書認証のCERT IDを使用し個々のユーザーを識別する
- ログは全て集約しているので簡単に分析できる
- AuthorizedPrincipalsFileを使ってアクセス制御を行う
といった感じでしょうか。
証明書認証には以下の理由からHashicorpのVaultを使ってみることにしました。
- 署名に必要な秘密鍵を公開しなくて済むので、ユーザーに公開鍵への署名を任せられます。
- ldap auth methodを使いActive Directoryに認証を任せると、token_display_name(今回の場合はldap-usernameという形式)がCERT IDにセットされるようになり、ユーザーがCERT IDを変更することが出来なくなります。
- 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
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まで上昇する。
ssコマンドなんかでも確認できて、下の画像の wscale:5,6がそれ。
tcp_rmemが3839488だった場合のWindow scale値は6で、通信相手のWindow scale値が5。
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
