Uploaded image for project: 'Mesos'
  1. Mesos
  2. MESOS-1729

LogZooKeeperTest.WriteRead fails due to SIGPIPE (escalated to SIGABRT)

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Resolved
    • Major
    • Resolution: Fixed
    • 0.21.0
    • 0.20.1
    • build, test

    • OSX 10.9.4, clang 3.4.
      Same or very similar results on Linux

    • Q3 Sprint 4

    Description

      The following is reported and 100% reproducible when running make check on my OSX box.

      [ RUN      ] LogZooKeeperTest.WriteRead
I0821 21:18:34.960811 2078368528 jvm.cpp:572] Looking up method <init>(Ljava/lang/String;)V
I0821 21:18:34.960934 2078368528 jvm.cpp:572] Looking up method deleteOnExit()V
I0821 21:18:34.961335 2078368528 jvm.cpp:572] Looking up method <init>(Ljava/io/File;Ljava/io/File;)V
log4j:WARN No appenders could be found for logger (org.apache.zookeeper.server.persistence.FileTxnSnapLog).
log4j:WARN Please initialize the log4j system properly.
I0821 21:18:35.004449 2078368528 jvm.cpp:572] Looking up method <init>()V
I0821 21:18:35.005053 2078368528 jvm.cpp:572] Looking up method <init>(Lorg/apache/zookeeper/server/persistence/FileTxnSnapLog;Lorg/apache/zookeeper/server/ZooKeeperServer$DataTreeBuilder;)V
I0821 21:18:35.025753 2078368528 jvm.cpp:572] Looking up method <init>()V
I0821 21:18:35.032670 2078368528 jvm.cpp:572] Looking up method <init>(I)V
I0821 21:18:35.032873 2078368528 jvm.cpp:572] Looking up method configure(Ljava/net/InetSocketAddress;I)V
I0821 21:18:35.038020 2078368528 jvm.cpp:572] Looking up method startup(Lorg/apache/zookeeper/server/ZooKeeperServer;)V
I0821 21:18:35.093870 2078368528 jvm.cpp:572] Looking up method getClientPort()I
I0821 21:18:35.093925 2078368528 zookeeper_test_server.cpp:158] Started ZooKeeperTestServer on port 52772
I0821 21:18:35.094081 2078368528 log_tests.cpp:1945] Using temporary directory '/tmp/LogZooKeeperTest_WriteRead_F8UzYv'
I0821 21:18:35.095954 2078368528 leveldb.cpp:176] Opened db in 1815us
I0821 21:18:35.096392 2078368528 leveldb.cpp:183] Compacted db in 428us
I0821 21:18:35.096420 2078368528 leveldb.cpp:198] Created db iterator in 7us
I0821 21:18:35.096432 2078368528 leveldb.cpp:204] Seeked to beginning of db in 8us
I0821 21:18:35.096442 2078368528 leveldb.cpp:273] Iterated through 0 keys in the db in 8us
I0821 21:18:35.096462 2078368528 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0821 21:18:35.097043 107220992 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 184us
I0821 21:18:35.097075 107220992 replica.cpp:320] Persisted replica status to VOTING
I0821 21:18:35.099768 2078368528 leveldb.cpp:176] Opened db in 1673us
I0821 21:18:35.100049 2078368528 leveldb.cpp:183] Compacted db in 270us
I0821 21:18:35.100070 2078368528 leveldb.cpp:198] Created db iterator in 6us
I0821 21:18:35.100080 2078368528 leveldb.cpp:204] Seeked to beginning of db in 5us
I0821 21:18:35.100088 2078368528 leveldb.cpp:273] Iterated through 0 keys in the db in 5us
I0821 21:18:35.100097 2078368528 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0821 21:18:35.100411 108294144 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 159us
I0821 21:18:35.100435 108294144 replica.cpp:320] Persisted replica status to VOTING
I0821 21:18:35.101984 2078368528 leveldb.cpp:176] Opened db in 1224us
I0821 21:18:35.102934 2078368528 leveldb.cpp:183] Compacted db in 942us
I0821 21:18:35.102958 2078368528 leveldb.cpp:198] Created db iterator in 8us
I0821 21:18:35.102972 2078368528 leveldb.cpp:204] Seeked to beginning of db in 8us
I0821 21:18:35.102984 2078368528 leveldb.cpp:273] Iterated through 1 keys in the db in 9us
I0821 21:18:35.102994 2078368528 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
2014-08-21 21:18:35,103:6420(0x106641000):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
2014-08-21 21:18:35,103:6420(0x106641000):ZOO_INFO@log_env@716: Client environment:host.name=lobomacpro2.fritz.box
2014-08-21 21:18:35,103:6420(0x106641000):ZOO_INFO@log_env@723: Client environment:os.name=Darwin
2014-08-21 21:18:35,103:6420(0x106641000):ZOO_INFO@log_env@724: Client environment:os.arch=13.3.0
2014-08-21 21:18:35,103:6420(0x106641000):ZOO_INFO@log_env@725: Client environment:os.version=Darwin Kernel Version 13.3.0: Tue Jun  3 21:27:35 PDT 2014; root:xnu-2422.110.17~1/RELEASE_X86_64
2014-08-21 21:18:35,103:6420(0x106641000):ZOO_INFO@log_env@733: Client environment:user.name=till
2014-08-21 21:18:35,103:6420(0x106641000):ZOO_INFO@log_env@741: Client environment:user.home=/Users/till
2014-08-21 21:18:35,103:6420(0x106641000):ZOO_INFO@log_env@753: Client environment:user.dir=/private/tmp/LogZooKeeperTest_WriteRead_F8UzYv
2014-08-21 21:18:35,103:6420(0x106641000):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:52772 sessionTimeout=5000 watcher=0x104710310 sessionId=0 sessionPasswd=<null> context=0x7fccdd206c20 flags=0
I0821 21:18:35.103281 108294144 log.cpp:238] Attempting to join replica to ZooKeeper group
2014-08-21 21:18:35,103:6420(0x1065be000):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
2014-08-21 21:18:35,103:6420(0x1065be000):ZOO_INFO@log_env@716: Client environment:host.name=lobomacpro2.fritz.box
2014-08-21 21:18:35,103:6420(0x1065be000):ZOO_INFO@log_env@723: Client environment:os.name=Darwin
2014-08-21 21:18:35,103:6420(0x1065be000):ZOO_INFO@log_env@724: Client environment:os.arch=13.3.0
2014-08-21 21:18:35,103:6420(0x1065be000):ZOO_INFO@log_env@725: Client environment:os.version=Darwin Kernel Version 13.3.0: Tue Jun  3 21:27:35 PDT 2014; root:xnu-2422.110.17~1/RELEASE_X86_64
2014-08-21 21:18:35,103:6420(0x1065be000):ZOO_INFO@log_env@733: Client environment:user.name=till
2014-08-21 21:18:35,103:6420(0x1065be000):ZOO_INFO@log_env@741: Client environment:user.home=/Users/till
2014-08-21 21:18:35,103:6420(0x1065be000):ZOO_INFO@log_env@753: Client environment:user.dir=/private/tmp/LogZooKeeperTest_WriteRead_F8UzYv
2014-08-21 21:18:35,103:6420(0x1065be000):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:52772 sessionTimeout=5000 watcher=0x104710310 sessionId=0 sessionPasswd=<null> context=0x7fccdd209ed0 flags=0
I0821 21:18:35.103443 108830720 recover.cpp:425] Starting replica recovery
I0821 21:18:35.103541 108830720 recover.cpp:451] Replica is in VOTING status
2014-08-21 21:18:35,103:6420(0x11857d000):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:52772]
2014-08-21 21:18:35,103:6420(0x118477000):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:52772]
I0821 21:18:35.103606 108830720 recover.cpp:440] Recover process terminated
I0821 21:18:35.104524 2078368528 leveldb.cpp:176] Opened db in 1247us
I0821 21:18:35.105363 2078368528 leveldb.cpp:183] Compacted db in 832us
I0821 21:18:35.105393 2078368528 leveldb.cpp:198] Created db iterator in 12us
I0821 21:18:35.105413 2078368528 leveldb.cpp:204] Seeked to beginning of db in 12us
I0821 21:18:35.105447 2078368528 leveldb.cpp:273] Iterated through 1 keys in the db in 16us
I0821 21:18:35.105473 2078368528 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
2014-08-21 21:18:35,105:6420(0x106641000):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
2014-08-21 21:18:35,105:6420(0x106641000):ZOO_INFO@log_env@716: Client environment:host.name=lobomacpro2.fritz.box
2014-08-21 21:18:35,105:6420(0x106641000):ZOO_INFO@log_env@723: Client environment:os.name=Darwin
2014-08-21 21:18:35,105:6420(0x106641000):ZOO_INFO@log_env@724: Client environment:os.arch=13.3.0
2014-08-21 21:18:35,105:6420(0x106641000):ZOO_INFO@log_env@725: Client environment:os.version=Darwin Kernel Version 13.3.0: Tue Jun  3 21:27:35 PDT 2014; root:xnu-2422.110.17~1/RELEASE_X86_64
2014-08-21 21:18:35,105:6420(0x106641000):ZOO_INFO@log_env@733: Client environment:user.name=till
2014-08-21 21:18:35,105:6420(0x106641000):ZOO_INFO@log_env@741: Client environment:user.home=/Users/till
2014-08-21 21:18:35,105:6420(0x106641000):ZOO_INFO@log_env@753: Client environment:user.dir=/private/tmp/LogZooKeeperTest_WriteRead_F8UzYv
2014-08-21 21:18:35,105:6420(0x106641000):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:52772 sessionTimeout=5000 watcher=0x104710310 sessionId=0 sessionPasswd=<null> context=0x7fccdb47d2c0 flags=0
I0821 21:18:35.105737 109367296 log.cpp:238] Attempting to join replica to ZooKeeper group
2014-08-21 21:18:35,105:6420(0x106747000):ZOO_INFO@log_env@712: Client environment:zookeeper.version=zookeeper C client 3.4.5
2014-08-21 21:18:35,105:6420(0x106747000):ZOO_INFO@log_env@716: Client environment:host.name=lobomacpro2.fritz.box
2014-08-21 21:18:35,105:6420(0x106747000):ZOO_INFO@log_env@723: Client environment:os.name=Darwin
2014-08-21 21:18:35,105:6420(0x106747000):ZOO_INFO@log_env@724: Client environment:os.arch=13.3.0
2014-08-21 21:18:35,105:6420(0x106747000):ZOO_INFO@log_env@725: Client environment:os.version=Darwin Kernel Version 13.3.0: Tue Jun  3 21:27:35 PDT 2014; root:xnu-2422.110.17~1/RELEASE_X86_64
2014-08-21 21:18:35,105:6420(0x106747000):ZOO_INFO@log_env@733: Client environment:user.name=till
2014-08-21 21:18:35,105:6420(0x106747000):ZOO_INFO@log_env@741: Client environment:user.home=/Users/till
I0821 21:18:35.105845 106147840 recover.cpp:425] Starting replica recovery
2014-08-21 21:18:35,105:6420(0x106747000):ZOO_INFO@log_env@753: Client environment:user.dir=/private/tmp/LogZooKeeperTest_WriteRead_F8UzYv
2014-08-21 21:18:35,105:6420(0x106747000):ZOO_INFO@zookeeper_init@786: Initiating client connection, host=127.0.0.1:52772 sessionTimeout=5000 watcher=0x104710310 sessionId=0 sessionPasswd=<null> context=0x7fccdb71bff0 flags=0
2014-08-21 21:18:35,105:6420(0x118693000):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:52772]
I0821 21:18:35.105955 109903872 recover.cpp:451] Replica is in VOTING status
I0821 21:18:35.106016 109903872 recover.cpp:440] Recover process terminated
2014-08-21 21:18:35,106:6420(0x118799000):ZOO_INFO@check_events@1703: initiated connection to server [127.0.0.1:52772]
I0821 21:18:35.106123 107220992 log.cpp:656] Attempting to start the writer
2014-08-21 21:18:35,119:6420(0x118477000):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:52772], sessionId=0x147fa019b250000, negotiated timeout=6000
I0821 21:18:35.119858 106684416 group.cpp:313] Group process (group(1)@127.0.0.1:52771) connected to ZooKeeper
I0821 21:18:35.119878 106684416 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
I0821 21:18:35.119894 106684416 group.cpp:385] Trying to create path '/log' in ZooKeeper
2014-08-21 21:18:35,119:6420(0x11857d000):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:52772], sessionId=0x147fa019b250001, negotiated timeout=6000
I0821 21:18:35.120141 107220992 group.cpp:313] Group process (group(2)@127.0.0.1:52771) connected to ZooKeeper
I0821 21:18:35.120157 107220992 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (1, 0, 0)
I0821 21:18:35.120165 107220992 group.cpp:385] Trying to create path '/log' in ZooKeeper
2014-08-21 21:18:35,120:6420(0x118693000):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:52772], sessionId=0x147fa019b250002, negotiated timeout=6000
I0821 21:18:35.120407 108830720 group.cpp:313] Group process (group(3)@127.0.0.1:52771) connected to ZooKeeper
I0821 21:18:35.120425 108830720 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (0, 0, 0)
I0821 21:18:35.120435 108830720 group.cpp:385] Trying to create path '/log' in ZooKeeper
2014-08-21 21:18:35,120:6420(0x118799000):ZOO_INFO@check_events@1750: session establishment complete on server [127.0.0.1:52772], sessionId=0x147fa019b250003, negotiated timeout=6000
I0821 21:18:35.120790 107757568 group.cpp:313] Group process (group(4)@127.0.0.1:52771) connected to ZooKeeper
I0821 21:18:35.120807 107757568 group.cpp:787] Syncing group operations: queue size (joins, cancels, datas) = (1, 0, 0)
I0821 21:18:35.120817 107757568 group.cpp:385] Trying to create path '/log' in ZooKeeper
I0821 21:18:35.139410 108294144 network.hpp:423] ZooKeeper group memberships changed
I0821 21:18:35.139467 109367296 group.cpp:658] Trying to get '/log/0000000000' in ZooKeeper
I0821 21:18:35.139775 106147840 network.hpp:423] ZooKeeper group memberships changed
I0821 21:18:35.139847 106684416 group.cpp:658] Trying to get '/log/0000000000' in ZooKeeper
I0821 21:18:35.141216 109367296 group.cpp:658] Trying to get '/log/0000000001' in ZooKeeper
I0821 21:18:35.141362 106684416 group.cpp:658] Trying to get '/log/0000000001' in ZooKeeper
I0821 21:18:35.141815 106147840 network.hpp:461] ZooKeeper group PIDs: { log-replica(3)@127.0.0.1:52771, log-replica(4)@127.0.0.1:52771 }
I0821 21:18:35.141955 108830720 network.hpp:461] ZooKeeper group PIDs: { log-replica(3)@127.0.0.1:52771, log-replica(4)@127.0.0.1:52771 }
I0821 21:18:35.142052 107757568 replica.cpp:474] Replica received implicit promise request with proposal 1
I0821 21:18:35.142137 106147840 replica.cpp:474] Replica received implicit promise request with proposal 1
I0821 21:18:35.142258 107757568 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 191us
I0821 21:18:35.142278 107757568 replica.cpp:342] Persisted promised to 1
I0821 21:18:35.142267 106147840 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 123us
I0821 21:18:35.142288 106147840 replica.cpp:342] Persisted promised to 1
I0821 21:18:35.142478 109903872 coordinator.cpp:230] Coordinator attemping to fill missing position
I0821 21:18:35.143013 106684416 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
I0821 21:18:35.143059 106147840 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
I0821 21:18:35.143126 106684416 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 103us
I0821 21:18:35.143136 106147840 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 74us
I0821 21:18:35.143149 106684416 replica.cpp:676] Persisted action at 0
I0821 21:18:35.143154 106147840 replica.cpp:676] Persisted action at 0
I0821 21:18:35.143472 106684416 replica.cpp:508] Replica received write request for position 0
I0821 21:18:35.143494 106684416 leveldb.cpp:438] Reading position from leveldb took 11us
I0821 21:18:35.143530 106147840 replica.cpp:508] Replica received write request for position 0
I0821 21:18:35.143550 106147840 leveldb.cpp:438] Reading position from leveldb took 11us
I0821 21:18:35.143579 106684416 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 81us
I0821 21:18:35.143594 106684416 replica.cpp:676] Persisted action at 0
I0821 21:18:35.143625 106147840 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 71us
I0821 21:18:35.143642 106147840 replica.cpp:676] Persisted action at 0
I0821 21:18:35.143841 109367296 replica.cpp:655] Replica received learned notice for position 0
I0821 21:18:35.143861 106147840 replica.cpp:655] Replica received learned notice for position 0
I0821 21:18:35.143932 109367296 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 88us
I0821 21:18:35.143937 106147840 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 71us
I0821 21:18:35.143959 109367296 replica.cpp:676] Persisted action at 0
I0821 21:18:35.143967 109367296 replica.cpp:661] Replica learned NOP action at position 0
I0821 21:18:35.143965 106147840 replica.cpp:676] Persisted action at 0
I0821 21:18:35.143976 106147840 replica.cpp:661] Replica learned NOP action at position 0
I0821 21:18:35.144122 107220992 log.cpp:672] Writer started with ending position 0
I0821 21:18:35.144250 106147840 log.cpp:680] Attempting to append 11 bytes to the log
I0821 21:18:35.144297 108294144 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
I0821 21:18:35.144521 106684416 replica.cpp:508] Replica received write request for position 1
I0821 21:18:35.144593 108830720 replica.cpp:508] Replica received write request for position 1
I0821 21:18:35.144613 106684416 leveldb.cpp:343] Persisting action (27 bytes) to leveldb took 87us
I0821 21:18:35.144630 106684416 replica.cpp:676] Persisted action at 1
I0821 21:18:35.144691 108830720 leveldb.cpp:343] Persisting action (27 bytes) to leveldb took 88us
I0821 21:18:35.144709 108830720 replica.cpp:676] Persisted action at 1
I0821 21:18:35.144906 106684416 replica.cpp:655] Replica received learned notice for position 1
I0821 21:18:35.144924 107220992 replica.cpp:655] Replica received learned notice for position 1
I0821 21:18:35.145002 106684416 leveldb.cpp:343] Persisting action (29 bytes) to leveldb took 87us
I0821 21:18:35.145009 107220992 leveldb.cpp:343] Persisting action (29 bytes) to leveldb took 80us
I0821 21:18:35.145019 106684416 replica.cpp:676] Persisted action at 1
I0821 21:18:35.145027 107220992 replica.cpp:676] Persisted action at 1
I0821 21:18:35.145030 106684416 replica.cpp:661] Replica learned APPEND action at position 1
I0821 21:18:35.145033 107220992 replica.cpp:661] Replica learned APPEND action at position 1
I0821 21:18:35.145308 107757568 leveldb.cpp:438] Reading position from leveldb took 11us
2014-08-21 21:18:35,145:6420(0x1067ca000):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x147fa019b250003 to [127.0.0.1:52772]

