appendix_bk.tex

%% -*- coding: utf-8-unix -*-

\chapter{テストシナリオ実装時のトラブルとワークアラウンド}
\label{cpt:troubles}

ネットワークのテストという観点で実際に発見できた問題点については
\ref{sec:statictest-founded-issues}節でとりあげている。本章では、テスト
シナリオ実装の際におきた問題点やワークアラウンドについて解説する。こうし
たワークアラウンドは、事情や理由がわからないと冗長あるいは不合理にみえる
ことがあるため、理由をふくめたノウハウを共有しておくことは重要である。本
章であげた実際のトラブルシュート事例をもとに、テストシナリオのデバッグを
どう考えるかについては\ref{sec:debugging-test-scenario}節で解説している。

本章では特に、テストを複数回実行すると成功・失敗がくりかえされてテスト結
果が不定になった例を選定している(付録~\ref{sec:ping-probrem}・付
録~\ref{sec:telnet-probrem})。このようなテストは flaky\footnote{flaky
=「当てにならない」} test とも呼ばれ、テストの連続実行(回帰テスト)におい
て問題となる。また、テストシナリオに本来であれば影響しないはずの条件変化
によって、テスト成否結果が変化した事例についてもとりあげた(付
録~\ref{sec:SSG-troubles})。

 \section{初回のping送受信失敗}
 \label{sec:ping-probrem}

    \paragraph{事象}
L3の通信試験(\code{ping}コマンド)で、最初の1パケット(場合によっては数パ
ケット)だけ送受信に失敗する。そのため、テスト実行ごとにコマンド実行結果
(ping packet loss)判定が変化して、テストが成功したり失敗したりする。

    \paragraph{原因と対処}
テスト対象が物理ネットワークであるため、ARP cache 等その時々のネットワー
ク状態による結果のゆらぎが発生してしまう。よく知られたワークアラウンドは、
テスト実行前に予備的なパケット送受信をおこなって、テスト対象ネットワーク
内の状態を更新しておくことである。本プロジェクトでも、
\lstref{lst:ping-workaround}のように ping packet loss 測定前に ping を1
パケット送受信しておく\footnote{本プロジェクトではこれを「捨てping」と呼
んでいる。}ことで回避している~\cite{examples-pr49}。

\begin{lstlisting}[language=,caption=予備的ping実行の例,label=lst:ping-workaround,linebackgroundcolor={\ifnum\value{lstnumber}=3 \color{green!30}\fi}]
When(/^ヨーヨーダイン社内部のユーザ PC に ping$/) do
  cd('.') do
    @src_host.exec "bash -c 'ping #{@user_pc.ip_address} -c 1; exit 0'"
    @src_host.exec "ping #{@user_pc.ip_address} -c 4 > log/ping.log"
  end
end
\end{lstlisting}

 \section{Netcat/telnetコマンドのデータ送受信順序}
 \label{sec:telnet-probrem}

    \paragraph{事象}
Telentを使った通信試験において、\lstref{lst:telnet-bk}のようにテストが10
回に1回程度しか成功しない事象が発生した。テストではサーバとして netcat
(\code{nc}コマンド)、クライアントとして\code{telnet} コマンドを使用して
いる(\lstref{lst:telnet-step})。
 
\begin{lstlisting}[caption=Telnetテストシナリオ,label=lst:telnet-bk]
tajima@nettester_2nd:~/repo/examples-tjmtrhs$ bundle exec cucumber features/telnet_internal_network.feature
@static
Feature: 社内テスト環境設定  ヨーヨーダイン社の開発者として、
社内テストサーバにアクセスしたい  なぜならテスト環境設定を行う必要があるから
Scenario: 社内テストサーバへアクセス            # features/telnet_internal_network.feature:8
Given ヨーヨーダイン社内部のテスト環境サーバ        # features/step_definitions/virtual_host.rb:14
 And ヨーヨーダイン社内部のクライアント            # features/step_definitions/virtual_host.rb:6
When 開発者 PC からテストサーバへTelnetでアクセス # features/step_definitions/telnet_steps.rb:2
 Then 社内テストサーバにアクセス成功             # features/step_definitions/telnet_steps.rb:20
expected "Trying 10.10.10.2...\nConnected to 10.10.10.2.\nEscape character is '^]'." to have file content: string includes: "TelnetOK" (RSpec::Expectations::ExpectationNotMetError)
     ./features/step_definitions/telnet_steps.rb:21:in `/^社内テストサーバにアクセス成功$/'      features/telnet_internal_network.feature:12:in `Then 社内テストサーバにアクセス成功' Failing Scenarios: cucumber features/telnet_internal_network.feature:8 #
 Scenario: 社内テストサーバへアクセス 1 scenario (1 failed) 4 steps (1 failed, 3 passed) 0m10.610s
\end{lstlisting}

\begin{lstlisting}[caption=telnetテストステップ,label=lst:telnet-step,linebackgroundcolor={\ifnum\value{lstnumber}>3 \ifnum\value{lstnumber}<6\color{green!30}\fi\fi}]
When(/^ヨーヨーダイン社内部のテスト環境サーバに telnet でログイン$/) do
  cd('.') do
    @telnet_service = AsyncExecutor.new(host: @test_host, result_file: 'log/telnet_server.log')
    @telnet_service.exec "bash -c 'echo LoginOK | sudo nc -l 23'"
    @src_host.exec "bash -c 'telnet #{@test_host.ip_address} > log/login.log; exit 0'"
  end
