java.net.SocketTimeoutException: Read timed out

Google Groups | Ron van der Vegt | 2 years ago
  1. 0

    Hbase unstable, master and regionservers crashes every night at ~ 00:07 UTC

    Google Groups | 2 years ago | Ron van der Vegt
    java.net.SocketTimeoutException: Read timed out
  2. 0

    Hi, I need some help understanding a recurring problem we're seeing with our zookeeper cluster. It's a five node cluster that ordinarily runs fine. Occasionally we see an error from which the cluster recovers, but it causes a lot of grief and I'm sure is representative of an unhealthy situation. To my eye it looks like an invalid bit of data getting into the system and not being handled gracefully; I'm the first to say my eye is not expert though, so I humbly submit an annotated log exert in the hope some who knows more than me can provide some illumination. The cluster seems to be ticking along fine, until we get errors on 2 of the 5 nodes like so: 2016-01-19 13:12:49,698 - WARN [QuorumPeer[myid=1]/0.0.0.0:2181:Follower@89] - Exception when following the leader java.io.EOFException at java.io.DataInputStream.readInt(DataInputStream.java:392) at org.apache.jute.BinaryInputArchive.readInt(BinaryInputArchive.java:63) at org.apache.zookeeper.server.quorum.QuorumPacket.deserialize(QuorumPacket.java:83) at org.apache.jute.BinaryInputArchive.readRecord(BinaryInputArchive.java:103) at org.apache.zookeeper.server.quorum.Learner.readPacket(Learner.java:153) at org.apache.zookeeper.server.quorum.Follower.followLeader(Follower.java:85) at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:786) 2016-01-19 13:12:49,698 - INFO [QuorumPeer[myid=1]/0.0.0.0:2181:Follower@166] - shutdown called java.lang.Exception: shutdown Follower at org.apache.zookeeper.server.quorum.Follower.shutdown(Follower.java:166) at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:790) This is immediately followed by 380 occurences of: 2016-01-19 13:12:49,699 - INFO [QuorumPeer[myid=1]/0.0.0.0:2181:NIOServerCnxn@1007] - Closed socket connection for client /X.Y.Z.56:59028 which had sessionid 0x151b01ee8330234 and a: 2016-01-19 13:12:49,766 - INFO [QuorumPeer[myid=1]/0.0.0.0:2181:FollowerZooKeeperServer@139] - Shutting down 2016-01-19 13:12:49,766 - INFO [QuorumPeer[myid=1]/0.0.0.0:2181:ZooKeeperServer@441] - shutting down 2016-01-19 13:12:49,766 - INFO [QuorumPeer[myid=1]/0.0.0.0:2181:FollowerRequestProcessor@105] - Shutting down 2016-01-19 13:12:49,766 - INFO [QuorumPeer[myid=1]/0.0.0.0:2181:CommitProcessor@181] - Shutting down 2016-01-19 13:12:49,766 - INFO [QuorumPeer[myid=1]/0.0.0.0:2181:FinalRequestProcessor@415] - shutdown of request processor complete 2016-01-19 13:12:49,767 - INFO [QuorumPeer[myid=1]/0.0.0.0:2181:SyncRequestProcessor@209] - Shutting down 2016-01-19 13:12:49,767 - INFO [CommitProcessor:1:CommitProcessor@150] - CommitProcessor exited loop! 2016-01-19 13:12:49,767 - INFO [FollowerRequestProcessor:1:FollowerRequestProcessor@95] - FollowerRequestProcessor exited loop! 2016-01-19 13:13:09,418 - WARN [SyncThread:1:FileTxnLog@334] - fsync-ing the write ahead log in SyncThread:1 took 30334ms which will adversely effect operation latency. See the ZooKeeper troubleshooting guide 2016-01-19 13:13:09,427 - WARN [SyncThread:1:SendAckRequestProcessor@64] - Closing connection to leader, exception during packet send java.net.SocketException: Socket closed at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:121) at java.net.SocketOutputStream.write(SocketOutputStream.java:159) at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82) at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140) at org.apache.zookeeper.server.quorum.Learner.writePacket(Learner.java:139) at org.apache.zookeeper.server.quorum.SendAckRequestProcessor.flush(SendAckRequestProcessor.java:62) at org.apache.zookeeper.server.SyncRequestProcessor.flush(SyncRequestProcessor.java:204) at org.apache.zookeeper.server.SyncRequestProcessor.run(SyncRequestProcessor.java:131) 2016-01-19 13:13:09,428 - INFO [SyncThread:1:SyncRequestProcessor@187] - SyncRequestProcessor exited! As a small aside, the fsync log errors for the first two servers to be hit are: 2016-01-19 13:13:09,418 - WARN [SyncThread:1:FileTxnLog@334] - fsync-ing the write ahead log in SyncThread:1 took 30334ms which will adversely effect operation latency. 2016-01-19 13:13:09,539 - WARN [SyncThread:2:FileTxnLog@334] - fsync-ing the write ahead log in SyncThread:2 took 30456ms which will adversely effect operation latency. If rewind from date of the entry the milliseconds given, you arrive within one millisecond of the same time on each server. But I digress. For the next 12 minutes or so, the logs are full of the below sort of exceptions, in seemingly no consistent order or frequency: 2016-01-19 13:13:09,440 - WARN [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@362] - Exception causing close of session 0x0 due to java.io.IOException: ZooKeeperServer not running 2016-01-19 13:13:09,441 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1007] - Closed socket connection for client /X.Y.Z.181:51381 (no session established for client) 2016-01-19 13:13:09,443 - WARN [QuorumPeer[myid=1]/0.0.0.0:2181:SendAckRequestProcessor@64] - Closing connection to leader, exception during packet send java.net.SocketException: Socket closed at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:121) at java.net.SocketOutputStream.write(SocketOutputStream.java:159) at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82) at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140) at org.apache.zookeeper.server.quorum.Learner.writePacket(Learner.java:139) at org.apache.zookeeper.server.quorum.SendAckRequestProcessor.flush(SendAckRequestProcessor.java:62) at org.apache.zookeeper.server.SyncRequestProcessor.flush(SyncRequestProcessor.java:204) at org.apache.zookeeper.server.SyncRequestProcessor.shutdown(SyncRequestProcessor.java:216) at org.apache.zookeeper.server.quorum.FollowerZooKeeperServer.shutdown(FollowerZooKeeperServer.java:147) at org.apache.zookeeper.server.quorum.Learner.shutdown(Learner.java:546) at org.apache.zookeeper.server.quorum.Follower.shutdown(Follower.java:167) at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:790) 2016-01-19 13:13:09,443 - INFO [QuorumPeer[myid=1]/0.0.0.0:2181:QuorumPeer@714] - LOOKING 2016-01-19 13:13:11,782 - WARN [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@357] - caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x1525a047dc20005, likely client has closed socket at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:228) at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208) at java.lang.Thread.run(Thread.java:744) 2016-01-19 13:13:11,783 - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1007] - Closed socket connection for client /X.Y.Z.1:59576 which had sessionid 0x1525a047dc20005 2016-01-19 13:13:11,784 - ERROR [CommitProcessor:1:NIOServerCnxn@178] - Unexpected Exception: java.nio.channels.CancelledKeyException at sun.nio.ch.SelectionKeyImpl.ensureValid(SelectionKeyImpl.java:73) at sun.nio.ch.SelectionKeyImpl.interestOps(SelectionKeyImpl.java:77) at org.apache.zookeeper.server.NIOServerCnxn.sendBuffer(NIOServerCnxn.java:151) at org.apache.zookeeper.server.NIOServerCnxn.sendResponse(NIOServerCnxn.java:1081) at org.apache.zookeeper.server.FinalRequestProcessor.processRequest(FinalRequestProcessor.java:404) at org.apache.zookeeper.server.quorum.CommitProcessor.run(CommitProcessor.java:74) 2016-01-19 13:25:43,898 - INFO [WorkerReceiver[myid=1]:FastLeaderElection@597] - Notification: 1 (message format version), 2 (n.leader), 0x2a001d352d (n.zxid), 0xb (n.round), LOOKING (n.state), 2 (n.sid), 0x2a (n.peerEpoch) FOLLOWING (my state) 2016-01-19 13:25:43,901 - WARN [QuorumPeer[myid=1]/0.0.0.0:2181:Follower@89] - Exception when following the leader java.net.SocketTimeoutException: Read timed out at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.read(SocketInputStream.java:152) at java.net.SocketInputStream.read(SocketInputStream.java:122) at java.io.BufferedInputStream.fill(BufferedInputStream.java:235) at java.io.BufferedInputStream.read(BufferedInputStream.java:254) at java.io.DataInputStream.readInt(DataInputStream.java:387) at org.apache.jute.BinaryInputArchive.readInt(BinaryInputArchive.java:63) at org.apache.zookeeper.server.quorum.QuorumPacket.deserialize(QuorumPacket.java:83) at org.apache.jute.BinaryInputArchive.readRecord(BinaryInputArchive.java:103) at org.apache.zookeeper.server.quorum.Learner.readPacket(Learner.java:153) at org.apache.zookeeper.server.quorum.Follower.followLeader(Follower.java:85) at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:786) 2016-01-19 13:25:43,901 - INFO [QuorumPeer[myid=1]/0.0.0.0:2181:Follower@166] - shutdown called java.lang.Exception: shutdown Follower at org.apache.zookeeper.server.quorum.Follower.shutdown(Follower.java:166) at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:790) Until eventually we get to: 2016-01-19 13:26:05,099 - INFO [QuorumPeer[myid=1]/0.0.0.0:2181:QuorumPeer@784] - FOLLOWING 2016-01-19 13:26:05,099 - INFO [QuorumPeer[myid=1]/0.0.0.0:2181:ZooKeeperServer@162] - Created server with tickTime 2000 minSessionTimeout 4000 maxSessionTimeout 40000 datadir /var/lib/zookeeper_1/data/version-2 snapdir /var/lib/zookeeper_1/data/version-2 2016-01-19 13:26:05,099 - INFO [QuorumPeer[myid=1]/0.0.0.0:2181:Follower@63] - FOLLOWING - LEADER ELECTION TOOK - 21179 2016-01-19 13:26:05,100 - WARN [QuorumPeer[myid=1]/0.0.0.0:2181:Learner@233] - Unexpected exception, tries=0, connecting to zoo005/X.Y.Z.71:2888 java.net.ConnectException: Connection refused at java.net.PlainSocketImpl.socketConnect(Native Method) at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:339) at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:200) at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:182) at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392) at java.net.Socket.connect(Socket.java:579) at org.apache.zookeeper.server.quorum.Learner.connectToLeader(Learner.java:225) at org.apache.zookeeper.server.quorum.Follower.followLeader(Follower.java:71) at org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:786) And things start to come right. Right about now, the three member which had so far escaped begin to exhibit the same behaviour. Again, if we look at the fsync messages: 2016-01-19 13:26:06,192 - WARN [SyncThread:3:FileTxnLog@334] - fsync-ing the write ahead log in SyncThread:3 took 51394ms which will adversely effect operation latency. 2016-01-19 13:26:05,960 - WARN [SyncThread:4:FileTxnLog@334] - fsync-ing the write ahead log in SyncThread:4 took 51162ms which will adversely effect operation latency. 2016-01-19 13:26:04,524 - WARN [SyncThread:5:FileTxnLog@334] - fsync-ing the write ahead log in SyncThread:5 took 49726ms which will adversely effect operation latency. And we rewind the number of milliseconds from the log entry timestamp, we arrive at exactly 13:25:14,798 for all three events. So, it looks for all the world like something entered the system at 13:12:39,084, caused havoc on two nodes for 12.5 minutes, then at 13:25:14,798 it got off those and made to the other three, where it again caused havoc, before things eventually recovered and the world kept on ticking, only a medium sized log explosion worse for it. There is nothing in any of the logs within a second of either of those times. I'm hoping someone familiar with the code can look at those stack traces and understand what might cause such an incident. I'm to help anyway I can. I have more complete logs, and we see this every couple of weeks or so, so can setup some additional logging if it would be of value. Let me know.

    Apache's JIRA Issue Tracker | 11 months ago | Gareth Humphries
    java.net.SocketTimeoutException: Read timed out
  3. 0

    Large number of errored transactions and periodic node disconnects on 3.4.6

    zookeeper-user | 2 years ago | R. Tyler Croy
    java.net.SocketTimeoutException: Read timed out
  4. Speed up your debug routine!

    Automated exception search integrated into your IDE

  5. 0

    Re: Large number of errored transactions and periodic node disconnects on 3.4.6

    zookeeper-user | 2 years ago | Flavio Junqueira
    java.net.SocketTimeoutException: Read timed out
  6. 0

    Re: Large number of errored transactions and periodic node disconnects on 3.4.6

    zookeeper-user | 2 years ago | R. Tyler Croy
    java.net.SocketTimeoutException: Read timed out

    Not finding the right solution?
    Take a tour to get the most out of Samebug.

    Tired of useless tips?

    Automated exception search integrated into your IDE

    Root Cause Analysis

    1. java.net.SocketTimeoutException

      Read timed out

      at java.net.SocketInputStream.socketRead0()
    2. Java RT
      DataInputStream.readInt
      1. java.net.SocketInputStream.socketRead0(Native Method)
      2. java.net.SocketInputStream.read(SocketInputStream.java:152)
      3. java.net.SocketInputStream.read(SocketInputStream.java:122)
      4. java.io.BufferedInputStream.fill(BufferedInputStream.java:235)
      5. java.io.BufferedInputStream.read(BufferedInputStream.java:254)
      6. java.io.DataInputStream.readInt(DataInputStream.java:387)
      6 frames