标签归档:linux

JDK在mac和linux上对connection reset的行为不一致?

遇到一个JDK(版本都是1.8.0_51-b16)在mac和linux上行为不一致的问题,这个问题是针对redis服务器端关闭连接时的状况处理;即在redis-server端设置连接的空闲时间,当超过这个空闲时间后server主动把该连接关闭掉。在我的mac上这个行为是符合预期的,对这个超时的连接再发起请求时会抛出 SocketException "Connection Reset",但在linux上却不会。

简单模拟一下,在Redis服务端配置timeout为3秒,客户端建立连接之后 sleep 4秒(或更久),让连接超时

import java.io.InputStream;
import java.io.OutputStream;
import java.net.InetSocketAddress;
import java.net.Socket;

public class ConnRestTest {

    public static void main(String[] args) throws Exception {
        Socket socket = new Socket();
        socket.connect(new InetSocketAddress("localhost", 6379));

        InputStream is = socket.getInputStream();
        OutputStream os = socket.getOutputStream();

        Thread.sleep(4000);

        os.write("*1\r\n$4\r\nPING\r\n".getBytes());
        os.flush();

        for (int i = 0; i < 7; i++) {
            int r = is.read();
            System.out.print( r == -1 ? r : (char) r);
        }

        socket.close();
    }
}

上面的代码在mac上运行后会看到如下异常(如果注释掉 Thread.sleep(4000) 会得到 "+PONG\r\n")

Exception in thread "main" java.net.SocketException: Connection reset
    at java.net.SocketInputStream.read(SocketInputStream.java:209)
    at java.net.SocketInputStream.read(SocketInputStream.java:141)
    at java.net.SocketInputStream.read(SocketInputStream.java:223)
    at com.wacai.common.redis.io.Test.main(Test.java:23)    

而在linux上运行后则是打印7个连续的"-1",即并不会抛出"Connection reset"

分别进行tcpdump,在mac上:

 ➜  sudo tcpdump -i lo0 port 6379

23:13:43.398003 IP localhost.63864 > localhost.6379: Flags [S], seq 1658673677, win 65535, options [mss 16344,nop,wscale 5,nop,nop,TS val 1063188198 ecr 0,sackOK,eol], length 0
23:13:43.398064 IP localhost.6379 > localhost.63864: Flags [S.], seq 355134851, ack 1658673678, win 65535, options [mss 16344,nop,wscale 5,nop,nop,TS val 1063188198 ecr 1063188198,sackOK,eol], length 0
23:13:43.398075 IP localhost.63864 > localhost.6379: Flags [.], ack 1, win 12759, options [nop,nop,TS val 1063188198 ecr 1063188198], length 0
23:13:43.398085 IP localhost.6379 > localhost.63864: Flags [.], ack 1, win 12759, options [nop,nop,TS val 1063188198 ecr 1063188198], length 0

23:13:47.063640 IP localhost.6379 > localhost.63864: Flags [F.], seq 1, ack 1, win 12759, options [nop,nop,TS val 1063191852 ecr 1063188198], length 0
23:13:47.063671 IP localhost.63864 > localhost.6379: Flags [.], ack 2, win 12759, options [nop,nop,TS val 1063191852 ecr 1063191852], length 0

23:13:48.403144 IP localhost.63864 > localhost.6379: Flags [P.], seq 1:15, ack 2, win 12759, options [nop,nop,TS val 1063193184 ecr 1063191852], length 14
23:13:48.403255 IP localhost.6379 > localhost.63864: Flags [R], seq 355134853, win 0, length 0  

在linux上:

$ sudo tcpflow -p -c -i lo port 6379

00:26:13.303233 IP localhost.34609 > localhost.6379: Flags [S], seq 1094106697, win 43690, options [mss 65495,sackOK,TS val 8462190 ecr 0,nop,wscale 7], length 0
00:26:13.303272 IP localhost.6379 > localhost.34609: Flags [S.], seq 2755621045, ack 1094106698, win 43690, options [mss 65495,sackOK,TS val 8462190 ecr 8462190,nop,wscale 7], length 0
00:26:13.303298 IP localhost.34609 > localhost.6379: Flags [.], ack 1, win 342, options [nop,nop,TS val 8462190 ecr 8462190], length 0

00:26:17.037992 IP localhost.6379 > localhost.34609: Flags [F.], seq 1, ack 1, win 342, options [nop,nop,TS val 8465925 ecr 8462190], length 0
00:26:17.038450 IP localhost.34609 > localhost.6379: Flags [.], ack 2, win 342, options [nop,nop,TS val 8465926 ecr 8465925], length 0

00:26:18.305591 IP localhost.34609 > localhost.6379: Flags [P.], seq 1:15, ack 2, win 342, options [nop,nop,TS val 8467193 ecr 8465925], length 14
00:26:18.305630 IP localhost.6379 > localhost.34609: Flags [R], seq 2755621047, win 0, length 0     

在mac上比linux上多了一次在连接建立后从server发给client端的ack,在3秒之后,连接因为超过空闲时间server端向client端发起了fin,client回复ack,之后client端程序对socket进行写操作,在tcpdump里看到标记为P的标记,然后server端发送了reset

在linux上看到连接状态的变化也符合预期:

$ netstat -antp | grep 6379
Proto Recv-Q Send-Q Local Address           Foreign Address         State       PID/Program name
tcp        0      0 127.0.0.1:6379          0.0.0.0:*               LISTEN      -
tcp        0      0 127.0.0.1:6379          127.0.0.1:34607         ESTABLISHED -
tcp6       0      0 127.0.0.1:34607         127.0.0.1:6379          ESTABLISHED 3683/java

tcp        0      0 127.0.0.1:6379          0.0.0.0:*               LISTEN      -
tcp        0      0 127.0.0.1:6379          127.0.0.1:34607         FIN_WAIT2   -
tcp6       1      0 127.0.0.1:34607         127.0.0.1:6379          CLOSE_WAIT  3683/java

按说server端发送reset标记后,mac上抛出异常的行为更符合预期,可能是JDK网络层面的实现细节不同,或者tcpdump出的数据已经能解释原因只是我看不出来。

作业控制与前台进程组

这篇文章是对之前的SIGTTIN信号量的疑惑?的解答,对于为何会有这种奇怪的用法,在另一篇shell下精确的定位一个命令 也介绍过了,这里想讨论的重点不在于怎么变通解决那个问题,而是导致SIGTTIN发生的机制是怎么引起的。我的同事对这个问题也产生了好奇,在stackoverflow上发帖,有人给出了解释,解答的人直接给出了bash的源码jobs.c里的initialize_job_control方法片段,指出SIGTTIN正是那里面的逻辑。不过如果你跟我一样对shell和linux系统调用都懂得很肤浅的话,这段代码并不容易懂,所以在这里更详细的解释一下这个问题的来龙去脉。

刚开始碰到这个问题的时候,通过strace看到了是SIGTTIN信号量所致,因为这个信号量默认的行为是让进程STOP(暂停),即通过ps观察到的状态为T。对于SIGTTIN信号量《Linux/UNIX系统编程手册》上是这么说的:

只有前台作业中的进程才能够从控制终端读取输入。这个限制条件避免了多个作业竞争读取终端输入。如果后台作业尝试从终端读取输入,就会接收到一个SIGTTIN信号。SIGTTIN信号的默认处理动作是停止作业。

但我们的脚本里并没有后台进程,那两个进程也没有读取终端,跟上面的解释对不上。也没有在网上搜到其它引发SIGTTIN信号的情况,在这里困惑了很久。不过凭直觉知道这个问题应该跟作业控制有关,在脚本里显式的开启作业控制,是能够正常运行的:

$ cat sleep.sh
#!/bin/bash
set -m
bash -ic 'sleep 3'
bash -ic 'sleep 2'