2014-08-21 21:18:35,145:6420(0x106641000):ZOO_INFO@zookeeper_close@2505: Closing zookeeper sessionId=0x147fa019b250002 to [127.0.0.1:52772]

W0821 21:18:35.145308 2078368528 glog.hpp:52] RAW: Received signal SIGPIPE; escalating to SIGABRT
*** Aborted at 1408648715 (unix time) try "date -d @1408648715" if you are using GNU date ***
PC: @     0x7fff8ee35292 __kill
*** SIGABRT (@0x7fff8ee35292) received by PID 6420 (TID 0x7fff7be16310) stack trace: ***
    @     0x7fff93e8a5aa _sigtramp
    @     0x7fff7c369338 usual
    @        0x106d6e37d os::Bsd::chained_handler()
    @        0x106d72166 JVM_handle_bsd_signal
    @     0x7fff93e8a5aa _sigtramp
    @                0x0 (unknown)
    @        0x10492a96b process::ProcessManager::wait()
    @        0x10492c95b process::wait()
    @        0x10482e5da mesos::internal::log::Log::~Log()
    @        0x10337b56e LogZooKeeperTest_WriteRead_Test::TestBody()
    @        0x103702f8c testing::internal::HandleExceptionsInMethodIfSupported<>()
    @        0x1036ee90a testing::Test::Run()
    @        0x1036ef592 testing::TestInfo::Run()
    @        0x1036efbd0 testing::TestCase::Run()
    @        0x1036f5425 testing::internal::UnitTestImpl::RunAllTests()
    @        0x103703754 testing::internal::HandleExceptionsInMethodIfSupported<>()
    @        0x1036f5159 testing::UnitTest::Run()
    @        0x1033b1a33 main
    @     0x7fff95dc05fd start
Abort trap: 6

      Attachments

        Issue Links

          is related to

          Bug - A problem which impairs or prevents the functions of the product. MESOS-2242 Make check segfault on CentOS5

          • Major - Major loss of function.
          • Open
          relates to

          Bug - A problem which impairs or prevents the functions of the product. MESOS-2407 libprocess segfaults when using GLOG_v=2

          • Major - Major loss of function.
          • Resolved

          Activity

            People

              vinodkone Vinod Kone
              tillt Till Toenshoff
              Jie Yu Jie Yu
              Votes:
              0 Vote for this issue
              Watchers:
              8 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: