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/06/19 03:16:36 UTC
Build failed in Jenkins: Mesos-Ubuntu-distcheck #157
See <https://builds.apache.org/job/Mesos-Ubuntu-distcheck/157/changes>
Changes:
[bmahler] Added logging for ip resolution errors in libprocess.
[bmahler] Added process delegate for accessing the scheduler endpoint.
------------------------------------------
[...truncated 57876 lines...]
I0619 01:16:36.044014 5221 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0619 01:16:36.044023 5221 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0619 01:16:36.044028 5221 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0619 01:16:36.044042 5221 authenticator.hpp:376] Authentication success
I0619 01:16:36.044169 5227 authenticatee.hpp:305] Authentication success
I0619 01:16:36.044698 5213 master.cpp:3497] Successfully authenticated principal 'test-principal' at scheduler-96575c61-76f0-4525-8fed-2264e84de37c@140.211.11.27:48847
I0619 01:16:36.044972 5231 sched.cpp:359] Successfully authenticated with master master@140.211.11.27:48847
I0619 01:16:36.044999 5231 sched.cpp:478] Sending registration request to master@140.211.11.27:48847
I0619 01:16:36.045068 5224 master.cpp:1196] Received registration request from scheduler-96575c61-76f0-4525-8fed-2264e84de37c@140.211.11.27:48847
I0619 01:16:36.045100 5224 master.cpp:1156] Authorizing framework principal 'test-principal' to receive offers for role 'role1'
I0619 01:16:36.045348 5220 master.cpp:1255] Registering framework 20140619-011635-453759884-48847-5135-0002 at scheduler-96575c61-76f0-4525-8fed-2264e84de37c@140.211.11.27:48847
I0619 01:16:36.045445 5210 sched.cpp:409] Framework registered with 20140619-011635-453759884-48847-5135-0002
I0619 01:16:36.045470 5210 sched.cpp:423] Scheduler::registered took 10645ns
I0619 01:16:36.045534 5221 hierarchical_allocator_process.hpp:331] Added framework 20140619-011635-453759884-48847-5135-0002
I0619 01:16:36.045601 5221 hierarchical_allocator_process.hpp:686] Performed allocation for 3 slaves in 52728ns
I0619 01:16:36.046247 5135 mesos_containerizer.cpp:125] Using isolation: posix/cpu,posix/mem
I0619 01:16:36.048532 5230 slave.cpp:143] Slave started on 184)@140.211.11.27:48847
I0619 01:16:36.048547 5230 credentials.hpp:35] Loading credentials for authentication from '/tmp/DRFAllocatorTest_DRFAllocatorProcess_NxjSbo/credential'
I0619 01:16:36.048673 5230 slave.cpp:243] Slave using credential for: test-principal
I0619 01:16:36.048758 5230 slave.cpp:256] Slave resources: cpus(*):4; mem(*):4096; disk(*):0; ports(*):[31000-32000]
I0619 01:16:36.048809 5230 slave.cpp:284] Slave hostname: hemera.apache.org
I0619 01:16:36.048817 5230 slave.cpp:285] Slave checkpoint: false
I0619 01:16:36.048888 5211 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 10.074947ms
I0619 01:16:36.048909 5211 replica.cpp:676] Persisted action at 8
I0619 01:16:36.049300 5216 replica.cpp:655] Replica received learned notice for position 8
I0619 01:16:36.049588 5232 state.cpp:33] Recovering state from '/tmp/DRFAllocatorTest_DRFAllocatorProcess_NxjSbo/meta'
I0619 01:16:36.049785 5231 status_update_manager.cpp:193] Recovering status update manager
I0619 01:16:36.050251 5231 mesos_containerizer.cpp:283] Recovering containerizer
I0619 01:16:36.050669 5210 slave.cpp:3068] Finished recovery
I0619 01:16:36.051018 5221 slave.cpp:537] New master detected at master@140.211.11.27:48847
I0619 01:16:36.051079 5221 slave.cpp:613] Authenticating with master master@140.211.11.27:48847
I0619 01:16:36.051103 5215 status_update_manager.cpp:167] New master detected at master@140.211.11.27:48847
I0619 01:16:36.051162 5221 slave.cpp:586] Detecting new master
I0619 01:16:36.051213 5222 authenticatee.hpp:128] Creating new client SASL connection
I0619 01:16:36.051466 5226 master.cpp:3457] Authenticating slave(184)@140.211.11.27:48847
I0619 01:16:36.051559 5226 authenticator.hpp:156] Creating new server SASL connection
I0619 01:16:36.051679 5226 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
I0619 01:16:36.051694 5226 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
I0619 01:16:36.051810 5221 authenticator.hpp:262] Received SASL authentication start
I0619 01:16:36.051849 5221 authenticator.hpp:384] Authentication requires more steps
I0619 01:16:36.051874 5221 authenticatee.hpp:265] Received SASL authentication step
I0619 01:16:36.051901 5221 authenticator.hpp:290] Received SASL authentication step
I0619 01:16:36.051952 5221 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0619 01:16:36.051962 5221 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I0619 01:16:36.051970 5221 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0619 01:16:36.051976 5221 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0619 01:16:36.051981 5221 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0619 01:16:36.051985 5221 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0619 01:16:36.051992 5221 authenticator.hpp:376] Authentication success
I0619 01:16:36.052065 5210 authenticatee.hpp:305] Authentication success
I0619 01:16:36.052074 5221 master.cpp:3497] Successfully authenticated principal 'test-principal' at slave(184)@140.211.11.27:48847
I0619 01:16:36.052263 5229 slave.cpp:670] Successfully authenticated with master master@140.211.11.27:48847
I0619 01:16:36.052304 5229 slave.cpp:908] Will retry registration in 13.300855ms if necessary
I0619 01:16:36.052342 5221 master.cpp:2736] Registering slave at slave(184)@140.211.11.27:48847 (hemera.apache.org) with id 20140619-011635-453759884-48847-5135-3
I0619 01:16:36.052438 5230 registrar.cpp:422] Attempting to update the 'registry'
I0619 01:16:36.061280 5216 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 11.955129ms
I0619 01:16:36.061332 5216 leveldb.cpp:401] Deleting ~2 keys from leveldb took 31310ns
I0619 01:16:36.061342 5216 replica.cpp:676] Persisted action at 8
I0619 01:16:36.061349 5216 replica.cpp:661] Replica learned TRUNCATE action at position 8
I0619 01:16:36.061677 5217 log.cpp:680] Attempting to append 897 bytes to the log
I0619 01:16:36.061769 5212 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 9
I0619 01:16:36.062556 5231 replica.cpp:508] Replica received write request for position 9
I0619 01:16:36.066651 5223 slave.cpp:908] Will retry registration in 37.42224ms if necessary
I0619 01:16:36.066695 5224 master.cpp:2724] Ignoring register slave message from slave(184)@140.211.11.27:48847 (hemera.apache.org) as admission is already in progress
I0619 01:16:36.073389 5231 leveldb.cpp:343] Persisting action (916 bytes) to leveldb took 10.807366ms
I0619 01:16:36.073418 5231 replica.cpp:676] Persisted action at 9
I0619 01:16:36.074049 5211 replica.cpp:655] Replica received learned notice for position 9
I0619 01:16:36.085521 5211 leveldb.cpp:343] Persisting action (918 bytes) to leveldb took 11.438781ms
I0619 01:16:36.085575 5211 replica.cpp:676] Persisted action at 9
I0619 01:16:36.085589 5211 replica.cpp:661] Replica learned APPEND action at position 9
I0619 01:16:36.086160 5221 registrar.cpp:479] Successfully updated 'registry'
I0619 01:16:36.086395 5224 log.cpp:699] Attempting to truncate the log to 9
I0619 01:16:36.086534 5221 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 10
I0619 01:16:36.086534 5217 master.cpp:2776] Registered slave 20140619-011635-453759884-48847-5135-3 at slave(184)@140.211.11.27:48847 (hemera.apache.org)
I0619 01:16:36.086565 5217 master.cpp:3923] Adding slave 20140619-011635-453759884-48847-5135-3 at slave(184)@140.211.11.27:48847 (hemera.apache.org) with cpus(*):4; mem(*):4096; disk(*):0; ports(*):[31000-32000]
I0619 01:16:36.087884 5210 slave.cpp:704] Registered with master master@140.211.11.27:48847; given slave ID 20140619-011635-453759884-48847-5135-3
I0619 01:16:36.088208 5218 replica.cpp:508] Replica received write request for position 10
I0619 01:16:36.088553 5226 hierarchical_allocator_process.hpp:444] Added slave 20140619-011635-453759884-48847-5135-3 (hemera.apache.org) with cpus(*):4; mem(*):4096; disk(*):0; ports(*):[31000-32000] (and cpus(*):4; mem(*):4096; disk(*):0; ports(*):[31000-32000] available)
I0619 01:16:36.088661 5226 hierarchical_allocator_process.hpp:750] Offering cpus(*):4; mem(*):4096; disk(*):0; ports(*):[31000-32000] on slave 20140619-011635-453759884-48847-5135-3 to framework 20140619-011635-453759884-48847-5135-0002
I0619 01:16:36.088829 5226 hierarchical_allocator_process.hpp:706] Performed allocation for slave 20140619-011635-453759884-48847-5135-3 in 206634ns
I0619 01:16:36.088891 5214 master.hpp:785] Adding offer 20140619-011635-453759884-48847-5135-3 with resources cpus(*):4; mem(*):4096; disk(*):0; ports(*):[31000-32000] on slave 20140619-011635-453759884-48847-5135-3 (hemera.apache.org)
I0619 01:16:36.088929 5214 master.cpp:3404] Sending 1 offers to framework 20140619-011635-453759884-48847-5135-0002
I0619 01:16:36.089170 5230 sched.cpp:546] Scheduler::resourceOffers took 29630ns
I0619 01:16:36.092115 5135 sched.cpp:139] Version: 0.20.0
I0619 01:16:36.092353 5232 sched.cpp:235] New master detected at master@140.211.11.27:48847
I0619 01:16:36.092372 5232 sched.cpp:285] Authenticating with master master@140.211.11.27:48847
I0619 01:16:36.092517 5211 authenticatee.hpp:128] Creating new client SASL connection
I0619 01:16:36.092702 5211 master.cpp:3457] Authenticating scheduler-01455cb3-ab62-4ff1-aae4-3394a5f2c4d8@140.211.11.27:48847
I0619 01:16:36.092856 5209 authenticator.hpp:156] Creating new server SASL connection
I0619 01:16:36.093091 5210 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
I0619 01:16:36.093122 5210 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
I0619 01:16:36.093703 5230 authenticator.hpp:262] Received SASL authentication start
I0619 01:16:36.093778 5230 authenticator.hpp:384] Authentication requires more steps
I0619 01:16:36.093818 5230 authenticatee.hpp:265] Received SASL authentication step
I0619 01:16:36.094140 5226 authenticator.hpp:290] Received SASL authentication step
I0619 01:16:36.094193 5226 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0619 01:16:36.094199 5226 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I0619 01:16:36.094208 5226 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0619 01:16:36.094213 5226 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0619 01:16:36.094218 5226 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0619 01:16:36.094221 5226 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0619 01:16:36.094230 5226 authenticator.hpp:376] Authentication success
I0619 01:16:36.094254 5226 authenticatee.hpp:305] Authentication success
I0619 01:16:36.094370 5219 master.cpp:3497] Successfully authenticated principal 'test-principal' at scheduler-01455cb3-ab62-4ff1-aae4-3394a5f2c4d8@140.211.11.27:48847
I0619 01:16:36.094581 5230 sched.cpp:359] Successfully authenticated with master master@140.211.11.27:48847
I0619 01:16:36.094595 5230 sched.cpp:478] Sending registration request to master@140.211.11.27:48847
I0619 01:16:36.094636 5230 master.cpp:1196] Received registration request from scheduler-01455cb3-ab62-4ff1-aae4-3394a5f2c4d8@140.211.11.27:48847
I0619 01:16:36.094725 5230 master.cpp:1156] Authorizing framework principal 'test-principal' to receive offers for role 'role1'
I0619 01:16:36.095087 5220 master.cpp:1255] Registering framework 20140619-011635-453759884-48847-5135-0003 at scheduler-01455cb3-ab62-4ff1-aae4-3394a5f2c4d8@140.211.11.27:48847
I0619 01:16:36.095155 5220 sched.cpp:409] Framework registered with 20140619-011635-453759884-48847-5135-0003
I0619 01:16:36.095180 5220 sched.cpp:423] Scheduler::registered took 10639ns
I0619 01:16:36.095221 5220 hierarchical_allocator_process.hpp:331] Added framework 20140619-011635-453759884-48847-5135-0003
I0619 01:16:36.095342 5220 hierarchical_allocator_process.hpp:686] Performed allocation for 4 slaves in 47244ns
I0619 01:16:36.095880 5135 mesos_containerizer.cpp:125] Using isolation: posix/cpu,posix/mem
I0619 01:16:36.098332 5211 slave.cpp:143] Slave started on 185)@140.211.11.27:48847
I0619 01:16:36.098356 5211 credentials.hpp:35] Loading credentials for authentication from '/tmp/DRFAllocatorTest_DRFAllocatorProcess_jFOGoJ/credential'
I0619 01:16:36.098559 5211 slave.cpp:243] Slave using credential for: test-principal
I0619 01:16:36.098649 5211 slave.cpp:256] Slave resources: cpus(*):1; mem(*):512; disk(*):0; ports(*):[31000-32000]
I0619 01:16:36.098714 5211 slave.cpp:284] Slave hostname: hemera.apache.org
I0619 01:16:36.098722 5211 slave.cpp:285] Slave checkpoint: false
I0619 01:16:36.099120 5228 state.cpp:33] Recovering state from '/tmp/DRFAllocatorTest_DRFAllocatorProcess_jFOGoJ/meta'
I0619 01:16:36.099298 5219 status_update_manager.cpp:193] Recovering status update manager
I0619 01:16:36.100184 5224 mesos_containerizer.cpp:283] Recovering containerizer
I0619 01:16:36.100806 5209 slave.cpp:3068] Finished recovery
I0619 01:16:36.101135 5211 slave.cpp:537] New master detected at master@140.211.11.27:48847
I0619 01:16:36.101194 5211 slave.cpp:613] Authenticating with master master@140.211.11.27:48847
I0619 01:16:36.101239 5219 status_update_manager.cpp:167] New master detected at master@140.211.11.27:48847
I0619 01:16:36.101337 5211 slave.cpp:586] Detecting new master
I0619 01:16:36.101352 5213 authenticatee.hpp:128] Creating new client SASL connection
I0619 01:16:36.101497 5218 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 13.270376ms
I0619 01:16:36.101519 5218 replica.cpp:676] Persisted action at 10
I0619 01:16:36.101536 5211 master.cpp:3457] Authenticating slave(185)@140.211.11.27:48847
I0619 01:16:36.101608 5211 authenticator.hpp:156] Creating new server SASL connection
I0619 01:16:36.101922 5214 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
I0619 01:16:36.101943 5214 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
I0619 01:16:36.102357 5227 replica.cpp:655] Replica received learned notice for position 10
I0619 01:16:36.102898 5209 authenticator.hpp:262] Received SASL authentication start
I0619 01:16:36.103124 5209 authenticator.hpp:384] Authentication requires more steps
I0619 01:16:36.103246 5224 authenticatee.hpp:265] Received SASL authentication step
I0619 01:16:36.103353 5224 authenticator.hpp:290] Received SASL authentication step
I0619 01:16:36.103376 5224 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0619 01:16:36.103384 5224 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I0619 01:16:36.103394 5224 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0619 01:16:36.103404 5224 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'hemera.apache.org' server FQDN: 'hemera.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0619 01:16:36.103411 5224 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0619 01:16:36.103417 5224 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0619 01:16:36.103430 5224 authenticator.hpp:376] Authentication success
I0619 01:16:36.103498 5224 master.cpp:3497] Successfully authenticated principal 'test-principal' at slave(185)@140.211.11.27:48847
I0619 01:16:36.103535 5210 authenticatee.hpp:305] Authentication success
I0619 01:16:36.103862 5212 slave.cpp:670] Successfully authenticated with master master@140.211.11.27:48847
I0619 01:16:36.104279 5217 master.cpp:2736] Registering slave at slave(185)@140.211.11.27:48847 (hemera.apache.org) with id 20140619-011635-453759884-48847-5135-4
I0619 01:16:36.104276 5212 slave.cpp:908] Will retry registration in 5.27901ms if necessary
I0619 01:16:36.104379 5217 registrar.cpp:422] Attempting to update the 'registry'
I0619 01:16:36.110299 5217 slave.cpp:908] Will retry registration in 31.180772ms if necessary
I0619 01:16:36.110321 5225 master.cpp:2724] Ignoring register slave message from slave(185)@140.211.11.27:48847 (hemera.apache.org) as admission is already in progress
I0619 01:16:36.113929 5227 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 11.52181ms
I0619 01:16:36.113996 5227 leveldb.cpp:401] Deleting ~2 keys from leveldb took 33526ns
I0619 01:16:36.114045 5227 replica.cpp:676] Persisted action at 10
I0619 01:16:36.114053 5227 replica.cpp:661] Replica learned TRUNCATE action at position 10
I0619 01:16:36.114373 5218 log.cpp:680] Attempting to append 1086 bytes to the log
I0619 01:16:36.114590 5214 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 11
I0619 01:16:36.115583 5222 replica.cpp:508] Replica received write request for position 11
I0619 01:16:36.130033 5222 leveldb.cpp:343] Persisting action (1105 bytes) to leveldb took 14.423155ms
I0619 01:16:36.130081 5222 replica.cpp:676] Persisted action at 11
I0619 01:16:36.131031 5216 replica.cpp:655] Replica received learned notice for position 11
I0619 01:16:36.141700 5227 slave.cpp:908] Will retry registration in 13.762067ms if necessary
I0619 01:16:36.141757 5232 master.cpp:2724] Ignoring register slave message from slave(185)@140.211.11.27:48847 (hemera.apache.org) as admission is already in progress
I0619 01:16:36.154201 5216 leveldb.cpp:343] Persisting action (1107 bytes) to leveldb took 23.14169ms
I0619 01:16:36.154245 5216 replica.cpp:676] Persisted action at 11
I0619 01:16:36.154259 5216 replica.cpp:661] Replica learned APPEND action at position 11
I0619 01:16:36.154971 5228 registrar.cpp:479] Successfully updated 'registry'
I0619 01:16:36.155280 5221 master.cpp:2776] Registered slave 20140619-011635-453759884-48847-5135-4 at slave(185)@140.211.11.27:48847 (hemera.apache.org)
I0619 01:16:36.155313 5221 master.cpp:3923] Adding slave 20140619-011635-453759884-48847-5135-4 at slave(185)@140.211.11.27:48847 (hemera.apache.org) with cpus(*):1; mem(*):512; disk(*):0; ports(*):[31000-32000]
I0619 01:16:36.155557 5222 slave.cpp:704] Registered with master master@140.211.11.27:48847; given slave ID 20140619-011635-453759884-48847-5135-4
I0619 01:16:36.155673 5218 log.cpp:699] Attempting to truncate the log to 11
I0619 01:16:36.155930 5226 hierarchical_allocator_process.hpp:444] Added slave 20140619-011635-453759884-48847-5135-4 (hemera.apache.org) with cpus(*):1; mem(*):512; disk(*):0; ports(*):[31000-32000] (and cpus(*):1; mem(*):512; disk(*):0; ports(*):[31000-32000] available)
I0619 01:16:36.156097 5217 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 12
I0619 01:16:36.156085 5226 hierarchical_allocator_process.hpp:750] Offering cpus(*):1; mem(*):512; disk(*):0; ports(*):[31000-32000] on slave 20140619-011635-453759884-48847-5135-4 to framework 20140619-011635-453759884-48847-5135-0001
I0619 01:16:36.156384 5226 hierarchical_allocator_process.hpp:706] Performed allocation for slave 20140619-011635-453759884-48847-5135-4 in 392237ns
I0619 01:16:36.156445 5224 master.hpp:785] Adding offer 20140619-011635-453759884-48847-5135-4 with resources cpus(*):1; mem(*):512; disk(*):0; ports(*):[31000-32000] on slave 20140619-011635-453759884-48847-5135-4 (hemera.apache.org)
I0619 01:16:36.156507 5224 master.cpp:3404] Sending 1 offers to framework 20140619-011635-453759884-48847-5135-0001
I0619 01:16:36.156777 5228 sched.cpp:546] Scheduler::resourceOffers took 41735ns
I0619 01:16:36.157114 5213 sched.cpp:747] Stopping framework '20140619-011635-453759884-48847-5135-0001'
I0619 01:16:36.157124 5221 replica.cpp:508] Replica received write request for position 12
I0619 01:16:36.157150 5229 sched.cpp:747] Stopping framework '20140619-011635-453759884-48847-5135-0002'
I0619 01:16:36.157198 5231 sched.cpp:747] Stopping framework '20140619-011635-453759884-48847-5135-0003'
I0619 01:16:36.157263 5228 sched.cpp:747] Stopping framework '20140619-011635-453759884-48847-5135-0000'
I0619 01:16:36.157354 5215 master.cpp:1485] Asked to unregister framework 20140619-011635-453759884-48847-5135-0001
I0619 01:16:36.157367 5215 master.cpp:3779] Removing framework 20140619-011635-453759884-48847-5135-0001
I0619 01:16:36.157462 5212 slave.cpp:1343] Asked to shut down framework 20140619-011635-453759884-48847-5135-0001 by master@140.211.11.27:48847
I0619 01:16:36.157482 5222 slave.cpp:1343] Asked to shut down framework 20140619-011635-453759884-48847-5135-0001 by master@140.211.11.27:48847
W0619 01:16:36.157490 5212 slave.cpp:1358] Cannot shut down unknown framework 20140619-011635-453759884-48847-5135-0001
W0619 01:16:36.157498 5222 slave.cpp:1358] Cannot shut down unknown framework 20140619-011635-453759884-48847-5135-0001
I0619 01:16:36.157521 5230 hierarchical_allocator_process.hpp:407] Deactivated framework 20140619-011635-453759884-48847-5135-0001
I0619 01:16:36.157537 5213 slave.cpp:1343] Asked to shut down framework 20140619-011635-453759884-48847-5135-0001 by master@140.211.11.27:48847
W0619 01:16:36.157562 5213 slave.cpp:1358] Cannot shut down unknown framework 20140619-011635-453759884-48847-5135-0001
I0619 01:16:36.157565 5223 slave.cpp:1343] Asked to shut down framework 20140619-011635-453759884-48847-5135-0001 by master@140.211.11.27:48847
W0619 01:16:36.157582 5223 slave.cpp:1358] Cannot shut down unknown framework 20140619-011635-453759884-48847-5135-0001
I0619 01:16:36.157593 5218 slave.cpp:1343] Asked to shut down framework 20140619-011635-453759884-48847-5135-0001 by master@140.211.11.27:48847
I0619 01:16:36.157591 5215 master.hpp:795] Removing offer 20140619-011635-453759884-48847-5135-2 with resources cpus(*):3; mem(*):2048; disk(*):0; ports(*):[31000-32000] on slave 20140619-011635-453759884-48847-5135-2 (hemera.apache.org)
W0619 01:16:36.157650 5218 slave.cpp:1358] Cannot shut down unknown framework 20140619-011635-453759884-48847-5135-0001
I0619 01:16:36.157716 5215 master.hpp:795] Removing offer 20140619-011635-453759884-48847-5135-4 with resources cpus(*):1; mem(*):512; disk(*):0; ports(*):[31000-32000] on slave 20140619-011635-453759884-48847-5135-4 (hemera.apache.org)
I0619 01:16:36.157800 5215 master.hpp:795] Removing offer 20140619-011635-453759884-48847-5135-1 with resources cpus(*):1; mem(*):512; disk(*):0; ports(*):[31000-32000] on slave 20140619-011635-453759884-48847-5135-1 (hemera.apache.org)
I0619 01:16:36.157809 5212 hierarchical_allocator_process.hpp:635] Recovered cpus(*):3; mem(*):2048; ports(*):[31000-32000] (total allocatable: cpus(*):3; mem(*):2048; disk(*):0; ports(*):[31000-32000]) on slave 20140619-011635-453759884-48847-5135-2 from framework 20140619-011635-453759884-48847-5135-0001
I0619 01:16:36.157866 5215 master.cpp:610] Master terminating
I0619 01:16:36.157901 5212 hierarchical_allocator_process.hpp:635] Recovered cpus(*):1; mem(*):512; ports(*):[31000-32000] (total allocatable: cpus(*):1; mem(*):512; disk(*):0; ports(*):[31000-32000]) on slave 20140619-011635-453759884-48847-5135-4 from framework 20140619-011635-453759884-48847-5135-0001
I0619 01:16:36.157915 5215 master.hpp:795] Removing offer 20140619-011635-453759884-48847-5135-3 with resources cpus(*):4; mem(*):4096; disk(*):0; ports(*):[31000-32000] on slave 20140619-011635-453759884-48847-5135-3 (hemera.apache.org)
I0619 01:16:36.158001 5212 hierarchical_allocator_process.hpp:635] Recovered cpus(*):1; mem(*):512; ports(*):[31000-32000] (total allocatable: cpus(*):1; mem(*):512; disk(*):0; ports(*):[31000-32000]) on slave 20140619-011635-453759884-48847-5135-1 from framework 20140619-011635-453759884-48847-5135-0001
I0619 01:16:36.158006 5215 master.hpp:795] Removing offer 20140619-011635-453759884-48847-5135-0 with resources cpus(*):2; mem(*):1024; disk(*):0; ports(*):[31000-32000] on slave 20140619-011635-453759884-48847-5135-0 (hemera.apache.org)
I0619 01:16:36.158051 5212 hierarchical_allocator_process.hpp:362] Removed framework 20140619-011635-453759884-48847-5135-0001
I0619 01:16:36.158604 5220 slave.cpp:2267] master@140.211.11.27:48847 exited
W0619 01:16:36.158630 5220 slave.cpp:2270] Master disconnected! Waiting for a new master to be elected
I0619 01:16:36.158639 5211 slave.cpp:2267] master@140.211.11.27:48847 exited
W0619 01:16:36.158659 5211 slave.cpp:2270] Master disconnected! Waiting for a new master to be elected
I0619 01:16:36.158711 5218 slave.cpp:2267] master@140.211.11.27:48847 exited
W0619 01:16:36.158735 5218 slave.cpp:2270] Master disconnected! Waiting for a new master to be elected
I0619 01:16:36.158752 5224 slave.cpp:2267] master@140.211.11.27:48847 exited
W0619 01:16:36.158769 5224 slave.cpp:2270] Master disconnected! Waiting for a new master to be elected
I0619 01:16:36.158778 5213 slave.cpp:2267] master@140.211.11.27:48847 exited
W0619 01:16:36.158794 5213 slave.cpp:2270] Master disconnected! Waiting for a new master to be elected
I0619 01:16:36.174202 5221 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 17.027155ms
I0619 01:16:36.174242 5221 replica.cpp:676] Persisted action at 12
I0619 01:16:36.175300 5135 slave.cpp:426] Slave terminating
I0619 01:16:36.177283 5135 slave.cpp:426] Slave terminating
I0619 01:16:36.178537 5232 slave.cpp:426] Slave terminating
I0619 01:16:36.180469 5209 slave.cpp:426] Slave terminating
I0619 01:16:36.181773 5135 slave.cpp:426] Slave terminating
[ OK ] DRFAllocatorTest.DRFAllocatorProcess (482 ms)
[----------] 1 test from DRFAllocatorTest (482 ms total)
[----------] Global test environment tear-down
[==========] 376 tests from 62 test cases ran. (381691 ms total)
[ PASSED ] 375 tests.
[ FAILED ] 1 test, listed below:
[ FAILED ] AllocatorZooKeeperTest/0.SlaveReregistersFirst, where TypeParam = mesos::internal::master::allocator::HierarchicalAllocatorProcess<mesos::internal::master::allocator::DRFSorter, mesos::internal::master::allocator::DRFSorter>
1 FAILED TEST
YOU HAVE 3 DISABLED TESTS
make[4]: *** [check-local] Error 1
make[4]: Leaving directory `/x1/jenkins/jenkins-slave/workspace/Mesos-Ubuntu-distcheck/build/mesos-0.20.0/_build/src'
make[3]: *** [check-am] Error 2
make[3]: Leaving directory `/x1/jenkins/jenkins-slave/workspace/Mesos-Ubuntu-distcheck/build/mesos-0.20.0/_build/src'
make[2]: *** [check] Error 2
make[2]: Leaving directory `/x1/jenkins/jenkins-slave/workspace/Mesos-Ubuntu-distcheck/build/mesos-0.20.0/_build/src'
make[1]: *** [check-recursive] Error 1
make[1]: Leaving directory `/x1/jenkins/jenkins-slave/workspace/Mesos-Ubuntu-distcheck/build/mesos-0.20.0/_build'
make: *** [distcheck] Error 1
Build step 'Execute shell' marked build as failure
Jenkins build is back to normal : Mesos-Ubuntu-distcheck #159
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://builds.apache.org/job/Mesos-Ubuntu-distcheck/159/changes>
Build failed in Jenkins: Mesos-Ubuntu-distcheck #158
Posted by Apache Jenkins Server <je...@builds.apache.org>.
See <https://builds.apache.org/job/Mesos-Ubuntu-distcheck/158/changes>
Changes:
[bmahler] Refactored os::user to return a Result.
[bmahler] Updated mesos to use refactored os::user call.
[vinod] Updated reviewbot to only build and test once.
------------------------------------------
[...truncated 57787 lines...]
I0619 02:34:05.628599 23997 exec.cpp:217] Executor::registered took 12455ns
I0619 02:34:05.628664 23997 exec.cpp:292] Executor asked to run task '1'
I0619 02:34:05.628702 23997 exec.cpp:301] Executor::launchTask took 23015ns
I0619 02:34:05.629223 23999 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 7.555962ms
I0619 02:34:05.629242 23999 replica.cpp:676] Persisted action at 4
I0619 02:34:05.629465 23993 replica.cpp:655] Replica received learned notice for position 4
I0619 02:34:05.630133 23997 exec.cpp:524] Executor sending status update TASK_RUNNING (UUID: 7d5ef0ee-0bf0-4d0b-8d0a-0c66e4df7845) for task 1 of framework 20140619-023405-1015726915-42911-23874-0000
I0619 02:34:05.630213 23997 slave.cpp:2024] Handling status update TASK_RUNNING (UUID: 7d5ef0ee-0bf0-4d0b-8d0a-0c66e4df7845) for task 1 of framework 20140619-023405-1015726915-42911-23874-0000 from executor(59)@67.195.138.60:42911
I0619 02:34:05.630318 23999 status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID: 7d5ef0ee-0bf0-4d0b-8d0a-0c66e4df7845) for task 1 of framework 20140619-023405-1015726915-42911-23874-0000
I0619 02:34:05.630338 23999 status_update_manager.cpp:499] Creating StatusUpdate stream for task 1 of framework 20140619-023405-1015726915-42911-23874-0000
I0619 02:34:05.630482 23999 status_update_manager.hpp:342] Checkpointing UPDATE for status update TASK_RUNNING (UUID: 7d5ef0ee-0bf0-4d0b-8d0a-0c66e4df7845) for task 1 of framework 20140619-023405-1015726915-42911-23874-0000
I0619 02:34:05.637545 23993 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 8.061805ms
I0619 02:34:05.637579 23993 leveldb.cpp:401] Deleting ~2 keys from leveldb took 16556ns
I0619 02:34:05.637590 23993 replica.cpp:676] Persisted action at 4
I0619 02:34:05.637600 23993 replica.cpp:661] Replica learned TRUNCATE action at position 4
I0619 02:34:05.716398 23999 status_update_manager.cpp:373] Forwarding status update TASK_RUNNING (UUID: 7d5ef0ee-0bf0-4d0b-8d0a-0c66e4df7845) for task 1 of framework 20140619-023405-1015726915-42911-23874-0000 to master@67.195.138.60:42911
I0619 02:34:05.716517 23998 slave.cpp:2182] Status update manager successfully handled status update TASK_RUNNING (UUID: 7d5ef0ee-0bf0-4d0b-8d0a-0c66e4df7845) for task 1 of framework 20140619-023405-1015726915-42911-23874-0000
I0619 02:34:05.716537 23998 slave.cpp:2188] Sending acknowledgement for status update TASK_RUNNING (UUID: 7d5ef0ee-0bf0-4d0b-8d0a-0c66e4df7845) for task 1 of framework 20140619-023405-1015726915-42911-23874-0000 to executor(59)@67.195.138.60:42911
I0619 02:34:05.716536 23997 master.cpp:3062] Status update TASK_RUNNING (UUID: 7d5ef0ee-0bf0-4d0b-8d0a-0c66e4df7845) for task 1 of framework 20140619-023405-1015726915-42911-23874-0000 from slave 20140619-023405-1015726915-42911-23874-0 at slave(184)@67.195.138.60:42911 (janus.apache.org)
I0619 02:34:05.716616 23997 exec.cpp:338] Executor received status update acknowledgement 7d5ef0ee-0bf0-4d0b-8d0a-0c66e4df7845 for task 1 of framework 20140619-023405-1015726915-42911-23874-0000
I0619 02:34:05.716644 23999 sched.cpp:637] Scheduler::statusUpdate took 50307ns
I0619 02:34:05.716704 23999 master.cpp:2586] Forwarding status update acknowledgement 7d5ef0ee-0bf0-4d0b-8d0a-0c66e4df7845 for task 1 of framework 20140619-023405-1015726915-42911-23874-0000 to slave 20140619-023405-1015726915-42911-23874-0 at slave(184)@67.195.138.60:42911 (janus.apache.org)
I0619 02:34:05.716835 23994 status_update_manager.cpp:398] Received status update acknowledgement (UUID: 7d5ef0ee-0bf0-4d0b-8d0a-0c66e4df7845) for task 1 of framework 20140619-023405-1015726915-42911-23874-0000
I0619 02:34:05.716858 23994 status_update_manager.hpp:342] Checkpointing ACK for status update TASK_RUNNING (UUID: 7d5ef0ee-0bf0-4d0b-8d0a-0c66e4df7845) for task 1 of framework 20140619-023405-1015726915-42911-23874-0000
I0619 02:34:05.761204 23994 slave.cpp:1610] Status update manager successfully handled status update acknowledgement (UUID: 7d5ef0ee-0bf0-4d0b-8d0a-0c66e4df7845) for task 1 of framework 20140619-023405-1015726915-42911-23874-0000
I0619 02:34:05.761960 23874 master.cpp:610] Master terminating
I0619 02:34:05.761962 23992 sched.cpp:747] Stopping framework '20140619-023405-1015726915-42911-23874-0000'
I0619 02:34:05.762033 23874 master.hpp:775] Removing task 1 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140619-023405-1015726915-42911-23874-0 (janus.apache.org)
W0619 02:34:05.762133 23874 master.cpp:4209] Removing task 1 of framework 20140619-023405-1015726915-42911-23874-0000 and slave 20140619-023405-1015726915-42911-23874-0 in non-terminal state TASK_RUNNING
I0619 02:34:05.762281 23994 hierarchical_allocator_process.hpp:635] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total allocatable: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]) on slave 20140619-023405-1015726915-42911-23874-0 from framework 20140619-023405-1015726915-42911-23874-0000
I0619 02:34:05.762330 23994 slave.cpp:2267] master@67.195.138.60:42911 exited
W0619 02:34:05.762346 23994 slave.cpp:2270] Master disconnected! Waiting for a new master to be elected
I0619 02:34:05.764117 23996 slave.cpp:2463] Executor 'default' of framework 20140619-023405-1015726915-42911-23874-0000 has exited with status 0
I0619 02:34:05.765401 23996 slave.cpp:2024] Handling status update TASK_LOST (UUID: aba7bc0d-ad1b-4068-93b2-0df0f913fc13) for task 1 of framework 20140619-023405-1015726915-42911-23874-0000 from @0.0.0.0:0
I0619 02:34:05.765427 23996 slave.cpp:3710] Terminating task 1
I0619 02:34:05.765563 23996 slave.cpp:426] Slave terminating
[ OK ] StatusUpdateManagerTest.CheckpointStatusUpdate (351 ms)
[----------] 7 tests from StatusUpdateManagerTest (2960 ms total)
[----------] 1 test from ZooKeeper
[ RUN ] ZooKeeper.URL
[ OK ] ZooKeeper.URL (0 ms)
[----------] 1 test from ZooKeeper (0 ms total)
[----------] 1 test from PerfTest
[ RUN ] PerfTest.Parse
W0619 02:34:05.767092 23874 perf.cpp:369] Unsupported perf counter, ignoring: <not supported>,cycles
[ OK ] PerfTest.Parse (1 ms)
[----------] 1 test from PerfTest (1 ms total)
[----------] 1 test from WhitelistTest
[ RUN ] WhitelistTest.WhitelistSlave
Using temporary directory '/tmp/WhitelistTest_WhitelistSlave_FRaqVH'
I0619 02:34:05.861855 23874 leveldb.cpp:176] Opened db in 93.947524ms
I0619 02:34:05.873539 23874 leveldb.cpp:183] Compacted db in 11.664291ms
I0619 02:34:05.873564 23874 leveldb.cpp:198] Created db iterator in 4137ns
I0619 02:34:05.873574 23874 leveldb.cpp:204] Seeked to beginning of db in 600ns
I0619 02:34:05.873580 23874 leveldb.cpp:273] Iterated through 0 keys in the db in 336ns
I0619 02:34:05.873594 23874 replica.cpp:741] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0619 02:34:05.873775 23999 recover.cpp:425] Starting replica recovery
I0619 02:34:05.873996 23998 recover.cpp:451] Replica is in EMPTY status
I0619 02:34:05.874450 23999 replica.cpp:638] Replica in EMPTY status received a broadcasted recover request
I0619 02:34:05.874569 23996 recover.cpp:188] Received a recover response from a replica in EMPTY status
I0619 02:34:05.874814 23992 recover.cpp:542] Updating replica status to STARTING
I0619 02:34:05.875092 23999 master.cpp:286] Master 20140619-023405-1015726915-42911-23874 (janus.apache.org) started on 67.195.138.60:42911
I0619 02:34:05.875111 23999 master.cpp:323] Master only allowing authenticated frameworks to register
I0619 02:34:05.875119 23999 master.cpp:328] Master only allowing authenticated slaves to register
I0619 02:34:05.875128 23999 credentials.hpp:35] Loading credentials for authentication from '/tmp/WhitelistTest_WhitelistSlave_FRaqVH/credentials'
I0619 02:34:05.875181 23999 master.cpp:354] Authorization enabled
I0619 02:34:05.875622 23995 hierarchical_allocator_process.hpp:301] Initializing hierarchical allocator process with master : master@67.195.138.60:42911
I0619 02:34:05.875987 23999 master.cpp:1077] The newly elected leader is master@67.195.138.60:42911 with id 20140619-023405-1015726915-42911-23874
I0619 02:34:05.876001 23999 master.cpp:1090] Elected as the leading master!
I0619 02:34:05.876011 23999 master.cpp:908] Recovering from registrar
I0619 02:34:05.876091 23999 registrar.cpp:313] Recovering registrar
I0619 02:34:05.876318 23995 hierarchical_allocator_process.hpp:511] Updated slave white list: { dummy-slave, janus.apache.org }
I0619 02:34:05.909519 23996 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 34.63532ms
I0619 02:34:05.909543 23996 replica.cpp:320] Persisted replica status to STARTING
I0619 02:34:05.909667 23997 recover.cpp:451] Replica is in STARTING status
I0619 02:34:05.910025 23998 replica.cpp:638] Replica in STARTING status received a broadcasted recover request
I0619 02:34:05.910176 23994 recover.cpp:188] Received a recover response from a replica in STARTING status
I0619 02:34:05.910342 23999 recover.cpp:542] Updating replica status to VOTING
I0619 02:34:05.920742 23994 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 10.339563ms
I0619 02:34:05.920764 23994 replica.cpp:320] Persisted replica status to VOTING
I0619 02:34:05.920835 23993 recover.cpp:556] Successfully joined the Paxos group
I0619 02:34:05.920943 23993 recover.cpp:440] Recover process terminated
I0619 02:34:05.921135 23996 log.cpp:656] Attempting to start the writer
I0619 02:34:05.921663 23999 replica.cpp:474] Replica received implicit promise request with proposal 1
I0619 02:34:05.929069 23999 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 7.389763ms
I0619 02:34:05.929090 23999 replica.cpp:342] Persisted promised to 1
I0619 02:34:05.929306 23999 coordinator.cpp:230] Coordinator attemping to fill missing position
I0619 02:34:05.929803 23994 replica.cpp:375] Replica received explicit promise request for position 0 with proposal 2
I0619 02:34:05.937399 23994 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 7.57489ms
I0619 02:34:05.937424 23994 replica.cpp:676] Persisted action at 0
I0619 02:34:05.937907 23999 replica.cpp:508] Replica received write request for position 0
I0619 02:34:05.937953 23999 leveldb.cpp:438] Reading position from leveldb took 12393ns
I0619 02:34:05.945716 23999 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 7.748567ms
I0619 02:34:05.945734 23999 replica.cpp:676] Persisted action at 0
I0619 02:34:05.945979 23994 replica.cpp:655] Replica received learned notice for position 0
I0619 02:34:05.954063 23994 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 8.061537ms
I0619 02:34:05.954082 23994 replica.cpp:676] Persisted action at 0
I0619 02:34:05.954092 23994 replica.cpp:661] Replica learned NOP action at position 0
I0619 02:34:05.954345 23994 log.cpp:672] Writer started with ending position 0
I0619 02:34:05.954859 23995 leveldb.cpp:438] Reading position from leveldb took 11570ns
I0619 02:34:05.956456 23993 registrar.cpp:346] Successfully fetched the registry (0B)
I0619 02:34:05.956485 23993 registrar.cpp:422] Attempting to update the 'registry'
I0619 02:34:05.957999 23997 log.cpp:680] Attempting to append 138 bytes to the log
I0619 02:34:05.958081 23992 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 1
I0619 02:34:05.958431 23993 replica.cpp:508] Replica received write request for position 1
I0619 02:34:05.962378 23993 leveldb.cpp:343] Persisting action (157 bytes) to leveldb took 3.927043ms
I0619 02:34:05.962395 23993 replica.cpp:676] Persisted action at 1
I0619 02:34:05.962607 23997 replica.cpp:655] Replica received learned notice for position 1
I0619 02:34:05.970712 23997 leveldb.cpp:343] Persisting action (159 bytes) to leveldb took 8.08204ms
I0619 02:34:05.970731 23997 replica.cpp:676] Persisted action at 1
I0619 02:34:05.970741 23997 replica.cpp:661] Replica learned APPEND action at position 1
I0619 02:34:05.971153 23997 registrar.cpp:479] Successfully updated 'registry'
I0619 02:34:05.971276 23997 registrar.cpp:372] Successfully recovered registrar
I0619 02:34:05.971326 23994 log.cpp:699] Attempting to truncate the log to 1
I0619 02:34:05.971420 23993 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 2
I0619 02:34:05.971413 23996 master.cpp:935] Recovered 0 slaves from the Registry (100B) ; allowing 10mins for slaves to re-register
I0619 02:34:05.971781 23996 replica.cpp:508] Replica received write request for position 2
I0619 02:34:05.972316 23874 mesos_containerizer.cpp:125] Using isolation: posix/cpu,posix/mem
I0619 02:34:05.974527 23992 slave.cpp:143] Slave started on 185)@67.195.138.60:42911
I0619 02:34:05.974547 23992 credentials.hpp:35] Loading credentials for authentication from '/tmp/WhitelistTest_WhitelistSlave_NBJsEx/credential'
I0619 02:34:05.974620 23992 slave.cpp:243] Slave using credential for: test-principal
I0619 02:34:05.974736 23992 slave.cpp:256] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0619 02:34:05.974762 23992 slave.cpp:284] Slave hostname: janus.apache.org
I0619 02:34:05.974769 23992 slave.cpp:285] Slave checkpoint: false
I0619 02:34:05.975391 23998 state.cpp:33] Recovering state from '/tmp/WhitelistTest_WhitelistSlave_NBJsEx/meta'
I0619 02:34:05.975517 23994 status_update_manager.cpp:193] Recovering status update manager
I0619 02:34:05.975612 23997 mesos_containerizer.cpp:283] Recovering containerizer
I0619 02:34:05.975822 23997 slave.cpp:3068] Finished recovery
I0619 02:34:05.976093 23994 slave.cpp:537] New master detected at master@67.195.138.60:42911
I0619 02:34:05.976125 23994 slave.cpp:613] Authenticating with master master@67.195.138.60:42911
I0619 02:34:05.976155 23998 status_update_manager.cpp:167] New master detected at master@67.195.138.60:42911
I0619 02:34:05.976184 23994 slave.cpp:586] Detecting new master
I0619 02:34:05.976198 23997 authenticatee.hpp:128] Creating new client SASL connection
I0619 02:34:05.976346 23994 master.cpp:3457] Authenticating slave(185)@67.195.138.60:42911
I0619 02:34:05.976425 23997 authenticator.hpp:156] Creating new server SASL connection
I0619 02:34:05.976526 23998 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
I0619 02:34:05.976543 23998 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
I0619 02:34:05.976577 23998 authenticator.hpp:262] Received SASL authentication start
I0619 02:34:05.976631 23998 authenticator.hpp:384] Authentication requires more steps
I0619 02:34:05.976666 23998 authenticatee.hpp:265] Received SASL authentication step
I0619 02:34:05.976709 23998 authenticator.hpp:290] Received SASL authentication step
I0619 02:34:05.976727 23998 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'janus.apache.org' server FQDN: 'janus.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0619 02:34:05.976734 23998 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I0619 02:34:05.976747 23998 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0619 02:34:05.976758 23998 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'janus.apache.org' server FQDN: 'janus.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0619 02:34:05.976765 23998 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0619 02:34:05.976773 23998 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0619 02:34:05.976786 23998 authenticator.hpp:376] Authentication success
I0619 02:34:05.976824 23997 authenticatee.hpp:305] Authentication success
I0619 02:34:05.976840 23998 master.cpp:3497] Successfully authenticated principal 'test-principal' at slave(185)@67.195.138.60:42911
I0619 02:34:05.976897 23997 slave.cpp:670] Successfully authenticated with master master@67.195.138.60:42911
I0619 02:34:05.976938 23997 slave.cpp:908] Will retry registration in 3.575922ms if necessary
I0619 02:34:05.976982 23998 master.cpp:2736] Registering slave at slave(185)@67.195.138.60:42911 (janus.apache.org) with id 20140619-023405-1015726915-42911-23874-0
I0619 02:34:05.977112 23993 registrar.cpp:422] Attempting to update the 'registry'
I0619 02:34:05.978946 23874 sched.cpp:139] Version: 0.20.0
I0619 02:34:05.979058 23996 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 7.259012ms
I0619 02:34:05.979076 23996 replica.cpp:676] Persisted action at 2
I0619 02:34:05.979200 23992 sched.cpp:235] New master detected at master@67.195.138.60:42911
I0619 02:34:05.979220 23992 sched.cpp:285] Authenticating with master master@67.195.138.60:42911
I0619 02:34:05.979318 23997 authenticatee.hpp:128] Creating new client SASL connection
I0619 02:34:05.979504 23996 master.cpp:3457] Authenticating scheduler-c00afd76-569e-41bc-a816-e60d23fcc92c@67.195.138.60:42911
I0619 02:34:05.979586 23999 replica.cpp:655] Replica received learned notice for position 2
I0619 02:34:05.979626 23993 authenticator.hpp:156] Creating new server SASL connection
I0619 02:34:05.979732 23997 authenticatee.hpp:219] Received SASL authentication mechanisms: CRAM-MD5
I0619 02:34:05.979753 23997 authenticatee.hpp:245] Attempting to authenticate with mechanism 'CRAM-MD5'
I0619 02:34:05.979785 23997 authenticator.hpp:262] Received SASL authentication start
I0619 02:34:05.979823 23997 authenticator.hpp:384] Authentication requires more steps
I0619 02:34:05.979856 23997 authenticatee.hpp:265] Received SASL authentication step
I0619 02:34:05.979899 23997 authenticator.hpp:290] Received SASL authentication step
I0619 02:34:05.979920 23997 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'janus.apache.org' server FQDN: 'janus.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0619 02:34:05.979929 23997 auxprop.cpp:153] Looking up auxiliary property '*userPassword'
I0619 02:34:05.979943 23997 auxprop.cpp:153] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0619 02:34:05.979954 23997 auxprop.cpp:81] Request to lookup properties for user: 'test-principal' realm: 'janus.apache.org' server FQDN: 'janus.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0619 02:34:05.979962 23997 auxprop.cpp:103] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0619 02:34:05.979969 23997 auxprop.cpp:103] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0619 02:34:05.979981 23997 authenticator.hpp:376] Authentication success
I0619 02:34:05.980018 23993 authenticatee.hpp:305] Authentication success
I0619 02:34:05.980031 23997 master.cpp:3497] Successfully authenticated principal 'test-principal' at scheduler-c00afd76-569e-41bc-a816-e60d23fcc92c@67.195.138.60:42911
I0619 02:34:05.980136 23995 sched.cpp:359] Successfully authenticated with master master@67.195.138.60:42911
I0619 02:34:05.980154 23995 sched.cpp:478] Sending registration request to master@67.195.138.60:42911
I0619 02:34:05.980212 23993 master.cpp:1196] Received registration request from scheduler-c00afd76-569e-41bc-a816-e60d23fcc92c@67.195.138.60:42911
I0619 02:34:05.980237 23993 master.cpp:1156] Authorizing framework principal 'test-principal' to receive offers for role '*'
I0619 02:34:05.980377 23997 master.cpp:1255] Registering framework 20140619-023405-1015726915-42911-23874-0000 at scheduler-c00afd76-569e-41bc-a816-e60d23fcc92c@67.195.138.60:42911
I0619 02:34:05.980448 23993 sched.cpp:409] Framework registered with 20140619-023405-1015726915-42911-23874-0000
I0619 02:34:05.980478 23992 hierarchical_allocator_process.hpp:331] Added framework 20140619-023405-1015726915-42911-23874-0000
I0619 02:34:05.980479 23993 sched.cpp:423] Scheduler::registered took 14927ns
I0619 02:34:05.980495 23992 hierarchical_allocator_process.hpp:724] No resources available to allocate!
I0619 02:34:05.980518 23992 hierarchical_allocator_process.hpp:686] Performed allocation for 0 slaves in 23075ns
I0619 02:34:05.981153 23997 slave.cpp:908] Will retry registration in 24.63161ms if necessary
I0619 02:34:05.981210 23997 master.cpp:2724] Ignoring register slave message from slave(185)@67.195.138.60:42911 (janus.apache.org) as admission is already in progress
I0619 02:34:05.987375 23999 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 7.772958ms
I0619 02:34:05.987409 23999 leveldb.cpp:401] Deleting ~1 keys from leveldb took 14021ns
I0619 02:34:05.987421 23999 replica.cpp:676] Persisted action at 2
I0619 02:34:05.987431 23999 replica.cpp:661] Replica learned TRUNCATE action at position 2
I0619 02:34:05.987716 23999 log.cpp:680] Attempting to append 331 bytes to the log
I0619 02:34:05.987789 23995 coordinator.cpp:340] Coordinator attempting to write APPEND action at position 3
I0619 02:34:05.988085 23999 replica.cpp:508] Replica received write request for position 3
I0619 02:34:05.995704 23999 leveldb.cpp:343] Persisting action (350 bytes) to leveldb took 7.602868ms
I0619 02:34:05.995724 23999 replica.cpp:676] Persisted action at 3
I0619 02:34:05.995961 23998 replica.cpp:655] Replica received learned notice for position 3
I0619 02:34:06.004034 23998 leveldb.cpp:343] Persisting action (352 bytes) to leveldb took 8.05786ms
I0619 02:34:06.004055 23998 replica.cpp:676] Persisted action at 3
I0619 02:34:06.004065 23998 replica.cpp:661] Replica learned APPEND action at position 3
I0619 02:34:06.004442 23998 registrar.cpp:479] Successfully updated 'registry'
I0619 02:34:06.004480 23993 log.cpp:699] Attempting to truncate the log to 3
I0619 02:34:06.004582 23996 coordinator.cpp:340] Coordinator attempting to write TRUNCATE action at position 4
I0619 02:34:06.004720 23993 master.cpp:2776] Registered slave 20140619-023405-1015726915-42911-23874-0 at slave(185)@67.195.138.60:42911 (janus.apache.org)
I0619 02:34:06.004732 23993 master.cpp:3923] Adding slave 20140619-023405-1015726915-42911-23874-0 at slave(185)@67.195.138.60:42911 (janus.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I0619 02:34:06.004822 23997 slave.cpp:704] Registered with master master@67.195.138.60:42911; given slave ID 20140619-023405-1015726915-42911-23874-0
I0619 02:34:06.004941 23999 hierarchical_allocator_process.hpp:444] Added slave 20140619-023405-1015726915-42911-23874-0 (janus.apache.org) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (and cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] available)
I0619 02:34:06.005007 23999 hierarchical_allocator_process.hpp:750] Offering cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140619-023405-1015726915-42911-23874-0 to framework 20140619-023405-1015726915-42911-23874-0000
I0619 02:34:06.005105 23995 replica.cpp:508] Replica received write request for position 4
I0619 02:34:06.005148 23999 hierarchical_allocator_process.hpp:706] Performed allocation for slave 20140619-023405-1015726915-42911-23874-0 in 169051ns
I0619 02:34:06.005230 23996 master.hpp:785] Adding offer 20140619-023405-1015726915-42911-23874-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140619-023405-1015726915-42911-23874-0 (janus.apache.org)
I0619 02:34:06.005285 23996 master.cpp:3404] Sending 1 offers to framework 20140619-023405-1015726915-42911-23874-0000
I0619 02:34:06.005415 23999 sched.cpp:546] Scheduler::resourceOffers took 28562ns
I0619 02:34:06.005529 23874 master.cpp:610] Master terminating
I0619 02:34:06.005561 23999 sched.cpp:747] Stopping framework '20140619-023405-1015726915-42911-23874-0000'
I0619 02:34:06.005594 23874 master.hpp:795] Removing offer 20140619-023405-1015726915-42911-23874-0 with resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 20140619-023405-1015726915-42911-23874-0 (janus.apache.org)
I0619 02:34:06.006551 23999 slave.cpp:2267] master@67.195.138.60:42911 exited
W0619 02:34:06.006572 23999 slave.cpp:2270] Master disconnected! Waiting for a new master to be elected
I0619 02:34:06.012389 23995 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 7.243448ms
I0619 02:34:06.012409 23995 replica.cpp:676] Persisted action at 4
I0619 02:34:06.012964 23874 slave.cpp:426] Slave terminating
[ OK ] WhitelistTest.WhitelistSlave (247 ms)
[----------] 1 test from WhitelistTest (247 ms total)
[----------] Global test environment tear-down
[==========] 376 tests from 62 test cases ran. (334513 ms total)
[ PASSED ] 375 tests.
[ FAILED ] 1 test, listed below:
[ FAILED ] AllocatorZooKeeperTest/0.FrameworkReregistersFirst, where TypeParam = mesos::internal::master::allocator::HierarchicalAllocatorProcess<mesos::internal::master::allocator::DRFSorter, mesos::internal::master::allocator::DRFSorter>
1 FAILED TEST
YOU HAVE 3 DISABLED TESTS
make[4]: *** [check-local] Error 1
make[4]: Leaving directory `<https://builds.apache.org/job/Mesos-Ubuntu-distcheck/ws/build/mesos-0.20.0/_build/src'>
make[3]: *** [check-am] Error 2
make[3]: Leaving directory `<https://builds.apache.org/job/Mesos-Ubuntu-distcheck/ws/build/mesos-0.20.0/_build/src'>
make[2]: *** [check] Error 2
make[2]: Leaving directory `<https://builds.apache.org/job/Mesos-Ubuntu-distcheck/ws/build/mesos-0.20.0/_build/src'>
make[1]: *** [check-recursive] Error 1
make[1]: Leaving directory `<https://builds.apache.org/job/Mesos-Ubuntu-distcheck/ws/build/mesos-0.20.0/_build'>
make: *** [distcheck] Error 1
Build step 'Execute shell' marked build as failure