所以一定是在进程某个状态上的不一致导致的。上周末的时候阅读了一下strace的log,对出问题的脚本:

#!/bin/bash
bash -ic 'sleep 3'
bash -ic 'sleep 2'

使用strace -f -e verbose=all -t ./sleep.sh 2>log 得到更详细的日志

...
03:39:06 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f997f03ca10) = 9897
...
[pid  9897] 03:39:06 execve("/usr/bin/bash", ["bash", "-ic", "sleep 3"], [/* 30 vars */]) = 0
...
[pid  9897] 03:39:06 open("/dev/tty", O_RDWR|O_NONBLOCK) = 3
[pid  9897] 03:39:06 getrlimit(RLIMIT_NOFILE, {rlim_cur=1024, rlim_max=4*1024}) = 0
[pid  9897] 03:39:06 fcntl(255, F_GETFD) = -1 EBADF (Bad file descriptor)
[pid  9897] 03:39:06 dup2(3, 255)       = 255
[pid  9897] 03:39:06 close(3)           = 0
[pid  9897] 03:39:06 ioctl(255, TIOCGPGRP, [9891]) = 0
[pid  9897] 03:39:06 setpgid(0, 9897)   = 0 //第一个子进程更改了它的进程组ID
...
03:39:09 clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f997f03ca10) = 9922
...
[pid  9922] 03:39:09 execve("/usr/bin/bash", ["bash", "-ic", "sleep 2"], [/* 30 vars */]) = 0
...
[pid  9922] 03:39:09 access("/usr/bin/bash", R_OK) = 0
[pid  9922] 03:39:09 getpgrp()          = 9891
[pid  9922] 03:39:09 ioctl(2, SNDCTL_TMR_TIMEBASE or SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, 0x7ffd356e49c0) = -1 ENOTTY (Inappropriate ioctl for device)
[pid  9922] 03:39:09 open("/dev/tty", O_RDWR|O_NONBLOCK) = 3
[pid  9922] 03:39:09 getrlimit(RLIMIT_NOFILE, {rlim_cur=1024, rlim_max=4*1024}) = 0
[pid  9922] 03:39:09 fcntl(255, F_GETFD) = -1 EBADF (Bad file descriptor)
[pid  9922] 03:39:09 dup2(3, 255)       = 255
[pid  9922] 03:39:09 close(3)           = 0
[pid  9922] 03:39:09 ioctl(255, TIOCGPGRP, [9897]) = 0
[pid  9922] 03:39:09 rt_sigaction(SIGTTIN, {SIG_DFL, [], SA_RESTORER, 0x7f912a22b650}, {SIG_IGN, [], SA_RESTORER, 0x7f912a22b650}, 8) = 0
[pid  9922] 03:39:09 kill(0, SIGTTIN)   = 0
[pid  9896] 03:39:09 <... wait4 resumed> 0x7ffc5b5e6800, 0, NULL) = ? ERESTARTSYS (To be restarted if SA_RESTART is set)
[pid  9922] 03:39:09 --- SIGTTIN {si_signo=SIGTTIN, si_code=SI_USER, si_pid=9922, si_uid=1000} ---
[pid  9896] 03:39:09 --- SIGTTIN {si_signo=SIGTTIN, si_code=SI_USER, si_pid=9922, si_uid=1000} ---
[pid  9922] 03:39:09 --- stopped by SIGTTIN ---
[pid  9896] 03:39:09 --- stopped by SIGTTIN ---

确认这个SIGTTIN信号是第二个bash -ic 'sleep 2'进程发出的,kill(0, SIGTTIN)表示它把这个信号发送到自己所在的进程组,整个进程组的进程都接收到这个信号,所以它和它的父进程sleep.sh都变成了stop状态。

脚本里两次执行的bash -ic子进程也都是shell,它们在初始化的时候会有作业控制的逻辑,结合jobs.cinitialize_job_control方法里的代码(shell初始化时调用到这里):