end
\end{lstlisting}

    \paragraph{調査}

原因を調査するために、同様の操作を手動で実行した場合(成功する場合)とテス
トシナリオ実行で失敗する場合のそれぞれについて strace による調査を実施し
た。\lstref{lst:telnet-success}に成功時、\lstref{lst:telnet-fail}に失敗
時の strace ログを示す。どちらも前半部分は省略してあり、\code{connect}
から 終了(\code{exit})までのログを抜粋してある。

\begin{lstlisting}[language=,caption=Telnet成功時(手動),label=lst:telnet-success,linebackgroundcolor={\ifnum\value{lstnumber}>22 \ifnum\value{lstnumber}<29\color{green!30}\fi\fi}]
socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 3
setsockopt(3, SOL_IP, IP_TOS, [16], 4)  = 0
connect(3, {sa_family=AF_INET, sin_port=htons(8080), sin_addr=inet_addr("192.168.20.166")}, 16) = 0
open("/etc/telnetrc", O_RDONLY)         = -1 ENOENT (No such file or directory)
open("/home/nwtestsys/.telnetrc", O_RDONLY) = -1 ENOENT (No such file or directory)
write(1, "Trying 192.168.20.166...\nConnect"..., 80Trying 192.168.20.166...
Connected to 192.168.20.166.
Escape character is '^]'.
) = 80
rt_sigprocmask(SIG_BLOCK, NULL, [], 8)  = 0
rt_sigaction(SIGINT, {0x407fe0, [INT], SA_RESTORER|SA_RESTART, 0x7fa39fd524a0}, {SIG_DFL, [], 0}, 8) = 0
rt_sigaction(SIGQUIT, {0x407f90, [QUIT], SA_RESTORER|SA_RESTART, 0x7fa39fd524a0}, {SIG_DFL, [], 0}, 8) = 0
rt_sigaction(SIGWINCH, {0x407f70, [WINCH], SA_RESTORER|SA_RESTART, 0x7fa39fd524a0}, {SIG_DFL, [], 0}, 8) = 0
rt_sigaction(SIGTSTP, {0x40c4b0, [TSTP], SA_RESTORER|SA_RESTART, 0x7fa39fd524a0}, {0x40c4b0, [TSTP], SA_RESTORER|SA_RESTART, 0x7fa39fd524a0}, 8) = 0
ioctl(0, TCGETS, {B38400 opost isig icanon echo ...}) = 0
ioctl(0, SNDCTL_TMR_STOP or TCSETSW, {B38400 opost isig icanon echo ...}) = 0
ioctl(0, TCGETS, {B38400 opost isig icanon echo ...}) = 0
ioctl(0, FIONBIO, [1])                  = 0
ioctl(1, FIONBIO, [1])                  = 0
ioctl(3, FIONBIO, [1])                  = 0
setsockopt(3, SOL_SOCKET, SO_OOBINLINE, [1], 4) = 0
select(4, [0 3], [], [3], {0, 0})       = 1 (in [3], left {0, 0})
recvfrom(3, "TelnetOK\n", 8191, 0, NULL, NULL) = 9
select(4, [0 3], [1], [3], {0, 0})      = 2 (in [3], out [1], left {0, 0})
write(1, "TelnetOK\n", 9TelnetOK
)               = 9
recvfrom(3, "", 8183, 0, NULL, NULL)    = 0
rt_sigaction(SIGTSTP, {SIG_DFL, [TSTP], SA_RESTORER|SA_RESTART, 0x7fa39fd524a0}, {0x40c4b0, [TSTP], SA_RESTORER|SA_RESTART, 0x7fa39fd524a0}, 8) = 0
ioctl(0, TCGETS, {B38400 opost isig icanon echo ...}) = 0
ioctl(0, SNDCTL_TMR_STOP or TCSETSW, {B38400 opost isig icanon echo ...}) = 0
ioctl(0, TCGETS, {B38400 opost isig icanon echo ...}) = 0
ioctl(0, FIONBIO, [0])                  = 0
ioctl(1, FIONBIO, [0])                  = 0
close(3)                                = 0
rt_sigaction(SIGTSTP, {0x40c4b0, [TSTP], SA_RESTORER|SA_RESTART, 0x7fa39fd524a0}, {SIG_DFL, [TSTP], SA_RESTORER|SA_RESTART, 0x7fa39fd524a0}, 8) = 0
ioctl(0, TCGETS, {B38400 opost isig icanon echo ...}) = 0
ioctl(0, SNDCTL_TMR_STOP or TCSETSW, {B38400 opost isig icanon echo ...}) = 0
ioctl(0, TCGETS, {B38400 opost isig icanon echo ...}) = 0
ioctl(0, FIONBIO, [1])                  = 0
ioctl(1, FIONBIO, [1])                  = 0
select(2, NULL, [1], NULL, NULL)        = 1 (out [1])
rt_sigaction(SIGTSTP, {SIG_DFL, [TSTP], SA_RESTORER|SA_RESTART, 0x7fa39fd524a0}, {0x40c4b0, [TSTP], SA_RESTORER|SA_RESTART, 0x7fa39fd524a0}, 8) = 0
ioctl(0, TCGETS, {B38400 opost isig icanon echo ...}) = 0
ioctl(0, SNDCTL_TMR_STOP or TCSETSW, {B38400 opost isig icanon echo ...}) = 0
ioctl(0, TCGETS, {B38400 opost isig icanon echo ...}) = 0
ioctl(0, FIONBIO, [0])                  = 0
ioctl(1, FIONBIO, [0])                  = 0
rt_sigaction(SIGTSTP, {0x40c4b0, [TSTP], SA_RESTORER|SA_RESTART, 0x7fa39fd524a0}, {SIG_DFL, [TSTP], SA_RESTORER|SA_RESTART, 0x7fa39fd524a0}, 8) = 0
ioctl(0, TCGETS, {B38400 opost isig icanon echo ...}) = 0
ioctl(0, SNDCTL_TMR_STOP or TCSETSW, {B38400 opost isig icanon echo ...}) = 0
ioctl(0, TCGETS, {B38400 opost isig icanon echo ...}) = 0
ioctl(0, FIONBIO, [1])                  = 0
ioctl(1, FIONBIO, [1])                  = 0
select(2, NULL, [1], NULL, NULL)        = 1 (out [1])
rt_sigaction(SIGTSTP, {SIG_DFL, [TSTP], SA_RESTORER|SA_RESTART, 0x7fa39fd524a0}, {0x40c4b0, [TSTP], SA_RESTORER|SA_RESTART, 0x7fa39fd524a0}, 8) = 0
ioctl(0, TCGETS, {B38400 opost isig icanon echo ...}) = 0
ioctl(0, SNDCTL_TMR_STOP or TCSETSW, {B38400 opost isig icanon echo ...}) = 0
ioctl(0, TCGETS, {B38400 opost isig icanon echo ...}) = 0
ioctl(0, FIONBIO, [0])                  = 0
ioctl(1, FIONBIO, [0])                  = 0
write(2, "Connection closed by foreign hos"..., 35Connection closed by foreign host.
) = 35
close(-1)                               = -1 EBADF (Bad file descriptor)
exit_group(1)                           = ?
+++ exited with 1 +++
\end{lstlisting}

