天天看点

【BUG 记录】docker-compose搭建zookeeper 集群:log4j日志异常记录

docker-compose 搭建zookeeper集群

​​Docker-compose部署单主机zookeeper集群​​ 这篇博客介绍了我使用docker-compose 搭建zookeeper集群的过程,但是我发现zookeeper服务的守护进程的log4j的日志文件是输出到屏幕上的(终端),而没有重定向输入到指定文件里面,所以我有点好奇,就仔细看了一下,如果有理解错误的地方,还望大家批评指正。

我在服务器上部署三个zookeeper节点

服务器创建如下文件夹,便于后面容器zookeeper的指定文件夹(日志文件,配置文件等)的挂载

mkdir -p /home/xt/zookeeper/zookeeper-1/data
mkdir -p /home/xt/zookeeper/zookeeper-1/datalog
mkdir -p /home/xt/zookeeper/zookeeper-1/logs
mkdir -p /home/xt/zookeeper/zookeeper-1/conf      

log4j日志文件异常

**请大家注意:**这里的/logs文件夹保存的是log4j的日志文件,但是经过我后面实验,发现log4j的日志文件,只有一个.log的文件会打印到这个文件夹下面。但是按照下载zookeeper jar包,然后使用如下命令来启动zookeeper服务的形式(不采用docker,采用传统方式)

zkServer.sh  start      

采用这种形式来启动zookeeper服务,是还有一个.out文件的,里面保存的是zookeeper 服务的守护进程的输出,也就是日志

脚本zkServer.sh文件如下,使用docker-compose启动zookeeper服务的时候,并没有执行如上命令,所以守护进程日志文件(.out文件)并不会打印到/logs下面,但是会默认的打印到控制台或者终端屏幕上面

【BUG 记录】docker-compose搭建zookeeper 集群:log4j日志异常记录

等容器启动后,再次进入容器里面使用zkServer.sh start或者restart均不能启动成功,第一个命令应该是因为端口占用,第二个命令运行如下。

【BUG 记录】docker-compose搭建zookeeper 集群:log4j日志异常记录

脚本文件内容如下,我是在zookeeper的bin文件夹,也就是zkServer.sh文件所在的地方运行的脚本

【BUG 记录】docker-compose搭建zookeeper 集群:log4j日志异常记录

所以说不太好弄,我这里就不详细追究了。因为要使用zkServer.sh脚本运行zookeeper就必须要进入容器内部,但是容器不执行起来,我又进不去(我们不可能使用docker-compose 启动zookeeper服务,然后进入到容器里面重新启动这么麻烦的方式)

【BUG 记录】docker-compose搭建zookeeper 集群:log4j日志异常记录

docker是怎么运行zookeeper服务的

那么docker又是怎么运行zookeeper服务的呢

可以看看这篇

(​​docker是怎么运行容器服务的​​)

我们从这里可以知道,docker 其实还是使用zookeeper所自带的zkServer.sh脚本来启动zookeeper服务的,但是默认使用的是

zkServer.sh start-foreground      

zkServer.sh start-foreground脚本代码如下

start-foreground)
    ZOO_CMD=(exec "$JAVA")
    if [ "${ZOO_NOEXEC}" != "" ]; then
      ZOO_CMD=("$JAVA")
    fi
    "${ZOO_CMD[@]}" $ZOO_DATADIR_AUTOCREATE "-Dzookeeper.log.dir=${ZOO_LOG_DIR}" \
    "-Dzookeeper.log.file=${ZOO_LOG_FILE}" "-Dzookeeper.root.logger=${ZOO_LOG4J_PROP}" \
    -XX:+HeapDumpOnOutOfMemoryError -XX:OnOutOfMemoryError='kill -9 %p' \
    -cp "$CLASSPATH" $JVMFLAGS $ZOOMAIN "$ZOOCFG"
    ;;      

而 zkServer.sh start 的脚本代码是这样的,两者是有差异的,start将zookeeper守护进程的日志输出重定向到了/logs文件夹下的.out文件

#$ZOO_LOG_DIR 是从环境变量中拿到的,这个环境变量是dockerfile中构建镜像的时候定义的,这里是/logs 文件夹
ZOO_LOG_FILE=zookeeper-$USER-server-$HOSTNAME.log
_ZOO_DAEMON_OUT="$ZOO_LOG_DIR/zookeeper-$USER-server-$HOSTNAME.out"
start)
    echo  -n "Starting zookeeper ... "
    if [ -f "$ZOOPIDFILE" ]; then
      if kill -0 `cat "$ZOOPIDFILE"` > /dev/null 2>&1; then
         echo $command already running as process `cat "$ZOOPIDFILE"`.
         exit 1
      fi
    fi
    nohup "$JAVA" $ZOO_DATADIR_AUTOCREATE "-Dzookeeper.log.dir=${ZOO_LOG_DIR}" \
    "-Dzookeeper.log.file=${ZOO_LOG_FILE}" "-Dzookeeper.root.logger=${ZOO_LOG4J_PROP}" \
    -XX:+HeapDumpOnOutOfMemoryError -XX:OnOutOfMemoryError='kill -9 %p' \
    -cp "$CLASSPATH" $JVMFLAGS $ZOOMAIN "$ZOOCFG" > "$_ZOO_DAEMON_OUT" 2>&1 < /dev/null &
    #在这里输出到了 $_ZOO_DAEMON_OUT
    #其余代码已经删除      

所以,直接拉取zookeeper启动zookeeper服务的方式,在/logs文件下看不到zookeeper守护进程的日志输出(.out文件)

既然docker 还是通过zkserver.sh来启动zookeeper服务的,那就问题不大了

我们是可以更改覆盖掉dockerfile中的最后这两条语句的

ENTRYPOINT ["/docker-entrypoint.sh"]
CMD ["zkServer.sh", "start-foreground"]      

可以在docker run中覆盖,在docker-compose中可以覆盖这两条指令

我这里在docker-compose.yml文件中覆盖cmd指令,给每一个zookeeper server 添加如下指令

command: ["zkServer.sh", "start"]      

添加之后,每次docker 启动容器服务的时候,就会这样

/docker-entrypoint.sh zkServer.sh start      

但是这样启动zookeeper集群,出现了如此错误

【BUG 记录】docker-compose搭建zookeeper 集群:log4j日志异常记录

zKserver.sh start做了什么操作,导致zkserver.sh start_foregound能够成功启动zookeeper集群服务,而zkserver.sh start 不行呢,我们来仔细看看脚本文件

start 方法脚本详细注释如下

#$ZOO_LOG_DIR 是从环境变量中拿到的
ZOO_LOG_FILE=zookeeper-$USER-server-$HOSTNAME.log
_ZOO_DAEMON_OUT="$ZOO_LOG_DIR/zookeeper-$USER-server-$HOSTNAME.out"
case $1 in
start)
    echo  -n "Starting zookeeper ... "
    #-f     如果文件存在且为普通文件则为真 ,普通文件:非目录文件或者设备文件
    if [ -f "$ZOOPIDFILE" ]; then
         # kill -0 pid 不发送任何信号,但是系统会进行错误检查。
         # 所以经常用来检查一个进程是否存在,存在返回0;不存在返回1
         # 2>&1 解释:将标准错误 2 重定向到标准输出 &1 ,标准输出 &1 再被重定向输入到 /dev/null
         # /dev/null 空设备,是一个特殊的设备文件,它丢弃一切写入其中的数据(但报告写入操作成功),读取它则会立即得到一个EOF
      if kill -0 `cat "$ZOOPIDFILE"` > /dev/null 2>&1; then
         echo $command already running as process `cat "$ZOOPIDFILE"`.
         exit 1
      fi
      # 正常执行完毕返回0,异常结束返回1
    fi
     # nohup 英文全称 no hang up(不挂起),用于在系统后台不挂断地运行命令,退出终端不会影响程序的运行。
     # 下面这条语句是用来启动zookeeper服务的
    nohup "$JAVA" $ZOO_DATADIR_AUTOCREATE "-Dzookeeper.log.dir=${ZOO_LOG_DIR}" \
    "-Dzookeeper.log.file=${ZOO_LOG_FILE}" "-Dzookeeper.root.logger=${ZOO_LOG4J_PROP}" \
    -XX:+HeapDumpOnOutOfMemoryError -XX:OnOutOfMemoryError='kill -9 %p' \
    -cp "$CLASSPATH" $JVMFLAGS $ZOOMAIN "$ZOOCFG" > "$_ZOO_DAEMON_OUT" 2>&1 < /dev/null &
    # $? 显示最后命令的退出状态。0表示没有错误,其他任何值表明有错误
    if [ $? -eq 0 ]
    then
      case "$OSTYPE" in
      *solaris*)
        /bin/echo "${!}\\c" > "$ZOOPIDFILE"
        ;;
      *)
       # $!  后台运行的最后一个进程的ID号 ,这里可以看出是将进程号写入磁盘的ZOOPIDFILE文件里面,在我下面的结果中可以看到,已经有文件生成
       # 到这里都是成功运行的,磁盘的这个文件里面已经有了pid号
        /bin/echo -n $! > "$ZOOPIDFILE"
        ;;
      esac
      if [ $? -eq 0 ];
      then
        sleep 1
        # cat(英文全拼:concatenate)命令用于连接文件并打印到标准输出设备上。
        pid=$(cat "${ZOOPIDFILE}")
        # ps -p 指定进程识别码,并列出该进程的状况,上一步将进程号写入到了本地文件,但是到这一步
        # 确运行失败,说明发生了什么问题导致进程运行终止
        if ps -p "${pid}" > /dev/null 2>&1; then
          echo STARTED
        else
          echo FAILED TO START
          exit 1
        fi
      else
        echo FAILED TO WRITE PID
        exit 1
      fi
    else
      echo SERVER DID NOT START
      exit 1
    fi
    ;;      

启动之后,/logs里面生成了这些文件,说明脚本前面一部分没有问题,zookeeper也成功启动了,那是什么原因导致集群启动失败呢?

【BUG 记录】docker-compose搭建zookeeper 集群:log4j日志异常记录
【BUG 记录】docker-compose搭建zookeeper 集群:log4j日志异常记录

我们去看看.out的日志文件(这里已经成功写入了,在脚本文件exit 1之前写入的)

2022-01-09 13:24:06,247 [myid:3] - WARN  [QuorumConnectionThread-[myid=3]-1:QuorumCnxManager@401] - Cannot open channel to 1 at election address zookeeper-1:3888
java.net.UnknownHostException: zookeeper-1
  at java.base/java.net.AbstractPlainSocketImpl.connect(Unknown Source)
  at java.base/java.net.SocksSocketImpl.connect(Unknown Source)
  at java.base/java.net.Socket.connect(Unknown Source)
  at org.apache.zookeeper.server.quorum.QuorumCnxManager.initiateConnection(QuorumCnxManager.java:384)
  at org.apache.zookeeper.server.quorum.QuorumCnxManager$QuorumConnectionReqThread.run(QuorumCnxManager.java:458)
  at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
  at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
  at java.base/java.lang.Thread.run(Unknown Source)
2022-01-09 13:24:06,249 [myid:3] - INFO  [WorkerReceiver[myid=3]:FastLeaderElection$Messenger$WorkerReceiver@390] - Notification: my state:LOOKING; n.sid:3, n.state:LOOKING, n.leader:3, n.round:0x1, n.peerEpoch:0x5, n.zxid:0x400000001, message format version:0x2, n.config version:0x0
2022-01-09 13:24:06,249 [myid:3] - WARN  [QuorumConnectionThread-[myid=3]-2:QuorumCnxManager@401] - Cannot open channel to 2 at election address zookeeper-2:3888
java.net.UnknownHostException: zookeeper-2
  at java.base/java.net.AbstractPlainSocketImpl.connect(Unknown Source)
  at java.base/java.net.SocksSocketImpl.connect(Unknown Source)
  at java.base/java.net.Socket.connect(Unknown Source)
  at org.apache.zookeeper.server.quorum.QuorumCnxManager.initiateConnection(QuorumCnxManager.java:384)
  at org.apache.zookeeper.server.quorum.QuorumCnxManager$QuorumConnectionReqThread.run(QuorumCnxManager.java:458)
  at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
  at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
  at java.base/java.lang.Thread.run(Unknown Source)      

通过如上如此可以发现,他连接不上其他zookeeper服务的3888端口,我们都知道这个3888是用来选举zookeeper集群leader使用的端口。

如此看来,真相已经大白了。

启动了一个zookeeper server ,但是连接不上其他server 。(因为zookeeper肯定不是并行创建的,有先后关系,肯定会出现连不上另一个server的情况)

我先前使用默认配置来搭建zookeeper集群的时候,也报出了这样的日志:说是连不上其他zookeeper server的2888和3888端口。(这是必然的,因为server无法同时创建,除非你计算机的每一个内核都同时运行一个server出来,在一个cpu核里面,cpu都是分时给每个进程使用的)

为什么zkServer.sh start-foreground 能成功,而zkServer.sh start 不能运行成功呢?

原因应该是下面这一段代码,这是zkServer.sh start中有,而start-foreground里面没有的一段代码,大致意思就是说如果监测到这个进程没有正常进行活动,就返回失败,异常退出。

sleep 1
# cat(英文全拼:concatenate)命令用于连接文件并打印到标准输出设备上。
pid=$(cat "${ZOOPIDFILE}")
# ps -p 指定进程识别码,并列出该进程的状况,上一步将进程号写入到了本地文件,但是到这一步
# 却运行失败,说明发生了什么问题导致进程运行终止
if ps -p "${pid}" > /dev/null 2>&1; then
  echo STARTED
else
  echo FAILED TO START
  exit 1      

start-foreground启动的zookeeper集群虽然也报出了连接不上其他server 2888和3888端口的异常,但是他没有这些代码来结束已经建立好了运行的server,只要时间一长,三台server都成功运行,自然能连接上2888和3888端口,zookeeper集群也就搭建成功了