/* We can only have job control if we are interactive. */
if (interactive == 0)
{
  job_control = 0;
  original_pgrp = NO_PID;
  shell_tty = fileno (stderr);
}
else
{
  shell_tty = -1;

  /* If forced_interactive is set, we skip the normal check that stderr
    is attached to a tty, so we need to check here.  If it's not, we
    need to see whether we have a controlling tty by opening /dev/tty,
    since trying to use job control tty pgrp manipulations on a non-tty
    is going to fail. */ 
    // bash "-i" 参数会启用 forced_interactive
  if (forced_interactive && isatty (fileno (stderr)) == 0)
    shell_tty = open ("/dev/tty", O_RDWR|O_NONBLOCK);

  /* Get our controlling terminal.  If job_control is set, or
    interactive is set, then this is an interactive shell no
     matter where fd 2 is directed. */
   if (shell_tty == -1)
    shell_tty = dup (fileno (stderr));/* fd 2 */

  shell_tty = move_to_high_fd (shell_tty, 1, -1);

  /* Compensate for a bug in systems that compiled the BSD
 rlogind with DEBUG defined, like NeXT and Alliant. */
  if (shell_pgrp == 0)
{
  shell_pgrp = getpid ();
  setpgid (0, shell_pgrp);
  tcsetpgrp (shell_tty, shell_pgrp);
}

  while ((terminal_pgrp = tcgetpgrp (shell_tty)) != -1)
{
  if (shell_pgrp != terminal_pgrp)
    {
      SigHandler *ottin;

      ottin = set_signal_handler(SIGTTIN, SIG_DFL);
      kill (0, SIGTTIN); // 第二次执行bash -ic时触发了这里
      set_signal_handler (SIGTTIN, ottin);
      continue;
    }
  break;
}
if (terminal_pgrp == -1)
t_errno = errno;

  /* Make sure that we are using the new line discipline. */
  if (set_new_line_discipline (shell_tty) < 0)
{
  sys_error (_("initialize_job_control: line discipline"));
  job_control = 0;
}
  else
{
  original_pgrp = shell_pgrp;
  shell_pgrp = getpid ();

  // 第一次bash -ic 'sleep 3'触发了这里的 setpgid 修改了当前进程组
  if ((original_pgrp != shell_pgrp) && (setpgid (0, shell_pgrp) < 0))
    {
      sys_error (_("initialize_job_control: setpgid"));
      shell_pgrp = original_pgrp;
    }

  job_control = 1;

  /* If (and only if) we just set our process group to our pid,
     thereby becoming a process group leader, and the terminal
     is not in the same process group as our (new) process group,
     then set the terminal's process group to our (new) process
     group.  If that fails, set our process group back to what it
     was originally (so we can still read from the terminal) and
     turn off job control.  */
  if (shell_pgrp != original_pgrp && shell_pgrp != terminal_pgrp)
    {
      if (give_terminal_to (shell_pgrp, 0) < 0)
    {
      t_errno = errno;
      setpgid (0, original_pgrp);
      shell_pgrp = original_pgrp;
      job_control = 0;
    }
   }
...

关键点就在于shell_pgrpterminal_pgrp这两个变量,shell_pgrp是当前进程组,而terminal_pgrp是占用当前控制终端的进程所在的进程组(前台进程组),这些状态都是可以通过ps观察到的,可以跟踪一下:

$ ps xfo pid,ppid,pgid,sid,tpgid,stat,tty,command | awk "NR==1||/pts\/2/"
  PID  PPID  PGID   SID TPGID STAT TT       COMMAND
12413 12410 12410 12410    -1 S    ?        sshd: hongjiang@pts/0
12414 12413 12414 12414 12580 Ss   pts/0     \_ -bash
12579 12414 12579 12414 12580 S    pts/0         \_ /bin/bash ./sleep.sh
12580 12579 12580 12414 12580 S+   pts/0             \_ sleep 3

$ ps xfo pid,ppid,pgid,sid,tpgid,stat,tty,command | awk "NR==1||/pts\/2/"
  PID  PPID  PGID   SID TPGID STAT TT       COMMAND
12413 12410 12410 12410    -1 S    ?        sshd: hongjiang@pts/0
12414 12413 12414 12414 12414 Ss+  pts/0     \_ -bash
12579 12414 12579 12414 12414 T    pts/0         \_ /bin/bash ./sleep.sh
12607 12579 12579 12414 12414 T    pts/0             \_ bash -ic sleep 2

在第一次执行bash -ic 'sleep 3'的时候,sleep.sh父进程先clone出bash子进程(pid 12580),因为-i参数强制这个bash子进程用交互式运行,它会加载$HOME下的.bashrc等文件,这个过程可能会fork/clone出若干子进程(所以会看到第二次bash -ic sleep 2进程的ID跟第一次不是连续的),等这些配置文件加载完之后,它并不是fork/clone的形式执行sleep 3而是使用当前进程(12580)执行的sleep 3,这里很关键的信息是"PGID"和"TPGID"都是本身进程ID,而非父进程ID,跟第二次的状态不一样。

因为脚本默认是关闭作业控制的,本来每个子进程并不会设置为独立的进程组,比如下面这个脚本:

$ cat a.sh
#!/bin/bash
/usr/bin/sleep 10

$ ps xfo pid,ppid,pgid,sid,tpgid,stat,tty,command | awk "NR==1||/pts\/2/"
  PID  PPID  PGID   SID TPGID STAT TT       COMMAND
12668 12665 12665 12665    -1 S    ?        sshd: hongjiang@pts/2
12669 12668 12669 12669 12736 Ss   pts/2     \_ -bash
12736 12669 12736 12669 12736 S+   pts/2         \_ /bin/bash ./a.sh
12737 12736 12736 12669 12736 S+   pts/2             \_ /usr/bin/sleep 10

上面脚本执行时sleep子进程"PGID"和"TPGID"都是进程父进程a.sh的,并没有被设置为一个独立的进程组。

sleep.sh脚本里之所以会对子进程设置一个独立的进程组,是因为"-i"参数使得bash -ic 'sleep 3'在非交互式脚本里运行时进程被强制设置成了独立的进程组(见initializejobcontroll里的setpgid),同时"TPGID"这个表示前台进程组的状态也被改为了bash -ic 'sleep 3'的进程组ID。

那为什么在接下来的bash -ic 'sleep 2'子进程执行时却不像前面的那样呢?这正是最诡异的地方。它们所在的sleep.sh脚本是非交互式运行的,它本来预期脚本执行过程不应该产生与脚本进程组不一致的前台进程组,所以前台子进程组结束的时候,不会去更新"TPGID",可以用下面脚本来验证:

$ cat wait.sh
#!/bin/bash
bash -ic 'sleep 5'
sleep 4
sleep 3 &  #不让wait.sh进程立即退出
wait

上面wait.sh脚本里第一个子进程强制修改了"TPGID",子进程退出,以及后续再执行前台进程都不会去更新这个状态

$ ps xfo pid,ppid,pgid,sid,tpgid,stat,tty,command | awk "NR==1||/pts\/0/"
  PID  PPID  PGID   SID TPGID STAT TT       COMMAND
13867 13864 13864 13864    -1 S    ?        sshd: hongjiang@pts/0
13868 13867 13868 13868 14138 Ss   pts/0     \_ -bash
14137 13868 14137 13868 14138 S    pts/0         \_ /bin/bash ./wait.sh
14138 14137 14138 13868 14138 S+   pts/0             \_ sleep 5

$ ps xfo pid,ppid,pgid,sid,tpgid,stat,tty,command | awk "NR==1||/pts\/0/"
  PID  PPID  PGID   SID TPGID STAT TT       COMMAND
13867 13864 13864 13864    -1 S    ?        sshd: hongjiang@pts/0
13868 13867 13868 13868 14138 Ss   pts/0     \_ -bash
14137 13868 14137 13868 14138 S    pts/0         \_ /bin/bash ./wait.sh
14165 14137 14137 13868 14138 S    pts/0             \_ sleep 4

$ ps xfo pid,ppid,pgid,sid,tpgid,stat,tty,command | awk "NR==1||/pts\/0/"
  PID  PPID  PGID   SID TPGID STAT TT       COMMAND
13867 13864 13864 13864    -1 S    ?        sshd: hongjiang@pts/0
13868 13867 13868 13868 14138 Ss   pts/0     \_ -bash
14137 13868 14137 13868 14138 S    pts/0         \_ /bin/bash ./wait.sh
14168 14137 14137 13868 14138 S    pts/0             \_ sleep 3

回到sleep.sh脚本里,第二行bash -ic 'sleep 2'子进程初始化时,"TPGID"仍是上个进程bash -ic 'sleep 3'修改过的值。而bash -ic 'sleep 2'子进程也因为"-i"参数让自己以交互式运行,但是在还没有执行到setpgid之前,就先触发了SIGTTIN的逻辑:

if (shell_pgrp != terminal_pgrp)
{
    SigHandler *ottin;

    ottin = set_signal_handler(SIGTTIN, SIG_DFL);
    kill (0, SIGTTIN);
    set_signal_handler (SIGTTIN, ottin);
    continue;
}

因为这段代码会认为终端被其他前台进程占用,对当前进程组发出SIGTTIN信号。在这个场景里,这恰好是一种误会!

当我们显式的对sleep.sh脚本设置开启作业控制时:

$ cat sleep.sh
#!/bin/bash
set -m
bash -ic 'sleep 3'
bash -ic 'sleep 2'

$ ps xfo pid,ppid,pgid,sid,tpgid,stat,tty,command | awk "NR==1||/pts\/2/"
  PID  PPID  PGID   SID TPGID STAT TT       COMMAND
12668 12665 12665 12665    -1 S    ?        sshd: hongjiang@pts/2
12669 12668 12669 12669 12874 Ss   pts/2     \_ -bash
12873 12669 12873 12669 12874 S    pts/2         \_ /bin/bash ./sleep.sh
12874 12873 12874 12669 12874 S+   pts/2             \_ sleep 3

$ ps xfo pid,ppid,pgid,sid,tpgid,stat,tty,command | awk "NR==1||/pts\/2/"
  PID  PPID  PGID   SID TPGID STAT TT       COMMAND
12668 12665 12665 12665    -1 S    ?        sshd: hongjiang@pts/2
12669 12668 12669 12669 12901 Ss   pts/2     \_ -bash
12873 12669 12873 12669 12901 S    pts/2         \_ /bin/bash ./sleep.sh
12901 12873 12901 12669 12901 S+   pts/2             \_ sleep 2

它对每个子进程都设置为独立的进程组,并在每个进程(前台)结束的时候更新"TPGID"为父进程组ID,避免了initialize_job_controll里发送SIGTTIN的逻辑。

有很多shell的问题都是跟作业控制相关的,另一个例子参考tomcat进程意外退出的问题分析;作业控制可以玩出很多高阶花样,但它也大大增加了shell的复杂度,这个例子是一个典型的反面教材,最好不要在非交互式脚本里调用bash -ic来执行命令。

通过strace查看一个进程的标准输出内容

线上某个业务java进程出了一些麻烦,去诊断的时候发现jstack无法输出,可能是jdk或os版本的问题。这时还可以尝试一下kill -3,它默认会输出到进程的标准输出。如果不幸这个进程的标准输出被重定向到了 /dev/null 或者重定向到某个文件,但却因为很多其他日志也在大量的输出,导致日志文件过大,要从中找出线程栈相关的日志,还要耗点时间;这个时候,可以通过strace来跟踪一个进程的标准输入。

strace输出的信息需要一些处理,可以通过管道与其他命令组合(通过-o参数或-ff参数)

这里 -o 参数后边是一个字符串表示输出文件,如果字符串开头是一个"|"会被strace识别为管道

$ strace -f -e trace=write -e verbose=none -e write=1,2 -q -p $pid -o "| grep '^ |' | cut -c11-60 | sed -e 's/ //g' | xxd -r -p"

或者 -ff 参数,用管道与其他命令组合,注意strace的错误输出也要重定向

$ strace -ff -e trace=write -e write=1,2 -s 1024 -q -p $pid 2>&1 | cut -c11-60 | sed -e 's/ //g' | xxd -r -p

不过这两种方式都遇到一个问题,因为buffer的问题导致管道后边的命令没能完全处理strace跟踪到的数据(要等到后续的数据塞满buffer),有点像grep需要--line-buffer解决缓冲区问题,但不知道这里有什么方式,尝试过stdbuf也没有解决。最后只能分两步,先把strace的内容输出到文件,然后再对内容解析:

$ strace -f -e trace=write -e write=1,2 -q -p $pid  -o /tmp/slog

$ grep " |" /tmp/slog | cut -c11-60 | sed -e 's/ //g' | xxd -r -p

tmux下显示ssh目标host的问题

当在tmux下ssh到远程机器时,希望显示远程host,google后找到了一段对ssh封装过的函数:

ssh() {
    if [ "$(ps -p $(ps -p $$ -o ppid=) -o comm=)" = "tmux" ]; then
        tmux rename-window "$*"
        command ssh "$@"
        tmux set-window-option automatic-rename "on" 1>/dev/null
    else
        command ssh "$@"
    fi
}

这段函数在我的mac上运行效果正常,如下图

但当我在一台linux上运行时,ctrl-d退出远程ssh时,会一直卡在退出状态,不管ctrl-c或什么操作也无法回到原bash,如下图

此时只通过tmux的kill-window的操作方式来关掉这个窗口,而在mac下是没有这个问题的,分析了一下,发现在我的mac上,tmux被oh-my-zsh给alias成了一个_zsh_tmux_plugin_run函数:

➜  which ssh
ssh () {
    if [ "$(ps -p $(ps -p $$ -o ppid=) -o comm=)" = "tmux" ]
    then
        _zsh_tmux_plugin_run rename-window "$*"
        command ssh "$@"
        _zsh_tmux_plugin_run set-window-option automatic-rename "on" 1>/dev/null
    else
        command ssh "$@"
    fi
}

_zsh_tmux_plugin_run又做了一些环境变量的判断和处理,猜测可能是因为这些环境变量的差异所导致,先去掉tmux set-window-option automatic-rename "on" 这句最后对标准输出的重定向,看看输出什么信息,结果在修改之后却可以正常了:

还不太清楚为何这个重定向导致了ssh退出后没法回到原shell下,先记录下这个现象。

一次编码问题的排查

上周遇到的一个问题,代码里有通过scala.io.Source.fromFile 方式读取文件内容,并且没有指定编码格式,开始程序运行是ok的,后来添加了中文,发现在某些情况下会遇到乱码问题,并不是必然发生的,而是不同的人ssh登录到linux的测试环境启动应用可能会有不同的结果。这里记录一下当时的情况。

问题的排查,首先确认Source.fromFile这个api里面对编码的使用方式:

def fromFile(name: String)(implicit codec: Codec): BufferedSource =
    fromFile(new JFile(name))(codec)

不指定编码的话,系统使用了一个隐式参数作为默认编码,看一下它是什么:

scala>  def f(implicit c: io.Codec) = c
f: (implicit c: scala.io.Codec)scala.io.Codec

scala> f.name
res6: String = US-ASCII

这台linux上显示的是US-ASCII,而在我的mac上是UTF-8,看来是编码设置的问题,这个值应该是jvm的系统属性里编码相关的:

scala> System.getProperties.foreach(s => if (s.toString.indexOf("enc") != -1) println(s) )
(file.encoding.pkg,sun.io)
(sun.jnu.encoding,ANSI_X3.4-1968)
(file.encoding,ANSI_X3.4-1968)
(sun.io.unicode.encoding,UnicodeLittle)

测试了一下是file.encoding这个系统属性,修改这个属性为UTF-8后确实可以正常的。但是另一个同事登录这台linux后运行却跟我的情况不同,他登录后(使用同一账号)直接jvm的file.encoding默认就是UTF-8,这看起来有些奇怪。

jvm的系统属性,其实也是根据OS的环境变量得到的。虽然这台机器的LANGLC_*等指定了UTF-8,但并不意味jvm的file.encoding也一样:

$ locale
LANG=en_US.UTF-8
LC_CTYPE=UTF-8
LC_NUMERIC="en_US.UTF-8"
LC_TIME="en_US.UTF-8"
LC_COLLATE="en_US.UTF-8"
LC_MONETARY="en_US.UTF-8"
LC_MESSAGES="en_US.UTF-8"
LC_PAPER="en_US.UTF-8"
LC_NAME="en_US.UTF-8"
LC_ADDRESS="en_US.UTF-8"
LC_TELEPHONE="en_US.UTF-8"
LC_MEASUREMENT="en_US.UTF-8"
LC_IDENTIFICATION="en_US.UTF-8"
LC_ALL=

要确认file.encoding属性的话,可以使用locale charmap命令,我指定的结果显示:

$ locale charmap
ANSI_X3.4-1968

ANSI_X3.4-1968是系统默认的编码,而另一个同事显示的是”UTF-8″,又把怀疑落在ssh客户端上。我是在mac下直接通过ssh命令的方式登录,而他则是在windows下使用putty登录。各自打开ssh的 -verbose参数:

$ ssh -v xxx@ip

他的展示信息里出现了:

debug1: Sending env LC_ALL = en_US.UTF-8 
debug1: Sending env LANG = zh_CN.UTF-8 

而我的ssh客户端则没有这些信息,确实是ssh客户端配置所引起的差异。(关于LC_*LC_ALL等环境变量的关系后续有精力再整理)

检测最耗cpu的线程的脚本

这个脚本用于定位出当前java进程里最耗cpu的那个线程,给出cpu的占用率和当前堆栈信息。这个脚本仅限于linux上,我没有找到在mac下定位线程使用cpu情况的工具,如果你知道请告诉我一下。

先模拟一个耗cpu的java进程,启动一个scala的repl并在上面跑一段死循环:

scala> while(true) {}

脚本执行效果:

$ ./busythread.sh `pidof java`
tid: 431  cpu: %98.8
"main" prio=10 tid=0x00007f777800a000 nid=0x1af runnable [0x00007f7781c2e000]
    java.lang.Thread.State: RUNNABLE
    at $line3.$read$$iw$$iw$.<init>(<console>:8)
    at $line3.$read$$iw$$iw$.<clinit>(<console>)
    at $line3.$eval$.$print$lzycompute(<console>:7)
    - locked <0x00000000fc201758> (a $line3.$eval$)
    at $line3.$eval$.$print(<console>:6)
    at $line3.$eval.$print(<console>)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:606)
    at scala.tools.nsc.interpreter.IMain$ReadEvalPrint.call(IMain.scala:739)
    at scala.tools.nsc.interpreter.IMain$Request.loadAndRun(IMain.scala:986)
    at scala.tools.nsc.interpreter.IMain$WrappedRequest$$anonfun$loadAndRunReq$1.apply(IMain.scala:593)
    at scala.tools.nsc.interpreter.IMain$WrappedRequest$$anonfun$loadAndRunReq$1.apply(IMain.scala:592)
    at scala.reflect.internal.util.ScalaClassLoader$class.asContext(ScalaClassLoader.scala:31)
    at scala.reflect.internal.util.AbstractFileClassLoader.asContext(AbstractFileClassLoader.scala:19)
    at scala.tools.nsc.interpreter.IMain$WrappedRequest.loadAndRunReq(IMain.scala:592)
    at scala.tools.nsc.interpreter.IMain.interpret(IMain.scala:524)
    at scala.tools.nsc.interpreter.IMain.interpret(IMain.scala:520)

脚本内容:

#!/bin/bash

if [ $# -eq 0 ];then
    echo "please enter java pid"
    exit -1
fi

pid=$1
jstack_cmd=""

if [[ $JAVA_HOME != "" ]]; then
    jstack_cmd="$JAVA_HOME/bin/jstack"
else
    r=`which jstack 2>/dev/null`
    if [[ $r != "" ]]; then
        jstack_cmd=$r
    else
        echo "can not find jstack"
        exit -2
    fi
fi

#line=`top -H  -o %CPU -b -n 1  -p $pid | sed '1,/^$/d' | grep -v $pid | awk 'NR==2'`

line=`top -H -b -n 1 -p $pid | sed '1,/^$/d' | sed '1d;/^$/d' | grep -v $pid | sort -nrk9 | head -1`
echo "$line" | awk '{print "tid: "$1," cpu: %"$9}'
tid_0x=`printf "%0x" $(echo "$line" | awk '{print $1}')`
$jstack_cmd $pid | grep $tid_0x -A20 | sed -n '1,/^$/p'

脚本已放到服务器上,可以通过下面的方式执行:

$ bash <(curl -s http://hongjiang.info/busythread.sh)  java_pid

update: 感谢容若的反馈,很多环境的procps版本较低,top还不支持-o参数,排序那块用sort解决了,脚本已更新。

tomcat-connector的微调(1): acceptCount参数

对于acceptCount这个参数,含义跟字面意思并不是特别一致(个人感觉),容易跟maxConnections,maxThreads等参数混淆;实际上这个参数在tomcat里会被映射成backlog:

static {
    replacements.put("acceptCount", "backlog");
    replacements.put("connectionLinger", "soLinger");
    replacements.put("connectionTimeout", "soTimeout");
    replacements.put("rootFile", "rootfile");
}

backlog表示积压待处理的事物,是socket的参数,在bind的时候传入的,比如在Endpoint里的bind方法里:

public void bind() throws Exception {

    serverSock = ServerSocketChannel.open();
    ...
    serverSock.socket().bind(addr,getBacklog());
    ...
}

这个参数跟tcp底层实现的半连接队列和完全连接队列有什么关系呢?我们在tomcat默认BIO模式下模拟一下它的效果。

模拟的思路还是简单的通过shell脚本,建立一个长连接发送请求,持有20秒再断开,好有时间观察网络状态。注意BIO模式下默认超过75%的线程时会关闭keep-alive,需要把这个百分比调成100,这样就不会关闭keep-alive了。修改后的connector如下,最后边的三行参数是新增的:

<Connector port="8080" protocol="HTTP/1.1"
    connectionTimeout="20000"
    redirectPort="8443"        

    maxThreads="1"
    disableKeepAlivePercentage="100"
    acceptCount="2"
/>

上面的配置里我们把tomcat的最大线程数设置为1个,一直开启keep-alive,acceptCount设置为2。在linux上可以通过ss命令检测参数是否生效:

$ ss -ant  
State       Recv-Q Send-Q     Local Address:Port     Peer Address:Port
LISTEN      0      2          :::7001                :::*

可以看到7001端口是LISTEN状态,send-q的值是2,也就是我们设置的backlog的值。如果我们不设置,tomcat默认会设置为100,java则默认是50。

然后用下面的脚本模拟一次长连接:

$ { 
    echo -ne "POST /main HTTP/1.1\nhost: localhost:7001\n\n";
    sleep 20
  } | telnet localhost 7001

这个时候看服务器端socket的状况,是ESTABLISHED,并且Recv-QSend-Q都是没有堆积的,说明请求已经处理完

$ netstat -an | awk 'NR==2 || $4~/7001/'
Proto Recv-Q Send-Q  Local Address          Foreign Address        (state)
tcp4       0      0  127.0.0.1.7001         127.0.0.1.54453        ESTABLISHED

现在我们模拟多个连接:

$ for i in {1..5}; do 
    ( 
        {
          echo -ne "POST /main HTTP/1.1\nhost: localhost:7001\n\n"; 
          sleep 20
        } | telnet localhost 7001
    )&;  
  done 

上面发起了5个链接,服务器端只有1个线程,只有第一个连接上的请求会被处理,另外4次连接,有2个连接还是完成了建立(ESTABLISHED状态),还有2个连接则因为服务器端的连接队列已满,没有响应,发送端处于SYN_SENT状态。下面列出发送端的tcp状态:

$ netstat -an | awk 'NR==2 || $5~/7001/'
Proto Recv-Q Send-Q  Local Address          Foreign Address        (state)
tcp4       0      0  127.0.0.1.51389        127.0.0.1.7001         SYN_SENT
tcp4       0      0  127.0.0.1.51388        127.0.0.1.7001         SYN_SENT
tcp4       0      0  127.0.0.1.51387        127.0.0.1.7001         ESTABLISHED
tcp4       0      0  127.0.0.1.51386        127.0.0.1.7001         ESTABLISHED
tcp4       0      0  127.0.0.1.51385        127.0.0.1.7001         ESTABLISHED

再看tomcat端的状态:

$ netstat -an | awk 'NR==2 || $4~/7001/'
Proto Recv-Q Send-Q  Local Address          Foreign Address        (state)
tcp4      45      0  127.0.0.1.7001         127.0.0.1.51387        ESTABLISHED
tcp4      45      0  127.0.0.1.7001         127.0.0.1.51386        ESTABLISHED
tcp4       0      0  127.0.0.1.7001         127.0.0.1.51385        ESTABLISHED

有3个链接,除了第一条连接请求的Recv-Q是0,另外两个连接的Recv-Q则有数据堆积(大小表示发送过来的字节长度)。注意,在ESTABLISHED状态下看到的Recv-QSend-Q的大小与在LISTEN状态下的含义不同,在LISTEN状态下的大小表示队列的长度,而非数据的大小。

从上面的模拟可以看出acceptCount参数是指服务器端线程都处于busy状态时(线程池已满),还可接受的连接数,即tcp的完全连接队列的大小。对于完全队列的计算,在linux上是:

min(backlog,somaxconn) 

backlog参数和proc/sys/net/core/somaxconn这两个值哪个小选哪个。

不过acceptCount/backlog参数还不仅仅决定完全连接队列的大小,对于半连接队列也有影响。参考同事飘零的blog,在linux 2.6.20内核之后,它的计算方式大致是:

table_entries = min(min(somaxconn,backlog),tcp_max_syn_backlog)
roundup_pow_of_two(table_entries + 1)

第二行的函数roundup_pow_of_two表示取最近的2的n次方的值,举例来说:假设somaxconn为128,backlog值为50,tcp_max_syn_backlog值为4096,则第一步计算出来的为50,然后roundup_pow_of_two(50 + 1),找到比51大的2的n次方的数为64,所以最终半连接队列的长度是64。

所以对于acceptCount这个值,需要慎重对待,如果请求量不是很大,通常tomcat默认的100也ok,但若访问量较大的情况,建议这个值设置的大一些,比如1024或更大。如果在tomcat前边一层对synflood攻击的防御没有把握的话,最好也开启syn cookie来防御。

tomcat进程意外退出: oom-killer

在非jvm crash引起的tomcat进程意外退出的故障里,oom-killer是见过的比例最多的情况,排查这类问题时应首先判断是否由oom-killer所致。这个问题在答疑中遇到好几次,记录一下给新人了解。

定位oom-killer通常比较简单,直接通过dmesg即可看到:

$  sudo dmesg | grep java | grep -i oom-killer
[6989889.606947] java invoked oom-killer: gfp_mask=0x280da, order=0, oom_adj=0, oom_score_adj=0
[7061818.494917] java invoked oom-killer: gfp_mask=0x201da, order=0, oom_adj=0, oom_score_adj=0
[7108961.621382] java invoked oom-killer: gfp_mask=0x280da, order=0, oom_adj=0, oom_score_adj=0

或者在日志中按java关键字搜索,会看到类似下面的日志:

[7250516.311246] Out of memory: Kill process 15041 (java) score 869 or sacrifice child
[7250516.311255] Killed process 15041, UID 505, (java) total-vm:2307028kB, anon-rss:1780636kB, file-rss:872kB

不过这里有个问题,日志的格式,不能之间看出被kill时的信息,除非你确定被kill的java进程id就是之前tomcat的进程id(在ali-tomcat会记录在一个文件里)。

在高版本的dmesg命令里,有一个很人性化的参数-T来以正常的时间格式来显示日志的,但很多时候会碰到比较低的版本:

$ rpm -qf /bin/dmesg
util-linux-2.13-0.56.el5

小于util-linux-2.20版本的无法使用这个参数,只有变通的通过下面的方式转换一下,从stackoverflow上学到的:

dmesg_with_human_timestamps () {
$(type -P dmesg) "$@" | perl -w -e 'use strict;
    my ($uptime) = do { local @ARGV="/proc/uptime";<>}; ($uptime) = ($uptime =~ /^(\d+)\./);
    foreach my $line (<>) {
        printf( ($line=~/^\[\s*(\d+)\.\d+\](.+)/) ? ( "[%s]%s\n", scalar localtime(time - $uptime + $1), $2 ) : $line )
    }'
}
alias dmesg=dmesg_with_human_timestamps

把上面的函数和alias加到.bashrc里,source一下,可以得到正常的日期格式了:

$ dmesg | grep "(java)"

[Thu Aug 28 20:50:14 2014] Out of memory: Kill process 18078 (java) score 872 or sacrifice child
[Thu Aug 28 20:50:14 2014] Killed process 18078, UID 505, (java) total-vm:2390108kB, anon-rss:1784964kB, file-rss:2048kB
[Fri Aug 29 14:48:06 2014] Out of memory: Kill process 15041 (java) score 869 or sacrifice child
[Fri Aug 29 14:48:06 2014] Killed process 15041, UID 505, (java) total-vm:2307028kB, anon-rss:1780636kB, file-rss:872kB

开启oom-killer的话,在/proc/pid下对每个进程都会多出3个与oom打分调节相关的文件,如果想要关闭,可能涉及运维的管理,要跟各方沟通好。临时对某个进程可以忽略oom-killer可以使用下面的方式:

$ echo -17 > /proc/$(pidof java)/oom_adj

更多有关oom-killer的可参看这篇

JVM上的随机数与熵池策略

在apache-tomcat官方文档:如何让tomcat启动更快 里面提到了一些启动时的优化项,其中一项是关于随机数生成时,采用的“熵源”(entropy source)的策略。

他提到tomcat7的session id的生成主要通过java.security.SecureRandom生成随机数来实现,随机数算法使用的是”SHA1PRNG”

private String secureRandomAlgorithm = "SHA1PRNG";

在sun/oracle的jdk里,这个算法的提供者在底层依赖到操作系统提供的随机数据,在linux上,与之相关的是/dev/random/dev/urandom,对于这两个设备块的描述以前也见过讨论随机数的文章,wiki中有比较详细的描述,摘抄过来,先看/dev/random

在读取时,/dev/random设备会返回小于熵池噪声总数的随机字节。/dev/random可生成高随机性的公钥或一次性密码本。若熵池空了,对/dev/random的读操作将会被阻塞,直到收集到了足够的环境噪声为止

/dev/urandom 则是一个非阻塞的发生器:

dev/random的一个副本是/dev/urandom (”unlocked”,非阻塞的随机数发生器),它会重复使用熵池中的数据以产生伪随机数据。这表示对/dev/urandom的读取操作不会产生阻塞,但其输出的熵可能小于/dev/random的。它可以作为生成较低强度密码的伪随机数生成器,不建议用于生成高强度长期密码。

另外wiki里也提到了为什么linux内核里的随机数生成器采用SHA1散列算法而非加密算法,是为了避开法律风险(密码出口限制)。

回到tomcat文档里的建议,采用非阻塞的熵源(entropy source),通过java系统属性来设置:

-Djava.security.egd=file:/dev/./urandom

这个系统属性egd表示熵收集守护进程(entropy gathering daemon),但这里值为何要在devrandom之间加一个点呢?是因为一个jdk的bug,在这个bug的连接里有人反馈及时对 securerandom.source 设置为 /dev/urandom 它也仍然使用的 /dev/random,有人提供了变通的解决方法,其中一个变通的做法是对securerandom.source设置为 /dev/./urandom 才行。也有人评论说这个不是bug,是有意为之。

我看了一下我当前所用的jdk7的java.security文件里,配置里仍使用的是/dev/urandom

#
# Select the source of seed data for SecureRandom. By default an
# attempt is made to use the entropy gathering device specified by
# the securerandom.source property. If an exception occurs when
# accessing the URL then the traditional system/thread activity
# algorithm is used.
#
# On Solaris and Linux systems, if file:/dev/urandom is specified and it
# exists, a special SecureRandom implementation is activated by default.
# This "NativePRNG" reads random bytes directly from /dev/urandom.
#
# On Windows systems, the URLs file:/dev/random and file:/dev/urandom
# enables use of the Microsoft CryptoAPI seed functionality.
#
securerandom.source=file:/dev/urandom

我不确定jdk7里,这个 /dev/urandom 也同那个bug报告里所说的等同于 /dev/random;要使用非阻塞的熵池,这里还是要修改为/dev/./urandom 呢,还是jdk7已经修复了这个问题,就是同注释里的意思,只好验证一下。

使用bug报告里给出的代码:

import java.security.SecureRandom;
class JRand {
    public static void main(String args[]) throws Exception {
        System.out.println("Ok: " +
            SecureRandom.getInstance("SHA1PRNG").nextLong());
    }
}

然后设置不同的系统属性来验证,先是在我的mac上:

% time java -Djava.security.egd=file:/dev/urandom  JRand
Ok: 8609191756834777000
java -Djava.security.egd=file:/dev/urandom JRand  
0.11s user 0.03s system 115% cpu 0.117 total

% time java -Djava.security.egd=file:/dev/./urandom  JRand
Ok: -3573266464480299009
java -Djava.security.egd=file:/dev/./urandom JRand  
0.11s user 0.03s system 116% cpu 0.116 total

可以看到/dev/urandom/dev/./urandom 的执行时间差不多,有点纳闷,再仔细看一下wiki里说的:

FreeBSD操作系统实现了256位的Yarrow算法变体,以提供伪随机数流。与Linux的/dev/random不同,FreeBSD的/dev/random不会产生阻塞,与Linux的/dev/urandom相似,提供了密码学安全的伪随机数发生器,而不是基于熵池。而FreeBSD的/dev/urandom则只是简单的链接到了/dev/random。

尽管在我的mac上/dev/urandom并不是/dev/random的链接,但mac与bsd内核应该是相近的,/dev/random也是非阻塞的,/dev/urandom是用来兼容linux系统的,这两个随机数生成器的行为是一致的。参考这里

然后再到一台ubuntu系统上测试:

% time java -Djava.security.egd=file:/dev/urandom  JRand
Ok: 6677107889555365492
java -Djava.security.egd=file:/dev/urandom JRand  
0.14s user 0.02s system 9% cpu 1.661 total

% time java -Djava.security.egd=file:/dev/./urandom  JRand
Ok: 5008413661952823775
java -Djava.security.egd=file:/dev/./urandom JRand  
0.12s user 0.02s system 99% cpu 0.145 total

这回差异就完全体现出来了,阻塞模式的熵池耗时用了1.6秒,而非阻塞模式则只用了0.14秒,差了一个数量级,当然代价是转换为对cpu的开销了。

// 补充,连续在ubuntu上测试几次/dev/random方式之后,导致熵池被用空,被阻塞了60秒左右。应用服务器端要避免这种方式。

shell脚本里后台进程忽略SIGINT信号问题排查

这篇blog是同事涧泉在和我一起分析tomcat进程意外退出时,针对`SIGINT`的疑惑,他的一些记录,我这里转载一下。

问题简述

写一个简单的 C 语言程序 “a.c”, 用一个死循环 hold 住.

int main() {
    for (;;) { }
    return 0;
}

写一个简单的 makefile 文件. 为了方便调试, 添加 -g 参数生成调试信息.

a: a.c
    gcc -g a.c -o a

编译程序:

[observer.hany@v125205215 ~/tmp]$ make
gcc -g a.c -o a

在当前 shell 下后台运行程序, 使用 kill 命令向进程发 SIGINT 信号, 可看到进程正常中断退出.

[observer.hany@v125205215 ~/tmp]$ ./a & 
[1] 32533
[observer.hany@v125205215 ~/tmp]$ ps -C a -f
UID        PID  PPID  C STIME TTY          TIME CMD
54241    32533  9744 98 11:37 pts/1    00:00:05 ./a

[observer.hany@v125205215 ~/tmp]$ kill -SIGINT 32533
[observer.hany@v125205215 ~/tmp]$ jobs
[1]+  中断                    ./a
[observer.hany@v125205215 ~/tmp]$ ps -C a -f
UID        PID  PPID  C STIME TTY          TIME CMD

编写如下简单 sh 脚本 “a.sh”.

#!/bin/bash
./a &

使用脚本启动后台进程, 再使用 kill 向进程发送 SIGINT 信号, 进程却不会退出.

[observer.hany@v125205215 ~/tmp]$ ./a.sh 
[observer.hany@v125205215 ~/tmp]$ ps -C a -f
UID        PID  PPID  C STIME TTY          TIME CMD
54241    12448     1 81 11:50 pts/1    00:00:03 ./a

[observer.hany@v125205215 ~/tmp]$ kill -2 12448
[observer.hany@v125205215 ~/tmp]$ ps -C a -f
UID        PID  PPID  C STIME TTY          TIME CMD
54241    12448     1 98 11:50 pts/1    00:37:24 ./a

但直接 kill (默认发送 SIGTERM 信号) 可以使进程退出.

[observer.hany@v125205215 ~/tmp]$ kill 12448
[observer.hany@v125205215 ~/tmp]$ ps -C a -f
UID        PID  PPID  C STIME TTY          TIME CMD

确认进程是否收到信号

尝试用 strace 命令查看两种情况下程序运行的差异.

第一种情况, shell 下直接运行程序:

[observer.hany@v125205215 ~/tmp]$ ./a &
[1] 5309
[observer.hany@v125205215 ~/tmp]$ ps -C a -f
UID        PID  PPID  C STIME TTY          TIME CMD
54241     5309  9744 99 12:51 pts/1    00:00:03 ./a

使用 strace 监控进程:

[observer.hany@v125205215 ~]$ sudo strace -p 5309
Process 5309 attached - interrupt to quit

发送 SIGINT 信号, 可以看到进程退出了.

[observer.hany@v125205215 ~/tmp]$ kill -SIGINT 5309
[observer.hany@v125205215 ~/tmp]$ jobs
[1]+  中断                    ./a
[observer.hany@v125205215 ~/tmp]$ ps -C a -f
UID        PID  PPID  C STIME TTY          TIME CMD

strace 监控到完整输出如下:

[observer.hany@v125205215 ~]$ sudo strace -p 5309
Process 5309 attached - interrupt to quit
--- SIGINT (Interrupt) @ 0 (0) ---
Process 5309 detached

第二种情况, 使用脚本在后台运行程序:

[observer.hany@v125205215 ~/tmp]$ ./a.sh 
[observer.hany@v125205215 ~/tmp]$ ps -C a -f
UID        PID  PPID  C STIME TTY          TIME CMD
54241     9512     1 99 12:55 pts/1    00:00:03 ./a

使用 strace 监控进程:

[observer.hany@v125205215 ~]$ sudo strace -p 9512
Process 9512 attached - interrupt to quit

发送 SIGINT 信号, 进程没有退出.

[observer.hany@v125205215 ~/tmp]$ kill -SIGINT 9512
[observer.hany@v125205215 ~/tmp]$ ps -C a -f
UID        PID  PPID  C STIME TTY          TIME CMD
54241     9512     1 98 12:55 pts/1    00:02:07 ./a

strace 可以看到进程确实收到了 SIGINT 信号, 但进程没有退出.

[observer.hany@v125205215 ~]$ sudo strace -p 9512
Process 9512 attached - interrupt to quit
--- SIGINT (Interrupt) @ 0 (0) ---

直接 kill (默认发送 SIGTERM 信号), 进程才退出.

[observer.hany@v125205215 ~/tmp]$ kill 9512
[observer.hany@v125205215 ~/tmp]$ ps -C a -f
UID        PID  PPID  C STIME TTY          TIME CMD

完整 strace 输出如下:

[observer.hany@v125205215 ~]$ sudo strace -p 9512
Process 9512 attached - interrupt to quit
--- SIGINT (Interrupt) @ 0 (0) ---
--- SIGTERM (Terminated) @ 0 (0) ---
Process 9512 detached

确认进程信号处理逻辑

查了一下 gnu libc Termination-Signals 文档和 linux man 7 signal 文档,
默认情况下进程对 SIGINT 和 SIGTERM 信号的处理过程都是 Term, 终止进程.

strace 只能看到进程收到了信号, 看不到进程对信号的处理过程.
猜想是不是可能两者的处理逻辑并不完全一致,
SIGINT 做了什么特殊判断, 在某种特殊情况下不终止程序.

尝试用 systemtap 监控 probe::signal.handle, 看是否能找到两种信号处理程序的差异.
因为测试机上 linux 内核和 stap 版本太低, 无法监控 “signal.handle”.
要调试具体信号处理逻辑, 需要调试到 linux 信号处理的内核代码,
目前难以做到, 放弃了这种方式.

查看进程信号处理 handler

因为不用 shell 启动进程时, 如 ubuntu 下 “Alt + F2” 运行程序,
进程也是会被 SIGINT 正常终止的.
怀疑是 shell 修改了进程的默认信号处理器.
尝试用 systemtap 监控 “syscall.sigaction” 系统调用,
测试机上的 linux 内核和 stap 版本也不支持监控 “syscall.sigaction”.
尝试监控了一下 probe::signal.do_action, 输出信息太多, 没有找到有用信息.

修改程序代码 “a.c”, 让进程启动时自己查询对应的信号处理器, 重新编译程序.

#include <stdio.h>
#include <signal.h>

struct sigaction hdl_int;
struct sigaction hdl_term;

int main() {
    sigaction(SIGINT, NULL, &hdl_int);
    sigaction(SIGTERM, NULL, &hdl_term);
    for (;;) { }
    return 0;
}

第一种情况, 直接在 shell 启动程序:

[observer.hany@v125205215 ~/tmp]$ ./a &
[1] 29385
[observer.hany@v125205215 ~/tmp]$ ps -C a -f
UID        PID  PPID  C STIME TTY          TIME CMD
54241    29385  9744 99 13:50 pts/1    00:00:04 ./a

使用 gdb attach 到进程 (省略了一些冗余输出):

[observer.hany@v125205215 ~/tmp]$ gdb a 29385
GNU gdb (GDB) Red Hat Enterprise Linux (7.0.1-37.el5)
... ...
Loaded symbols for /lib64/ld-linux-x86-64.so.2
main () at a.c:10
10      for (;;) { }

可以看到进程中断到第 10 行死循环的位置, 使用 gdb 查看获取的两个信号处理器信息:

(gdb) p hdl_int
$1 = {__sigaction_handler = {sa_handler = 0, sa_sigaction = 0}, sa_mask = {__val = {0, 
      0, 140526787057128, 1, 0, 1, 210456656896, 140733374433184, 0, 210455544752, 
      140526787062592, 4476012448, 4294967295, 140526787064672, 6293608, 0}}, 
  sa_flags = 0, sa_restorer = 0x31002302d0 <__restore_rt>}
(gdb) p hdl_term
$2 = {__sigaction_handler = {sa_handler = 0, sa_sigaction = 0}, sa_mask = {__val = {0, 
      0, 140526787057128, 1, 0, 1, 210456656896, 140733374433184, 0, 210455544752, 
      140526787062592, 4476012448, 4294967295, 140526787064672, 6293608, 0}}, 
  sa_flags = 0, sa_restorer = 0x31002302d0 <__restore_rt>}

看到两个信号处理器都是 “0”, 从信号处理头文件中可找到如下常量定义:

/* Fake signal functions.  */
#define SIG_ERR ((__sighandler_t) -1)           /* Error return.  */
#define SIG_DFL ((__sighandler_t) 0)            /* Default action.  */
#define SIG_IGN ((__sighandler_t) 1)            /* Ignore signal.  */

可知 “0” 表示默认信号处理程序, 但实际的信号处理逻辑函数地址是看不到的.

向进程发送 SIGINT 信号, 进程终止:

(gdb) signal SIGINT
Continuing with signal SIGINT.

Program terminated with signal SIGINT, Interrupt.
The program no longer exists.

第二中情况, 使用脚本启动后台进程.

[observer.hany@v125205215 ~/tmp]$ ./a.sh 
[observer.hany@v125205215 ~/tmp]$ ps -C a -f
UID        PID  PPID  C STIME TTY          TIME CMD
54241    13670     1 99 14:08 pts/0    00:00:03 ./a

gdb 重新 attach 到新进程:

(gdb) attach 13670
Attaching to program: /home/observer.hany/tmp/a, process 13670
Reading symbols from /usr/local/snoopy/lib/snoopy.so...done.
Loaded symbols for /usr/local/snoopy/lib/snoopy.so
Reading symbols from /lib64/libc.so.6...(no debugging symbols found)...done.
Loaded symbols for /lib64/libc.so.6
Reading symbols from /lib64/libdl.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib64/libdl.so.2
Reading symbols from /lib64/ld-linux-x86-64.so.2...(no debugging symbols found)...done.
Loaded symbols for /lib64/ld-linux-x86-64.so.2
main () at a.c:10
10      for (;;) { }

查看信号处理器信息:

(gdb) p hdl_int
$3 = {__sigaction_handler = {sa_handler = 0x1, sa_sigaction = 0x1}, sa_mask = {__val = {
      0, 0, 140457683965416, 1, 0, 1, 210456656896, 140733569554304, 0, 210455544752, 
      140457683970880, 4671133568, 4294967295, 140457683972960, 6293608, 0}}, 
  sa_flags = 0, sa_restorer = 0x31002302d0 <__restore_rt>}
(gdb) p hdl_term
$4 = {__sigaction_handler = {sa_handler = 0, sa_sigaction = 0}, sa_mask = {__val = {0, 
      0, 140457683965416, 1, 0, 1, 210456656896, 140733569554304, 0, 210455544752, 
      140457683970880, 4671133568, 4294967295, 140457683972960, 6293608, 0}}, 
  sa_flags = 0, sa_restorer = 0x31002302d0 <__restore_rt>}

这时看到 SIGINT 的信号处理器 hdl_int 是常量 “1”,
从头文件常量定义可查到即是 SIG_IGN, 忽略信号.

问题终于水落石出了, 原来是第二种情况, 在 shell 脚本运行后台程序时,
SIGINT 的信号处理器被设置成了 SIG_IGN, 忽略信号.

发送 SIGINT 信号, 可看到程序继续运行不会退出,
发送 SIGTERM 信号后, 程序终止.

(gdb) signal SIGINT
Continuing with signal SIGINT.
^C
Program received signal SIGINT, Interrupt.
main () at a.c:10
10      for (;;) { }
(gdb) signal SIGTERM
Continuing with signal SIGTERM.

Program terminated with signal SIGTERM, Terminated.
The program no longer exists.

确认是进程信号处理器被修改,
重新修改监控 probe::signal.do_action 的 stap 脚本,
缩小监控范围, 只监控信号为 SIGINT (常量 “2”) 并且用户 pid 为当前测试用户的调用.

function time_str() {
    return ctime(gettimeofday_s() + 8 * 60 * 60);
}

probe begin {
    printdln(" ", time_str(), "BEGIN");
}

probe end {
    printdln(" ", time_str(), "END");
}

probe signal.do_action {
    if (sig != 2
        || uid() != 54241
        // || execname() != "a"
        // || execname() != "bash"
        ) {
        next;
    }
    printdln(" ", time_str(), execname(), name,
        sig_name, sa_handler,
        "")
}

启动 stap 监控脚本:

[observer.hany@v125205215 ~]$ sudo stap -g trace-sig.stp
[sudo] password for observer.hany: 
Tue Feb 11 14:26:43 2014 BEGIN

再次执行 ./a.sh 脚本, 果然监控到如下输出:

Tue Feb 11 14:29:50 2014 bash do_action SIGINT 4491008 
Tue Feb 11 14:29:50 2014 bash do_action SIGINT 4491008 
Tue Feb 11 14:29:50 2014 bash do_action SIGINT 0 
Tue Feb 11 14:29:50 2014 a.sh do_action SIGINT 0 
Tue Feb 11 14:29:50 2014 a.sh do_action SIGINT 0 
Tue Feb 11 14:29:50 2014 a.sh do_action SIGINT 0 
Tue Feb 11 14:29:50 2014 a.sh do_action SIGINT 1 
Tue Feb 11 14:29:50 2014 bash do_action SIGINT 4491008 
Tue Feb 11 14:29:50 2014 bash do_action SIGINT 4491008 
Tue Feb 11 14:29:50 2014 bash do_action SIGINT 4703312 
Tue Feb 11 14:29:50 2014 a do_action SIGINT 0 

确认是 “a.sh” 脚本进程执行了将 SIGINT 的处理器设置成 “1”, 即 SIG_IGN, 的操作.

非交互式 shell 问题

后来找到 Get rid of SIGINT 这篇文章 (需要翻墙才能访问),
讲到这是非交互式 shell 的一个问题.

shell 命令行下是交互式模式 (interactive),
运行是脚本时是非交互式模式 (non-interactive).
非交互式 shell 默认禁用了 job control,
这时启动后台进程时 shell 会设置后台进程忽略 SIGINT 等信号.
大概行为伪码如下:

if(!fork()) {
  /* child */
  signal(SIGINT, SIG_IGN);
  signal(SIGQUIT, SIG_IGN);

  execve(...cmd...);
}

execve 启动进程时会继承信号处理器:

  • POSIX.1-2001 specifies that the dispositions of any signals that are
    ignored or set to the default are left unchanged.

因此默认情况下 shell 脚本启动的后台进程会忽略 SIGINT 等信号.
可以在 shell 脚本中设置 set -m 打开 job control, 避免这个问题.