\begin{lstlisting}[language=,caption=Telnet失敗時,label=lst:telnet-fail,linebackgroundcolor={\ifnum\value{lstnumber}>24 \ifnum\value{lstnumber}<26\color{green!30}\fi\fi}]
socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 3
setsockopt(3, SOL_IP, IP_TOS, [16], 4)  = 0
connect(3, {sa_family=AF_INET, sin_port=htons(23), sin_addr=inet_addr("10.10.10.2")}, 16) = 0
open("/etc/telnetrc", O_RDONLY)         = -1 ENOENT (No such file or directory)
open("/root/.telnetrc", O_RDONLY)       = -1 ENOENT (No such file or directory)

write(1, "Trying 10.10.10.2...\nConnected t"..., 72Trying 10.10.10.2...
Connected to 10.10.10.2.
Escape character is '^]'.
) = 72
rt_sigprocmask(SIG_BLOCK, NULL, [], 8)  = 0
rt_sigaction(SIGINT, {0x407fe0, [INT], SA_RESTORER|SA_RESTART, 0x7fdd72e1d4a0}, {SIG_DFL, [], 0}, 8) = 0
rt_sigaction(SIGQUIT, {0x407f90, [QUIT], SA_RESTORER|SA_RESTART, 0x7fdd72e1d4a0}, {SIG_DFL, [], 0}, 8) = 0
rt_sigaction(SIGWINCH, {0x407f70, [WINCH], SA_RESTORER|SA_RESTART, 0x7fdd72e1d4a0}, {SIG_DFL, [], 0}, 8) = 0
rt_sigaction(SIGTSTP, {0x40c4b0, [TSTP], SA_RESTORER|SA_RESTART, 0x7fdd72e1d4a0}, {0x40c4b0, [TSTP], SA_RESTORER|SA_RESTART, 0x7fdd72e1d4a0}, 8) = 0
ioctl(0, TCGETS, 0x7ffc1c8e01d0)        = -1 ENOTTY (Inappropriate ioctl for device)
ioctl(0, SNDCTL_TMR_STOP or TCSETSW, {B0 opost isig icanon echo ...}) = -1 ENOTTY (Inappropriate ioctl for device)
ioctl(0, TCGETS, 0x7ffc1c8e01d0)        = -1 ENOTTY (Inappropriate ioctl for device)
ioctl(0, SNDCTL_TMR_START or TCSETS, {B0 opost isig icanon echo ...}) = -1 ENOTTY (Inappropriate ioctl for device)
ioctl(0, FIONBIO, [1])                  = 0
ioctl(1, FIONBIO, [1])                  = 0
ioctl(3, FIONBIO, [1])                  = 0
setsockopt(3, SOL_SOCKET, SO_OOBINLINE, [1], 4) = 0
select(4, [0 3], [3], [3], {0, 0})      = 2 (in [0], out [3], left {0, 0})
sendto(3, "\377\375\3\377\373\30\377\373\37\377\373 \377\373!\377\373\"\377\373'\377\375\5", 24, 0, NULL, 0) = 24
read(0, "", 8191)                       = 0
ioctl(0, TCGETS, 0x7ffc1c8e01a0)        = -1 ENOTTY (Inappropriate ioctl for device)
rt_sigaction(SIGTSTP, {SIG_DFL, [TSTP], SA_RESTORER|SA_RESTART, 0x7fdd72e1d4a0}, {0x40c4b0, [TSTP], SA_RESTORER|SA_RESTART, 0x7fdd72e1d4a0}, 8) = 0
ioctl(0, TCGETS, 0x7ffc1c8e01f0)        = -1 ENOTTY (Inappropriate ioctl for device)
ioctl(0, SNDCTL_TMR_STOP or TCSETSW, {B0 -opost -isig -icanon -echo ...}) = -1 ENOTTY (Inappropriate ioctl for device)
ioctl(0, TCGETS, 0x7ffc1c8e01f0)        = -1 ENOTTY (Inappropriate ioctl for device)
ioctl(0, SNDCTL_TMR_START or TCSETS, {B0 -opost -isig -icanon -echo ...}) = -1 ENOTTY (Inappropriate ioctl for device)
ioctl(0, FIONBIO, [0])                  = 0
ioctl(1, FIONBIO, [0])                  = 0
close(3)                                = 0
rt_sigaction(SIGTSTP, {0x40c4b0, [TSTP], SA_RESTORER|SA_RESTART, 0x7fdd72e1d4a0}, {SIG_DFL, [TSTP], SA_RESTORER|SA_RESTART, 0x7fdd72e1d4a0}, 8) = 0
ioctl(0, TCGETS, 0x7ffc1c8e01c0)        = -1 ENOTTY (Inappropriate ioctl for device)
ioctl(0, SNDCTL_TMR_STOP or TCSETSW, {B0 opost -isig -icanon echo ...}) = -1 ENOTTY (Inappropriate ioctl for device)
ioctl(0, TCGETS, 0x7ffc1c8e01c0)        = -1 ENOTTY (Inappropriate ioctl for device)
ioctl(0, SNDCTL_TMR_START or TCSETS, {B0 opost -isig -icanon echo ...}) = -1 ENOTTY (Inappropriate ioctl for device)
ioctl(0, FIONBIO, [1])                  = 0
ioctl(1, FIONBIO, [1])                  = 0
select(2, NULL, [1], NULL, NULL)        = 1 (out [1])
rt_sigaction(SIGTSTP, {SIG_DFL, [TSTP], SA_RESTORER|SA_RESTART, 0x7fdd72e1d4a0}, {0x40c4b0, [TSTP], SA_RESTORER|SA_RESTART, 0x7fdd72e1d4a0}, 8) = 0
ioctl(0, TCGETS, 0x7ffc1c8e01c0)        = -1 ENOTTY (Inappropriate ioctl for device)
ioctl(0, SNDCTL_TMR_STOP or TCSETSW, {B0 -opost -isig -icanon -echo ...}) = -1 ENOTTY (Inappropriate ioctl for device)
ioctl(0, TCGETS, 0x7ffc1c8e01c0)        = -1 ENOTTY (Inappropriate ioctl for device)
ioctl(0, SNDCTL_TMR_START or TCSETS, {B0 -opost -isig -icanon -echo ...}) = -1 ENOTTY (Inappropriate ioctl for device)
ioctl(0, FIONBIO, [0])                  = 0
ioctl(1, FIONBIO, [0])                  = 0
rt_sigaction(SIGTSTP, {0x40c4b0, [TSTP], SA_RESTORER|SA_RESTART, 0x7fdd72e1d4a0}, {SIG_DFL, [TSTP], SA_RESTORER|SA_RESTART, 0x7fdd72e1d4a0}, 8) = 0
ioctl(0, TCGETS, 0x7ffc1c8e01c0)        = -1 ENOTTY (Inappropriate ioctl for device)
ioctl(0, SNDCTL_TMR_STOP or TCSETSW, {B0 opost -isig -icanon echo ...}) = -1 ENOTTY (Inappropriate ioctl for device)
ioctl(0, TCGETS, 0x7ffc1c8e01c0)        = -1 ENOTTY (Inappropriate ioctl for device)
ioctl(0, SNDCTL_TMR_START or TCSETS, {B0 opost -isig -icanon echo ...}) = -1 ENOTTY (Inappropriate ioctl for device)
ioctl(0, FIONBIO, [1])                  = 0
ioctl(1, FIONBIO, [1])                  = 0
select(2, NULL, [1], NULL, NULL)        = 1 (out [1])
rt_sigaction(SIGTSTP, {SIG_DFL, [TSTP], SA_RESTORER|SA_RESTART, 0x7fdd72e1d4a0}, {0x40c4b0, [TSTP], SA_RESTORER|SA_RESTART, 0x7fdd72e1d4a0}, 8) = 0
ioctl(0, TCGETS, 0x7ffc1c8e01d0)        = -1 ENOTTY (Inappropriate ioctl for device)
ioctl(0, SNDCTL_TMR_STOP or TCSETSW, {B0 -opost -isig -icanon -echo ...}) = -1 ENOTTY (Inappropriate ioctl for device)
ioctl(0, TCGETS, 0x7ffc1c8e01d0)        = -1 ENOTTY (Inappropriate ioctl for device)
ioctl(0, SNDCTL_TMR_START or TCSETS, {B0 -opost -isig -icanon -echo ...}) = -1 ENOTTY (Inappropriate ioctl for device)
ioctl(0, FIONBIO, [0])                  = 0
ioctl(1, FIONBIO, [0])                  = 0
write(2, "Connection closed by foreign hos"..., 35Connection closed by foreign host.
) = 35
close(-1)                               = -1 EBADF (Bad file descriptor)
exit_group(1)                           = ?
+++ exited with 1 +++
\end{lstlisting}

