You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@mesos.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2014/10/29 09:29:46 UTC
Build failed in Jenkins:
Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME #2227
See <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/2227/changes>
Changes:
[benjamin.hindman] Fixed signedness compilation bug.
------------------------------------------
[...truncated 69451 lines...]
I1029 08:29:01.746940 32251 master.cpp:358] Master only allowing authenticated frameworks to register
I1029 08:29:01.746958 32251 master.cpp:363] Master only allowing authenticated slaves to register
I1029 08:29:01.746973 32251 credentials.hpp:36] Loading credentials for authentication from '/tmp/MasterSlaveReconciliationTest_ReconcileLostTask_dHQFbB/credentials'
I1029 08:29:01.747167 32251 master.cpp:392] Authorization enabled
I1029 08:29:01.747524 32261 master.cpp:120] No whitelist given. Advertising offers for all slaves
I1029 08:29:01.747531 32260 replica.cpp:638] Replica in STARTING status received a broadcasted recover request
I1029 08:29:01.747757 32253 hierarchical_allocator_process.hpp:299] Initializing hierarchical allocator process with master : master@67.195.81.187:40696
I1029 08:29:01.748066 32259 recover.cpp:188] Received a recover response from a replica in STARTING status
I1029 08:29:01.748724 32251 master.cpp:1242] The newly elected leader is master@67.195.81.187:40696 with id 20141029-082901-3142697795-40696-32232
I1029 08:29:01.748754 32251 master.cpp:1255] Elected as the leading master!
I1029 08:29:01.748769 32251 master.cpp:1073] Recovering from registrar
I1029 08:29:01.748764 32255 recover.cpp:554] Updating replica status to VOTING
I1029 08:29:01.749003 32249 registrar.cpp:313] Recovering registrar
I1029 08:29:01.749435 32261 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 461205ns
I1029 08:29:01.749469 32261 replica.cpp:320] Persisted replica status to VOTING
I1029 08:29:01.749611 32255 recover.cpp:568] Successfully joined the Paxos group
I1029 08:29:01.749806 32255 recover.cpp:452] Recover process terminated
I1029 08:29:01.750274 32254 log.cpp:656] Attempting to start the writer
I1029 08:29:01.751739 32259 replica.cpp:474] Replica received implicit promise request with proposal 1
I1029 08:29:01.752102 32259 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 335010ns
I1029 08:29:01.752128 32259 replica.cpp:342] Persisted promised to 1
I1029 08:29:01.752923 32251 coordinator.cpp:230] Coordinator attemping to fill missing position
I1029 08:29:01.754606 32261 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
I1029 08:29:01.754984 32261 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 341669ns
I1029 08:29:01.755012 32261 replica.cpp:676] Persisted action at 0
I1029 08:29:01.756240 32258 replica.cpp:508] Replica received write request for position 0
I1029 08:29:01.756314 32258 leveldb.cpp:438] Reading position from leveldb took 42163ns
I1029 08:29:01.756639 32258 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 285232ns
I1029 08:29:01.756667 32258 replica.cpp:676] Persisted action at 0
I1029 08:29:01.757210 32261 replica.cpp:655] Replica received learned notice for position 0
I1029 08:29:01.757375 32261 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 136938ns
I1029 08:29:01.757402 32261 replica.cpp:676] Persisted action at 0
I1029 08:29:01.757426 32261 replica.cpp:661] Replica learned NOP action at position 0
I1029 08:29:01.757891 32256 log.cpp:672] Writer started with ending position 0
I1029 08:29:01.758985 32255 leveldb.cpp:438] Reading position from leveldb took 24641ns
I1029 08:29:01.762171 32257 registrar.cpp:346] Successfully fetched the registry (0B) in 13.080064ms
I1029 08:29:01.762275 32257 registrar.cpp:445] Applied 1 operations in 25968ns; attempting to update the 'registry'
I1029 08:29:01.765403 32258 log.cpp:680] Attempting to append 139 bytes to the log
I1029 08:29:01.765553 32256 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
I1029 08:29:01.766399 32261 replica.cpp:508] Replica received write request for position 1
I1029 08:29:01.766787 32261 leveldb.cpp:343] Persisting action (158 bytes) to leveldb took 356567ns
I1029 08:29:01.766810 32261 replica.cpp:676] Persisted action at 1
I1029 08:29:01.767429 32253 replica.cpp:655] Replica received learned notice for position 1
I1029 08:29:01.767731 32253 leveldb.cpp:343] Persisting action (160 bytes) to leveldb took 271318ns
I1029 08:29:01.767755 32253 replica.cpp:676] Persisted action at 1
I1029 08:29:01.767773 32253 replica.cpp:661] Replica learned APPEND action at position 1
I1029 08:29:01.768581 32257 registrar.cpp:490] Successfully updated the 'registry' in 6.209792ms
I1029 08:29:01.768728 32257 registrar.cpp:376] Successfully recovered registrar
I1029 08:29:01.768862 32246 log.cpp:699] Attempting to truncate the log to 1
I1029 08:29:01.769008 32259 master.cpp:1100] Recovered 0 slaves from the Registry (101B) ; allowing 10mins for slaves to re-register
I1029 08:29:01.769173 32261 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
I1029 08:29:01.769971 32252 replica.cpp:508] Replica received write request for position 2
I1029 08:29:01.770251 32252 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 249793ns
I1029 08:29:01.770273 32252 replica.cpp:676] Persisted action at 2
I1029 08:29:01.770901 32247 replica.cpp:655] Replica received learned notice for position 2
I1029 08:29:01.771379 32247 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 439672ns
I1029 08:29:01.771445 32247 leveldb.cpp:401] Deleting ~1 keys from leveldb took 32272ns
I1029 08:29:01.771468 32247 replica.cpp:676] Persisted action at 2
I1029 08:29:01.771492 32247 replica.cpp:661] Replica learned TRUNCATE action at position 2
I1029 08:29:01.783360 32232 containerizer.cpp:100] Using isolation: posix/cpu,posix/mem
I1029 08:29:01.784912 32248 slave.cpp:169] Slave started on 221)@67.195.81.187:40696
I1029 08:29:01.785006 32248 credentials.hpp:84] Loading credential for authentication from '/tmp/MasterSlaveReconciliationTest_ReconcileLostTask_tRTNTJ/credential'
I1029 08:29:01.785164 32248 slave.cpp:276] Slave using credential for: test-principal
I1029 08:29:01.785475 32248 slave.cpp:289] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I1029 08:29:01.785598 32248 slave.cpp:318] Slave hostname: pomona.apache.org
I1029 08:29:01.785616 32248 slave.cpp:319] Slave checkpoint: false
W1029 08:29:01.785626 32248 slave.cpp:321] Disabling checkpointing is deprecated and the --checkpoint flag will be removed in a future release. Please avoid using this flag
I1029 08:29:01.786360 32260 state.cpp:33] Recovering state from '/tmp/MasterSlaveReconciliationTest_ReconcileLostTask_tRTNTJ/meta'
I1029 08:29:01.786676 32261 status_update_manager.cpp:197] Recovering status update manager
I1029 08:29:01.786864 32246 containerizer.cpp:281] Recovering containerizer
I1029 08:29:01.787552 32251 slave.cpp:3456] Finished recovery
I1029 08:29:01.787946 32251 slave.cpp:602] New master detected at master@67.195.81.187:40696
I1029 08:29:01.787988 32256 status_update_manager.cpp:171] Pausing sending status updates
I1029 08:29:01.787999 32251 slave.cpp:665] Authenticating with master master@67.195.81.187:40696
I1029 08:29:01.788132 32259 authenticatee.hpp:133] Creating new client SASL connection
I1029 08:29:01.788136 32251 slave.cpp:638] Detecting new master
I1029 08:29:01.788336 32259 master.cpp:3853] Authenticating slave(221)@67.195.81.187:40696
I1029 08:29:01.788488 32251 authenticator.hpp:161] Creating new server SASL connection
I1029 08:29:01.788584 32259 authenticatee.hpp:224] Received SASL authentication mechanisms: CRAM-MD5
I1029 08:29:01.788611 32259 authenticatee.hpp:250] Attempting to authenticate with mechanism 'CRAM-MD5'
I1029 08:29:01.788748 32250 authenticator.hpp:267] Received SASL authentication start
I1029 08:29:01.788852 32250 authenticator.hpp:389] Authentication requires more steps
I1029 08:29:01.788981 32254 authenticatee.hpp:270] Received SASL authentication step
I1029 08:29:01.789067 32254 authenticator.hpp:295] Received SASL authentication step
I1029 08:29:01.789090 32254 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1029 08:29:01.789099 32254 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I1029 08:29:01.789124 32254 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1029 08:29:01.789141 32254 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1029 08:29:01.789149 32254 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1029 08:29:01.789155 32254 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1029 08:29:01.789166 32254 authenticator.hpp:381] Authentication success
I1029 08:29:01.789247 32249 authenticatee.hpp:310] Authentication success
I1029 08:29:01.789247 32256 master.cpp:3893] Successfully authenticated principal 'test-principal' at slave(221)@67.195.81.187:40696
I1029 08:29:01.789551 32254 slave.cpp:722] Successfully authenticated with master master@67.195.81.187:40696
I1029 08:29:01.789638 32254 slave.cpp:1050] Will retry registration in 14.558697ms if necessary
I1029 08:29:01.789758 32247 master.cpp:3032] Registering slave at slave(221)@67.195.81.187:40696 (pomona.apache.org) with id 20141029-082901-3142697795-40696-32232-S0
I1029 08:29:01.790158 32250 registrar.cpp:445] Applied 1 operations in 55741ns; attempting to update the 'registry'
I1029 08:29:01.790506 32232 sched.cpp:137] Version: 0.21.0
I1029 08:29:01.790932 32248 sched.cpp:233] New master detected at master@67.195.81.187:40696
I1029 08:29:01.790983 32248 sched.cpp:283] Authenticating with master master@67.195.81.187:40696
I1029 08:29:01.791153 32249 authenticatee.hpp:133] Creating new client SASL connection
I1029 08:29:01.791319 32252 master.cpp:3853] Authenticating scheduler-57a5867a-c38f-4940-b626-3b457eb16121@67.195.81.187:40696
I1029 08:29:01.791473 32247 authenticator.hpp:161] Creating new server SASL connection
I1029 08:29:01.791578 32258 authenticatee.hpp:224] Received SASL authentication mechanisms: CRAM-MD5
I1029 08:29:01.791600 32258 authenticatee.hpp:250] Attempting to authenticate with mechanism 'CRAM-MD5'
I1029 08:29:01.791674 32249 authenticator.hpp:267] Received SASL authentication start
I1029 08:29:01.791720 32249 authenticator.hpp:389] Authentication requires more steps
I1029 08:29:01.791785 32258 authenticatee.hpp:270] Received SASL authentication step
I1029 08:29:01.791873 32252 authenticator.hpp:295] Received SASL authentication step
I1029 08:29:01.791899 32252 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1029 08:29:01.791908 32252 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I1029 08:29:01.791929 32252 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1029 08:29:01.791949 32252 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1029 08:29:01.791959 32252 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1029 08:29:01.791965 32252 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1029 08:29:01.791975 32252 authenticator.hpp:381] Authentication success
I1029 08:29:01.792035 32249 authenticatee.hpp:310] Authentication success
I1029 08:29:01.792098 32247 master.cpp:3893] Successfully authenticated principal 'test-principal' at scheduler-57a5867a-c38f-4940-b626-3b457eb16121@67.195.81.187:40696
I1029 08:29:01.792270 32255 sched.cpp:357] Successfully authenticated with master master@67.195.81.187:40696
I1029 08:29:01.792302 32255 sched.cpp:476] Sending registration request to master@67.195.81.187:40696
I1029 08:29:01.792421 32247 master.cpp:1362] Received registration request for framework 'default' at scheduler-57a5867a-c38f-4940-b626-3b457eb16121@67.195.81.187:40696
I1029 08:29:01.792487 32247 master.cpp:1321] Authorizing framework principal 'test-principal' to receive offers for role '*'
I1029 08:29:01.792841 32254 master.cpp:1426] Registering framework 20141029-082901-3142697795-40696-32232-0000 (default) at scheduler-57a5867a-c38f-4940-b626-3b457eb16121@67.195.81.187:40696
I1029 08:29:01.793159 32247 hierarchical_allocator_process.hpp:329] Added framework 20141029-082901-3142697795-40696-32232-0000
I1029 08:29:01.793190 32247 hierarchical_allocator_process.hpp:697] No resources available to allocate!
I1029 08:29:01.793205 32247 hierarchical_allocator_process.hpp:659] Performed allocation for 0 slaves in 18354ns
I1029 08:29:01.793267 32256 sched.cpp:407] Framework registered with 20141029-082901-3142697795-40696-32232-0000
I1029 08:29:01.793364 32258 log.cpp:680] Attempting to append 316 bytes to the log
I1029 08:29:01.793377 32256 sched.cpp:421] Scheduler::registered took 18044ns
I1029 08:29:01.793473 32253 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3
I1029 08:29:01.794193 32249 replica.cpp:508] Replica received write request for position 3
I1029 08:29:01.794703 32249 leveldb.cpp:343] Persisting action (335 bytes) to leveldb took 483307ns
I1029 08:29:01.794726 32249 replica.cpp:676] Persisted action at 3
I1029 08:29:01.795399 32259 replica.cpp:655] Replica received learned notice for position 3
I1029 08:29:01.795842 32259 leveldb.cpp:343] Persisting action (337 bytes) to leveldb took 412342ns
I1029 08:29:01.795874 32259 replica.cpp:676] Persisted action at 3
I1029 08:29:01.795899 32259 replica.cpp:661] Replica learned APPEND action at position 3
I1029 08:29:01.796898 32253 registrar.cpp:490] Successfully updated the 'registry' in 6.681856ms
I1029 08:29:01.797178 32257 log.cpp:699] Attempting to truncate the log to 3
I1029 08:29:01.797451 32250 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4
I1029 08:29:01.797663 32256 slave.cpp:2522] Received ping from slave-observer(198)@67.195.81.187:40696
I1029 08:29:01.797827 32252 master.cpp:3086] Registered slave 20141029-082901-3142697795-40696-32232-S0 at slave(221)@67.195.81.187:40696 (pomona.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I1029 08:29:01.797948 32256 slave.cpp:756] Registered with master master@67.195.81.187:40696; given slave ID 20141029-082901-3142697795-40696-32232-S0
I1029 08:29:01.798121 32249 status_update_manager.cpp:178] Resuming sending status updates
I1029 08:29:01.798086 32246 hierarchical_allocator_process.hpp:442] Added slave 20141029-082901-3142697795-40696-32232-S0 (pomona.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
I1029 08:29:01.798364 32246 hierarchical_allocator_process.hpp:734] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20141029-082901-3142697795-40696-32232-S0 to framework 20141029-082901-3142697795-40696-32232-0000
I1029 08:29:01.798773 32246 hierarchical_allocator_process.hpp:679] Performed allocation for slave 20141029-082901-3142697795-40696-32232-S0 in 583233ns
I1029 08:29:01.798876 32255 replica.cpp:508] Replica received write request for position 4
I1029 08:29:01.799067 32258 master.cpp:3795] Sending 1 offers to framework 20141029-082901-3142697795-40696-32232-0000 (default) at scheduler-57a5867a-c38f-4940-b626-3b457eb16121@67.195.81.187:40696
I1029 08:29:01.799401 32255 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 487021ns
I1029 08:29:01.799437 32255 replica.cpp:676] Persisted action at 4
I1029 08:29:01.799464 32254 sched.cpp:544] Scheduler::resourceOffers took 74901ns
I1029 08:29:01.800565 32249 replica.cpp:655] Replica received learned notice for position 4
I1029 08:29:01.800915 32249 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 317125ns
I1029 08:29:01.800974 32249 leveldb.cpp:401] Deleting ~2 keys from leveldb took 30440ns
I1029 08:29:01.800992 32249 replica.cpp:676] Persisted action at 4
I1029 08:29:01.801015 32249 replica.cpp:661] Replica learned TRUNCATE action at position 4
I1029 08:29:01.801224 32258 master.cpp:2321] Processing reply for offers: [ 20141029-082901-3142697795-40696-32232-O0 ] on slave 20141029-082901-3142697795-40696-32232-S0 at slave(221)@67.195.81.187:40696 (pomona.apache.org) for framework 20141029-082901-3142697795-40696-32232-0000 (default) at scheduler-57a5867a-c38f-4940-b626-3b457eb16121@67.195.81.187:40696
W1029 08:29:01.801374 32258 master.cpp:1969] Executor default for task 1 uses less CPUs (None) than the minimum required (0.01). Please update your executor, as this will be mandatory in future releases.
W1029 08:29:01.801412 32258 master.cpp:1980] Executor default for task 1 uses less memory (None) than the minimum required (32MB). Please update your executor, as this will be mandatory in future releases.
I1029 08:29:01.801522 32258 master.cpp:2417] Authorizing framework principal 'test-principal' to launch task 1 as user 'jenkins'
I1029 08:29:01.802527 32254 master.hpp:877] Adding task 1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20141029-082901-3142697795-40696-32232-S0 (pomona.apache.org)
I1029 08:29:01.802645 32254 master.cpp:2480] Launching task 1 of framework 20141029-082901-3142697795-40696-32232-0000 (default) at scheduler-57a5867a-c38f-4940-b626-3b457eb16121@67.195.81.187:40696 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20141029-082901-3142697795-40696-32232-S0 at slave(221)@67.195.81.187:40696 (pomona.apache.org)
I1029 08:29:01.807513 32261 slave.cpp:602] New master detected at master@67.195.81.187:40696
I1029 08:29:01.807621 32260 status_update_manager.cpp:171] Pausing sending status updates
I1029 08:29:01.807621 32261 slave.cpp:665] Authenticating with master master@67.195.81.187:40696
I1029 08:29:01.807837 32261 slave.cpp:638] Detecting new master
I1029 08:29:01.807936 32248 authenticatee.hpp:133] Creating new client SASL connection
I1029 08:29:01.808363 32258 master.cpp:3853] Authenticating slave(221)@67.195.81.187:40696
I1029 08:29:01.808797 32246 authenticator.hpp:161] Creating new server SASL connection
I1029 08:29:01.809051 32256 authenticatee.hpp:224] Received SASL authentication mechanisms: CRAM-MD5
I1029 08:29:01.809103 32256 authenticatee.hpp:250] Attempting to authenticate with mechanism 'CRAM-MD5'
I1029 08:29:01.809370 32257 authenticator.hpp:267] Received SASL authentication start
I1029 08:29:01.809425 32257 authenticator.hpp:389] Authentication requires more steps
I1029 08:29:01.809512 32257 authenticatee.hpp:270] Received SASL authentication step
I1029 08:29:01.809648 32246 authenticator.hpp:295] Received SASL authentication step
I1029 08:29:01.809682 32246 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1029 08:29:01.809695 32246 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I1029 08:29:01.809736 32246 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1029 08:29:01.809777 32246 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1029 08:29:01.809793 32246 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1029 08:29:01.809803 32246 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1029 08:29:01.809819 32246 authenticator.hpp:381] Authentication success
I1029 08:29:01.809927 32247 authenticatee.hpp:310] Authentication success
I1029 08:29:01.809936 32257 master.cpp:3893] Successfully authenticated principal 'test-principal' at slave(221)@67.195.81.187:40696
I1029 08:29:01.810453 32251 slave.cpp:722] Successfully authenticated with master master@67.195.81.187:40696
I1029 08:29:01.810636 32251 slave.cpp:1050] Will retry registration in 12.388106ms if necessary
I1029 08:29:01.810950 32253 master.cpp:3159] Re-registering slave 20141029-082901-3142697795-40696-32232-S0 at slave(221)@67.195.81.187:40696 (pomona.apache.org)
W1029 08:29:01.811121 32253 master.cpp:3956] Task 1 of framework 20141029-082901-3142697795-40696-32232-0000 unknown to the slave 20141029-082901-3142697795-40696-32232-S0 at slave(221)@67.195.81.187:40696 (pomona.apache.org) during re-registration: reconciling with the slave
W1029 08:29:01.811403 32253 master.cpp:4033] Executor default of framework 20141029-082901-3142697795-40696-32232-0000 possibly unknown to the slave 20141029-082901-3142697795-40696-32232-S0 at slave(221)@67.195.81.187:40696 (pomona.apache.org)
I1029 08:29:01.811498 32253 master.cpp:4705] Removing executor 'default' with resources of framework 20141029-082901-3142697795-40696-32232-0000 on slave 20141029-082901-3142697795-40696-32232-S0 at slave(221)@67.195.81.187:40696 (pomona.apache.org)
I1029 08:29:01.811636 32259 slave.cpp:824] Re-registered with master master@67.195.81.187:40696
W1029 08:29:01.811743 32259 slave.cpp:882] Slave reconciling task 1 of framework 20141029-082901-3142697795-40696-32232-0000 in state TASK_LOST: task unknown to the slave
I1029 08:29:01.811813 32260 status_update_manager.cpp:178] Resuming sending status updates
I1029 08:29:01.814267 32246 status_update_manager.cpp:317] Received status update TASK_LOST (UUID: 7b17c02a-8489-4887-b425-e9de19507164) for task 1 of framework 20141029-082901-3142697795-40696-32232-0000
I1029 08:29:01.814338 32246 status_update_manager.cpp:494] Creating StatusUpdate stream for task 1 of framework 20141029-082901-3142697795-40696-32232-0000
I1029 08:29:01.814589 32246 status_update_manager.cpp:371] Forwarding update TASK_LOST (UUID: 7b17c02a-8489-4887-b425-e9de19507164) for task 1 of framework 20141029-082901-3142697795-40696-32232-0000 to the slave
I1029 08:29:01.814786 32260 slave.cpp:2442] Forwarding the update TASK_LOST (UUID: 7b17c02a-8489-4887-b425-e9de19507164) for task 1 of framework 20141029-082901-3142697795-40696-32232-0000 to master@67.195.81.187:40696
I1029 08:29:01.814998 32260 slave.cpp:2369] Status update manager successfully handled status update TASK_LOST (UUID: 7b17c02a-8489-4887-b425-e9de19507164) for task 1 of framework 20141029-082901-3142697795-40696-32232-0000
I1029 08:29:01.815536 32249 master.cpp:3410] Forwarding status update TASK_LOST (UUID: 7b17c02a-8489-4887-b425-e9de19507164) for task 1 of framework 20141029-082901-3142697795-40696-32232-0000
I1029 08:29:01.816026 32249 master.cpp:3382] Status update TASK_LOST (UUID: 7b17c02a-8489-4887-b425-e9de19507164) for task 1 of framework 20141029-082901-3142697795-40696-32232-0000 from slave 20141029-082901-3142697795-40696-32232-S0 at slave(221)@67.195.81.187:40696 (pomona.apache.org)
I1029 08:29:01.816092 32249 master.cpp:4617] Updating the latest state of task 1 of framework 20141029-082901-3142697795-40696-32232-0000 to TASK_LOST
I1029 08:29:01.816208 32259 sched.cpp:635] Scheduler::statusUpdate took 68988ns
I1029 08:29:01.816612 32253 sched.cpp:745] Stopping framework '20141029-082901-3142697795-40696-32232-0000'
I1029 08:29:01.816648 32249 master.cpp:677] Master terminating
I1029 08:29:01.816759 32249 master.cpp:4676] Removing task 1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework 20141029-082901-3142697795-40696-32232-0000 on slave 20141029-082901-3142697795-40696-32232-S0 at slave(221)@67.195.81.187:40696 (pomona.apache.org)
I1029 08:29:01.816819 32251 hierarchical_allocator_process.hpp:563] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total allocatable: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) on slave 20141029-082901-3142697795-40696-32232-S0 from framework 20141029-082901-3142697795-40696-32232-0000
I1029 08:29:01.817541 32256 slave.cpp:2607] master@67.195.81.187:40696 exited
W1029 08:29:01.817574 32256 slave.cpp:2610] Master disconnected! Waiting for a new master to be elected
I1029 08:29:01.822736 32232 slave.cpp:484] Slave terminating
[ OK ] MasterSlaveReconciliationTest.ReconcileLostTask (88 ms)
[----------] 5 tests from MasterSlaveReconciliationTest (525 ms total)
[----------] 1 test from HTTP
[ RUN ] HTTP.ModelTask
[ OK ] HTTP.ModelTask (1 ms)
[----------] 1 test from HTTP (1 ms total)
[----------] 2 tests from CpuIsolatorTest/2, where TypeParam = mesos::internal::tests::Module<mesos::internal::slave::Isolator, (mesos::internal::tests::ModuleID)1>
[ RUN ] CpuIsolatorTest/2.SystemCpuUsage
Using temporary directory '/tmp/CpuIsolatorTest_2_SystemCpuUsage_Kio5IS'
I1029 08:29:01.832018 32232 launcher.cpp:137] Forked child with pid '5285' for container 'system_cpu_usage'
[ OK ] CpuIsolatorTest/2.SystemCpuUsage (418 ms)
[ RUN ] CpuIsolatorTest/2.UserCpuUsage
Using temporary directory '/tmp/CpuIsolatorTest_2_UserCpuUsage_VeBKtb'
I1029 08:29:02.249784 32232 launcher.cpp:137] Forked child with pid '5289' for container 'user_cpu_usage'
[ OK ] CpuIsolatorTest/2.UserCpuUsage (406 ms)
[----------] 2 tests from CpuIsolatorTest/2 (824 ms total)
[----------] Global test environment tear-down
[==========] 449 tests from 70 test cases ran. (317294 ms total)
[ PASSED ] 448 tests.
[ FAILED ] 1 test, listed below:
[ FAILED ] MasterAuthorizationTest.DuplicateReregistration
1 FAILED TEST
YOU HAVE 6 DISABLED TESTS
make[3]: *** [check-local] Error 1
make[3]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/src'>
make[2]: *** [check-am] Error 2
make[2]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/src'>
make[1]: *** [check] Error 2
make[1]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/src'>
make: *** [check-recursive] Error 1
Test finished
Exit status: 2
Build step 'Execute shell' marked build as failure
Recording test results
Build failed in Jenkins:
Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME #2230
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/2230/changes>
Changes:
[vinodkone] Added MesosCon'14 playlist to presentations.
------------------------------------------
[...truncated 15872 lines...]
I1030 05:54:04.505708 29517 replica.cpp:676] Persisted action at 2
I1030 05:54:04.505733 29517 replica.cpp:661] Replica learned TRUNCATE action at position 2
I1030 05:54:04.518836 29520 slave.cpp:169] Slave started on 27)@67.195.81.187:54775
I1030 05:54:04.518879 29520 credentials.hpp:84] Loading credential for authentication from '/tmp/ReconciliationTest_TaskStateMismatch_jXTxgL/credential'
I1030 05:54:04.519043 29520 slave.cpp:276] Slave using credential for: test-principal
I1030 05:54:04.519332 29520 slave.cpp:289] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I1030 05:54:04.519435 29520 slave.cpp:318] Slave hostname: pomona.apache.org
I1030 05:54:04.519454 29520 slave.cpp:319] Slave checkpoint: false
W1030 05:54:04.519462 29520 slave.cpp:321] Disabling checkpointing is deprecated and the --checkpoint flag will be removed in a future release. Please avoid using this flag
I1030 05:54:04.520382 29526 state.cpp:33] Recovering state from '/tmp/ReconciliationTest_TaskStateMismatch_jXTxgL/meta'
I1030 05:54:04.521198 29519 status_update_manager.cpp:197] Recovering status update manager
I1030 05:54:04.521605 29521 slave.cpp:3456] Finished recovery
I1030 05:54:04.522595 29515 status_update_manager.cpp:171] Pausing sending status updates
I1030 05:54:04.522593 29524 slave.cpp:602] New master detected at master@67.195.81.187:54775
I1030 05:54:04.522677 29524 slave.cpp:665] Authenticating with master master@67.195.81.187:54775
I1030 05:54:04.522855 29524 slave.cpp:638] Detecting new master
I1030 05:54:04.522924 29522 authenticatee.hpp:133] Creating new client SASL connection
I1030 05:54:04.523164 29512 master.cpp:3853] Authenticating slave(27)@67.195.81.187:54775
I1030 05:54:04.523605 29523 authenticator.hpp:161] Creating new server SASL connection
I1030 05:54:04.523784 29523 authenticatee.hpp:224] Received SASL authentication mechanisms: CRAM-MD5
I1030 05:54:04.523813 29523 authenticatee.hpp:250] Attempting to authenticate with mechanism 'CRAM-MD5'
I1030 05:54:04.523910 29519 authenticator.hpp:267] Received SASL authentication start
I1030 05:54:04.524049 29519 authenticator.hpp:389] Authentication requires more steps
I1030 05:54:04.524139 29519 authenticatee.hpp:270] Received SASL authentication step
I1030 05:54:04.524343 29524 authenticator.hpp:295] Received SASL authentication step
I1030 05:54:04.524382 29524 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1030 05:54:04.524395 29524 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I1030 05:54:04.524438 29524 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1030 05:54:04.524466 29524 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1030 05:54:04.524479 29524 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1030 05:54:04.524488 29524 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1030 05:54:04.524507 29524 authenticator.hpp:381] Authentication success
I1030 05:54:04.524592 29523 authenticatee.hpp:310] Authentication success
I1030 05:54:04.524618 29524 master.cpp:3893] Successfully authenticated principal 'test-principal' at slave(27)@67.195.81.187:54775
I1030 05:54:04.524847 29519 slave.cpp:722] Successfully authenticated with master master@67.195.81.187:54775
I1030 05:54:04.525086 29519 slave.cpp:1050] Will retry registration in 1.045728ms if necessary
I1030 05:54:04.525368 29524 master.cpp:3032] Registering slave at slave(27)@67.195.81.187:54775 (pomona.apache.org) with id 20141030-055359-3142697795-54775-29497-S0
I1030 05:54:04.525885 29523 registrar.cpp:445] Applied 1 operations in 94940ns; attempting to update the 'registry'
I1030 05:54:04.526000 29497 sched.cpp:137] Version: 0.21.0
I1030 05:54:04.526583 29521 slave.cpp:1050] Will retry registration in 17.399441ms if necessary
I1030 05:54:04.526733 29526 master.cpp:3020] Ignoring register slave message from slave(27)@67.195.81.187:54775 (pomona.apache.org) as admission is already in progress
I1030 05:54:04.526758 29514 sched.cpp:233] New master detected at master@67.195.81.187:54775
I1030 05:54:04.526803 29514 sched.cpp:283] Authenticating with master master@67.195.81.187:54775
I1030 05:54:04.527016 29518 authenticatee.hpp:133] Creating new client SASL connection
I1030 05:54:04.527230 29524 master.cpp:3853] Authenticating scheduler-f20094cf-64d7-434e-a8e1-532ef8a8a141@67.195.81.187:54775
I1030 05:54:04.527487 29512 authenticator.hpp:161] Creating new server SASL connection
I1030 05:54:04.527606 29516 authenticatee.hpp:224] Received SASL authentication mechanisms: CRAM-MD5
I1030 05:54:04.527649 29516 authenticatee.hpp:250] Attempting to authenticate with mechanism 'CRAM-MD5'
I1030 05:54:04.527742 29516 authenticator.hpp:267] Received SASL authentication start
I1030 05:54:04.527794 29516 authenticator.hpp:389] Authentication requires more steps
I1030 05:54:04.527885 29516 authenticatee.hpp:270] Received SASL authentication step
I1030 05:54:04.527986 29516 authenticator.hpp:295] Received SASL authentication step
I1030 05:54:04.528019 29516 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1030 05:54:04.528034 29516 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I1030 05:54:04.528065 29516 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1030 05:54:04.528090 29516 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1030 05:54:04.528101 29516 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1030 05:54:04.528110 29516 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1030 05:54:04.529158 29524 log.cpp:680] Attempting to append 316 bytes to the log
I1030 05:54:04.545205 29511 slave.cpp:1050] Will retry registration in 50.72335ms if necessary
I1030 05:54:04.545310 29519 master.cpp:3020] Ignoring register slave message from slave(27)@67.195.81.187:54775 (pomona.apache.org) as admission is already in progress
I1030 05:54:05.499511 29514 hierarchical_allocator_process.hpp:697] No resources available to allocate!
I1030 05:54:07.770174 29516 authenticator.hpp:381] Authentication success
I1030 05:54:07.770304 29514 hierarchical_allocator_process.hpp:659] Performed allocation for 0 slaves in 2.270803805secs
I1030 05:54:07.770408 29521 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3
I1030 05:54:07.770439 29512 authenticatee.hpp:310] Authentication success
I1030 05:54:07.770506 29515 master.cpp:3893] Successfully authenticated principal 'test-principal' at scheduler-f20094cf-64d7-434e-a8e1-532ef8a8a141@67.195.81.187:54775
I1030 05:54:07.770843 29512 sched.cpp:357] Successfully authenticated with master master@67.195.81.187:54775
I1030 05:54:07.770891 29512 sched.cpp:476] Sending registration request to master@67.195.81.187:54775
I1030 05:54:07.771092 29515 master.cpp:1362] Received registration request for framework 'default' at scheduler-f20094cf-64d7-434e-a8e1-532ef8a8a141@67.195.81.187:54775
I1030 05:54:07.771183 29515 master.cpp:1321] Authorizing framework principal 'test-principal' to receive offers for role '*'
I1030 05:54:07.771579 29512 replica.cpp:508] Replica received write request for position 3
I1030 05:54:07.771793 29512 leveldb.cpp:343] Persisting action (335 bytes) to leveldb took 173691ns
I1030 05:54:07.771795 29524 master.cpp:1426] Registering framework 20141030-055359-3142697795-54775-29497-0000 (default) at scheduler-f20094cf-64d7-434e-a8e1-532ef8a8a141@67.195.81.187:54775
I1030 05:54:07.771822 29512 replica.cpp:676] Persisted action at 3
I1030 05:54:07.772176 29512 hierarchical_allocator_process.hpp:329] Added framework 20141030-055359-3142697795-54775-29497-0000
I1030 05:54:07.772207 29512 hierarchical_allocator_process.hpp:697] No resources available to allocate!
I1030 05:54:07.772220 29512 hierarchical_allocator_process.hpp:659] Performed allocation for 0 slaves in 19422ns
I1030 05:54:07.772459 29526 sched.cpp:407] Framework registered with 20141030-055359-3142697795-54775-29497-0000
I1030 05:54:07.772558 29526 sched.cpp:421] Scheduler::registered took 65296ns
I1030 05:54:07.772671 29524 replica.cpp:655] Replica received learned notice for position 3
I1030 05:54:07.773195 29524 leveldb.cpp:343] Persisting action (337 bytes) to leveldb took 495300ns
I1030 05:54:07.773221 29524 replica.cpp:676] Persisted action at 3
I1030 05:54:07.773244 29524 replica.cpp:661] Replica learned APPEND action at position 3
I1030 05:54:07.774744 29516 registrar.cpp:490] Successfully updated the 'registry' in 3.248780032secs
I1030 05:54:07.775080 29523 log.cpp:699] Attempting to truncate the log to 3
I1030 05:54:07.775238 29520 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4
I1030 05:54:07.775401 29523 slave.cpp:2522] Received ping from slave-observer(25)@67.195.81.187:54775
I1030 05:54:07.775495 29519 master.cpp:3086] Registered slave 20141030-055359-3142697795-54775-29497-S0 at slave(27)@67.195.81.187:54775 (pomona.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I1030 05:54:07.775574 29523 slave.cpp:756] Registered with master master@67.195.81.187:54775; given slave ID 20141030-055359-3142697795-54775-29497-S0
I1030 05:54:07.775686 29515 status_update_manager.cpp:178] Resuming sending status updates
I1030 05:54:07.775676 29526 hierarchical_allocator_process.hpp:442] Added slave 20141030-055359-3142697795-54775-29497-S0 (pomona.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
I1030 05:54:07.775938 29526 hierarchical_allocator_process.hpp:734] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20141030-055359-3142697795-54775-29497-S0 to framework 20141030-055359-3142697795-54775-29497-0000
I1030 05:54:07.776259 29517 replica.cpp:508] Replica received write request for position 4
I1030 05:54:07.776388 29526 hierarchical_allocator_process.hpp:679] Performed allocation for slave 20141030-055359-3142697795-54775-29497-S0 in 627202ns
I1030 05:54:07.776723 29517 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 403977ns
I1030 05:54:07.776726 29514 master.cpp:3795] Sending 1 offers to framework 20141030-055359-3142697795-54775-29497-0000 (default) at scheduler-f20094cf-64d7-434e-a8e1-532ef8a8a141@67.195.81.187:54775
I1030 05:54:07.776757 29517 replica.cpp:676] Persisted action at 4
I1030 05:54:07.777396 29525 replica.cpp:655] Replica received learned notice for position 4
I1030 05:54:07.777694 29524 sched.cpp:544] Scheduler::resourceOffers took 534035ns
I1030 05:54:07.777719 29525 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 295210ns
I1030 05:54:07.777772 29525 leveldb.cpp:401] Deleting ~2 keys from leveldb took 27312ns
I1030 05:54:07.777791 29525 replica.cpp:676] Persisted action at 4
I1030 05:54:07.777813 29525 replica.cpp:661] Replica learned TRUNCATE action at position 4
I1030 05:54:07.778673 29519 master.cpp:2321] Processing reply for offers: [ 20141030-055359-3142697795-54775-29497-O0 ] on slave 20141030-055359-3142697795-54775-29497-S0 at slave(27)@67.195.81.187:54775 (pomona.apache.org) for framework 20141030-055359-3142697795-54775-29497-0000 (default) at scheduler-f20094cf-64d7-434e-a8e1-532ef8a8a141@67.195.81.187:54775
W1030 05:54:07.778784 29519 master.cpp:1969] Executor default for task 0 uses less CPUs (None) than the minimum required (0.01). Please update your executor, as this will be mandatory in future releases.
W1030 05:54:07.778818 29519 master.cpp:1980] Executor default for task 0 uses less memory (None) than the minimum required (32MB). Please update your executor, as this will be mandatory in future releases.
I1030 05:54:07.778919 29519 master.cpp:2417] Authorizing framework principal 'test-principal' to launch task 0 as user 'jenkins'
I1030 05:54:07.779989 29512 master.hpp:877] Adding task 0 with resources cpus(*):1; mem(*):512 on slave 20141030-055359-3142697795-54775-29497-S0 (pomona.apache.org)
I1030 05:54:07.780067 29512 master.cpp:2480] Launching task 0 of framework 20141030-055359-3142697795-54775-29497-0000 (default) at scheduler-f20094cf-64d7-434e-a8e1-532ef8a8a141@67.195.81.187:54775 with resources cpus(*):1; mem(*):512 on slave 20141030-055359-3142697795-54775-29497-S0 at slave(27)@67.195.81.187:54775 (pomona.apache.org)
I1030 05:54:07.780411 29521 slave.cpp:1081] Got assigned task 0 for framework 20141030-055359-3142697795-54775-29497-0000
I1030 05:54:07.780939 29518 hierarchical_allocator_process.hpp:563] Recovered cpus(*):1; mem(*):512; disk(*):1024; ports(*):[31000-32000] (total allocatable: cpus(*):1; mem(*):512; disk(*):1024; ports(*):[31000-32000]) on slave 20141030-055359-3142697795-54775-29497-S0 from framework 20141030-055359-3142697795-54775-29497-0000
I1030 05:54:07.780995 29521 slave.cpp:1191] Launching task 0 for framework 20141030-055359-3142697795-54775-29497-0000
I1030 05:54:07.780998 29518 hierarchical_allocator_process.hpp:599] Framework 20141030-055359-3142697795-54775-29497-0000 filtered slave 20141030-055359-3142697795-54775-29497-S0 for 5secs
Itests/reconciliation_tests.cpp:112: Failure
Failed to wait 10secs for update
tests/reconciliation_tests.cpp:104: Failure
Actual function call count doesn't match EXPECT_CALL(sched, statusUpdate(&driver, _))...
Expected: to be called once
1030 05:54:07.783726 29521 slave.cpp:3871] Launching executor default of framework 20141030-055359-3142697795-54775-29497-0000 in work directory '/tmp/ReconciliationTest_TaskStateMismatch_jXTxgL/slaves/20141030-055359-3142697795-54775-29497-S0/frameworks/20141030-055359-3142697795-54775-29497-0000/executors/default/runs/f62d63de-e21a-438c-917d-ca4b61c34519'
Actual: never called - unsatisfied and active
I1030 05:54:08.771411 29516 hierarchical_allocator_process.hpp:816] Filtered cpus(*):1; mem(*):512; disk(*):1024; ports(*):[31000-32000] on slave 20141030-055359-3142697795-54775-29497-S0 for framework 20141030-055359-3142697795-54775-29497-0000
I1030 05:54:09.499510 29514 master.cpp:120] No whitelist given. Advertising offers for all slaves
I1030 05:54:17.775676 29526 master.cpp:768] Framework 20141030-055359-3142697795-54775-29497-0000 (default) at scheduler-f20094cf-64d7-434e-a8e1-532ef8a8a141@67.195.81.187:54775 disconnected
I1030 05:54:20.124783 29516 hierarchical_allocator_process.hpp:659] Performed allocation for 1 slaves in 11.353661562secs
I1030 05:54:20.124831 29526 master.cpp:1731] Disconnecting framework 20141030-055359-3142697795-54775-29497-0000 (default) at scheduler-f20094cf-64d7-434e-a8e1-532ef8a8a141@67.195.81.187:54775
tests/reconciliation_tests.cpp:100: Failure
Actual function call count doesn't match EXPECT_CALL(exec, launchTask(_, _))...
Expected: to be called once
Actual: never called - unsatisfied and active
tests/reconciliation_tests.cpp:98: Failure
Actual function call count doesn't match EXPECT_CALL(exec, registered(_, _, _, _))...
Expected: to be called once
Actual: never called - unsatisfied and active
I1030 05:54:20.124938 29526 master.cpp:1747] Deactivating framework 20141030-055359-3142697795-54775-29497-0000 (default) at scheduler-f20094cf-64d7-434e-a8e1-532ef8a8a141@67.195.81.187:54775
F1030 05:54:20.124938 29521 logging.cpp:57] RAW: Pure virtual method called
I1030 05:54:20.125049 29526 master.cpp:790] Giving framework 20141030-055359-3142697795-54775-29497-0000 (default) at scheduler-f20094cf-64d7-434e-a8e1-532ef8a8a141@67.195.81.187:54775 0ns to failover
I1030 05:54:20.125176 29516 hierarchical_allocator_process.hpp:405] Deactivated framework 20141030-055359-3142697795-54775-29497-0000
I1030 05:54:20.125305 29515 master.cpp:3665] Framework failover timeout, removing framework 20141030-055359-3142697795-54775-29497-0000 (default) at scheduler-f20094cf-64d7-434e-a8e1-532ef8a8a141@67.195.81.187:54775
I1030 05:54:20.125332 29515 master.cpp:4201] Removing framework 20141030-055359-3142697795-54775-29497-0000 (default) at scheduler-f20094cf-64d7-434e-a8e1-532ef8a8a141@67.195.81.187:54775
I1030 05:54:20.127970 29515 master.cpp:4617] Updating the latest state of task 0 of framework 20141030-055359-3142697795-54775-29497-0000 to TASK_KILLED
I1030 05:54:20.128203 29515 master.cpp:4676] Removing task 0 with resources cpus(*):1; mem(*):512 of framework 20141030-055359-3142697795-54775-29497-0000 on slave 20141030-055359-3142697795-54775-29497-S0 at slave(27)@67.195.81.187:54775 (pomona.apache.org)
I1030 05:54:20.128458 29520 hierarchical_allocator_process.hpp:563] Recovered cpus(*):1; mem(*):512 (total allocatable: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) on slave 20141030-055359-3142697795-54775-29497-S0 from framework 20141030-055359-3142697795-54775-29497-0000
I1030 05:54:20.128635 29515 master.cpp:4705] Removing executor 'default' with resources of framework 20141030-055359-3142697795-54775-29497-0000 on slave 20141030-055359-3142697795-54775-29497-S0 at slave(27)@67.195.81.187:54775 (pomona.apache.org)
I1030 05:54:20.129112 29515 master.cpp:677] Master terminating
I1030 05:54:20.129189 29523 hierarchical_allocator_process.hpp:360] Removed framework 20141030-055359-3142697795-54775-29497-0000
[ FAILED ] ReconciliationTest.TaskStateMismatch (21026 ms)
[ RUN ] ReconciliationTest.UnknownSlave
Using temporary directory '/tmp/ReconciliationTest_UnknownSlave_sz29uu'
@ 0x2adeb902ca8e google::LogMessage::Fail()
@ 0x2adeb9032182 google::RawLog__()
I1030 05:54:20.137413 29497 leveldb.cpp:176] Opened db in 2.509172ms
I1030 05:54:20.138386 29497 leveldb.cpp:183] Compacted db in 938375ns
I1030 05:54:20.138420 29497 leveldb.cpp:198] Created db iterator in 7060ns
I1030 05:54:20.138438 29497 leveldb.cpp:204] Seeked to beginning of db in 1280ns
I1030 05:54:20.138449 29497 leveldb.cpp:273] Iterated through 0 keys in the db in 630ns
@ 0x2adeb86bfb86 __cxa_pure_virtual
I1030 05:54:22.333158 29497 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I1030 05:54:22.334003 29517 recover.cpp:437] Starting replica recovery
I1030 05:54:22.334370 29517 recover.cpp:463] Replica is in EMPTY status
I1030 05:54:22.336093 29515 replica.cpp:638] Replica in EMPTY status received a broadcasted recover request
I1030 05:54:22.336302 29526 recover.cpp:188] Received a recover response from a replica in EMPTY status
I1030 05:54:22.336704 29524 recover.cpp:554] Updating replica status to STARTING
I1030 05:54:22.337630 29522 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 737us
I1030 05:54:22.337677 29522 replica.cpp:320] Persisted replica status to STARTING
I1030 05:54:22.337810 29526 master.cpp:312] Master 20141030-055422-3142697795-54775-29497 (pomona.apache.org) started on 67.195.81.187:54775
I1030 05:54:22.337862 29526 master.cpp:358] Master only allowing authenticated frameworks to register
I1030 05:54:22.337878 29526 master.cpp:363] Master only allowing authenticated slaves to register
I1030 05:54:22.337898 29526 credentials.hpp:36] Loading credentials for authentication from '/tmp/ReconciliationTest_UnknownSlave_sz29uu/credentials'
I1030 05:54:22.338032 29516 recover.cpp:463] Replica is in STARTING status
I1030 05:54:22.338163 29526 master.cpp:392] Authorization enabled
@ 0x2adeb89807bd mesos::internal::slave::Framework::launchExecutor()
I1030 05:54:22.338692 29515 master.cpp:120] No whitelist given. Advertising offers for all slaves
I1030 05:54:22.339212 29519 hierarchical_allocator_process.hpp:299] Initializing hierarchical allocator process with master : master@67.195.81.187:54775
I1030 05:54:22.339202 29522 replica.cpp:638] Replica in STARTING status received a broadcasted recover request
I1030 05:54:22.339773 29514 recover.cpp:188] Received a recover response from a replica in STARTING status
I1030 05:54:22.339844 29520 master.cpp:1242] The newly elected leader is master@67.195.81.187:54775 with id 20141030-055422-3142697795-54775-29497
I1030 05:54:22.339879 29520 master.cpp:1255] Elected as the leading master!
I1030 05:54:22.339900 29520 master.cpp:1073] Recovering from registrar
I1030 05:54:22.340183 29515 registrar.cpp:313] Recovering registrar
I1030 05:54:22.340446 29518 recover.cpp:554] Updating replica status to VOTING
I1030 05:54:22.341236 29520 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 565518ns
I1030 05:54:22.341262 29520 replica.cpp:320] Persisted replica status to VOTING
I1030 05:54:22.341406 29520 recover.cpp:568] Successfully joined the Paxos group
I1030 05:54:22.341653 29520 recover.cpp:452] Recover process terminated
I1030 05:54:22.342217 29526 log.cpp:656] Attempting to start the writer
@ 0x2adeb8968b5a mesos::internal::slave::Slave::_runTask()
I1030 05:54:22.343890 29512 replica.cpp:474] Replica received implicit promise request with proposal 1
I1030 05:54:22.344487 29512 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 563202ns
I1030 05:54:22.344512 29512 replica.cpp:342] Persisted promised to 1
@ 0x2adeb89a0a0b _ZZN7process8dispatchIN5mesos8internal5slave5SlaveERKNS_6FutureIbEERKNS1_13FrameworkInfoERKNS1_11FrameworkIDERKSsRKNS1_8TaskInfoES6_S9_SC_SsSH_EEvRKNS_3PIDIT_EEMSL_FvT0_T1_T2_T3_T4_ET5_T6_T7_T8_T9_ENKUlPNS_11ProcessBaseEE_clES12_
I1030 05:54:22.345145 29523 coordinator.cpp:230] Coordinator attemping to fill missing position
I1030 05:54:22.346741 29520 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
I1030 05:54:22.347309 29520 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 531407ns
I1030 05:54:22.347337 29520 replica.cpp:676] Persisted action at 0
I1030 05:54:22.348525 29522 replica.cpp:508] Replica received write request for position 0
I1030 05:54:22.348575 29522 leveldb.cpp:438] Reading position from leveldb took 24419ns
I1030 05:54:22.349072 29522 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 463209ns
I @ 0x2adeb89c6fdd _ZNSt17_Function_handlerIFvPN7process11ProcessBaseEEZNS0_8dispatchIN5mesos8internal5slave5SlaveERKNS0_6FutureIbEERKNS5_13FrameworkInfoERKNS5_11FrameworkIDERKSsRKNS5_8TaskInfoESA_SD_SG_SsSL_EEvRKNS0_3PIDIT_EEMSP_FvT0_T1_T2_T3_T4_ET5_T6_T7_T8_T9_EUlS2_E_E9_M_invokeERKSt9_Any_dataS2_
1030 05:54:22.349097 29522 replica.cpp:676] Persisted action at 0
I1030 05:54:22.643363 29524 replica.cpp:655] Replica received learned notice for position 0
I1030 05:54:22.644031 29524 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 626475ns
I1030 05:54:22.644059 29524 replica.cpp:676] Persisted action at 0
I1030 05:54:22.644081 29524 replica.cpp:661] Replica learned NOP action at position 0
I1030 05:54:22.644937 29513 log.cpp:672] Writer started with ending position 0
I1030 05:54:22.646476 29522 leveldb.cpp:438] Reading position from leveldb took 29654ns
@ 0x2adeb8fbe89f std::function<>::operator()()
I1030 05:54:22.649744 29511 registrar.cpp:346] Successfully fetched the registry (0B) in 309.50912ms
I1030 05:54:22.649865 29511 registrar.cpp:445] Applied 1 operations in 26852ns; attempting to update the 'registry'
@ 0x2adeb8f9fb67 process::ProcessBase::visit()
I1030 05:54:22.652909 29525 log.cpp:680] Attempting to append 139 bytes to the log
I1030 05:54:22.653067 29512 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
I1030 05:54:22.654033 29516 replica.cpp:508] Replica received write request for position 1
I1030 05:54:22.654588 29516 leveldb.cpp:343] Persisting action (158 bytes) to leveldb took 521467ns
I1030 05:54:22.654619 29516 replica.cpp:676] Persisted action at 1
@ 0x2adeb8faa49c process::DispatchEvent::visit()
I1030 05:54:22.655232 29514 replica.cpp:655] Replica received learned notice for position 1
I1030 05:54:22.655637 29514 leveldb.cpp:343] Persisting action (160 bytes) to leveldb took 378403ns
I1030 05:54:22.655663 29514 replica.cpp:676] Persisted action at 1
I1030 05:54:22.655683 29514 replica.cpp:661] Replica learned APPEND action at position 1
I1030 05:54:22.656695 29523 registrar.cpp:490] Successfully updated the 'registry' in 6.767872ms
I1030 05:54:22.656848 29523 registrar.cpp:376] Successfully recovered registrar
I1030 05:54:22.656976 29518 log.cpp:699] Attempting to truncate the log to 1
@ 0x8f6fa2 process::ProcessBase::serve()
I1030 05:54:22.657117 29511 master.cpp:1100] Recovered 0 slaves from the Registry (101B) ; allowing 10mins for slaves to re-register
I1030 05:54:22.657215 29516 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
I1030 05:54:22.658125 29516 replica.cpp:508] Replica received write request for position 2
I1030 05:54:22.658622 29516 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 462724ns
I1030 05:54:22.658648 29516 replica.cpp:676] Persisted action at 2
I1030 05:54:22.659272 29514 replica.cpp:655] Replica received learned notice for position 2
I1030 05:54:22.659711 29514 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 395532ns
I1030 05:54:22.659757 29514 leveldb.cpp:401] Deleting ~1 keys from leveldb took 22259ns
I1030 05:54:22.659775 29514 replica.cpp:676] Persisted action at 2
I1030 05:54:22.659796 29514 replica.cpp:661] Replica learned TRUNCATE action at position 2
@ 0x2adeb8f9bddc process::ProcessManager::resume()
@ 0x2adeb8f924a1 process::schedule()
@ 0x2adebb2f0182 start_thread
@ 0x2adebb600fbd (unknown)
make[3]: *** [check-local] Aborted
make[3]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/src'>
make[2]: *** [check-am] Error 2
make[2]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/src'>
make[1]: *** [check] Error 2
make[1]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/src'>
make: *** [check-recursive] Error 1
Test finished
Exit status: 2
Build step 'Execute shell' marked build as failure
Recording test results
Build failed in Jenkins:
Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME #2229
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/2229/changes>
Changes:
[idownes] Define MNT_DETACH for pid isolator.
------------------------------------------
[...truncated 69433 lines...]
I1029 20:01:09.767547 27824 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1029 20:01:09.767561 27824 authenticator.hpp:381] Authentication success
I1029 20:01:09.767650 27824 authenticatee.hpp:310] Authentication success
I1029 20:01:09.767752 27820 master.cpp:3893] Successfully authenticated principal 'test-principal' at scheduler-433d5fe0-5dd8-4eb7-96a1-75a171494d2f@67.195.81.190:41000
I1029 20:01:09.768019 27824 sched.cpp:357] Successfully authenticated with master master@67.195.81.190:41000
I1029 20:01:09.768048 27824 sched.cpp:476] Sending registration request to master@67.195.81.190:41000
I1029 20:01:09.768321 27820 master.cpp:1362] Received registration request for framework 'framework3' at scheduler-433d5fe0-5dd8-4eb7-96a1-75a171494d2f@67.195.81.190:41000
I1029 20:01:09.768384 27820 master.cpp:1321] Authorizing framework principal 'test-principal' to receive offers for role 'role3'
I1029 20:01:09.768911 27823 master.cpp:1426] Registering framework 20141029-200107-3193029443-41000-27796-0002 (framework3) at scheduler-433d5fe0-5dd8-4eb7-96a1-75a171494d2f@67.195.81.190:41000
I1029 20:01:09.769162 27817 sched.cpp:407] Framework registered with 20141029-200107-3193029443-41000-27796-0002
I1029 20:01:09.769201 27817 sched.cpp:421] Scheduler::registered took 16443ns
I1029 20:01:09.769261 27825 hierarchical_allocator_process.hpp:329] Added framework 20141029-200107-3193029443-41000-27796-0002
I1029 20:01:09.769722 27825 hierarchical_allocator_process.hpp:734] Offering cpus(role3):4; mem(role3):4096; disk(role3):0; ports(role3):[31000-32000] on slave 20141029-200107-3193029443-41000-27796-S2 to framework 20141029-200107-3193029443-41000-27796-0002
I1029 20:01:09.770187 27825 hierarchical_allocator_process.hpp:659] Performed allocation for 4 slaves in 903391ns
I1029 20:01:09.770460 27819 master.cpp:3795] Sending 1 offers to framework 20141029-200107-3193029443-41000-27796-0002 (framework3) at scheduler-433d5fe0-5dd8-4eb7-96a1-75a171494d2f@67.195.81.190:41000
I1029 20:01:09.770774 27816 sched.cpp:544] Scheduler::resourceOffers took 45045ns
I1029 20:01:09.772645 27796 containerizer.cpp:100] Using isolation: posix/cpu,posix/mem
I1029 20:01:09.776811 27820 slave.cpp:169] Slave started on 221)@67.195.81.190:41000
I1029 20:01:09.776852 27820 credentials.hpp:84] Loading credential for authentication from '/tmp/ReservationAllocatorTest_ReservedResources_amUsCX/credential'
I1029 20:01:09.777021 27820 slave.cpp:276] Slave using credential for: test-principal
I1029 20:01:09.777241 27820 slave.cpp:289] Slave resources: cpus(role1):1; mem(role1):512; disk(role1):0; ports(role1):[31000-32000]
I1029 20:01:09.777340 27820 slave.cpp:318] Slave hostname: pietas.apache.org
I1029 20:01:09.777358 27820 slave.cpp:319] Slave checkpoint: false
W1029 20:01:09.777366 27820 slave.cpp:321] Disabling checkpointing is deprecated and the --checkpoint flag will be removed in a future release. Please avoid using this flag
I1029 20:01:09.778183 27811 state.cpp:33] Recovering state from '/tmp/ReservationAllocatorTest_ReservedResources_amUsCX/meta'
I1029 20:01:09.778393 27817 status_update_manager.cpp:197] Recovering status update manager
I1029 20:01:09.778676 27815 containerizer.cpp:281] Recovering containerizer
I1029 20:01:09.779857 27816 slave.cpp:3456] Finished recovery
I1029 20:01:09.780598 27816 slave.cpp:602] New master detected at master@67.195.81.190:41000
I1029 20:01:09.780638 27816 slave.cpp:665] Authenticating with master master@67.195.81.190:41000
I1029 20:01:09.780674 27825 status_update_manager.cpp:171] Pausing sending status updates
I1029 20:01:09.780791 27816 slave.cpp:638] Detecting new master
I1029 20:01:09.780843 27818 authenticatee.hpp:133] Creating new client SASL connection
I1029 20:01:09.781141 27810 master.cpp:3853] Authenticating slave(221)@67.195.81.190:41000
I1029 20:01:09.781342 27816 authenticator.hpp:161] Creating new server SASL connection
I1029 20:01:09.781508 27816 authenticatee.hpp:224] Received SASL authentication mechanisms: CRAM-MD5
I1029 20:01:09.781529 27816 authenticatee.hpp:250] Attempting to authenticate with mechanism 'CRAM-MD5'
I1029 20:01:09.781632 27824 authenticator.hpp:267] Received SASL authentication start
I1029 20:01:09.781687 27824 authenticator.hpp:389] Authentication requires more steps
I1029 20:01:09.781771 27824 authenticatee.hpp:270] Received SASL authentication step
I1029 20:01:09.781875 27824 authenticator.hpp:295] Received SASL authentication step
I1029 20:01:09.781903 27824 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'pietas.apache.org' server FQDN: 'pietas.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1029 20:01:09.781915 27824 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I1029 20:01:09.781945 27824 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1029 20:01:09.781968 27824 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'pietas.apache.org' server FQDN: 'pietas.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1029 20:01:09.781980 27824 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1029 20:01:09.781988 27824 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1029 20:01:09.782004 27824 authenticator.hpp:381] Authentication success
I1029 20:01:09.782112 27824 authenticatee.hpp:310] Authentication success
I1029 20:01:09.782143 27821 master.cpp:3893] Successfully authenticated principal 'test-principal' at slave(221)@67.195.81.190:41000
I1029 20:01:09.782546 27824 slave.cpp:722] Successfully authenticated with master master@67.195.81.190:41000
I1029 20:01:09.782659 27824 slave.cpp:1050] Will retry registration in 11.769712ms if necessary
I1029 20:01:09.782820 27815 master.cpp:3032] Registering slave at slave(221)@67.195.81.190:41000 (pietas.apache.org) with id 20141029-200107-3193029443-41000-27796-S4
I1029 20:01:09.783329 27817 registrar.cpp:445] Applied 1 operations in 133421ns; attempting to update the 'registry'
I1029 20:01:09.785845 27817 log.cpp:680] Attempting to append 1127 bytes to the log
I1029 20:01:09.795310 27810 slave.cpp:1050] Will retry registration in 37.030767ms if necessary
I1029 20:01:09.795497 27814 master.cpp:3020] Ignoring register slave message from slave(221)@67.195.81.190:41000 (pietas.apache.org) as admission is already in progress
I1029 20:01:09.913693 27811 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 9
I1029 20:01:09.914785 27819 replica.cpp:508] Replica received write request for position 9
I1029 20:01:09.915117 27819 leveldb.cpp:343] Persisting action (1146 bytes) to leveldb took 294042ns
I1029 20:01:09.915148 27819 replica.cpp:676] Persisted action at 9
I1029 20:01:09.916208 27815 replica.cpp:655] Replica received learned notice for position 9
I1029 20:01:09.916882 27815 leveldb.cpp:343] Persisting action (1148 bytes) to leveldb took 644425ns
I1029 20:01:09.916908 27815 replica.cpp:676] Persisted action at 9
I1029 20:01:09.916930 27815 replica.cpp:661] Replica learned APPEND action at position 9
I1029 20:01:09.918350 27820 registrar.cpp:490] Successfully updated the 'registry' in 134.961152ms
I1029 20:01:09.918740 27813 log.cpp:699] Attempting to truncate the log to 9
I1029 20:01:09.918941 27810 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 10
I1029 20:01:09.919064 27816 slave.cpp:2522] Received ping from slave-observer(201)@67.195.81.190:41000
I1029 20:01:09.919123 27811 master.cpp:3086] Registered slave 20141029-200107-3193029443-41000-27796-S4 at slave(221)@67.195.81.190:41000 (pietas.apache.org) with cpus(role1):1; mem(role1):512; disk(role1):0; ports(role1):[31000-32000]
I1029 20:01:09.919225 27816 slave.cpp:756] Registered with master master@67.195.81.190:41000; given slave ID 20141029-200107-3193029443-41000-27796-S4
I1029 20:01:09.919546 27822 status_update_manager.cpp:178] Resuming sending status updates
I1029 20:01:09.919711 27810 hierarchical_allocator_process.hpp:442] Added slave 20141029-200107-3193029443-41000-27796-S4 (pietas.apache.org) with cpus(role1):1; mem(role1):512; disk(role1):0; ports(role1):[31000-32000] (and cpus(role1):1; mem(role1):512; disk(role1):0; ports(role1):[31000-32000] available)
I1029 20:01:09.919790 27822 replica.cpp:508] Replica received write request for position 10
I1029 20:01:09.920136 27822 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 311126ns
I1029 20:01:09.920131 27810 hierarchical_allocator_process.hpp:734] Offering cpus(role1):1; mem(role1):512; disk(role1):0; ports(role1):[31000-32000] on slave 20141029-200107-3193029443-41000-27796-S4 to framework 20141029-200107-3193029443-41000-27796-0000
I1029 20:01:09.920161 27822 replica.cpp:676] Persisted action at 10
I1029 20:01:09.920377 27810 hierarchical_allocator_process.hpp:679] Performed allocation for slave 20141029-200107-3193029443-41000-27796-S4 in 583079ns
I1029 20:01:09.920769 27811 replica.cpp:655] Replica received learned notice for position 10
I1029 20:01:09.920958 27817 master.cpp:3795] Sending 1 offers to framework 20141029-200107-3193029443-41000-27796-0000 (framework1) at scheduler-bf4f0d6f-a260-4866-aa57-59024a517c4d@67.195.81.190:41000
I1029 20:01:09.921269 27811 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 474524ns
I1029 20:01:09.921293 27813 sched.cpp:544] Scheduler::resourceOffers took 49416ns
I1029 20:01:09.921353 27811 leveldb.cpp:401] Deleting ~2 keys from leveldb took 54019ns
I1029 20:01:09.921383 27811 replica.cpp:676] Persisted action at 10
I1029 20:01:09.921417 27811 replica.cpp:661] Replica learned TRUNCATE action at position 10
I1029 20:01:09.921733 27814 sched.cpp:745] Stopping framework '20141029-200107-3193029443-41000-27796-0002'
I1029 20:01:09.921768 27815 sched.cpp:745] Stopping framework '20141029-200107-3193029443-41000-27796-0000'
I1029 20:01:09.921787 27816 sched.cpp:745] Stopping framework '20141029-200107-3193029443-41000-27796-0001'
I1029 20:01:09.921880 27821 master.cpp:677] Master terminating
I1029 20:01:09.924136 27816 slave.cpp:2607] master@67.195.81.190:41000 exited
W1029 20:01:09.924165 27816 slave.cpp:2610] Master disconnected! Waiting for a new master to be elected
I1029 20:01:09.924201 27813 slave.cpp:2607] master@67.195.81.190:41000 exited
W1029 20:01:09.924247 27813 slave.cpp:2610] Master disconnected! Waiting for a new master to be elected
I1029 20:01:09.924223 27810 slave.cpp:2607] master@67.195.81.190:41000 exited
W1029 20:01:09.924288 27810 slave.cpp:2610] Master disconnected! Waiting for a new master to be elected
I1029 20:01:09.924309 27819 slave.cpp:2607] master@67.195.81.190:41000 exited
I1029 20:01:09.924320 27818 slave.cpp:2607] master@67.195.81.190:41000 exited
W1029 20:01:09.924342 27819 slave.cpp:2610] Master disconnected! Waiting for a new master to be elected
W1029 20:01:09.924358 27818 slave.cpp:2610] Master disconnected! Waiting for a new master to be elected
I1029 20:01:09.930064 27796 slave.cpp:484] Slave terminating
I1029 20:01:09.932471 27796 slave.cpp:484] Slave terminating
I1029 20:01:09.934528 27796 slave.cpp:484] Slave terminating
I1029 20:01:09.936530 27817 slave.cpp:484] Slave terminating
I1029 20:01:09.938618 27796 slave.cpp:484] Slave terminating
[ OK ] ReservationAllocatorTest.ReservedResources (2451 ms)
[----------] 2 tests from ReservationAllocatorTest (3094 ms total)
[----------] 2 tests from AttributesTest
[ RUN ] AttributesTest.Equality
[ OK ] AttributesTest.Equality (0 ms)
[ RUN ] AttributesTest.Parsing
[ OK ] AttributesTest.Parsing (1 ms)
[----------] 2 tests from AttributesTest (1 ms total)
[----------] 35 tests from ResourcesTest
[ RUN ] ResourcesTest.Find
[ OK ] ResourcesTest.Find (1 ms)
[ RUN ] ResourcesTest.SetEquals
[ OK ] ResourcesTest.SetEquals (0 ms)
[ RUN ] ResourcesTest.ScalarSubset2
[ OK ] ResourcesTest.ScalarSubset2 (0 ms)
[ RUN ] ResourcesTest.SetAddition
[ OK ] ResourcesTest.SetAddition (0 ms)
[ RUN ] ResourcesTest.ScalarAddition
[ OK ] ResourcesTest.ScalarAddition (0 ms)
[ RUN ] ResourcesTest.RangesSubtraction
[ OK ] ResourcesTest.RangesSubtraction (0 ms)
[ RUN ] ResourcesTest.Ports
[ OK ] ResourcesTest.Ports (1 ms)
[ RUN ] ResourcesTest.ScalarAddition2
[ OK ] ResourcesTest.ScalarAddition2 (0 ms)
[ RUN ] ResourcesTest.EmptyUnequal
[ OK ] ResourcesTest.EmptyUnequal (0 ms)
[ RUN ] ResourcesTest.Printing
[ OK ] ResourcesTest.Printing (0 ms)
[ RUN ] ResourcesTest.ScalarEquals
[ OK ] ResourcesTest.ScalarEquals (0 ms)
[ RUN ] ResourcesTest.RangesSubtraction1
[ OK ] ResourcesTest.RangesSubtraction1 (0 ms)
[ RUN ] ResourcesTest.RangesAddition4
[ OK ] ResourcesTest.RangesAddition4 (1 ms)
[ RUN ] ResourcesTest.RangesAddition2
[ OK ] ResourcesTest.RangesAddition2 (0 ms)
[ RUN ] ResourcesTest.SetSubset
[ OK ] ResourcesTest.SetSubset (0 ms)
[ RUN ] ResourcesTest.RangesSubtraction2
[ OK ] ResourcesTest.RangesSubtraction2 (0 ms)
[ RUN ] ResourcesTest.ScalarSubset
[ OK ] ResourcesTest.ScalarSubset (0 ms)
[ RUN ] ResourcesTest.RangesSubtraction3
[ OK ] ResourcesTest.RangesSubtraction3 (0 ms)
[ RUN ] ResourcesTest.ScalarSubtraction2
[ OK ] ResourcesTest.ScalarSubtraction2 (0 ms)
[ RUN ] ResourcesTest.FlattenRoles
[ OK ] ResourcesTest.FlattenRoles (0 ms)
[ RUN ] ResourcesTest.SetSubtraction
[ OK ] ResourcesTest.SetSubtraction (1 ms)
[ RUN ] ResourcesTest.RangesAddition
[ OK ] ResourcesTest.RangesAddition (0 ms)
[ RUN ] ResourcesTest.RangesSubtraction5
[ OK ] ResourcesTest.RangesSubtraction5 (0 ms)
[ RUN ] ResourcesTest.Resources
[ OK ] ResourcesTest.Resources (0 ms)
[ RUN ] ResourcesTest.ScalarSubtraction
[ OK ] ResourcesTest.ScalarSubtraction (0 ms)
[ RUN ] ResourcesTest.RangesSubtraction4
[ OK ] ResourcesTest.RangesSubtraction4 (0 ms)
[ RUN ] ResourcesTest.RangesSubtraction6
[ OK ] ResourcesTest.RangesSubtraction6 (0 ms)
[ RUN ] ResourcesTest.BadResourcesNotAllocatable
[ OK ] ResourcesTest.BadResourcesNotAllocatable (0 ms)
[ RUN ] ResourcesTest.ParseError
[ OK ] ResourcesTest.ParseError (0 ms)
[ RUN ] ResourcesTest.ParsingWithRoles
[ OK ] ResourcesTest.ParsingWithRoles (0 ms)
[ RUN ] ResourcesTest.InitializedIsEmpty
[ OK ] ResourcesTest.InitializedIsEmpty (0 ms)
[ RUN ] ResourcesTest.RangesAdditon3
[ OK ] ResourcesTest.RangesAdditon3 (1 ms)
[ RUN ] ResourcesTest.RangesSubset
[ OK ] ResourcesTest.RangesSubset (0 ms)
[ RUN ] ResourcesTest.RangesEquals
[ OK ] ResourcesTest.RangesEquals (0 ms)
[ RUN ] ResourcesTest.Parsing
[ OK ] ResourcesTest.Parsing (0 ms)
[----------] 35 tests from ResourcesTest (117 ms total)
[----------] 3 tests from GarbageCollectorTest
[ RUN ] GarbageCollectorTest.Unschedule
Using temporary directory '/tmp/GarbageCollectorTest_Unschedule_AWxnXw'
I1029 20:01:10.063221 27812 gc.cpp:84] Unscheduling 'bogus' from gc
I1029 20:01:10.063886 27812 gc.cpp:56] Scheduling 'file1' for gc 10secs in the future
I1029 20:01:10.064044 27812 gc.cpp:56] Scheduling 'file2' for gc 10secs in the future
I1029 20:01:10.064129 27812 gc.cpp:56] Scheduling 'file3' for gc 10secs in the future
I1029 20:01:10.064209 27812 gc.cpp:84] Unscheduling 'file2' from gc
I1029 20:01:10.074157 27822 gc.cpp:84] Unscheduling 'file3' from gc
I1029 20:01:10.084421 27823 gc.cpp:84] Unscheduling 'file1' from gc
I1029 20:01:10.096211 27821 gc.cpp:155] Ignoring gc event at 0ns as the paths were already removed, or were unscheduled
[ OK ] GarbageCollectorTest.Unschedule (73 ms)
[ RUN ] GarbageCollectorTest.Prune
Using temporary directory '/tmp/GarbageCollectorTest_Prune_QII2t6'
I1029 20:01:10.135681 27818 gc.cpp:56] Scheduling 'file1' for gc 10secs in the future
I1029 20:01:10.135833 27818 gc.cpp:56] Scheduling 'file2' for gc 10secs in the future
I1029 20:01:10.135920 27818 gc.cpp:56] Scheduling 'file3' for gc 15secs in the future
I1029 20:01:10.135999 27818 gc.cpp:56] Scheduling 'file4' for gc 15secs in the future
I1029 20:01:10.136077 27818 gc.cpp:84] Unscheduling 'file3' from gc
I1029 20:01:10.156009 27813 gc.cpp:167] Pruning directories with remaining removal time 10secs
I1029 20:01:10.156090 27813 gc.cpp:134] Deleting file1
I1029 20:01:10.156141 27813 gc.cpp:143] Deleted 'file1'
I1029 20:01:10.156167 27813 gc.cpp:134] Deleting file2
I1029 20:01:10.156199 27813 gc.cpp:143] Deleted 'file2'
I1029 20:01:10.176352 27816 gc.cpp:167] Pruning directories with remaining removal time 15secs
I1029 20:01:10.176508 27816 gc.cpp:134] Deleting file4
I1029 20:01:10.176563 27816 gc.cpp:143] Deleted 'file4'
[ OK ] GarbageCollectorTest.Prune (51 ms)
[ RUN ] GarbageCollectorTest.Schedule
Using temporary directory '/tmp/GarbageCollectorTest_Schedule_yE838F'
I1029 20:01:10.187319 27816 gc.cpp:56] Scheduling 'file1' for gc 10secs in the future
I1029 20:01:10.187497 27816 gc.cpp:56] Scheduling 'file2' for gc 10secs in the future
I1029 20:01:10.187609 27816 gc.cpp:56] Scheduling 'file3' for gc 15secs in the future
I1029 20:01:10.228978 27815 gc.cpp:134] Deleting file1
I1029 20:01:10.229038 27815 gc.cpp:143] Deleted 'file1'
I1029 20:01:10.229069 27815 gc.cpp:134] Deleting file2
I1029 20:01:10.229109 27815 gc.cpp:143] Deleted 'file2'
I1029 20:01:10.258406 27823 gc.cpp:134] Deleting file3
I1029 20:01:10.258491 27823 gc.cpp:143] Deleted 'file3'
[ OK ] GarbageCollectorTest.Schedule (92 ms)
[----------] 3 tests from GarbageCollectorTest (216 ms total)
[----------] Global test environment tear-down
[==========] 449 tests from 70 test cases ran. (283265 ms total)
[ PASSED ] 448 tests.
[ FAILED ] 1 test, listed below:
[ FAILED ] HealthCheckTest.GracePeriod
1 FAILED TEST
YOU HAVE 6 DISABLED TESTS
make[3]: *** [check-local] Error 1
make[3]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/src'>
make[2]: *** [check-am] Error 2
make[2]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/src'>
make[1]: *** [check] Error 2
make[1]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/src'>
make: *** [check-recursive] Error 1
Test finished
Exit status: 2
Build step 'Execute shell' marked build as failure
Recording test results
Build failed in Jenkins:
Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME #2228
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/2228/changes>
Changes:
[benjamin.hindman] Fixed bug with snapshot positions when writing log diffs.
------------------------------------------
[...truncated 69376 lines...]
I1029 09:40:19.075613 3139 hierarchical_allocator_process.hpp:299] Initializing hierarchical allocator process with master : master@67.195.81.187:52646
I1029 09:40:19.077009 3135 replica.cpp:638] Replica in EMPTY status received a broadcasted recover request
I1029 09:40:19.077117 3143 master.cpp:1242] The newly elected leader is master@67.195.81.187:52646 with id 20141029-094017-3142697795-52646-3116
I1029 09:40:19.077160 3143 master.cpp:1255] Elected as the leading master!
I1029 09:40:19.077182 3143 master.cpp:1073] Recovering from registrar
I1029 09:40:19.077455 3141 registrar.cpp:313] Recovering registrar
I1029 09:40:19.077568 3139 recover.cpp:188] Received a recover response from a replica in EMPTY status
I1029 09:40:19.078191 3131 recover.cpp:554] Updating replica status to STARTING
I1029 09:40:19.079345 3138 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 985524ns
I1029 09:40:19.079370 3138 replica.cpp:320] Persisted replica status to STARTING
I1029 09:40:19.079610 3143 recover.cpp:463] Replica is in STARTING status
I1029 09:40:19.080679 3132 replica.cpp:638] Replica in STARTING status received a broadcasted recover request
I1029 09:40:19.081054 3137 recover.cpp:188] Received a recover response from a replica in STARTING status
I1029 09:40:19.081483 3133 recover.cpp:554] Updating replica status to VOTING
I1029 09:40:19.082223 3135 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 585974ns
I1029 09:40:19.082250 3135 replica.cpp:320] Persisted replica status to VOTING
I1029 09:40:19.082372 3131 recover.cpp:568] Successfully joined the Paxos group
I1029 09:40:19.082594 3131 recover.cpp:452] Recover process terminated
I1029 09:40:19.083050 3135 log.cpp:656] Attempting to start the writer
I1029 09:40:19.084597 3142 replica.cpp:474] Replica received implicit promise request with proposal 1
I1029 09:40:19.085218 3142 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 588099ns
I1029 09:40:19.085243 3142 replica.cpp:342] Persisted promised to 1
I1029 09:40:19.085911 3138 coordinator.cpp:230] Coordinator attemping to fill missing position
I1029 09:40:19.087317 3141 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
I1029 09:40:19.087848 3141 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 494271ns
I1029 09:40:19.087873 3141 replica.cpp:676] Persisted action at 0
I1029 09:40:19.089040 3131 replica.cpp:508] Replica received write request for position 0
I1029 09:40:19.089090 3131 leveldb.cpp:438] Reading position from leveldb took 24077ns
I1029 09:40:19.089602 3131 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 478794ns
I1029 09:40:19.089628 3131 replica.cpp:676] Persisted action at 0
I1029 09:40:19.090229 3144 replica.cpp:655] Replica received learned notice for position 0
I1029 09:40:19.090790 3144 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 530255ns
I1029 09:40:19.090814 3144 replica.cpp:676] Persisted action at 0
I1029 09:40:19.090836 3144 replica.cpp:661] Replica learned NOP action at position 0
I1029 09:40:19.091418 3141 log.cpp:672] Writer started with ending position 0
I1029 09:40:19.092674 3139 leveldb.cpp:438] Reading position from leveldb took 23812ns
I1029 09:40:19.095818 3136 registrar.cpp:346] Successfully fetched the registry (0B) in 18.313984ms
I1029 09:40:19.095935 3136 registrar.cpp:445] Applied 1 operations in 19557ns; attempting to update the 'registry'
I1029 09:40:19.098989 3139 log.cpp:680] Attempting to append 138 bytes to the log
I1029 09:40:19.099138 3141 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
I1029 09:40:19.099973 3140 replica.cpp:508] Replica received write request for position 1
I1029 09:40:19.100742 3140 leveldb.cpp:343] Persisting action (157 bytes) to leveldb took 730714ns
I1029 09:40:19.100769 3140 replica.cpp:676] Persisted action at 1
I1029 09:40:19.101434 3142 replica.cpp:655] Replica received learned notice for position 1
I1029 09:40:19.101959 3142 leveldb.cpp:343] Persisting action (159 bytes) to leveldb took 494168ns
I1029 09:40:19.101985 3142 replica.cpp:676] Persisted action at 1
I1029 09:40:19.102006 3142 replica.cpp:661] Replica learned APPEND action at position 1
I1029 09:40:19.103004 3131 registrar.cpp:490] Successfully updated the 'registry' in 7.01696ms
I1029 09:40:19.103142 3131 registrar.cpp:376] Successfully recovered registrar
I1029 09:40:19.103440 3144 log.cpp:699] Attempting to truncate the log to 1
I1029 09:40:19.103482 3132 master.cpp:1100] Recovered 0 slaves from the Registry (100B) ; allowing 10mins for slaves to re-register
I1029 09:40:19.103621 3134 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
I1029 09:40:19.104642 3133 replica.cpp:508] Replica received write request for position 2
I1029 09:40:19.105180 3133 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 504427ns
I1029 09:40:19.105206 3133 replica.cpp:676] Persisted action at 2
I1029 09:40:19.105888 3136 replica.cpp:655] Replica received learned notice for position 2
I1029 09:40:19.106431 3136 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 516554ns
I1029 09:40:19.106487 3136 leveldb.cpp:401] Deleting ~1 keys from leveldb took 29777ns
I1029 09:40:19.106506 3136 replica.cpp:676] Persisted action at 2
I1029 09:40:19.106528 3136 replica.cpp:661] Replica learned TRUNCATE action at position 2
I1029 09:40:19.118141 3142 slave.cpp:169] Slave started on 221)@67.195.81.187:52646
I1029 09:40:19.118172 3142 credentials.hpp:84] Loading credential for authentication from '/tmp/SlaveTest_IgnoreNonLeaderStatusUpdateAcknowledgement_E7ceOa/credential'
I1029 09:40:19.118276 3142 slave.cpp:276] Slave using credential for: test-principal
I1029 09:40:19.118526 3142 slave.cpp:289] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I1029 09:40:19.118598 3142 slave.cpp:318] Slave hostname: pomona.apache.org
I1029 09:40:19.118610 3142 slave.cpp:319] Slave checkpoint: false
W1029 09:40:19.118616 3142 slave.cpp:321] Disabling checkpointing is deprecated and the --checkpoint flag will be removed in a future release. Please avoid using this flag
I1029 09:40:19.119204 3135 state.cpp:33] Recovering state from '/tmp/SlaveTest_IgnoreNonLeaderStatusUpdateAcknowledgement_E7ceOa/meta'
I1029 09:40:19.119446 3143 status_update_manager.cpp:197] Recovering status update manager
I1029 09:40:19.119691 3133 slave.cpp:3456] Finished recovery
I1029 09:40:19.120076 3137 status_update_manager.cpp:171] Pausing sending status updates
I1029 09:40:19.120087 3134 slave.cpp:602] New master detected at master@67.195.81.187:52646
I1029 09:40:19.120126 3134 slave.cpp:665] Authenticating with master master@67.195.81.187:52646
I1029 09:40:19.120234 3134 slave.cpp:638] Detecting new master
I1029 09:40:19.120264 3141 authenticatee.hpp:133] Creating new client SASL connection
I1029 09:40:19.120486 3143 master.cpp:3853] Authenticating slave(221)@67.195.81.187:52646
I1029 09:40:19.120631 3135 authenticator.hpp:161] Creating new server SASL connection
I1029 09:40:19.120779 3138 authenticatee.hpp:224] Received SASL authentication mechanisms: CRAM-MD5
I1029 09:40:19.120800 3138 authenticatee.hpp:250] Attempting to authenticate with mechanism 'CRAM-MD5'
I1029 09:40:19.120910 3140 authenticator.hpp:267] Received SASL authentication start
I1029 09:40:19.122623 3116 sched.cpp:137] Version: 0.21.0
I1029 09:40:19.140969 3140 authenticator.hpp:389] Authentication requires more steps
I1029 09:40:19.141086 3134 authenticatee.hpp:270] Received SASL authentication step
I1029 09:40:19.141243 3142 authenticator.hpp:295] Received SASL authentication step
I1029 09:40:19.141300 3142 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1029 09:40:19.141329 3142 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I1029 09:40:19.141367 3142 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1029 09:40:19.141397 3142 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1029 09:40:19.141410 3142 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1029 09:40:19.141419 3142 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1029 09:40:19.141437 3142 authenticator.hpp:381] Authentication success
I1029 09:40:19.141552 3137 authenticatee.hpp:310] Authentication success
I1029 09:40:19.141607 3139 sched.cpp:233] New master detected at master@67.195.81.187:52646
I1029 09:40:19.141614 3136 master.cpp:3893] Successfully authenticated principal 'test-principal' at slave(221)@67.195.81.187:52646
I1029 09:40:19.141655 3139 sched.cpp:283] Authenticating with master master@67.195.81.187:52646
I1029 09:40:19.141803 3133 slave.cpp:722] Successfully authenticated with master master@67.195.81.187:52646
I1029 09:40:19.141935 3133 slave.cpp:1050] Will retry registration in 1.851985ms if necessary
I1029 09:40:19.141953 3135 authenticatee.hpp:133] Creating new client SASL connection
I1029 09:40:19.142122 3136 master.cpp:3032] Registering slave at slave(221)@67.195.81.187:52646 (pomona.apache.org) with id 20141029-094017-3142697795-52646-3116-S0
I1029 09:40:19.142488 3136 master.cpp:3853] Authenticating scheduler-9e111951-0c27-4675-bf72-1d22f8fc41b3@67.195.81.187:52646
I1029 09:40:19.142570 3144 registrar.cpp:445] Applied 1 operations in 53671ns; attempting to update the 'registry'
I1029 09:40:19.142714 3142 authenticator.hpp:161] Creating new server SASL connection
I1029 09:40:19.142868 3142 authenticatee.hpp:224] Received SASL authentication mechanisms: CRAM-MD5
I1029 09:40:19.142894 3142 authenticatee.hpp:250] Attempting to authenticate with mechanism 'CRAM-MD5'
I1029 09:40:19.142984 3142 authenticator.hpp:267] Received SASL authentication start
I1029 09:40:19.143038 3142 authenticator.hpp:389] Authentication requires more steps
I1029 09:40:19.143129 3142 authenticatee.hpp:270] Received SASL authentication step
I1029 09:40:19.143240 3142 authenticator.hpp:295] Received SASL authentication step
I1029 09:40:19.143295 3142 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1029 09:40:19.143311 3142 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I1029 09:40:19.143342 3142 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1029 09:40:19.143368 3142 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'pomona.apache.org' server FQDN: 'pomona.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1029 09:40:19.143379 3142 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1029 09:40:19.143388 3142 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1029 09:40:19.143406 3142 authenticator.hpp:381] Authentication success
I1029 09:40:19.143496 3143 authenticatee.hpp:310] Authentication success
I1029 09:40:19.143502 3142 master.cpp:3893] Successfully authenticated principal 'test-principal' at scheduler-9e111951-0c27-4675-bf72-1d22f8fc41b3@67.195.81.187:52646
I1029 09:40:19.143746 3135 sched.cpp:357] Successfully authenticated with master master@67.195.81.187:52646
I1029 09:40:19.143772 3135 sched.cpp:476] Sending registration request to master@67.195.81.187:52646
I1029 09:40:19.143894 3142 master.cpp:1362] Received registration request for framework 'default' at scheduler-9e111951-0c27-4675-bf72-1d22f8fc41b3@67.195.81.187:52646
I1029 09:40:19.143965 3142 master.cpp:1321] Authorizing framework principal 'test-principal' to receive offers for role '*'
I1029 09:40:19.144382 3134 slave.cpp:1050] Will retry registration in 26.869214ms if necessary
I1029 09:40:19.144412 3131 master.cpp:1426] Registering framework 20141029-094017-3142697795-52646-3116-0000 (default) at scheduler-9e111951-0c27-4675-bf72-1d22f8fc41b3@67.195.81.187:52646
I1029 09:40:19.144719 3140 hierarchical_allocator_process.hpp:329] Added framework 20141029-094017-3142697795-52646-3116-0000
I1029 09:40:19.144750 3140 hierarchical_allocator_process.hpp:697] No resources available to allocate!
I1029 09:40:19.144767 3140 hierarchical_allocator_process.hpp:659] Performed allocation for 0 slaves in 20887ns
I1029 09:40:19.144899 3131 master.cpp:3020] Ignoring register slave message from slave(221)@67.195.81.187:52646 (pomona.apache.org) as admission is already in progress
I1029 09:40:19.144927 3140 sched.cpp:407] Framework registered with 20141029-094017-3142697795-52646-3116-0000
I1029 09:40:19.145021 3140 sched.cpp:421] Scheduler::registered took 66223ns
I1029 09:40:19.146101 3138 log.cpp:680] Attempting to append 314 bytes to the log
I1029 09:40:19.146260 3130 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3
I1029 09:40:19.147037 3132 replica.cpp:508] Replica received write request for position 3
I1029 09:40:19.147657 3132 leveldb.cpp:343] Persisting action (333 bytes) to leveldb took 595290ns
I1029 09:40:19.147685 3132 replica.cpp:676] Persisted action at 3
I1029 09:40:19.148233 3143 replica.cpp:655] Replica received learned notice for position 3
I1029 09:40:19.148720 3143 leveldb.cpp:343] Persisting action (335 bytes) to leveldb took 463427ns
I1029 09:40:19.148741 3143 replica.cpp:676] Persisted action at 3
I1029 09:40:19.148756 3143 replica.cpp:661] Replica learned APPEND action at position 3
I1029 09:40:19.149673 3132 registrar.cpp:490] Successfully updated the 'registry' in 7.045888ms
I1029 09:40:19.149961 3136 log.cpp:699] Attempting to truncate the log to 3
I1029 09:40:19.150087 3135 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4
I1029 09:40:19.150274 3138 slave.cpp:2522] Received ping from slave-observer(200)@67.195.81.187:52646
I1029 09:40:19.150388 3145 master.cpp:3086] Registered slave 20141029-094017-3142697795-52646-3116-S0 at slave(221)@67.195.81.187:52646 (pomona.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I1029 09:40:19.150473 3138 slave.cpp:756] Registered with master master@67.195.81.187:52646; given slave ID 20141029-094017-3142697795-52646-3116-S0
I1029 09:40:19.150538 3133 hierarchical_allocator_process.hpp:442] Added slave 20141029-094017-3142697795-52646-3116-S0 (pomona.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
I1029 09:40:19.150576 3130 status_update_manager.cpp:178] Resuming sending status updates
I1029 09:40:19.150753 3133 hierarchical_allocator_process.hpp:734] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20141029-094017-3142697795-52646-3116-S0 to framework 20141029-094017-3142697795-52646-3116-0000
I1029 09:40:19.150900 3144 replica.cpp:508] Replica received write request for position 4
I1029 09:40:19.205476 3133 hierarchical_allocator_process.hpp:679] Performed allocation for slave 20141029-094017-3142697795-52646-3116-S0 in 54.856249ms
I1029 09:40:19.205835 3133 master.cpp:3795] Sending 1 offers to framework 20141029-094017-3142697795-52646-3116-0000 (default) at scheduler-9e111951-0c27-4675-bf72-1d22f8fc41b3@67.195.81.187:52646
I1029 09:40:19.205899 3144 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 745444ns
I1029 09:40:19.205925 3144 replica.cpp:676] Persisted action at 4
I1029 09:40:19.206272 3145 sched.cpp:544] Scheduler::resourceOffers took 103845ns
I1029 09:40:19.206784 3142 replica.cpp:655] Replica received learned notice for position 4
I1029 09:40:19.207487 3142 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 667602ns
I1029 09:40:19.207556 3142 leveldb.cpp:401] Deleting ~2 keys from leveldb took 37231ns
I1029 09:40:19.207578 3142 replica.cpp:676] Persisted action at 4
I1029 09:40:19.207600 3142 replica.cpp:661] Replica learned TRUNCATE action at position 4
I1029 09:40:19.210643 3145 master.cpp:2321] Processing reply for offers: [ 20141029-094017-3142697795-52646-3116-O0 ] on slave 20141029-094017-3142697795-52646-3116-S0 at slave(221)@67.195.81.187:52646 (pomona.apache.org) for framework 20141029-094017-3142697795-52646-3116-0000 (default) at scheduler-9e111951-0c27-4675-bf72-1d22f8fc41b3@67.195.81.187:52646
W1029 09:40:19.210777 3145 master.cpp:1969] Executor default for task ca34806b-376a-46da-b742-903aae98f312 uses less CPUs (None) than the minimum required (0.01). Please update your executor, as this will be mandatory in future releases.
W1029 09:40:19.210810 3145 master.cpp:1980] Executor default for task ca34806b-376a-46da-b742-903aae98f312 uses less memory (None) than the minimum required (32MB). Please update your executor, as this will be mandatory in future releases.
I1029 09:40:19.210913 3145 master.cpp:2417] Authorizing framework principal 'test-principal' to launch task ca34806b-376a-46da-b742-903aae98f312 as user 'jenkins'
I1029 09:40:19.212076 3144 master.hpp:877] Adding task ca34806b-376a-46da-b742-903aae98f312 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20141029-094017-3142697795-52646-3116-S0 (pomona.apache.org)
I1029 09:40:19.212195 3144 master.cpp:2480] Launching task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000 (default) at scheduler-9e111951-0c27-4675-bf72-1d22f8fc41b3@67.195.81.187:52646 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20141029-094017-3142697795-52646-3116-S0 at slave(221)@67.195.81.187:52646 (pomona.apache.org)
I1029 09:40:19.212568 3136 slave.cpp:1081] Got assigned task ca34806b-376a-46da-b742-903aae98f312 for framework 20141029-094017-3142697795-52646-3116-0000
I1029 09:40:19.213148 3136 slave.cpp:1191] Launching task ca34806b-376a-46da-b742-903aae98f312 for framework 20141029-094017-3142697795-52646-3116-0000
I1029 09:40:19.215901 3136 slave.cpp:3871] Launching executor default of framework 20141029-094017-3142697795-52646-3116-0000 in work directory '/tmp/SlaveTest_IgnoreNonLeaderStatusUpdateAcknowledgement_E7ceOa/slaves/20141029-094017-3142697795-52646-3116-S0/frameworks/20141029-094017-3142697795-52646-3116-0000/executors/default/runs/b836c8a7-d495-4ecc-9c1f-4b4d0b47841d'
I1029 09:40:19.219048 3136 exec.cpp:132] Version: 0.21.0
I1029 09:40:19.219317 3132 exec.cpp:182] Executor started at: executor(74)@67.195.81.187:52646 with pid 3116
I1029 09:40:19.219502 3136 slave.cpp:1317] Queuing task 'ca34806b-376a-46da-b742-903aae98f312' for executor default of framework '20141029-094017-3142697795-52646-3116-0000
I1029 09:40:19.219641 3136 slave.cpp:555] Successfully attached file '/tmp/SlaveTest_IgnoreNonLeaderStatusUpdateAcknowledgement_E7ceOa/slaves/20141029-094017-3142697795-52646-3116-S0/frameworks/20141029-094017-3142697795-52646-3116-0000/executors/default/runs/b836c8a7-d495-4ecc-9c1f-4b4d0b47841d'
I1029 09:40:19.219727 3136 slave.cpp:1849] Got registration for executor 'default' of framework 20141029-094017-3142697795-52646-3116-0000 from executor(74)@67.195.81.187:52646
I1029 09:40:19.220155 3136 slave.cpp:1968] Flushing queued task ca34806b-376a-46da-b742-903aae98f312 for executor 'default' of framework 20141029-094017-3142697795-52646-3116-0000
I1029 09:40:19.220214 3138 exec.cpp:206] Executor registered on slave 20141029-094017-3142697795-52646-3116-S0
I1029 09:40:19.220577 3136 slave.cpp:2802] Monitoring executor 'default' of framework '20141029-094017-3142697795-52646-3116-0000' in container 'b836c8a7-d495-4ecc-9c1f-4b4d0b47841d'
I1029 09:40:19.222697 3138 exec.cpp:218] Executor::registered took 29157ns
I1029 09:40:19.222894 3138 exec.cpp:293] Executor asked to run task 'ca34806b-376a-46da-b742-903aae98f312'
I1029 09:40:19.222977 3138 exec.cpp:302] Executor::launchTask took 61419ns
I1029 09:40:19.225311 3138 exec.cpp:525] Executor sending status update TASK_RUNNING (UUID: cd782c8c-ef08-44f9-b308-b8d9b6d4534b) for task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000
I1029 09:40:19.225558 3136 slave.cpp:2202] Handling status update TASK_RUNNING (UUID: cd782c8c-ef08-44f9-b308-b8d9b6d4534b) for task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000 from executor(74)@67.195.81.187:52646
I1029 09:40:19.225837 3131 status_update_manager.cpp:317] Received status update TASK_RUNNING (UUID: cd782c8c-ef08-44f9-b308-b8d9b6d4534b) for task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000
I1029 09:40:19.225882 3131 status_update_manager.cpp:494] Creating StatusUpdate stream for task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000
I1029 09:40:19.226078 3131 status_update_manager.cpp:371] Forwarding update TASK_RUNNING (UUID: cd782c8c-ef08-44f9-b308-b8d9b6d4534b) for task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000 to the slave
I1029 09:40:19.226388 3133 slave.cpp:2442] Forwarding the update TASK_RUNNING (UUID: cd782c8c-ef08-44f9-b308-b8d9b6d4534b) for task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000 to master@67.195.81.187:52646
I1029 09:40:19.226567 3133 slave.cpp:2369] Status update manager successfully handled status update TASK_RUNNING (UUID: cd782c8c-ef08-44f9-b308-b8d9b6d4534b) for task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000
I1029 09:40:19.226599 3133 slave.cpp:2375] Sending acknowledgement for status update TASK_RUNNING (UUID: cd782c8c-ef08-44f9-b308-b8d9b6d4534b) for task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000 to executor(74)@67.195.81.187:52646
I1029 09:40:19.226709 3138 master.cpp:3410] Forwarding status update TASK_RUNNING (UUID: cd782c8c-ef08-44f9-b308-b8d9b6d4534b) for task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000
I1029 09:40:19.226758 3133 exec.cpp:339] Executor received status update acknowledgement cd782c8c-ef08-44f9-b308-b8d9b6d4534b for task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000
I1029 09:40:19.226868 3138 master.cpp:3382] Status update TASK_RUNNING (UUID: cd782c8c-ef08-44f9-b308-b8d9b6d4534b) for task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000 from slave 20141029-094017-3142697795-52646-3116-S0 at slave(221)@67.195.81.187:52646 (pomona.apache.org)
I1029 09:40:19.226920 3138 master.cpp:4617] Updating the latest state of task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000 to TASK_RUNNING
I1029 09:40:19.226987 3144 sched.cpp:635] Scheduler::statusUpdate took 34407ns
I1029 09:40:19.272017 3144 master.cpp:2882] Forwarding status update acknowledgement cd782c8c-ef08-44f9-b308-b8d9b6d4534b for task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000 (default) at scheduler-9e111951-0c27-4675-bf72-1d22f8fc41b3@67.195.81.187:52646 to slave 20141029-094017-3142697795-52646-3116-S0 at slave(221)@67.195.81.187:52646 (pomona.apache.org)
W1029 09:40:19.290961 3134 slave.cpp:1756] Ignoring status update acknowledgement message from master@127.0.0.1:1 because it is not the expected master: master@67.195.81.187:52646
I1029 09:40:19.301856 3134 hierarchical_allocator_process.hpp:659] Performed allocation for 1 slaves in 132814ns
I1029 09:40:19.301957 3135 master.cpp:120] No whitelist given. Advertising offers for all slaves
W1029 09:40:19.302175 3139 status_update_manager.cpp:472] Resending status update TASK_RUNNING (UUID: cd782c8c-ef08-44f9-b308-b8d9b6d4534b) for task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000
I1029 09:40:19.302208 3139 status_update_manager.cpp:371] Forwarding update TASK_RUNNING (UUID: cd782c8c-ef08-44f9-b308-b8d9b6d4534b) for task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000 to the slave
I1029 09:40:19.302577 3136 slave.cpp:2442] Forwarding the update TASK_RUNNING (UUID: cd782c8c-ef08-44f9-b308-b8d9b6d4534b) for task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000 to master@67.195.81.187:52646
I1029 09:40:19.302829 3136 master.cpp:3410] Forwarding status update TASK_RUNNING (UUID: cd782c8c-ef08-44f9-b308-b8d9b6d4534b) for task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000
I1029 09:40:19.302960 3136 master.cpp:3382] Status update TASK_RUNNING (UUID: cd782c8c-ef08-44f9-b308-b8d9b6d4534b) for task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000 from slave 20141029-094017-3142697795-52646-3116-S0 at slave(221)@67.195.81.187:52646 (pomona.apache.org)
I1029 09:40:19.303009 3136 master.cpp:4617] Updating the latest state of task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000 to TASK_RUNNING
I1029 09:40:19.303073 3139 sched.cpp:635] Scheduler::statusUpdate took 26282ns
I1029 09:40:19.303308 3139 master.cpp:2882] Forwarding status update acknowledgement cd782c8c-ef08-44f9-b308-b8d9b6d4534b for task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000 (default) at scheduler-9e111951-0c27-4675-bf72-1d22f8fc41b3@67.195.81.187:52646 to slave 20141029-094017-3142697795-52646-3116-S0 at slave(221)@67.195.81.187:52646 (pomona.apache.org)
I1029 09:40:19.303616 3131 status_update_manager.cpp:389] Received status update acknowledgement (UUID: cd782c8c-ef08-44f9-b308-b8d9b6d4534b) for task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000
I1029 09:40:19.303843 3130 slave.cpp:1789] Status update manager successfully handled status update acknowledgement (UUID: cd782c8c-ef08-44f9-b308-b8d9b6d4534b) for task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000
I1029 09:40:19.331620 3116 master.cpp:677] Master terminating
I1029 09:40:19.331665 3131 sched.cpp:745] Stopping framework '20141029-094017-3142697795-52646-3116-0000'
W1029 09:40:19.331760 3116 master.cpp:4662] Removing task ca34806b-376a-46da-b742-903aae98f312 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework 20141029-094017-3142697795-52646-3116-0000 on slave 20141029-094017-3142697795-52646-3116-S0 at slave(221)@67.195.81.187:52646 (pomona.apache.org) in non-terminal state TASK_RUNNING
I1029 09:40:19.332249 3132 hierarchical_allocator_process.hpp:563] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total allocatable: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) on slave 20141029-094017-3142697795-52646-3116-S0 from framework 20141029-094017-3142697795-52646-3116-0000
I1029 09:40:19.332370 3116 master.cpp:4705] Removing executor 'default' with resources of framework 20141029-094017-3142697795-52646-3116-0000 on slave 20141029-094017-3142697795-52646-3116-S0 at slave(221)@67.195.81.187:52646 (pomona.apache.org)
I1029 09:40:19.333036 3134 slave.cpp:2607] master@67.195.81.187:52646 exited
W1029 09:40:19.333071 3134 slave.cpp:2610] Master disconnected! Waiting for a new master to be elected
I1029 09:40:19.338084 3145 slave.cpp:2860] Executor 'default' of framework 20141029-094017-3142697795-52646-3116-0000 exited with status 0
I1029 09:40:19.340365 3145 slave.cpp:2202] Handling status update TASK_LOST (UUID: 738b05f1-43cf-48f3-a770-6512e44c7c20) for task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000 from @0.0.0.0:0
I1029 09:40:19.340446 3145 slave.cpp:4179] Terminating task ca34806b-376a-46da-b742-903aae98f312
I1029 09:40:19.340796 3145 slave.cpp:484] Slave terminating
I1029 09:40:19.340869 3145 slave.cpp:1522] Asked to shut down framework 20141029-094017-3142697795-52646-3116-0000 by @0.0.0.0:0
I1029 09:40:19.340893 3145 slave.cpp:1547] Shutting down framework 20141029-094017-3142697795-52646-3116-0000
I1029 09:40:19.340950 3145 slave.cpp:2997] Cleaning up executor 'default' of framework 20141029-094017-3142697795-52646-3116-0000
I1029 09:40:19.341166 3136 gc.cpp:56] Scheduling '/tmp/SlaveTest_IgnoreNonLeaderStatusUpdateAcknowledgement_E7ceOa/slaves/20141029-094017-3142697795-52646-3116-S0/frameworks/20141029-094017-3142697795-52646-3116-0000/executors/default/runs/b836c8a7-d495-4ecc-9c1f-4b4d0b47841d' for gc 6.99999605291556days in the future
I1029 09:40:19.341214 3145 slave.cpp:3074] Cleaning up framework 20141029-094017-3142697795-52646-3116-0000
I1029 09:40:19.341369 3143 status_update_manager.cpp:279] Closing status update streams for framework 20141029-094017-3142697795-52646-3116-0000
I1029 09:40:19.341408 3136 gc.cpp:56] Scheduling '/tmp/SlaveTest_IgnoreNonLeaderStatusUpdateAcknowledgement_E7ceOa/slaves/20141029-094017-3142697795-52646-3116-S0/frameworks/20141029-094017-3142697795-52646-3116-0000/executors/default' for gc 6.99999605142519days in the future
I1029 09:40:19.341442 3143 status_update_manager.cpp:525] Cleaning up status update stream for task ca34806b-376a-46da-b742-903aae98f312 of framework 20141029-094017-3142697795-52646-3116-0000
I1029 09:40:19.341562 3136 gc.cpp:56] Scheduling '/tmp/SlaveTest_IgnoreNonLeaderStatusUpdateAcknowledgement_E7ceOa/slaves/20141029-094017-3142697795-52646-3116-S0/frameworks/20141029-094017-3142697795-52646-3116-0000' for gc 6.99999604953778days in the future
[ OK ] SlaveTest.IgnoreNonLeaderStatusUpdateAcknowledgement (2207 ms)
[----------] 12 tests from SlaveTest (11982 ms total)
[----------] Global test environment tear-down
[==========] 449 tests from 70 test cases ran. (420137 ms total)
[ PASSED ] 447 tests.
[ FAILED ] 2 tests, listed below:
[ FAILED ] ExamplesTest.JavaLog
[ FAILED ] CoordinatorTest.TruncateNotLearnedFill
2 FAILED TESTS
YOU HAVE 6 DISABLED TESTS
make[3]: *** [check-local] Error 1
make[3]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/src'>
make[2]: *** [check-am] Error 2
make[2]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/src'>
make[1]: *** [check] Error 2
make[1]: Leaving directory `<https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-In-Src-Set-JAVA_HOME/ws/src'>
make: *** [check-recursive] Error 1
Test finished
Exit status: 2
Build step 'Execute shell' marked build as failure
Recording test results