作者归档:hongjiang

《Scala函数式编程》中文版勘误2

感谢 shuai.xie 提出的这段漏掉的内容,这里补充一下。

这里b的类型声明并不是必须的。因为我们已经告诉Scala返回类型为B => C,Scala会从上下文获知b的类型,方法的实现部分只需要写为 b => f(a,b)就可以了。如果Scala能够推断出函数字面量的类型,就可以省略掉它的类型声明。

相关阅读:《Scala函数式编程》中文版勘误

记录几个实践中的问题

1) nginx禁止对写操作timeout时retry

以前遇到的一个case,业务那边说一笔请求从nginx端发送给后端tomcat了2次(落在两个不同的tomcat节点上)。后来发现是nginx发给后端节点timeout,然后做了重试,发给了另一个节点。默认情况下nginx对后端error 和 timeout 都会做retry,可以明确的禁止在timeout的情况下禁止retry。当然如果集群读写分离的话,对于只读集群retry是无所谓的,但对于写确实存在问题。

2) kafka重启时因为数据日志文件名被人重命名过而导致启动失败

启动kafka broker的时候,会重新load之前的每个topic的数据,正常情况下会提示每个topic恢复完成。

INFO Recovering unflushed segment 588022 in log xxx-topic-0. (kafka.log.Log)
INFO Completed load of log xxx-topic-0 with log end offset 590676 (kafka.log.Log)

但当有些topic下的数据恢复失败的时候,会导致broker关闭,异常如下

ERROR There was an error in one of the threads during logs loading: java.lang.NumberFormatException: For input string: "test" (kafka.log.LogManager)
FATAL [Kafka Server 3], Fatal error during KafkaServer startup. Prepare to shutdown (kafka.server.KafkaServer)

java.lang.NumberFormatException: For input string: "test"
      at java.lang.NumberFormatException.forInputString(NumberFormatException.java:65)
      at java.lang.Long.parseLong(Long.java:589)
      at java.lang.Long.parseLong(Long.java:631)
      at scala.collection.immutable.StringLike$class.toLong(StringLike.scala:251)
      at scala.collection.immutable.StringOps.toLong(StringOps.scala:30)
      at kafka.log.Log$$anonfun$loadSegments$4.apply(Log.scala:152)
      at kafka.log.Log$$anonfun$loadSegments$4.apply(Log.scala:141)
      at scala.collection.TraversableLike$WithFilter$$anonfun$foreach$1.apply(TraversableLike.scala:778)
      at scala.collection.IndexedSeqOptimized$class.foreach(IndexedSeqOptimized.scala:33)
      at scala.collection.mutable.ArrayOps$ofRef.foreach(ArrayOps.scala:186)
      at scala.collection.TraversableLike$WithFilter.foreach(TraversableLike.scala:777)
      at kafka.log.Log.loadSegments(Log.scala:141)
      at kafka.log.Log.<init>(Log.scala:67)
      at kafka.log.LogManager$$anonfun$loadLogs$2$$anonfun$3$$anonfun$apply$7$$anonfun$apply$1.apply$mcV$sp(LogManager.scala:142)
      at kafka.utils.Utils$$anon$1.run(Utils.scala:54)
      at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
      at java.util.concurrent.FutureTask.run(FutureTask.java:266)
      at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
      at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
      at java.lang.Thread.run(Thread.java:745)

这是因为某个目录下,存在一个 test.log 的文件

$ ls mytopic-0/
00000000000000000485.index  00000000000000000485.log  00000000000000000568.index  00000000000000000568.log  test.log

看上去这个 test.log 当时是把 00…log 给拷贝了一个,然后用编辑器去查看内容。而事后忘了清理掉,导致重启时把这个文件当成一个畸形文件了。因为kafka broker要求所有数据文件名称都是Long类型的。

3) 又一个actor阻塞的例子

在我自己的mac上测试的时候,一切正常,部署到dev环境就严重超时。jstack观察发现又是误用阻塞操作导致所有actor的线程都被阻塞所致,当时 EventProcessor 这个 Router 背后的实例数设置的是40,而这台dev环境的linux只有2核,根据当时akka的配置里的并发因子算出并发线程数是32,所以32个线程基本都被 eventProcessor 的40个actor全给占用了,因为它是不断发消息轮询的(我的mac是8核,运行时的线程数要大于40不会发生全部被阻塞的情况)。解决方式,一方面调大并发因子,把线城数提升上去,另一方面控制 eventProcessor 的实例数,不让它的阻塞操作影响到其他actor。(其实根上是没设计好,没有隔离阻塞操作,只不过这正好是个小应用,不需要过多考虑。)

有道词典的异常堆栈

碰巧抓住了有道词典的异常页面,从堆栈里能看出他们的一些技术栈,他们使用的是Resin-3.0.21,一个十多年前曾流行过现在不太主流的应用容器,但在网易、搜狐、人人等公司这个容器依然很常见。他们用http去访问cassandra?

java.lang.NoSuchFieldError: INSTANCE
 at org.apache.http.conn.ssl.SSLConnectionSocketFactory.<clinit>(SSLConnectionSocketFactory.java:144)
 at org.apache.http.client.fluent.Executor.<clinit>(Executor.java:78)
 at org.apache.http.client.fluent.Request.execute(Request.java:177)
 at toolbox.cassandra.client.CassandraClient.httpGet(CassandraClient.java:47)
 at toolbox.cassandra.client.CassandraClient.init(CassandraClient.java:129)
 at toolbox.cassandra.client.CassandraClient.getInstance(CassandraClient.java:75)
 at outfox.dict.front.data.ugc.AsynUgcClient.<clinit>(AsynUgcClient.java:88)
 at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
 at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)
 at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
 at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
 at org.springframework.beans.BeanUtils.instantiateClass(BeanUtils.java:148)
 at org.springframework.beans.factory.support.SimpleInstantiationStrategy.instantiate(SimpleInstantiationStrategy.java:87)
 at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.instantiateBean(AbstractAutowireCapableBeanFactory.java:1000)
 at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBeanInstance(AbstractAutowireCapableBeanFactory.java:953)
 at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:487)
 at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:458)
 at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:295)
 at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:223)
 at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:292)
 at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:194)
 at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:628)
 at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:932)
 at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:479)
 at org.springframework.web.servlet.FrameworkServlet.configureAndRefreshWebApplicationContext(FrameworkServlet.java:651)
 at org.springframework.web.servlet.FrameworkServlet.createWebApplicationContext(FrameworkServlet.java:599)
 at org.springframework.web.servlet.FrameworkServlet.createWebApplicationContext(FrameworkServlet.java:665)
 at org.springframework.web.servlet.FrameworkServlet.initWebApplicationContext(FrameworkServlet.java:518)
 at org.springframework.web.servlet.FrameworkServlet.initServletBean(FrameworkServlet.java:459)
 at org.springframework.web.servlet.HttpServletBean.init(HttpServletBean.java:136)
 at javax.servlet.GenericServlet.init(GenericServlet.java:69)
 at outfox.dict.front.web.DictServlet.init(DictServlet.java:57)
 at com.caucho.server.dispatch.ServletConfigImpl.createServletImpl(ServletConfigImpl.java:646)
 at com.caucho.server.dispatch.ServletConfigImpl.createServlet(ServletConfigImpl.java:587)
 at com.caucho.server.dispatch.ServletManager.init(ServletManager.java:154)
 at com.caucho.server.webapp.Application.start(Application.java:1654)
 at com.caucho.server.deploy.DeployController.startImpl(DeployController.java:621)
 at com.caucho.server.deploy.StartAutoRedeployAutoStrategy.startOnInit(StartAutoRedeployAutoStrategy.java:72)
 at com.caucho.server.deploy.DeployController.startOnInit(DeployController.java:509)
 at com.caucho.server.deploy.DeployContainer.start(DeployContainer.java:153)
 at com.caucho.server.webapp.ApplicationContainer.start(ApplicationContainer.java:670)
 at com.caucho.server.host.Host.start(Host.java:420)
 at com.caucho.server.deploy.DeployController.startImpl(DeployController.java:621)
 at com.caucho.server.deploy.StartAutoRedeployAutoStrategy.startOnInit(StartAutoRedeployAutoStrategy.java:72)
 at com.caucho.server.deploy.DeployController.startOnInit(DeployController.java:509)
 at com.caucho.server.deploy.DeployContainer.start(DeployContainer.java:153)
 at com.caucho.server.host.HostContainer.start(HostContainer.java:504)
 at com.caucho.server.resin.ServletServer.start(ServletServer.java:971)
 at com.caucho.server.deploy.DeployController.startImpl(DeployController.java:621)
 at com.caucho.server.deploy.AbstractDeployControllerStrategy.start(AbstractDeployControllerStrategy.java:56)
 at com.caucho.server.deploy.DeployController.start(DeployController.java:517)
 at com.caucho.server.resin.ResinServer.start(ResinServer.java:546)
 at com.caucho.server.resin.Resin.init(Resin.java)
 at com.caucho.server.resin.Resin.main(Resin.java:625)

OneApm的问题

1) 我们没有使用它的大数据版本,普通版本在压测情况下服务器端如果吞吐不够,agent端会缓存大量的数据导致full gc,这里它占据了1G的内存

2) 对HttpURLConnection拦截时可能发生空指针异常,导致业务线程终止

java.lang.NullPointerException
 at com.blueware.monitor.bridge.reflect.ClassReflection$2.run(ClassReflection.java:30) ~[?:?]
 at com.blueware.monitor.bridge.reflect.ClassReflection$2.run(ClassReflection.java:28) ~[?:?]
 at java.security.AccessController.doPrivileged(Native Method) ~[?:1.8.0_65]
 at com.blueware.monitor.bridge.reflect.ClassReflection.loadClass(ClassReflection.java:28) ~[?:?]
 at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1441) ~[?:1.8.0_65]
 at sun.net.www.protocol.http.HttpURLConnection.getHeaderField(HttpURLConnection.java:2979) ~[?:1.8.0_65]
 at java.net.HttpURLConnection.getResponseCode(HttpURLConnection.java:489) ~[?:1.8.0_65]
 at com...

tomcat8.5.8遇到的两个问题

压力测试场景,前端nginx反向代理到4个tomcat实例,在其中的一个实例上产生了大量的countDownConnection Incorrect connection count警告

 WARNING [http-nio-8080-exec-48] org.apache.tomcat.util.net.AbstractEndpoint.countDownConnection Incorrect connection count, multiple socket.close called on the same socket.

另外一个异常是4个tomcat实例上都看到的NPE异常:

Exception in thread "http-nio-8080-AsyncTimeout" java.lang.NullPointerException
  at org.apache.coyote.AbstractProcessor.doTimeoutAsync(AbstractProcessor.java:528)
  at org.apache.coyote.AbstractProcessor.timeoutAsync(AbstractProcessor.java:518)
  at org.apache.coyote.AbstractProtocol$AsyncTimeout.run(AbstractProtocol.java:1130)
  at java.lang.Thread.run(Thread.java:745)

使用了servlet3.0,connector配置如下:

 <Connector port="8080" protocol="org.apache.coyote.http11.Http11NioProtocol"
           connectionTimeout="20000" redirectPort="8443" maxParameterCount="2000" maxKeepAliveRequests="-1"
       maxThreads="200" maxPostSize="20971520" acceptCount="1024" useBodyEncodingForURI="true"
        URIEncoding="UTF-8"/>

已将bug提交到了bugzilla,在这里记录一下,后续跟踪。

scala雾中风景(27): lambda表达式里的return是抛异常实现的

尽管Scala和其他函数式编程都不太鼓励使用return,但我不喜欢太多缩进的代码,所以很少用较多的逻辑嵌套(除非是那种非常对称的嵌套),而是喜欢将不满足条件的先return掉。最近遇到一个scala里的流控陷阱,即在lambda里的return背后实际是通过特定的异常来实现的。

对于流控和异常捕获之前也遇到过其他陷阱,但稍不留意仍可能重犯,比如下面这段代码:

try {
    ...
    for (topicMeta <- resp.topicsMetadata; partMeta <- topicMeta.partitionsMetadata) {
      if (topicMeta.topic == p.topic && partMeta.partitionId == p.partition) {
        redisClient.hset(key, field, node.host + ":" + node.port)
        return
      }
    }
} catch {
    case e: Throwable =>
    ...
}

它是一段在actor里的逻辑,因为不希望非预期异常导致这个actor重启,所以是对Throwable进行的捕获,然而运行时竟捕获到了scala.runtime.NonLocalReturnControl$mcV$sp这样的异常。for语法糖容易让人忘记它里面的操作可能是一段匿名函数,简化一下这个例子:

➜  cat Test.scala
object Test {
    def main(args: Array[String]) {
        val list = List("A", "B", "C")
        for (e1 <- list) {
            if (e1 == "C") {
                println("ok, do something.")
                return
            }
        }
    }   
}

看看它编译的中间环节:

➜  scalac -Xprint:explicitouter Test.scala
[[syntax trees at end of             explicitouter]] // Test.scala
package <empty> {
object Test extends Object {
def <init>(): Test.type = {
  Test.super.<init>();
  ()
};
def main(args: Array[String]): Unit = {
  <synthetic> val nonLocalReturnKey1: Object = new Object();
  try {
    val list: List[String] = immutable.this.List.apply[String](scala.this.Predef.wrapRefArray[String](Array[String]{"A", "B", "C"}));
    list.foreach[Unit]({
      @SerialVersionUID(value = 0) final <synthetic> class $anonfun extends scala.runtime.AbstractFunction1[String,Unit] with Serializable {
        def <init>(): <$anon: String => Unit> = {
          $anonfun.super.<init>();
          ()
        };
        final def apply(e1: String): Unit = if (e1.==("C"))
          {
            scala.this.Predef.println("ok, do something.");
            throw new scala.runtime.NonLocalReturnControl$mcV$sp(nonLocalReturnKey1, ())
          }
        else
          ()
      };
      (new <$anon: String => Unit>(): String => Unit)
    })
  } catch {
    case (ex @ (_: scala.runtime.NonLocalReturnControl[Unit @unchecked])) => if (ex.key().eq(nonLocalReturnKey1))
      ex.value$mcV$sp()
    else
      throw ex
  }
}
}
}

很明显return在嵌套的匿名函数里是无法跳出外层函数的,所以编译器通过抛出 scala.runtime.NonLocalReturnControl 异常来实现跳出最外层。所有的lambda中使用return都是如此:

def main(args: Array[String]) {
    val lambda: String => Unit =
        (str: String) => { if ("hit" == str) return } //跳出main

    try {
        lambda("hit")
    } catch {
        case e: Throwable => //scala.runtime.NonLocalReturnControl
        e.printStackTrace()
    }
}

还是要注意对Throwable的捕获,不要干扰流控逻辑:

try{
    ...
}catch {
case e0: ControlThrowable => throw e0 // 不要干预流控的异常
case e1: Throwable => e1.printStackTrace
}   

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出的数据已经能解释原因只是我看不出来。

zsh的字符串替换引起的卡顿

我的mac系统每次启动后第一次打开iterm2的时候,oh-my-zsh的启动总是明显的卡顿一下,而之后退出iterm2重启动则不会有这个卡顿,也就是只在第一次启动iterm2的时候发生。对启动的zsh增加了-xv参数后观察,发现这个卡顿发生在git_compare_version函数的第4行:

找到这个函数后,发现第4行的操作并不是git等网络操作,而是一个字符串替换的操作,它使用zsh内置的字符串替换功能:INSTALLED_GIT_VERSION=(${(s/./)INSTALLED_GIT_VERSION[3]})

非常的不符合直觉(直觉上以为卡顿是因为网络阻塞引起的),模拟一下,在一个脚本里使用这个字符串替换操作,看看具体的耗时情况:

$ cat zsh-test.sh
#!/usr/bin/env zsh -xv
export PS4=$'%D{%M%S%.} %N:%i> '

INSTALLED_GIT_VERSION=($(command git --version 2>/dev/null));
INSTALLED_GIT_VERSION=(${(s/./)INSTALLED_GIT_VERSION[3]});
echo "$INSTALLED_GIT_VERSION"

然后再启动时调用这个zsh脚本:

$ cat run.sh
#!/usr/bin/env zsh -xv
export PS4=$'%D{%M%S%.} %N:%i> '
./zsh-test.sh

重启系统,启动后在bash下执行run.sh脚本:

INSTALLED_GIT_VERSION=($(command git --version 2>/dev/null));
5649865 ./zsh-test.sh:4> INSTALLED_GIT_VERSION=5649867 ./zsh-test.sh:4> git --version
5649865 ./zsh-test.sh:4> INSTALLED_GIT_VERSION=( git version 2.8.4 '(Apple' 'Git-73)' ) 
INSTALLED_GIT_VERSION=(${(s/./)INSTALLED_GIT_VERSION[3]});
5650999 ./zsh-test.sh:5> INSTALLED_GIT_VERSION=( 2 8 4 )

看到zsh-test.sh里的第5行字符串替换的操作耗时用了1秒多时间,如果再次执行的话会降到几个毫秒。这真是个蹊跷的问题,发邮件给 zsh-works@zsh.org 好几周也没有人回复,先在博客里记录一下这个问题,以后再追踪。zsh版本是:5.2 (x86_64-apple-darwin16.0.0)。

作业控制与前台进程组

这篇文章是对之前的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来执行命令。

Redis返回(nil)在lua里是boolean类型而非nil

Redis里执行gethget不存在的key或field时返回值在终端显式的是”(nil)”

127.0.0.1:6379> get notexist
(nil)

当使用lua脚本执行逻辑时,如果要判断这个值,很容易让人迷惑以为它是nil,从而导致判断不成立,实际它是一个boolean的值

127.0.0.1:6379> eval "local v=redis.call('get',KEYS[1]); return type(v)" 1 notexist
"boolean"

所以在脚本里判断获取的结果不为空,正确的方式还有判断false的情况:

local v=redis.call('hget',KEYS[1], ARGV[1]); 
if (v ~= nil or (type(v) == 'boolean' and v)) then 
    return 'not-empty'; 
end