成功時(\lstref{lst:telnet-success})では、\code{connect}後にサーバからの
\verb|recvfrom(3, "TelnetOK\n", ...)|\footnote{\lstref{lst:telnet-step}
などテストステップのコード中では\code{LoginOK}となっている。これは、トラ
ブルシュートと前後してリファクタリング(テスト結果判定の処理統一)をおこなっ
たためである。ロジックとしては同様。結果判定の統一については
\ref{sec:refactor-filename}節参照。}が先にきている(23行目)。しかし、失敗
時(\lstref{lst:telnet-fail})では、クライアントからのネゴシエーションの
\verb|sendto(3, "\377...", ...)|が先に実行されている(25行目)。この場合後
続の\code{write}は実行されていない(そもそも\code{recv}しない)。

これらの strace ログから、トラブルの原因は送受信順序によるものと仮定した。
仮定を実証するために、telnetクライアントを改変する。Telnetクライアントが
\code{connect}したあとサーバから来るデータを先に受ける(\code{recv})ため
に、\code{connect}のあとに\code{sleep}を入れる
(\lstref{lst:modified-telnet-client})。これをビルドして
(\lstref{lst:howto-build-telnet})、テストステップの中で使用する
(\lstref{lst:telnet-step})。結果として、エラーが発生しなくなることを確認
できた。

\begin{lstlisting}[caption=telnetクライアント改変,label=lst:modified-telnet-client]
--- netkit-telnet-0.17/telnet/netlink.cc        2017-03-21 00:30:45.990808011 +0900
+++ netkit-telnet-0.17-mod/telnet/netlink.cc    2017-03-21 00:24:45.178808011 +0900
@@ -158,6 +158,7 @@
     if (::connect(net, addr->ai_addr, addr->ai_addrlen) < 0) {
        return 1;
     }
+    sleep(10);
     return 2;
 }
\end{lstlisting}

\begin{lstlisting}[language=sh,caption=telnetクライアントのビルド手順,label=lst:howto-build-telnet]
sudo echo "deb http://gb.archive.ubuntu.com/ubuntu/ xenial main restricted" | sudo tee -a /etc/apt/sources.list
sudo echo "deb-src http://gb.archive.ubuntu.com/ubuntu/ xenial main restricted" | sudo tee -a /etc/apt/sources.list
sudo apt-get source telnet
sudo apt-get install libncurses-dev
cd netkit-telnet-0.17
./configure
cd telnet
make
\end{lstlisting}

\begin{lstlisting}[caption=改変telnetクライアントの使用,label=lst:telnet-step,linebackgroundcolor={\ifnum\value{lstnumber}=5 \color{green!30}\fi}]
When(/^ヨーヨーダイン社内部のテスト環境サーバに telnet でログイン$/) do
  cd('.') do
    @telnet_service = AsyncExecutor.new(host: @test_host, result_file: 'log/telnet_server.log')
    @telnet_service.exec "bash -c 'echo LoginOK | sudo nc -l 23'"
    @src_host.exec "bash -c '/home/nwtestsys/examples/telnet-source/netkit-telnet-0.17/telnet/telnet #{@test_host.ip_address} > log/login.log; exit 0'"
  end
end
\end{lstlisting}

    \paragraph{結果と対処}
サーバ (netcat) はクライアントからの接続を受け付けて echo するとすぐに切
断する。結果としてサーバから送られたデータの \code{recv} とクライアント
が送るデータの \code{sendto} のどちらが早いかという順序(タイミング)問題
が発生していたと考えられる。

こうした問題はサーバ側に telnet デーモン (telnetd) を使用することで回避
可能である。しかし、telnetd を使用すると対話的処理が必要になってしまうた
め、テストステップが複雑になる。そこで、クライアント側に Net::Telnet を
使用することで問題を回避している(\lstref{lst:telnet-step-new})。

