@idownes: Can you take a look? Don't think we have seen this before. I0926 18:44:19.449905 2941 launcher.cpp:137] Forked child with pid '2960' for container '13af5d4f-ac1f-41e0-a708-4e0984a240a9' I0926 18:44:19.450646 2946 launcher.cpp:137] Forked child with pid '2961' for container '6f1d854c-3134-4d7f-87a7-0d62ecc7c559' I0926 18:44:19.451575 2945 launcher.cpp:137] Forked child with pid '2962' for container 'df8e9e17-8fba-4bd9-a1f7-3e27e1f2ce2b' I0926 18:44:19.452193 2946 containerizer.cpp:510] Fetching URIs for container '6f1d854c-3134-4d7f-87a7-0d62ecc7c559' using command '/home/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/build/src/mesos-fetcher' I0926 18:44:19.452507 2945 containerizer.cpp:510] Fetching URIs for container 'df8e9e17-8fba-4bd9-a1f7-3e27e1f2ce2b' using command '/home/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/build/src/mesos-fetcher' I0926 18:44:19.452527 2941 containerizer.cpp:510] Fetching URIs for container '13af5d4f-ac1f-41e0-a708-4e0984a240a9' using command '/home/jenkins/jenkins-slave/workspace/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/build/src/mesos-fetcher' chown: changing ownership of '/tmp/mesos-u7FCJx/0/slaves/20140926-184414-3176252227-35391-2913-1/frameworks/20140926-184414-3176252227-35391-2913-0000/executors/default/runs/6f1d854c-3134-4d7f-87a7-0d62ecc7c559/stderr': Operation not permitted I0926 18:44:19.463068 2946 containerizer.cpp:882] Destroying container '6f1d854c-3134-4d7f-87a7-0d62ecc7c559' E0926 18:44:19.463068 2937 slave.cpp:2564] Container '6f1d854c-3134-4d7f-87a7-0d62ecc7c559' for executor 'default' of framework '20140926-184414-3176252227-35391-2913-0000' failed to start: Failed to redirect stderr: Failed to chown: Failed to execute 'chown -R 0:2395 '/tmp/mesos-u7FCJx/0/slaves/20140926-184414-3176252227-35391-2913-1/frameworks/20140926-184414-3176252227-35391-2913-0000/executors/default/runs/6f1d854c-3134-4d7f-87a7-0d62ecc7c559/stderr'' (exit status: 256): Success I0926 18:44:19.550873 2943 containerizer.cpp:997] Executor for container '6f1d854c-3134-4d7f-87a7-0d62ecc7c559' has exited I0926 18:44:19.552175 2948 slave.cpp:2675] Executor 'default' of framework 20140926-184414-3176252227-35391-2913-0000 terminated with signal Killed E0926 18:44:19.552392 2949 slave.cpp:2945] Failed to unmonitor container for executor default of framework 20140926-184414-3176252227-35391-2913-0000: Not monitored
On Fri, Sep 26, 2014 at 11:49 AM, Apache Jenkins Server < [email protected]> wrote: > See < > https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/2396/changes > > > > Changes: > > [idownes] Dynamically change poll interval in the reaper. > > ------------------------------------------ > [...truncated 60663 lines...] > I0926 18:48:24.275391 2615 slave.cpp:169] Slave started on 211)@ > 67.195.81.189:40593 > I0926 18:48:24.275414 2615 credentials.hpp:84] Loading credential for > authentication from > '/tmp/AllocatorTest_0_SchedulerFailover_VehnAb/credential' > I0926 18:48:24.275486 2615 slave.cpp:276] Slave using credential for: > test-principal > I0926 18:48:24.275574 2615 slave.cpp:289] Slave resources: cpus(*):3; > mem(*):1024; disk(*):3.70122e+06; ports(*):[31000-32000] > I0926 18:48:24.275625 2615 slave.cpp:317] Slave hostname: > proserpina.apache.org > I0926 18:48:24.275635 2615 slave.cpp:318] Slave checkpoint: false > I0926 18:48:24.275926 2611 state.cpp:33] Recovering state from > '/tmp/AllocatorTest_0_SchedulerFailover_VehnAb/meta' > I0926 18:48:24.276057 2619 status_update_manager.cpp:193] Recovering > status update manager > I0926 18:48:24.276173 2618 slave.cpp:3277] Finished recovery > I0926 18:48:24.276412 2618 slave.cpp:604] New master detected at > [email protected]:40593 > I0926 18:48:24.276444 2618 slave.cpp:678] Authenticating with master > [email protected]:40593 > I0926 18:48:24.276459 2619 status_update_manager.cpp:167] New master > detected at [email protected]:40593 > I0926 18:48:24.276496 2618 slave.cpp:651] Detecting new master > I0926 18:48:24.276500 2619 authenticatee.hpp:128] Creating new client > SASL connection > I0926 18:48:24.276595 2612 master.cpp:3737] Authenticating slave(211)@ > 67.195.81.189:40593 > I0926 18:48:24.276664 2611 authenticator.hpp:156] Creating new server > SASL connection > I0926 18:48:24.276741 2605 authenticatee.hpp:219] Received SASL > authentication mechanisms: CRAM-MD5 > I0926 18:48:24.276763 2605 authenticatee.hpp:245] Attempting to > authenticate with mechanism 'CRAM-MD5' > I0926 18:48:24.276793 2605 authenticator.hpp:262] Received SASL > authentication start > I0926 18:48:24.276834 2605 authenticator.hpp:384] Authentication requires > more steps > I0926 18:48:24.276877 2611 authenticatee.hpp:265] Received SASL > authentication step > I0926 18:48:24.276923 2611 authenticator.hpp:290] Received SASL > authentication step > I0926 18:48:24.277535 2591 sched.cpp:137] Version: 0.21.0 > I0926 18:48:24.313247 2611 auxprop.cpp:81] Request to lookup properties > for user: 'test-principal' realm: 'proserpina.apache.org' server FQDN: ' > proserpina.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false > SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false > I0926 18:48:24.313259 2611 auxprop.cpp:153] Looking up auxiliary property > '*userPassword' > I0926 18:48:24.313271 2611 auxprop.cpp:153] Looking up auxiliary property > '*cmusaslsecretCRAM-MD5' > I0926 18:48:24.313287 2611 auxprop.cpp:81] Request to lookup properties > for user: 'test-principal' realm: 'proserpina.apache.org' server FQDN: ' > proserpina.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false > SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true > I0926 18:48:24.313297 2611 auxprop.cpp:103] Skipping auxiliary property > '*userPassword' since SASL_AUXPROP_AUTHZID == true > I0926 18:48:24.313304 2611 auxprop.cpp:103] Skipping auxiliary property > '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true > I0926 18:48:24.313319 2611 authenticator.hpp:376] Authentication success > I0926 18:48:24.313382 2616 sched.cpp:233] New master detected at > [email protected]:40593 > I0926 18:48:24.313397 2611 master.cpp:3777] Successfully authenticated > principal 'test-principal' at slave(211)@67.195.81.189:40593 > I0926 18:48:24.313403 2616 sched.cpp:283] Authenticating with master > [email protected]:40593 > I0926 18:48:24.313405 2608 authenticatee.hpp:305] Authentication success > I0926 18:48:24.313529 2610 authenticatee.hpp:128] Creating new client > SASL connection > I0926 18:48:24.313558 2611 slave.cpp:735] Successfully authenticated with > master [email protected]:40593 > I0926 18:48:24.313606 2611 slave.cpp:998] Will retry registration in > 1.907537ms if necessary > I0926 18:48:24.313635 2617 master.cpp:3737] Authenticating > [email protected]:40593 > I0926 18:48:24.313694 2610 authenticator.hpp:156] Creating new server > SASL connection > I0926 18:48:24.313752 2617 master.cpp:2930] Registering slave at > slave(211)@67.195.81.189:40593 (proserpina.apache.org) with id > 20140926-184824-3176252227-40593-2591-0 > I0926 18:48:24.313763 2620 authenticatee.hpp:219] Received SASL > authentication mechanisms: CRAM-MD5 > I0926 18:48:24.313786 2620 authenticatee.hpp:245] Attempting to > authenticate with mechanism 'CRAM-MD5' > I0926 18:48:24.313823 2620 authenticator.hpp:262] Received SASL > authentication start > I0926 18:48:24.313864 2620 authenticator.hpp:384] Authentication requires > more steps > I0926 18:48:24.313866 2610 registrar.cpp:422] Attempting to update the > 'registry' > I0926 18:48:24.313897 2620 authenticatee.hpp:265] Received SASL > authentication step > I0926 18:48:24.313952 2612 authenticator.hpp:290] Received SASL > authentication step > I0926 18:48:24.313974 2612 auxprop.cpp:81] Request to lookup properties > for user: 'test-principal' realm: 'proserpina.apache.org' server FQDN: ' > proserpina.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false > SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false > I0926 18:48:24.313982 2612 auxprop.cpp:153] Looking up auxiliary property > '*userPassword' > I0926 18:48:24.313990 2612 auxprop.cpp:153] Looking up auxiliary property > '*cmusaslsecretCRAM-MD5' > I0926 18:48:24.313997 2612 auxprop.cpp:81] Request to lookup properties > for user: 'test-principal' realm: 'proserpina.apache.org' server FQDN: ' > proserpina.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false > SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true > I0926 18:48:24.314003 2612 auxprop.cpp:103] Skipping auxiliary property > '*userPassword' since SASL_AUXPROP_AUTHZID == true > I0926 18:48:24.314008 2612 auxprop.cpp:103] Skipping auxiliary property > '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true > I0926 18:48:24.314018 2612 authenticator.hpp:376] Authentication success > I0926 18:48:24.314055 2620 authenticatee.hpp:305] Authentication success > I0926 18:48:24.314076 2612 master.cpp:3777] Successfully authenticated > principal 'test-principal' at > [email protected]:40593 > I0926 18:48:24.314169 2609 sched.cpp:357] Successfully authenticated with > master [email protected]:40593 > I0926 18:48:24.314188 2609 sched.cpp:476] Sending registration request to > [email protected]:40593 > I0926 18:48:24.314260 2615 master.cpp:1360] Received registration request > from [email protected]:40593 > I0926 18:48:24.314285 2615 master.cpp:1320] Authorizing framework > principal 'test-principal' to receive offers for role '*' > I0926 18:48:24.314393 2620 master.cpp:1419] Registering framework > 20140926-184824-3176252227-40593-2591-0000 at > [email protected]:40593 > I0926 18:48:24.314474 2608 sched.cpp:407] Framework registered with > 20140926-184824-3176252227-40593-2591-0000 > I0926 18:48:24.314510 2608 sched.cpp:421] Scheduler::registered took > 17387ns > I0926 18:48:24.314559 2608 hierarchical_allocator_process.hpp:329] Added > framework 20140926-184824-3176252227-40593-2591-0000 > I0926 18:48:24.314576 2608 hierarchical_allocator_process.hpp:697] No > resources available to allocate! > I0926 18:48:24.314587 2608 hierarchical_allocator_process.hpp:659] > Performed allocation for 0 slaves in 11731ns > I0926 18:48:24.314965 2614 log.cpp:680] Attempting to append 344 bytes to > the log > I0926 18:48:24.315013 2609 coordinator.cpp:340] Coordinator attempting to > write APPEND action at position 3 > I0926 18:48:24.315323 2605 replica.cpp:508] Replica received write > request for position 3 > I0926 18:48:24.315490 2605 leveldb.cpp:343] Persisting action (363 bytes) > to leveldb took 148761ns > I0926 18:48:24.315505 2605 replica.cpp:676] Persisted action at 3 > I0926 18:48:24.315718 2608 replica.cpp:655] Replica received learned > notice for position 3 > I0926 18:48:24.315816 2619 slave.cpp:998] Will retry registration in > 26.895354ms if necessary > I0926 18:48:24.315847 2617 master.cpp:2918] Ignoring register slave > message from slave(211)@67.195.81.189:40593 (proserpina.apache.org) as > admission is already in progress > I0926 18:48:24.316205 2608 leveldb.cpp:343] Persisting action (365 bytes) > to leveldb took 467558ns > I0926 18:48:24.316226 2608 replica.cpp:676] Persisted action at 3 > I0926 18:48:24.316238 2608 replica.cpp:661] Replica learned APPEND action > at position 3 > I0926 18:48:24.316515 2607 registrar.cpp:479] Successfully updated > 'registry' > I0926 18:48:24.316582 2617 log.cpp:699] Attempting to truncate the log to > 3 > I0926 18:48:24.316606 2620 master.cpp:2970] Registered slave > 20140926-184824-3176252227-40593-2591-0 at slave(211)@67.195.81.189:40593 > (proserpina.apache.org) > I0926 18:48:24.316632 2614 coordinator.cpp:340] Coordinator attempting to > write TRUNCATE action at position 4 > I0926 18:48:24.316623 2620 master.cpp:4180] Adding slave > 20140926-184824-3176252227-40593-2591-0 at slave(211)@67.195.81.189:40593 > (proserpina.apache.org) with cpus(*):3; mem(*):1024; disk(*):3.70122e+06; > ports(*):[31000-32000] > I0926 18:48:24.316707 2619 slave.cpp:769] Registered with master > [email protected]:40593; given slave ID > 20140926-184824-3176252227-40593-2591-0 > I0926 18:48:24.316754 2619 slave.cpp:2351] Received ping from > slave-observer(188)@67.195.81.189:40593 > I0926 18:48:24.316896 2615 hierarchical_allocator_process.hpp:442] Added > slave 20140926-184824-3176252227-40593-2591-0 (proserpina.apache.org) > with cpus(*):3; mem(*):1024; disk(*):3.70122e+06; ports(*):[31000-32000] > (and cpus(*):3; mem(*):1024; disk(*):3.70122e+06; ports(*):[31000-32000] > available) > I0926 18:48:24.317070 2612 replica.cpp:508] Replica received write > request for position 4 > I0926 18:48:24.317078 2615 hierarchical_allocator_process.hpp:734] > Offering cpus(*):3; mem(*):1024; disk(*):3.70122e+06; > ports(*):[31000-32000] on slave 20140926-184824-3176252227-40593-2591-0 to > framework 20140926-184824-3176252227-40593-2591-0000 > I0926 18:48:24.317183 2615 hierarchical_allocator_process.hpp:679] > Performed allocation for slave 20140926-184824-3176252227-40593-2591-0 in > 200099ns > I0926 18:48:24.317219 2618 master.hpp:868] Adding offer > 20140926-184824-3176252227-40593-2591-0 with resources cpus(*):3; > mem(*):1024; disk(*):3.70122e+06; ports(*):[31000-32000] on slave > 20140926-184824-3176252227-40593-2591-0 (proserpina.apache.org) > I0926 18:48:24.317471 2612 leveldb.cpp:343] Persisting action (16 bytes) > to leveldb took 381928ns > I0926 18:48:24.459338 2612 replica.cpp:676] Persisted action at 4 > I0926 18:48:24.459374 2618 master.cpp:3679] Sending 1 offers to framework > 20140926-184824-3176252227-40593-2591-0000 > I0926 18:48:24.459640 2611 replica.cpp:655] Replica received learned > notice for position 4 > I0926 18:48:24.459707 2618 sched.cpp:544] Scheduler::resourceOffers took > 168497ns > I0926 18:48:24.459892 2605 master.hpp:877] Removing offer > 20140926-184824-3176252227-40593-2591-0 with resources cpus(*):3; > mem(*):1024; disk(*):3.70122e+06; ports(*):[31000-32000] on slave > 20140926-184824-3176252227-40593-2591-0 (proserpina.apache.org) > I0926 18:48:24.459941 2605 master.cpp:2274] Processing reply for offers: > [ 20140926-184824-3176252227-40593-2591-0 ] on slave > 20140926-184824-3176252227-40593-2591-0 at slave(211)@67.195.81.189:40593 > (proserpina.apache.org) for framework > 20140926-184824-3176252227-40593-2591-0000 > W0926 18:48:24.459969 2605 master.cpp:1944] 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. > W0926 18:48:24.459982 2605 master.cpp:1955] 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. > I0926 18:48:24.459993 2605 master.cpp:2357] Authorizing framework > principal 'test-principal' to launch task 0 as user 'user1' > I0926 18:48:24.460170 2611 leveldb.cpp:343] Persisting action (18 bytes) > to leveldb took 512044ns > I0926 18:48:24.460202 2611 leveldb.cpp:401] Deleting ~2 keys from leveldb > took 15974ns > I0926 18:48:24.460211 2611 replica.cpp:676] Persisted action at 4 > I0926 18:48:24.460221 2611 replica.cpp:661] Replica learned TRUNCATE > action at position 4 > I0926 18:48:24.460283 2608 master.hpp:845] Adding task 0 with resources > cpus(*):1; mem(*):256 on slave 20140926-184824-3176252227-40593-2591-0 ( > proserpina.apache.org) > I0926 18:48:24.460316 2608 master.cpp:2423] Launching task 0 of framework > 20140926-184824-3176252227-40593-2591-0000 with resources cpus(*):1; > mem(*):256 on slave 20140926-184824-3176252227-40593-2591-0 at slave(211)@ > 67.195.81.189:40593 (proserpina.apache.org) > I0926 18:48:24.460436 2616 slave.cpp:1029] Got assigned task 0 for > framework 20140926-184824-3176252227-40593-2591-0000 > I0926 18:48:24.460650 2616 slave.cpp:1139] Launching task 0 for framework > 20140926-184824-3176252227-40593-2591-0000 > I0926 18:48:24.460657 2612 hierarchical_allocator_process.hpp:563] > Recovered cpus(*):2; mem(*):768; disk(*):3.70122e+06; > ports(*):[31000-32000] (total allocatable: cpus(*):2; mem(*):768; > disk(*):3.70122e+06; ports(*):[31000-32000]) on slave > 20140926-184824-3176252227-40593-2591-0 from framework > 20140926-184824-3176252227-40593-2591-0000 > I0926 18:48:24.462682 2616 exec.cpp:132] Version: 0.21.0 > I0926 18:48:24.462780 2611 exec.cpp:182] Executor started at: > executor(68)@67.195.81.189:40593 with pid 2591 > I0926 18:48:24.462782 2616 slave.cpp:1252] Queuing task '0' for executor > default of framework '20140926-184824-3176252227-40593-2591-0000 > I0926 18:48:24.462833 2616 slave.cpp:560] Successfully attached file > '/tmp/AllocatorTest_0_SchedulerFailover_VehnAb/slaves/20140926-184824-3176252227-40593-2591-0/frameworks/20140926-184824-3176252227-40593-2591-0000/executors/default/runs/3d85c1fe-ab3c-459d-bb68-0d67532adb2b' > I0926 18:48:24.462863 2616 slave.cpp:2617] Monitoring executor 'default' > of framework '20140926-184824-3176252227-40593-2591-0000' in container > '3d85c1fe-ab3c-459d-bb68-0d67532adb2b' > I0926 18:48:24.462921 2616 slave.cpp:1762] Got registration for executor > 'default' of framework 20140926-184824-3176252227-40593-2591-0000 from > executor(68)@67.195.81.189:40593 > I0926 18:48:24.463016 2616 slave.cpp:1881] Flushing queued task 0 for > executor 'default' of framework 20140926-184824-3176252227-40593-2591-0000 > I0926 18:48:24.463088 2610 exec.cpp:206] Executor registered on slave > 20140926-184824-3176252227-40593-2591-0 > I0926 18:48:24.464265 2610 exec.cpp:218] Executor::registered took 14605ns > I0926 18:48:24.464336 2610 exec.cpp:293] Executor asked to run task '0' > I0926 18:48:24.464377 2610 exec.cpp:302] Executor::launchTask took 24488ns > I0926 18:48:24.464560 2606 sched.cpp:745] Stopping framework > '20140926-184824-3176252227-40593-2591-0000' > I0926 18:48:24.464640 2607 master.cpp:767] Framework > 20140926-184824-3176252227-40593-2591-0000 disconnected > I0926 18:48:24.464658 2607 master.cpp:1705] Disconnecting framework > 20140926-184824-3176252227-40593-2591-0000 > I0926 18:48:24.464669 2607 master.cpp:1721] Deactivating framework > 20140926-184824-3176252227-40593-2591-0000 > I0926 18:48:24.464689 2607 master.cpp:789] Giving framework > 20140926-184824-3176252227-40593-2591-0000 10secs to failover > I0926 18:48:24.464763 2610 hierarchical_allocator_process.hpp:405] > Deactivated framework 20140926-184824-3176252227-40593-2591-0000 > I0926 18:48:24.466629 2591 sched.cpp:137] Version: 0.21.0 > I0926 18:48:24.466871 2620 sched.cpp:233] New master detected at > [email protected]:40593 > I0926 18:48:24.466887 2620 sched.cpp:283] Authenticating with master > [email protected]:40593 > I0926 18:48:24.466950 2618 authenticatee.hpp:128] Creating new client > SASL connection > I0926 18:48:24.467051 2614 master.cpp:3737] Authenticating > [email protected]:40593 > I0926 18:48:24.467113 2618 authenticator.hpp:156] Creating new server > SASL connection > I0926 18:48:24.467175 2620 authenticatee.hpp:219] Received SASL > authentication mechanisms: CRAM-MD5 > I0926 18:48:24.467191 2620 authenticatee.hpp:245] Attempting to > authenticate with mechanism 'CRAM-MD5' > I0926 18:48:24.467234 2606 authenticator.hpp:262] Received SASL > authentication start > I0926 18:48:24.467272 2606 authenticator.hpp:384] Authentication requires > more steps > I0926 18:48:24.467303 2606 authenticatee.hpp:265] Received SASL > authentication step > I0926 18:48:24.467352 2618 authenticator.hpp:290] Received SASL > authentication step > I0926 18:48:24.467373 2618 auxprop.cpp:81] Request to lookup properties > for user: 'test-principal' realm: 'proserpina.apache.org' server FQDN: ' > proserpina.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false > SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false > I0926 18:48:24.467381 2618 auxprop.cpp:153] Looking up auxiliary property > '*userPassword' > I0926 18:48:24.467392 2618 auxprop.cpp:153] Looking up auxiliary property > '*cmusaslsecretCRAM-MD5' > I0926 18:48:24.467401 2618 auxprop.cpp:81] Request to lookup properties > for user: 'test-principal' realm: 'proserpina.apache.org' server FQDN: ' > proserpina.apache.org' SASL_AUXPROP_VERIFY_AGAINST_HASH: false > SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true > I0926 18:48:24.467406 2618 auxprop.cpp:103] Skipping auxiliary property > '*userPassword' since SASL_AUXPROP_AUTHZID == true > I0926 18:48:24.467411 2618 auxprop.cpp:103] Skipping auxiliary property > '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true > I0926 18:48:24.467422 2618 authenticator.hpp:376] Authentication success > I0926 18:48:24.467459 2606 authenticatee.hpp:305] Authentication success > I0926 18:48:24.467473 2618 master.cpp:3777] Successfully authenticated > principal 'test-principal' at > [email protected]:40593 > I0926 18:48:24.467567 2606 sched.cpp:357] Successfully authenticated with > master [email protected]:40593 > I0926 18:48:24.467581 2606 sched.cpp:476] Sending registration request to > [email protected]:40593 > I0926 18:48:24.467634 2619 master.cpp:1484] Received re-registration > request from framework 20140926-184824-3176252227-40593-2591-0000 at > [email protected]:40593 > I0926 18:48:24.536190 2619 master.cpp:1320] Authorizing framework > principal 'test-principal' to receive offers for role '*' > I0926 18:48:24.536344 2610 master.cpp:1535] Re-registering framework > 20140926-184824-3176252227-40593-2591-0000 at > [email protected]:40593 > I0926 18:48:24.536370 2610 master.cpp:1562] Framework > 20140926-184824-3176252227-40593-2591-0000 failed over > I0926 18:48:24.536478 2615 sched.cpp:407] Framework registered with > 20140926-184824-3176252227-40593-2591-0000 > I0926 18:48:24.536512 2615 sched.cpp:421] Scheduler::registered took > 15541ns > I0926 18:48:24.536559 2616 slave.cpp:1612] Updating framework > 20140926-184824-3176252227-40593-2591-0000 pid to > [email protected]:40593 > I0926 18:48:24.536576 2619 hierarchical_allocator_process.hpp:375] > Activated framework 20140926-184824-3176252227-40593-2591-0000 > I0926 18:48:24.536625 2619 hierarchical_allocator_process.hpp:734] > Offering cpus(*):2; mem(*):768; disk(*):3.70122e+06; ports(*):[31000-32000] > on slave 20140926-184824-3176252227-40593-2591-0 to framework > 20140926-184824-3176252227-40593-2591-0000 > I0926 18:48:24.536715 2619 hierarchical_allocator_process.hpp:659] > Performed allocation for 1 slaves in 122571ns > I0926 18:48:24.536758 2619 master.hpp:868] Adding offer > 20140926-184824-3176252227-40593-2591-1 with resources cpus(*):2; > mem(*):768; disk(*):3.70122e+06; ports(*):[31000-32000] on slave > 20140926-184824-3176252227-40593-2591-0 (proserpina.apache.org) > I0926 18:48:24.536811 2619 master.cpp:3679] Sending 1 offers to framework > 20140926-184824-3176252227-40593-2591-0000 > I0926 18:48:24.536943 2616 sched.cpp:544] Scheduler::resourceOffers took > 18954ns > I0926 18:48:24.537188 2607 master.cpp:676] Master terminating > I0926 18:48:24.537188 2614 sched.cpp:745] Stopping framework > '20140926-184824-3176252227-40593-2591-0000' > W0926 18:48:24.537230 2607 master.cpp:4471] Removing task 0 with > resources cpus(*):1; mem(*):256 of framework > 20140926-184824-3176252227-40593-2591-0000 on slave > 20140926-184824-3176252227-40593-2591-0 at slave(211)@67.195.81.189:40593 > (proserpina.apache.org) in non-terminal state TASK_STAGING > I0926 18:48:24.537313 2607 master.cpp:4514] Removing executor 'default' > with resources of framework 20140926-184824-3176252227-40593-2591-0000 on > slave 20140926-184824-3176252227-40593-2591-0 at slave(211)@ > 67.195.81.189:40593 (proserpina.apache.org) > I0926 18:48:24.537369 2607 master.hpp:877] Removing offer > 20140926-184824-3176252227-40593-2591-1 with resources cpus(*):2; > mem(*):768; disk(*):3.70122e+06; ports(*):[31000-32000] on slave > 20140926-184824-3176252227-40593-2591-0 (proserpina.apache.org) > I0926 18:48:24.537400 2611 hierarchical_allocator_process.hpp:563] > Recovered cpus(*):1; mem(*):256 (total allocatable: cpus(*):1; mem(*):256) > on slave 20140926-184824-3176252227-40593-2591-0 from framework > 20140926-184824-3176252227-40593-2591-0000 > I0926 18:48:24.537518 2607 slave.cpp:2436] [email protected]:40593 > exited > W0926 18:48:24.537531 2607 slave.cpp:2439] Master disconnected! Waiting > for a new master to be elected > I0926 18:48:24.538852 2617 slave.cpp:2675] Executor 'default' of > framework 20140926-184824-3176252227-40593-2591-0000 exited with status 0 > I0926 18:48:24.539633 2617 slave.cpp:2115] Handling status update > TASK_LOST (UUID: 93135ada-0709-41ed-ac3a-57921bb8d187) for task 0 of > framework 20140926-184824-3176252227-40593-2591-0000 from @0.0.0.0:0 > I0926 18:48:24.539660 2617 slave.cpp:3995] Terminating task 0 > I0926 18:48:24.539736 2617 slave.cpp:483] Slave terminating > I0926 18:48:24.539749 2617 slave.cpp:1435] Asked to shut down framework > 20140926-184824-3176252227-40593-2591-0000 by @0.0.0.0:0 > I0926 18:48:24.539757 2617 slave.cpp:1460] Shutting down framework > 20140926-184824-3176252227-40593-2591-0000 > I0926 18:48:24.539767 2617 slave.cpp:2811] Cleaning up executor 'default' > of framework 20140926-184824-3176252227-40593-2591-0000 > I0926 18:48:24.539839 2618 gc.cpp:56] Scheduling > '/tmp/AllocatorTest_0_SchedulerFailover_VehnAb/slaves/20140926-184824-3176252227-40593-2591-0/frameworks/20140926-184824-3176252227-40593-2591-0000/executors/default/runs/3d85c1fe-ab3c-459d-bb68-0d67532adb2b' > for gc 6.99999375223407days in the future > I0926 18:48:24.539863 2617 slave.cpp:2886] Cleaning up framework > 20140926-184824-3176252227-40593-2591-0000 > I0926 18:48:24.539898 2618 gc.cpp:56] Scheduling > '/tmp/AllocatorTest_0_SchedulerFailover_VehnAb/slaves/20140926-184824-3176252227-40593-2591-0/frameworks/20140926-184824-3176252227-40593-2591-0000/executors/default' > for gc 6.99999375172444days in the future > I0926 18:48:24.539921 2606 status_update_manager.cpp:282] Closing status > update streams for framework 20140926-184824-3176252227-40593-2591-0000 > I0926 18:48:24.539930 2618 gc.cpp:56] Scheduling > '/tmp/AllocatorTest_0_SchedulerFailover_VehnAb/slaves/20140926-184824-3176252227-40593-2591-0/frameworks/20140926-184824-3176252227-40593-2591-0000' > for gc 6.99999375103111days in the future > [ OK ] AllocatorTest/0.SchedulerFailover (404 ms) > [----------] 14 tests from AllocatorTest/0 (18299 ms total) > > [----------] 3 tests from MesosContainerizerIsolatorPreparationTest > [ RUN ] MesosContainerizerIsolatorPreparationTest.MultipleScripts > Using temporary directory > '/tmp/MesosContainerizerIsolatorPreparationTest_MultipleScripts_aQdKHt' > I0926 18:48:24.541612 2605 containerizer.cpp:394] Starting container > 'test_container' for executor 'executor' of framework '' > I0926 18:48:24.543483 2610 launcher.cpp:137] Forked child with pid '6651' > for container 'test_container' > I0926 18:48:24.544095 2605 containerizer.cpp:510] Fetching URIs for > container 'test_container' using command '< > https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/ws/build/src/mesos-fetcher > '> > I0926 18:48:24.724109 2608 containerizer.cpp:997] Executor for container > 'test_container' has exited > I0926 18:48:24.724153 2608 containerizer.cpp:882] Destroying container > 'test_container' > W0926 18:48:24.738945 2620 containerizer.cpp:872] Ignoring destroy of > unknown container: test_container > [ OK ] MesosContainerizerIsolatorPreparationTest.MultipleScripts > (198 ms) > [ RUN ] MesosContainerizerIsolatorPreparationTest.ScriptFails > Using temporary directory > '/tmp/MesosContainerizerIsolatorPreparationTest_ScriptFails_NwiklM' > I0926 18:48:24.739914 2617 containerizer.cpp:394] Starting container > 'test_container' for executor 'executor' of framework '' > I0926 18:48:24.741267 2607 launcher.cpp:137] Forked child with pid '6684' > for container 'test_container' > I0926 18:48:24.741938 2608 containerizer.cpp:510] Fetching URIs for > container 'test_container' using command '< > https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/ws/build/src/mesos-fetcher > '> > I0926 18:48:24.925732 2605 containerizer.cpp:997] Executor for container > 'test_container' has exited > I0926 18:48:24.925781 2605 containerizer.cpp:882] Destroying container > 'test_container' > [ OK ] MesosContainerizerIsolatorPreparationTest.ScriptFails (201 ms) > [ RUN ] MesosContainerizerIsolatorPreparationTest.ScriptSucceeds > Using temporary directory > '/tmp/MesosContainerizerIsolatorPreparationTest_ScriptSucceeds_rUABv5' > I0926 18:48:24.941324 2616 containerizer.cpp:394] Starting container > 'test_container' for executor 'executor' of framework '' > I0926 18:48:24.943204 2606 launcher.cpp:137] Forked child with pid '6715' > for container 'test_container' > I0926 18:48:24.943547 2616 containerizer.cpp:510] Fetching URIs for > container 'test_container' using command '< > https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/ws/build/src/mesos-fetcher > '> > I0926 18:48:25.126603 2608 containerizer.cpp:997] Executor for container > 'test_container' has exited > I0926 18:48:25.126649 2608 containerizer.cpp:882] Destroying container > 'test_container' > [ OK ] MesosContainerizerIsolatorPreparationTest.ScriptSucceeds (201 > ms) > [----------] 3 tests from MesosContainerizerIsolatorPreparationTest (600 > ms total) > > [----------] 2 tests from FetcherTest > [ RUN ] FetcherTest.FileLocalhostURI > Using temporary directory '/tmp/FetcherTest_FileLocalhostURI_ds4vcp' > WARNING: Logging before InitGoogleLogging() is written to STDERR > I0926 18:48:25.178911 6747 fetcher.cpp:76] Fetching URI > 'file://localhost/tmp/FetcherTest_FileLocalhostURI_ds4vcp/from/test' > I0926 18:48:25.179033 6747 fetcher.cpp:179] Copying resource from > '/tmp/FetcherTest_FileLocalhostURI_ds4vcp/from/test' to > '/tmp/FetcherTest_FileLocalhostURI_ds4vcp' > I0926 18:48:25.181974 6747 fetcher.cpp:255] Skipped extracting path > '/tmp/FetcherTest_FileLocalhostURI_ds4vcp/test' > [ OK ] FetcherTest.FileLocalhostURI (86 ms) > [ RUN ] FetcherTest.FileURI > Using temporary directory '/tmp/FetcherTest_FileURI_1S2l7I' > WARNING: Logging before InitGoogleLogging() is written to STDERR > I0926 18:48:25.263098 6764 fetcher.cpp:76] Fetching URI > 'file:///tmp/FetcherTest_FileURI_1S2l7I/from/test' > I0926 18:48:25.263205 6764 fetcher.cpp:179] Copying resource from > '/tmp/FetcherTest_FileURI_1S2l7I/from/test' to > '/tmp/FetcherTest_FileURI_1S2l7I' > I0926 18:48:25.266103 6764 fetcher.cpp:255] Skipped extracting path > '/tmp/FetcherTest_FileURI_1S2l7I/test' > [ OK ] FetcherTest.FileURI (101 ms) > [----------] 2 tests from FetcherTest (187 ms total) > > [----------] Global test environment tear-down > [==========] 371 tests from 60 test cases ran. (258043 ms total) > [ PASSED ] 370 tests. > [ FAILED ] 1 test, listed below: > [ FAILED ] ExamplesTest.LowLevelSchedulerLibprocess > > 1 FAILED TEST > YOU HAVE 5 DISABLED TESTS > > make[3]: *** [check-local] Error 1 > make[3]: Leaving directory `< > https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/ws/build/src > '> > make[2]: *** [check-am] Error 2 > make[2]: Leaving directory `< > https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/ws/build/src > '> > make[1]: *** [check] Error 2 > make[1]: Leaving directory `< > https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/ws/build/src > '> > make: *** [check-recursive] Error 1 > Test finished > Exit status: 2 > Build step 'Execute shell' marked build as failure > Recording test results >
