[ https://issues.apache.org/jira/browse/MESOS-1729?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Vinod Kone resolved MESOS-1729. ------------------------------- Resolution: Fixed Fix Version/s: 0.21.0 commit 6af543211d7c35e783fb8b23341810fa678fb78a Author: Vinod Kone <vinodk...@gmail.com> Date: Wed Aug 27 15:47:58 2014 -0700 Fixed signal handling for Mesos. Review: https://reviews.apache.org/r/25129 > LogZooKeeperTest.WriteRead fails due to SIGPIPE (escalated to SIGABRT) > ---------------------------------------------------------------------- > > Key: MESOS-1729 > URL: https://issues.apache.org/jira/browse/MESOS-1729 > Project: Mesos > Issue Type: Bug > Components: build, test > Affects Versions: 0.21.0 > Environment: OSX 10.9.4, clang 3.4. > Same or very similar results on Linux > Reporter: Till Toenshoff > Assignee: Vinod Kone > Labels: test > Fix For: 0.21.0 > > > The following is reported and 100% reproducible when running {{make check}} > on my OSX box. > {noformat} > [ 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 > {noformat} -- This message was sent by Atlassian JIRA (v6.2#6252)