\begin{lstlisting}[caption=修正後テストステップ,label=lst:telnet-step-new,linebackgroundcolor={\ifnum\value{lstnumber}=5 \color{green!30}\fi}]
When(/^社内のテスト環境サーバに telnet でログイン$/) do
  cd('.') do
    @telnet_service = AsyncExecutor.new(host: @test_host, result_file: 'log/telnet_host.log')
    @telnet_service.exec "bash -c 'echo LoginOK | sudo nc -l 23'"
    @src_host.exec "ruby -e \"require 'net/telnet'; Net::Telnet.new('Host' => '#{@test_host.ip_address}', 'Port' => '23').cmd('') {|res| print res}\" > log/login.log"
  end
end
\end{lstlisting}

 \section{Juniper SSG の不正なパケット処理に関連するトラブル}
 \label{sec:SSG-troubles}

この節では、
\begin{itemize}
 \item NetTesterサーバまたは物理OpenFlowスイッチによる不正なパケットの生成
 \item FW (Juniper SSG)による不正なパケットの処理
\end{itemize}
に関連すると考えられた事象について解説する。いずれもワークアラウンドによっ
て回避しており、詳細原因までは追求できていないが、テスター・テスト対象ネッ
トワーク(内部の機器)それぞれの動作によるトラブルだと推測される。こうした
組み合せによるトラブルでは不可解な事象が発生し、かつ原因の推定が難しいた
め注意が必要である。

 \subsection{TCP checksum offload 動作に関連するトラブル}
 \label{sec:tcp-checksum-offload-trouble}

\ref{sec:nettester-server-software}節では、トラブルによりテェックサム計
算オフロードを無効化を設定していることを述べた。本節ではその際の事象と調
査内容について解説する。

    \paragraph{事象}
テストシナリオ中、TCP接続をおこなうツールを利用したとき、通信が成功せず
にテストが失敗する。あるいはTCPコネクションが確立するが、単純な接続確認・
送受信しかしないテストにもかかわらず、終了するまでに2分前後かかる。TCPで
はなくICMP(ping)に変更すると、同様のテスト条件でも問題が発生しない。

    \paragraph{調査}
通信種別によって問題の有無が変化するため、以下のように順を追って調査して
いる。
\begin{itemize}
 \item テストノードのパッチ接続先の条件による事象変化の確認。(パッチ接続
       先ポートの access/trunk による違いの確認。)
 \item Tester set の変更による事象変化の確認。(異なる物理OFS/サーバによ
       るハードウェア等の切り分け。)
 \item テストトラフィックのパケットキャプチャ取得と比較。(テストノード
       /NetTesterサーバ出口/OFS入出力/テスト用ネットワークにあるL2SW/FW
       それぞれの入出力などを個別にキャプチャ取得。)
\end{itemize}

最終的に、以下の条件で TCP パケットのチェックサムが incorrect となってい
ることがわかった。
\begin{itemize}
 \item テスト用ノードをテスト対象ネットワークに trunk port で接続させる。
       (OVS で VLAN Tag を操作する。)
 \item テストトラフィックとして TCP 通信をおこなう。
       \begin{itemize}
        \item SYN/FIN フラグがついたトラフィックについては問題が発生しな
              い。(TCPで特定のフラグがついたパケットで問題がおきる。)
        \item ICMP 通信については問題が発生しない。
       \end{itemize}
 \item L2SW(Cisco Catalyst3750G)内のL2セグメントで折りかえす場合は問題発
       生せず。FW (Juniper SSG)を経由する通信(テストトラフィック)につい
       て影響をうけている。
\end{itemize}

条件を変えながらキャプチャをみていると、VLAN tag ありでテスト対象ネット
ワークへテストノードをパッチするケースでは、TCP sequence number が不正に
なったり、その結果としてパケット再送が発生していることがわかった。テスト
ノードを access port へパッチすると発生しないことから、NetTester による
VLAN tag 操作がおこなわれるポイントでの問題と考えられた。

実際にどのようなパケットが生成されていたかを\lstref{lst:capture-untag}お
よび\lstref{lst:capture-tag}に示す。それぞれ、NetTesterサーバ(KVMホスト
上の仮想マシン)のSSW--PSW間通信をパススルーしているKVMホストの物理NICで
取得したものである(\figref{fig:poc-env-physical-detail}のem2)。VLAN Tag
およびチェックサムについてまとめると\tabref{tab:capture-result}のように
なる。

\begin{lstlisting}[language=,caption=KVM Hostキャプチャ(タグなし),label=lst:capture-untag]
20:59:31.948164 00:d9:87:40:c2:7d > 00:10:db:ff:20:60, ethertype IPv4 (0x0800), length 66: (tos 0x0, ttl 64, id 1192, offset 0, flags [DF], proto TCP (6), length 52)	10.10.10.4.44910 > 10.10.0.100.80: Flags [.], cksum 0x1ea2 (incorrect -> 0xbd9a), seq 1, ack 1, win 229, options [nop,nop,TS val 3228510328 ecr 3228510328], length 0
20:59:31.948196 00:d9:87:40:c2:7d > 00:10:db:ff:20:60, ethertype 802.1Q (0x8100), length 70: vlan 2025, p 0, ethertype IPv4, (tos 0x0, ttl 64, id 1192, offset 0, flags [DF], proto TCP (6), length 52)	10.10.10.4.44910 > 10.10.0.100.80: Flags [.], cksum 0xbd9a (correct), seq 1, ack 1, win 229, options [nop,nop,TS val 3228510328 ecr 3228510328], length 0
\end{lstlisting}

