天天看點

【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叢集也就搭建成功了