\begin{lstlisting}[language=,caption=KVM Hostキャプチャ(タグあり),label=lst:capture-tag]
20:59:33.565558 00:2a:28:4d:69:2f > 00:10:db:ff:20:60, ethertype 802.1Q (0x8100), length 70: vlan 2023, p 0, ethertype IPv4, (tos 0x0, ttl 64, id 57905, offset 0, flags [DF], proto TCP (6), length 52)	10.10.0.100.80 > 10.10.10.4.44910: Flags [.], cksum 0x1ea2 (incorrect -> 0xba70), seq 1, ack 3, win 227, options [nop,nop,TS val 3228510733 ecr 3228510733], length 0 
20:59:33.565738 00:10:db:ff:20:60 > 00:d9:87:40:c2:7d, ethertype IPv4 (0x0800), length 66: (tos 0x0, ttl 63, id 57905, offset 0, flags [DF], proto TCP (6), length 52)	10.10.0.100.80 > 10.10.10.4.44910: Flags [.], cksum 0x1ea2 (incorrect -> 0xca49), seq 4294963240, ack 3, win 227, options [nop,nop,TS val 3228510733 ecr 3228510733], length 0
\end{lstlisting}

\begin{table}[h]
 \centering
 \caption{パケットキャプチャ結果}
 \label{tab:capture-result}
 \begin{tabularx}{\linewidth}{l|X|X}
  \hline
  パッチのVLAN Tag設定
  & NetTester Server to Testee (1行目)
  & Testee to NetTester Server (2行目,L3終端後) \\
  \hline
  \hline
  Tag なし (\lstref{lst:capture-untag})
  & Checksum incorrect
  & Checksum correct \\
  Tag あり (\lstref{lst:capture-tag})
  & Checksum incorrect
  & Checksum incorrect \\
  \hline
 \end{tabularx}
\end{table}

    \paragraph{結果と対処}
\tabref{tab:capture-result}に示したように、VLAN tag などいくつかの条件で
はチェックサムが incorrect になってしまい、テストトラフィックとして生成
したTCP通信がうまくいかなかった。\tabref{tab:capture-result}の結果からサー
バ物理NICでのパケット処理機能がうまく機能していないと予想された。そこで、
対処としてチェックサムオフロードの機能を無効~\cite{net-tester-pr7}にして
いる(\ref{sec:nettester-server-software}節)。
\begin{lstlisting}[language=,]
sudo ip netns exec [test node (netns)] ethtool -K [test node veth] tx off
\end{lstlisting}

根本的な原因までは調査・追求していない。Tag (dot1q tag) がある場合にチェッ
クサムオフロードがうまく機能しない理由については不明(未調査)である。原因
としては、FW(SSG)が不正なチェックサムをもつパケットをうまく処理できずに、
一部だけ通してしまう可能性も考えられる。

参考情報として、NICの情報を\lstref{lst:nic-info}に、NICドライバの情報を
\lstref{lst:nic-driver-info}に示す。

\begin{lstlisting}[language=,caption=NIC情報,label=lst:nic-info]
tajima@NW-TEST-SYS-PJ-SERV:~$ sudo lspci | grep -i network
01:00.0 Ethernet controller: Intel Corporation I350 Gigabit Network Connection (rev 01)
01:00.1 Ethernet controller: Intel Corporation I350 Gigabit Network Connection (rev 01)
07:00.0 Ethernet controller: Intel Corporation I350 Gigabit Network Connection (rev 01)
07:00.1 Ethernet controller: Intel Corporation I350 Gigabit Network Connection (rev 01)
\end{lstlisting}

\begin{lstlisting}[language=,caption=NICドライバ情報,label=lst:nic-driver-info]
tajima@NW-TEST-SYS-PJ-SERV:~$ sudo ethtool -i em2
driver: igb
version: 5.2.13-k
firmware-version: 1.61, 0x8000090e
bus-info: 0000:07:00.1
supports-statistics: yes
supports-test: yes
supports-eeprom-access: yes
supports-register-dump: yes
supports-priv-flags: no
\end{lstlisting}

 \subsection{物理OFSリプレースにともなうFW動作トラブル}
 \label{sec:ofs-replace-fw-trouble}

    \paragraph{事象}
本プロジェクトの検証環境は沖縄オープンラボラトリのテストベッドを借用した。
OpenFlowスイッチなどもオープンラボの機材を利用している。一部のOFS(OFS1)
についてオープンラボ内部の機材交換が発生した際に、交換前はすべて成功して
いたテストの一部が失敗するようになった。このとき、テストをくりかえすと成
功・失敗は変化し、常に失敗し続けるわけではない(高頻度で失敗するシナリオ
がある)。

    \paragraph{調査}
失敗するテストシナリオを比較すると、L3でセグメントを経由する通信をおこな
うテストシナリオが高頻度で失敗することがわかった。PoC環境のL3 (default
gateway)はFWであるため、FWの動作に何らかの問題があることが想定された。問
題箇所のしぼりこみ・切り分け対応としては以下の調査をおこなった。

\begin{itemize}
 \item テスト用ノード(クライアント・サーバ)側でパケットキャプチャ
       \begin{itemize}
        \item FWでNATしている(セッション情報が表示される;
              \lstref{lst:fw-nat-info})ものの、実際にテストノード側でパ
              ケットを見るとNATされていない(\lstref{lst:server-capture})。
        \item テスト用ノードからreplyしていても届いていないことがある。
       \end{itemize}
 \item FW1/2 を再起動させる : 問題解決せず
 \item 物理OFSのフローテーブルのクリア : 問題解決せず
 \item L2SW, SSGの MACアドレステーブルのチェック
       \begin{itemize}
        \item SSGがサーバ側のMACアドレスを学習できていない。
        \item テストノードから default gateway への ICMP に応答がない。
       \end{itemize}
 \item FWハードウェアのきりわけ
       \begin{itemize}
        \item FW1のアップリンクをリンクダウンさせ、強制的にFW2がactiveに
              なるように変更してテストを実行。テストは通るが、いくつかの
              テストシナリオでは完了までに時間がかかる(数分)。
       \end{itemize}
\end{itemize}

\begin{lstlisting}[language=,caption=FW NATセッション情報,label=lst:fw-nat-info]
test:FW1(M)-> get session
nat used ipv6 addr: allocated 0/maximum 64256
alloc 4/max 16064, alloc failed 0, mcast alloc 0, di alloc failed 0
total reserved 0, free sessions in shared pool 16060
id 15689/s**,vsys 0,flag 48000000/4000/0001/0000,policy 24,time 2, dip 4 module 0
 if 6(nspflag 801805):10.10.0.100/45402->198.51.100.3/80,6,00217094feda,sess token 18,vlan 2023,tun 0,vsd 0,route 5,wsf 0
 if 0(nspflag 10800804):203.0.113.6/8637<-198.51.100.3/80,6,00211c2c7245,sess token 17,vlan 2021,tun 0,vsd 0,route 7,wsf 7
\end{lstlisting}

\begin{lstlisting}[language=,caption=テストノード(サーバ)側キャプチャ,label=lst:server-capture]
tajima@nettester_1st:~$ sudo tcpdump -i ens5 -n -nn -v
tcpdump: listening on ens5, link-type EN10MB (Ethernet), capture size 262144 bytes
06:34:13.324210 ARP, Ethernet (len 6), IPv4 (len 4), Request who-has 10.10.0.1 tell 10.10.0.100, length 28
06:34:13.326263 ARP, Ethernet (len 6), IPv4 (len 4), Request who-has 10.10.0.1 tell 10.10.0.100, length 46
06:34:13.332088 ARP, Ethernet (len 6), IPv4 (len 4), Reply 10.10.0.1 is-at 00:10:db:ff:20:60, length 46
06:34:13.332542 IP (tos 0x0, ttl 64, id 32529, offset 0, flags [DF], proto TCP (6), length 60)
    10.10.0.100.45402 > 198.51.100.3.80: Flags [S], cksum 0xc51c (correct), seq 2276330937, win 29200, options [mss 1460,sackOK,TS val 578056872 ecr 0,nop,wscale 7], length 0
06:34:13.339657 IP (tos 0x0, ttl 64, id 32529, offset 0, flags [DF], proto TCP (6), length 60)
    10.10.0.100.45402 > 198.51.100.3.80: Flags [S], cksum 0xc51c (correct), seq 2276330937, win 29200, options [mss 1460,sackOK,TS val 578056872 ecr 0,nop,wscale 7], length 0
\end{lstlisting}

    \paragraph{結果と対処}

最終的には、交換(リプレース)した物理OpenFlowスイッチ(OFS1)の再起動で解決
した。原因としては次のような要因が推測される(詳細な原因追求はできていな
い)。
\begin{itemize}
 \item 付録~\ref{sec:tcp-checksum-offload-trouble}のように、FW(SSG)はパケッ
       トに不備があっても通してしまう事例がある。この事例でも物理
       OFS(OFS1)に何らかの不具合があって、パケットが全部は送信されていな
       いと仮定する。L2SWEX--FW1--L2SW1間は障害試験のためにOFS1を経由す
       る(\figref{fig:patch-layer1},
       \figref{fig:poc-env-physical-detail})。FW1がactiveな場合、L2SW-FW
       間トラフィックがOFS1を通るのでパケットに問題が発生する。しかしSSG
       はそれを無視して通す。FW2をactiveにするとOFS1を経由しないためにテ
       ストが成功する。
 \item 物理OpenFlowスイッチを交換したとき、交換後のスイッチは
       \code{fail\_mode=secure}ではなかったため learning switch として動
       作していた(\ref{sec:nettester-deploy-psw}節)。そのため、L2SWでは
       VLAN mismatch となっていた。その後\code{fail\_mode}を設定して
       VLAN mismatch 解決された。L2SW 側でインタフェース状態を確認してい
       たものの、物理OFS--L2SW間ポートに何かの状態が残っていた可能性があ
       る。(OFS1の再起動でおきたポートの up/down により問題が解決した。)
\end{itemize}

%%% Local Variables:
%%% mode: yatex
%%% TeX-master: "main.tex"
%%% End: