There were a couple of identical build failures, but they all have the same root-flakinesses.
There are a total of 3 issues with the test, tracked here: https://issues.apache.org/jira/browse/MESOS-3916 https://issues.apache.org/jira/browse/MESOS-4059 We have fixes (1 committed, 1 in review) (Thanks Neil!) for two flaky parts. The third is still under investigation, and is possibly a race related to some tech-debt: https://issues.apache.org/jira/browse/MESOS-3760 On Thu, Dec 3, 2015 at 7:45 PM, Benjamin Mahler <benjamin.mah...@gmail.com> wrote: > Joseph, can you please triage this maintenance test failure? > > I've pasted the logs here in case they get deleted from jenkins: > > [ RUN ] MasterMaintenanceTest.InverseOffersFilters > I1203 18:20:07.989888 341 leveldb.cpp:174] Opened db in 2.612076ms > I1203 18:20:07.990701 341 leveldb.cpp:181] Compacted db in 679308ns > I1203 18:20:07.990825 341 leveldb.cpp:196] Created db iterator in 36559ns > I1203 18:20:07.990929 341 leveldb.cpp:202] Seeked to beginning of db in > 2343ns > I1203 18:20:07.991020 341 leveldb.cpp:271] Iterated through 0 keys in the > db in 592ns > I1203 18:20:07.991153 341 replica.cpp:778] Replica recovered with log > positions 0 -> 0 with 1 holes and 0 unlearned > I1203 18:20:07.991922 369 recover.cpp:447] Starting replica recovery > I1203 18:20:07.992287 372 recover.cpp:473] Replica is in EMPTY status > I1203 18:20:07.993533 372 replica.cpp:674] Replica in EMPTY status received > a broadcasted recover request from (3826)@172.17.0.1:38193 > I1203 18:20:07.994379 369 recover.cpp:193] Received a recover response from > a replica in EMPTY status > I1203 18:20:07.994819 375 recover.cpp:564] Updating replica status to > STARTING > I1203 18:20:07.995513 375 leveldb.cpp:304] Persisting metadata (8 bytes) to > leveldb took 452853ns > I1203 18:20:07.995543 375 replica.cpp:321] Persisted replica status to > STARTING > I1203 18:20:07.995748 375 recover.cpp:473] Replica is in STARTING status > I1203 18:20:07.996718 375 master.cpp:365] Master > 78046f05-cfb7-4478-8385-528382f71b9e (d0573e529de6) started on > 172.17.0.1:38193 > I1203 18:20:07.996747 375 master.cpp:367] Flags at startup: --acls="" > --allocation_interval="1secs" --allocator="HierarchicalDRF" > --authenticate="false" --authenticate_slaves="true" > --authenticators="crammd5" --authorizers="local" > --credentials="/tmp/QOkgIh/credentials" --framework_sorter="drf" > --help="false" --hostname_lookup="true" --initialize_driver_logging="true" > --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" > --max_slave_ping_timeouts="5" --quiet="false" > --recovery_slave_removal_limit="100%" --registry="replicated_log" > --registry_fetch_timeout="1mins" --registry_store_timeout="25secs" > --registry_strict="true" --root_submissions="true" > --slave_ping_timeout="15secs" --slave_reregister_timeout="10mins" > --user_sorter="drf" --version="false" > --webui_dir="/mesos/mesos-0.27.0/_inst/share/mesos/webui" > --work_dir="/tmp/QOkgIh/master" --zk_session_timeout="10secs" > I1203 18:20:07.997158 375 master.cpp:414] Master allowing unauthenticated > frameworks to register > I1203 18:20:07.997176 375 master.cpp:417] Master only allowing > authenticated slaves to register > I1203 18:20:07.997187 375 credentials.hpp:35] Loading credentials for > authentication from '/tmp/QOkgIh/credentials' > I1203 18:20:07.997517 375 master.cpp:456] Using default 'crammd5' > authenticator > I1203 18:20:07.997722 375 master.cpp:493] Authorization enabled > I1203 18:20:07.997894 368 replica.cpp:674] Replica in STARTING status > received a broadcasted recover request from (3827)@172.17.0.1:38193 > I1203 18:20:07.998193 363 hierarchical.cpp:162] Initialized hierarchical > allocator process > I1203 18:20:07.998301 363 recover.cpp:193] Received a recover response from > a replica in STARTING status > I1203 18:20:07.998512 368 whitelist_watcher.cpp:77] No whitelist given > I1203 18:20:07.998734 367 recover.cpp:564] Updating replica status to VOTING > I1203 18:20:07.999285 363 leveldb.cpp:304] Persisting metadata (8 bytes) to > leveldb took 341976ns > I1203 18:20:07.999315 363 replica.cpp:321] Persisted replica status to > VOTING > I1203 18:20:07.999421 367 recover.cpp:578] Successfully joined the Paxos > group > I1203 18:20:07.999645 367 recover.cpp:462] Recover process terminated > I1203 18:20:08.001030 363 master.cpp:1637] The newly elected leader is > master@172.17.0.1:38193 with id 78046f05-cfb7-4478-8385-528382f71b9e > I1203 18:20:08.001060 363 master.cpp:1650] Elected as the leading master! > I1203 18:20:08.001078 363 master.cpp:1395] Recovering from registrar > I1203 18:20:08.001444 363 registrar.cpp:307] Recovering registrar > I1203 18:20:08.002307 368 log.cpp:659] Attempting to start the writer > I1203 18:20:08.005077 369 replica.cpp:494] Replica received implicit > promise request from (3828)@172.17.0.1:38193 with proposal 1 > I1203 18:20:08.005841 369 leveldb.cpp:304] Persisting metadata (8 bytes) to > leveldb took 688704ns > I1203 18:20:08.005873 369 replica.cpp:343] Persisted promised to 1 > I1203 18:20:08.007071 369 coordinator.cpp:238] Coordinator attempting to > fill missing positions > I1203 18:20:08.008887 374 replica.cpp:389] Replica received explicit > promise request from (3829)@172.17.0.1:38193 for position 0 with proposal 2 > I1203 18:20:08.009847 374 leveldb.cpp:341] Persisting action (8 bytes) to > leveldb took 897100ns > I1203 18:20:08.009886 374 replica.cpp:713] Persisted action at 0 > I1203 18:20:08.011418 365 replica.cpp:538] Replica received write request > for position 0 from (3830)@172.17.0.1:38193 > I1203 18:20:08.011507 365 leveldb.cpp:436] Reading position from leveldb > took 42134ns > I1203 18:20:08.011895 365 leveldb.cpp:341] Persisting action (14 bytes) to > leveldb took 334607ns > I1203 18:20:08.011924 365 replica.cpp:713] Persisted action at 0 > I1203 18:20:08.012511 372 replica.cpp:692] Replica received learned notice > for position 0 from @0.0.0.0:0 > I1203 18:20:08.012949 372 leveldb.cpp:341] Persisting action (16 bytes) to > leveldb took 409370ns > I1203 18:20:08.012974 372 replica.cpp:713] Persisted action at 0 > I1203 18:20:08.012995 372 replica.cpp:698] Replica learned NOP action at > position 0 > I1203 18:20:08.013542 367 log.cpp:675] Writer started with ending position 0 > I1203 18:20:08.014807 365 leveldb.cpp:436] Reading position from leveldb > took 31850ns > I1203 18:20:08.015921 365 registrar.cpp:340] Successfully fetched the > registry (0B) in 14.438912ms > I1203 18:20:08.016036 365 registrar.cpp:439] Applied 1 operations in > 32373ns; attempting to update the 'registry' > I1203 18:20:08.017218 370 log.cpp:683] Attempting to append 170 bytes to > the log > I1203 18:20:08.017415 371 coordinator.cpp:348] Coordinator attempting to > write APPEND action at position 1 > I1203 18:20:08.018331 372 replica.cpp:538] Replica received write request > for position 1 from (3831)@172.17.0.1:38193 > I1203 18:20:08.018755 372 leveldb.cpp:341] Persisting action (189 bytes) to > leveldb took 324453ns > I1203 18:20:08.018846 372 replica.cpp:713] Persisted action at 1 > I1203 18:20:08.019677 370 replica.cpp:692] Replica received learned notice > for position 1 from @0.0.0.0:0 > I1203 18:20:08.020063 370 leveldb.cpp:341] Persisting action (191 bytes) to > leveldb took 354812ns > I1203 18:20:08.020088 370 replica.cpp:713] Persisted action at 1 > I1203 18:20:08.020113 370 replica.cpp:698] Replica learned APPEND action at > position 1 > I1203 18:20:08.021123 367 registrar.cpp:484] Successfully updated the > 'registry' in 5.03296ms > I1203 18:20:08.021312 367 registrar.cpp:370] Successfully recovered > registrar > I1203 18:20:08.021391 372 log.cpp:702] Attempting to truncate the log to 1 > I1203 18:20:08.021559 372 coordinator.cpp:348] Coordinator attempting to > write TRUNCATE action at position 2 > I1203 18:20:08.021745 367 master.cpp:1447] Recovered 0 slaves from the > Registry (131B) ; allowing 10mins for slaves to re-register > I1203 18:20:08.021903 371 hierarchical.cpp:174] Allocator recovery is not > supported yet > I1203 18:20:08.023030 367 replica.cpp:538] Replica received write request > for position 2 from (3832)@172.17.0.1:38193 > I1203 18:20:08.023634 367 leveldb.cpp:341] Persisting action (16 bytes) to > leveldb took 366368ns > I1203 18:20:08.023663 367 replica.cpp:713] Persisted action at 2 > I1203 18:20:08.024610 363 replica.cpp:692] Replica received learned notice > for position 2 from @0.0.0.0:0 > I1203 18:20:08.025135 363 leveldb.cpp:341] Persisting action (18 bytes) to > leveldb took 451065ns > I1203 18:20:08.025202 363 leveldb.cpp:399] Deleting ~1 keys from leveldb > took 36771ns > I1203 18:20:08.025223 363 replica.cpp:713] Persisted action at 2 > I1203 18:20:08.025254 363 replica.cpp:698] Replica learned TRUNCATE action > at position 2 > I1203 18:20:08.039106 362 slave.cpp:189] Slave started on > 111)@172.17.0.1:38193 > I1203 18:20:08.039152 362 slave.cpp:190] Flags at startup: > --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5" > --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" > --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" > --cgroups_root="mesos" --container_disk_watch_interval="15secs" > --containerizers="mesos" > --credential="/tmp/MasterMaintenanceTest_InverseOffersFilters_t0jUCH/credential" > --default_role="*" --disk_watch_interval="1mins" --docker="docker" > --docker_auth_server="auth.docker.io" --docker_auth_server_port="443" > --docker_kill_orphans="true" > --docker_local_archives_dir="/tmp/mesos/images/docker" > --docker_puller="local" --docker_puller_timeout="60" > --docker_registry="registry-1.docker.io" --docker_registry_port="443" > --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" > --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" > --enforce_container_disk_quota="false" > --executor_registration_timeout="1mins" > --executor_shutdown_grace_period="5secs" > --fetcher_cache_dir="/tmp/MasterMaintenanceTest_InverseOffersFilters_t0jUCH/fetch" > --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" > --gc_disk_headroom="0.1" --hadoop_home="" --help="false" > --hostname="maintenance-host" --hostname_lookup="true" > --image_provisioner_backend="copy" --initialize_driver_logging="true" > --isolation="posix/cpu,posix/mem" > --launcher_dir="/mesos/mesos-0.27.0/_build/src" --logbufsecs="0" > --logging_level="INFO" --oversubscribed_resources_interval="15secs" > --perf_duration="10secs" --perf_interval="1mins" > --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect" > --recovery_timeout="15mins" --registration_backoff_factor="10ms" > --resources="cpus:2;mem:1024;disk:1024;ports:[31000-32000]" > --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox" > --strict="true" --switch_user="true" > --systemd_runtime_directory="/run/systemd/system" --version="false" > --work_dir="/tmp/MasterMaintenanceTest_InverseOffersFilters_t0jUCH" > I1203 18:20:08.039780 362 credentials.hpp:83] Loading credential for > authentication from > '/tmp/MasterMaintenanceTest_InverseOffersFilters_t0jUCH/credential' > I1203 18:20:08.040057 362 slave.cpp:320] Slave using credential for: > test-principal > I1203 18:20:08.040267 362 resources.cpp:478] Parsing resources as JSON > failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000] > Trying semicolon-delimited string format instead > I1203 18:20:08.040693 362 slave.cpp:390] Slave resources: cpus(*):2; > mem(*):1024; disk(*):1024; ports(*):[31000-32000] > I1203 18:20:08.040769 362 slave.cpp:398] Slave attributes: [ ] > I1203 18:20:08.040783 362 slave.cpp:403] Slave hostname: maintenance-host > I1203 18:20:08.040803 362 slave.cpp:408] Slave checkpoint: true > I1203 18:20:08.042142 368 state.cpp:52] Recovering state from > '/tmp/MasterMaintenanceTest_InverseOffersFilters_t0jUCH/meta' > I1203 18:20:08.042562 368 status_update_manager.cpp:200] Recovering status > update manager > I1203 18:20:08.042896 370 slave.cpp:4258] Finished recovery > I1203 18:20:08.043488 370 slave.cpp:4430] Querying resource estimator for > oversubscribable resources > I1203 18:20:08.044051 370 slave.cpp:727] New master detected at > master@172.17.0.1:38193 > I1203 18:20:08.044172 370 slave.cpp:790] Authenticating with master > master@172.17.0.1:38193 > I1203 18:20:08.044195 370 slave.cpp:795] Using default CRAM-MD5 > authenticatee > I1203 18:20:08.044390 370 slave.cpp:763] Detecting new master > I1203 18:20:08.044513 370 slave.cpp:4444] Received oversubscribable > resources from the resource estimator > I1203 18:20:08.044610 370 status_update_manager.cpp:174] Pausing sending > status updates > I1203 18:20:08.044750 370 authenticatee.cpp:121] Creating new client SASL > connection > I1203 18:20:08.045251 370 master.cpp:5308] Authenticating > slave(111)@172.17.0.1:38193 > I1203 18:20:08.045435 370 authenticator.cpp:413] Starting authentication > session for crammd5_authenticatee(288)@172.17.0.1:38193 > I1203 18:20:08.045776 370 authenticator.cpp:98] Creating new server SASL > connection > I1203 18:20:08.046074 370 authenticatee.cpp:212] Received SASL > authentication mechanisms: CRAM-MD5 > I1203 18:20:08.046924 370 authenticatee.cpp:238] Attempting to authenticate > with mechanism 'CRAM-MD5' > I1203 18:20:08.047127 370 authenticator.cpp:203] Received SASL > authentication start > I1203 18:20:08.047277 370 authenticator.cpp:325] Authentication requires > more steps > I1203 18:20:08.047448 370 authenticatee.cpp:258] Received SASL > authentication step > I1203 18:20:08.047642 370 authenticator.cpp:231] Received SASL > authentication step > I1203 18:20:08.047777 370 auxprop.cpp:107] Request to lookup properties for > user: 'test-principal' realm: 'd0573e529de6' server FQDN: 'd0573e529de6' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: false > I1203 18:20:08.047886 370 auxprop.cpp:179] Looking up auxiliary property > '*userPassword' > I1203 18:20:08.048015 370 auxprop.cpp:179] Looking up auxiliary property > '*cmusaslsecretCRAM-MD5' > I1203 18:20:08.048136 370 auxprop.cpp:107] Request to lookup properties for > user: 'test-principal' realm: 'd0573e529de6' server FQDN: 'd0573e529de6' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: true > I1203 18:20:08.048228 370 auxprop.cpp:129] Skipping auxiliary property > '*userPassword' since SASL_AUXPROP_AUTHZID == true > I1203 18:20:08.048313 370 auxprop.cpp:129] Skipping auxiliary property > '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true > I1203 18:20:08.048408 370 authenticator.cpp:317] Authentication success > I1203 18:20:08.048717 367 master.cpp:5338] Successfully authenticated > principal 'test-principal' at slave(111)@172.17.0.1:38193 > I1203 18:20:08.048852 374 authenticator.cpp:431] Authentication session > cleanup for crammd5_authenticatee(288)@172.17.0.1:38193 > I1203 18:20:08.048727 370 authenticatee.cpp:298] Authentication success > I1203 18:20:08.049576 370 slave.cpp:858] Successfully authenticated with > master master@172.17.0.1:38193 > I1203 18:20:08.049768 370 slave.cpp:1252] Will retry registration in > 17.23988ms if necessary > I1203 18:20:08.049981 372 master.cpp:4017] Registering slave at > slave(111)@172.17.0.1:38193 (maintenance-host) with id > 78046f05-cfb7-4478-8385-528382f71b9e-S0 > I1203 18:20:08.050596 372 registrar.cpp:439] Applied 1 operations in > 143816ns; attempting to update the 'registry' > I1203 18:20:08.051640 372 log.cpp:683] Attempting to append 343 bytes to > the log > I1203 18:20:08.051849 366 coordinator.cpp:348] Coordinator attempting to > write APPEND action at position 3 > I1203 18:20:08.052887 365 replica.cpp:538] Replica received write request > for position 3 from (3837)@172.17.0.1:38193 > I1203 18:20:08.053539 365 leveldb.cpp:341] Persisting action (362 bytes) to > leveldb took 600279ns > I1203 18:20:08.053568 365 replica.cpp:713] Persisted action at 3 > I1203 18:20:08.054618 363 replica.cpp:692] Replica received learned notice > for position 3 from @0.0.0.0:0 > I1203 18:20:08.055068 363 leveldb.cpp:341] Persisting action (364 bytes) to > leveldb took 414797ns > I1203 18:20:08.055097 363 replica.cpp:713] Persisted action at 3 > I1203 18:20:08.055121 363 replica.cpp:698] Replica learned APPEND action at > position 3 > I1203 18:20:08.056676 372 registrar.cpp:484] Successfully updated the > 'registry' in 6.00192ms > I1203 18:20:08.057006 375 log.cpp:702] Attempting to truncate the log to 3 > I1203 18:20:08.057199 369 coordinator.cpp:348] Coordinator attempting to > write TRUNCATE action at position 4 > I1203 18:20:08.057880 374 slave.cpp:3197] Received ping from > slave-observer(114)@172.17.0.1:38193 > I1203 18:20:08.058136 372 master.cpp:4085] Registered slave > 78046f05-cfb7-4478-8385-528382f71b9e-S0 at slave(111)@172.17.0.1:38193 > (maintenance-host) with cpus(*):2; mem(*):1024; disk(*):1024; > ports(*):[31000-32000] > I1203 18:20:08.058403 363 slave.cpp:902] Registered with master > master@172.17.0.1:38193; given slave ID > 78046f05-cfb7-4478-8385-528382f71b9e-S0 > I1203 18:20:08.058429 363 fetcher.cpp:79] Clearing fetcher cache > I1203 18:20:08.058434 367 hierarchical.cpp:380] Added slave > 78046f05-cfb7-4478-8385-528382f71b9e-S0 (maintenance-host) with cpus(*):2; > mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: ) > I1203 18:20:08.058631 367 hierarchical.cpp:1062] No resources available to > allocate! > I1203 18:20:08.058681 367 hierarchical.cpp:1155] No inverse offers to send > out! > I1203 18:20:08.058703 367 hierarchical.cpp:973] Performed allocation for > slave 78046f05-cfb7-4478-8385-528382f71b9e-S0 in 234246ns > I1203 18:20:08.058832 371 status_update_manager.cpp:181] Resuming sending > status updates > I1203 18:20:08.058789 363 slave.cpp:925] Checkpointing SlaveInfo to > '/tmp/MasterMaintenanceTest_InverseOffersFilters_t0jUCH/meta/slaves/78046f05-cfb7-4478-8385-528382f71b9e-S0/slave.info' > I1203 18:20:08.059510 363 slave.cpp:961] Forwarding total oversubscribed > resources > I1203 18:20:08.059532 367 replica.cpp:538] Replica received write request > for position 4 from (3838)@172.17.0.1:38193 > I1203 18:20:08.059667 363 master.cpp:4427] Received update of slave > 78046f05-cfb7-4478-8385-528382f71b9e-S0 at slave(111)@172.17.0.1:38193 > (maintenance-host) with total oversubscribed resources > I1203 18:20:08.060132 367 leveldb.cpp:341] Persisting action (16 bytes) to > leveldb took 562001ns > I1203 18:20:08.060159 367 replica.cpp:713] Persisted action at 4 > I1203 18:20:08.060317 375 hierarchical.cpp:434] Slave > 78046f05-cfb7-4478-8385-528382f71b9e-S0 (maintenance-host) updated with > oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024; > ports(*):[31000-32000], allocated: ) > I1203 18:20:08.060480 375 hierarchical.cpp:1062] No resources available to > allocate! > I1203 18:20:08.060520 375 hierarchical.cpp:1155] No inverse offers to send > out! > I1203 18:20:08.060542 375 hierarchical.cpp:973] Performed allocation for > slave 78046f05-cfb7-4478-8385-528382f71b9e-S0 in 186336ns > I1203 18:20:08.061152 367 replica.cpp:692] Replica received learned notice > for position 4 from @0.0.0.0:0 > I1203 18:20:08.061512 367 leveldb.cpp:341] Persisting action (18 bytes) to > leveldb took 328936ns > I1203 18:20:08.061578 367 leveldb.cpp:399] Deleting ~2 keys from leveldb > took 38088ns > I1203 18:20:08.061597 367 replica.cpp:713] Persisted action at 4 > I1203 18:20:08.061619 367 replica.cpp:698] Replica learned TRUNCATE action > at position 4 > I1203 18:20:08.064887 375 slave.cpp:189] Slave started on > 112)@172.17.0.1:38193 > I1203 18:20:08.064918 375 slave.cpp:190] Flags at startup: > --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5" > --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_enable_cfs="false" > --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" > --cgroups_root="mesos" --container_disk_watch_interval="15secs" > --containerizers="mesos" > --credential="/tmp/MasterMaintenanceTest_InverseOffersFilters_XSU2vX/credential" > --default_role="*" --disk_watch_interval="1mins" --docker="docker" > --docker_auth_server="auth.docker.io" --docker_auth_server_port="443" > --docker_kill_orphans="true" > --docker_local_archives_dir="/tmp/mesos/images/docker" > --docker_puller="local" --docker_puller_timeout="60" > --docker_registry="registry-1.docker.io" --docker_registry_port="443" > --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" > --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" > --enforce_container_disk_quota="false" > --executor_registration_timeout="1mins" > --executor_shutdown_grace_period="5secs" > --fetcher_cache_dir="/tmp/MasterMaintenanceTest_InverseOffersFilters_XSU2vX/fetch" > --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" > --gc_disk_headroom="0.1" --hadoop_home="" --help="false" > --hostname="maintenance-host-2" --hostname_lookup="true" > --image_provisioner_backend="copy" --initialize_driver_logging="true" > --isolation="posix/cpu,posix/mem" > --launcher_dir="/mesos/mesos-0.27.0/_build/src" --logbufsecs="0" > --logging_level="INFO" --oversubscribed_resources_interval="15secs" > --perf_duration="10secs" --perf_interval="1mins" > --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect" > --recovery_timeout="15mins" --registration_backoff_factor="10ms" > --resources="cpus:2;mem:1024;disk:1024;ports:[31000-32000]" > --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox" > --strict="true" --switch_user="true" > --systemd_runtime_directory="/run/systemd/system" --version="false" > --work_dir="/tmp/MasterMaintenanceTest_InverseOffersFilters_XSU2vX" > I1203 18:20:08.065491 375 credentials.hpp:83] Loading credential for > authentication from > '/tmp/MasterMaintenanceTest_InverseOffersFilters_XSU2vX/credential' > I1203 18:20:08.065738 375 slave.cpp:320] Slave using credential for: > test-principal > I1203 18:20:08.065961 375 resources.cpp:478] Parsing resources as JSON > failed: cpus:2;mem:1024;disk:1024;ports:[31000-32000] > Trying semicolon-delimited string format instead > I1203 18:20:08.066398 375 slave.cpp:390] Slave resources: cpus(*):2; > mem(*):1024; disk(*):1024; ports(*):[31000-32000] > I1203 18:20:08.066473 375 slave.cpp:398] Slave attributes: [ ] > I1203 18:20:08.066488 375 slave.cpp:403] Slave hostname: maintenance-host-2 > I1203 18:20:08.066498 375 slave.cpp:408] Slave checkpoint: true > I1203 18:20:08.068333 368 state.cpp:52] Recovering state from > '/tmp/MasterMaintenanceTest_InverseOffersFilters_XSU2vX/meta' > I1203 18:20:08.068681 368 status_update_manager.cpp:200] Recovering status > update manager > I1203 18:20:08.069042 371 slave.cpp:4258] Finished recovery > I1203 18:20:08.069588 371 slave.cpp:4430] Querying resource estimator for > oversubscribable resources > I1203 18:20:08.069870 371 slave.cpp:4444] Received oversubscribable > resources from the resource estimator > I1203 18:20:08.070039 371 slave.cpp:727] New master detected at > master@172.17.0.1:38193 > I1203 18:20:08.070108 368 status_update_manager.cpp:174] Pausing sending > status updates > I1203 18:20:08.070122 371 slave.cpp:790] Authenticating with master > master@172.17.0.1:38193 > I1203 18:20:08.070286 371 slave.cpp:795] Using default CRAM-MD5 > authenticatee > I1203 18:20:08.070444 371 slave.cpp:763] Detecting new master > I1203 18:20:08.070648 371 authenticatee.cpp:121] Creating new client SASL > connection > I1203 18:20:08.071916 360 master.cpp:5308] Authenticating > slave(112)@172.17.0.1:38193 > I1203 18:20:08.072032 374 authenticator.cpp:413] Starting authentication > session for crammd5_authenticatee(289)@172.17.0.1:38193 > I1203 18:20:08.072621 373 authenticator.cpp:98] Creating new server SASL > connection > I1203 18:20:08.073480 373 authenticatee.cpp:212] Received SASL > authentication mechanisms: CRAM-MD5 > I1203 18:20:08.073634 373 authenticatee.cpp:238] Attempting to authenticate > with mechanism 'CRAM-MD5' > I1203 18:20:08.074204 373 authenticator.cpp:203] Received SASL > authentication start > I1203 18:20:08.074339 373 authenticator.cpp:325] Authentication requires > more steps > I1203 18:20:08.074533 373 authenticatee.cpp:258] Received SASL > authentication step > I1203 18:20:08.074730 373 authenticator.cpp:231] Received SASL > authentication step > I1203 18:20:08.074868 373 auxprop.cpp:107] Request to lookup properties for > user: 'test-principal' realm: 'd0573e529de6' server FQDN: 'd0573e529de6' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: false > I1203 18:20:08.074981 373 auxprop.cpp:179] Looking up auxiliary property > '*userPassword' > I1203 18:20:08.075132 373 auxprop.cpp:179] Looking up auxiliary property > '*cmusaslsecretCRAM-MD5' > I1203 18:20:08.075253 373 auxprop.cpp:107] Request to lookup properties for > user: 'test-principal' realm: 'd0573e529de6' server FQDN: 'd0573e529de6' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: true > I1203 18:20:08.075352 373 auxprop.cpp:129] Skipping auxiliary property > '*userPassword' since SASL_AUXPROP_AUTHZID == true > I1203 18:20:08.075449 373 auxprop.cpp:129] Skipping auxiliary property > '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true > I1203 18:20:08.075562 373 authenticator.cpp:317] Authentication success > I1203 18:20:08.076290 373 authenticatee.cpp:298] Authentication success > I1203 18:20:08.076690 373 master.cpp:5338] Successfully authenticated > principal 'test-principal' at slave(112)@172.17.0.1:38193 > I1203 18:20:08.076859 367 authenticator.cpp:431] Authentication session > cleanup for crammd5_authenticatee(289)@172.17.0.1:38193 > I1203 18:20:08.077364 373 slave.cpp:858] Successfully authenticated with > master master@172.17.0.1:38193 > I1203 18:20:08.077898 373 slave.cpp:1252] Will retry registration in > 2.893325ms if necessary > I1203 18:20:08.078421 370 master.cpp:4017] Registering slave at > slave(112)@172.17.0.1:38193 (maintenance-host-2) with id > 78046f05-cfb7-4478-8385-528382f71b9e-S1 > I1203 18:20:08.079151 371 registrar.cpp:439] Applied 1 operations in > 116404ns; attempting to update the 'registry' > I1203 18:20:08.080432 368 log.cpp:683] Attempting to append 515 bytes to > the log > I1203 18:20:08.080684 368 coordinator.cpp:348] Coordinator attempting to > write APPEND action at position 5 > I1203 18:20:08.081620 368 slave.cpp:1252] Will retry registration in > 18.60268ms if necessary > I1203 18:20:08.081985 362 master.cpp:4005] Ignoring register slave message > from slave(112)@172.17.0.1:38193 (maintenance-host-2) as admission is already > in progress > I1203 18:20:08.082072 362 replica.cpp:538] Replica received write request > for position 5 from (3843)@172.17.0.1:38193 > I1203 18:20:08.082326 362 leveldb.cpp:341] Persisting action (534 bytes) to > leveldb took 221545ns > I1203 18:20:08.082352 362 replica.cpp:713] Persisted action at 5 > I1203 18:20:08.083313 362 replica.cpp:692] Replica received learned notice > for position 5 from @0.0.0.0:0 > I1203 18:20:08.083830 362 leveldb.cpp:341] Persisting action (536 bytes) to > leveldb took 489932ns > I1203 18:20:08.083856 362 replica.cpp:713] Persisted action at 5 > I1203 18:20:08.083878 362 replica.cpp:698] Replica learned APPEND action at > position 5 > I1203 18:20:08.086607 365 registrar.cpp:484] Successfully updated the > 'registry' in 7.361024ms > I1203 18:20:08.086846 362 log.cpp:702] Attempting to truncate the log to 5 > I1203 18:20:08.087077 362 coordinator.cpp:348] Coordinator attempting to > write TRUNCATE action at position 6 > I1203 18:20:08.088059 375 master.cpp:4085] Registered slave > 78046f05-cfb7-4478-8385-528382f71b9e-S1 at slave(112)@172.17.0.1:38193 > (maintenance-host-2) with cpus(*):2; mem(*):1024; disk(*):1024; > ports(*):[31000-32000] > I1203 18:20:08.088321 362 hierarchical.cpp:380] Added slave > 78046f05-cfb7-4478-8385-528382f71b9e-S1 (maintenance-host-2) with cpus(*):2; > mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: ) > I1203 18:20:08.088524 362 hierarchical.cpp:1062] No resources available to > allocate! > I1203 18:20:08.088575 362 hierarchical.cpp:1155] No inverse offers to send > out! > I1203 18:20:08.088601 362 hierarchical.cpp:973] Performed allocation for > slave 78046f05-cfb7-4478-8385-528382f71b9e-S1 in 240968ns > I1203 18:20:08.088644 360 replica.cpp:538] Replica received write request > for position 6 from (3844)@172.17.0.1:38193 > I1203 18:20:08.088717 361 slave.cpp:3197] Received ping from > slave-observer(115)@172.17.0.1:38193 > I1203 18:20:08.089000 361 slave.cpp:902] Registered with master > master@172.17.0.1:38193; given slave ID > 78046f05-cfb7-4478-8385-528382f71b9e-S1 > I1203 18:20:08.089025 361 fetcher.cpp:79] Clearing fetcher cache > I1203 18:20:08.089114 360 leveldb.cpp:341] Persisting action (16 bytes) to > leveldb took 427596ns > I1203 18:20:08.089143 360 replica.cpp:713] Persisted action at 6 > I1203 18:20:08.089632 374 status_update_manager.cpp:181] Resuming sending > status updates > I1203 18:20:08.089820 361 slave.cpp:925] Checkpointing SlaveInfo to > '/tmp/MasterMaintenanceTest_InverseOffersFilters_XSU2vX/meta/slaves/78046f05-cfb7-4478-8385-528382f71b9e-S1/slave.info' > I1203 18:20:08.090217 361 slave.cpp:961] Forwarding total oversubscribed > resources > I1203 18:20:08.090314 360 replica.cpp:692] Replica received learned notice > for position 6 from @0.0.0.0:0 > I1203 18:20:08.090492 361 master.cpp:4427] Received update of slave > 78046f05-cfb7-4478-8385-528382f71b9e-S1 at slave(112)@172.17.0.1:38193 > (maintenance-host-2) with total oversubscribed resources > I1203 18:20:08.090750 360 leveldb.cpp:341] Persisting action (18 bytes) to > leveldb took 402522ns > I1203 18:20:08.090843 360 leveldb.cpp:399] Deleting ~2 keys from leveldb > took 64765ns > I1203 18:20:08.090870 360 replica.cpp:713] Persisted action at 6 > I1203 18:20:08.090895 360 replica.cpp:698] Replica learned TRUNCATE action > at position 6 > I1203 18:20:08.090980 361 hierarchical.cpp:434] Slave > 78046f05-cfb7-4478-8385-528382f71b9e-S1 (maintenance-host-2) updated with > oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024; > ports(*):[31000-32000], allocated: ) > I1203 18:20:08.091161 361 hierarchical.cpp:1062] No resources available to > allocate! > I1203 18:20:08.091203 361 hierarchical.cpp:1155] No inverse offers to send > out! > I1203 18:20:08.091225 361 hierarchical.cpp:973] Performed allocation for > slave 78046f05-cfb7-4478-8385-528382f71b9e-S1 in 203111ns > I1203 18:20:08.094625 375 process.cpp:3067] Handling HTTP event for process > 'master' with path: '/master/maintenance/schedule' > I1203 18:20:08.094715 375 http.cpp:336] HTTP POST for > /master/maintenance/schedule from 172.17.0.1:35704 > I1203 18:20:08.095815 367 registrar.cpp:439] Applied 1 operations in > 233576ns; attempting to update the 'registry' > I1203 18:20:08.097347 374 log.cpp:683] Attempting to append 734 bytes to > the log > I1203 18:20:08.097617 374 coordinator.cpp:348] Coordinator attempting to > write APPEND action at position 7 > I1203 18:20:08.098783 374 replica.cpp:538] Replica received write request > for position 7 from (3845)@172.17.0.1:38193 > I1203 18:20:08.099269 374 leveldb.cpp:341] Persisting action (753 bytes) to > leveldb took 422267ns > I1203 18:20:08.099300 374 replica.cpp:713] Persisted action at 7 > I1203 18:20:08.100100 374 replica.cpp:692] Replica received learned notice > for position 7 from @0.0.0.0:0 > I1203 18:20:08.100509 374 leveldb.cpp:341] Persisting action (755 bytes) to > leveldb took 378294ns > I1203 18:20:08.100538 374 replica.cpp:713] Persisted action at 7 > I1203 18:20:08.100560 374 replica.cpp:698] Replica learned APPEND action at > position 7 > I1203 18:20:08.103358 368 registrar.cpp:484] Successfully updated the > 'registry' in 7.382784ms > I1203 18:20:08.103742 374 log.cpp:702] Attempting to truncate the log to 7 > I1203 18:20:08.104044 362 master.cpp:4483] Updating unavailability of slave > 78046f05-cfb7-4478-8385-528382f71b9e-S1 at slave(112)@172.17.0.1:38193 > (maintenance-host-2), starting at 2399.10961820361weeks > I1203 18:20:08.104357 374 coordinator.cpp:348] Coordinator attempting to > write TRUNCATE action at position 8 > I1203 18:20:08.105026 362 master.cpp:4483] Updating unavailability of slave > 78046f05-cfb7-4478-8385-528382f71b9e-S0 at slave(111)@172.17.0.1:38193 > (maintenance-host), starting at 2399.10961820361weeks > I1203 18:20:08.105545 363 hierarchical.cpp:1062] No resources available to > allocate! > I1203 18:20:08.105623 363 hierarchical.cpp:1155] No inverse offers to send > out! > I1203 18:20:08.105664 363 hierarchical.cpp:973] Performed allocation for > slave 78046f05-cfb7-4478-8385-528382f71b9e-S1 in 323361ns > I1203 18:20:08.105907 363 hierarchical.cpp:1062] No resources available to > allocate! > I1203 18:20:08.105969 363 hierarchical.cpp:1155] No inverse offers to send > out! > I1203 18:20:08.105998 363 hierarchical.cpp:973] Performed allocation for > slave 78046f05-cfb7-4478-8385-528382f71b9e-S0 in 227967ns > I1203 18:20:08.106138 362 master.cpp:4483] Updating unavailability of slave > 78046f05-cfb7-4478-8385-528382f71b9e-S0 at slave(111)@172.17.0.1:38193 > (maintenance-host), starting at 2399.10961820361weeks > I1203 18:20:08.106348 362 master.cpp:4483] Updating unavailability of slave > 78046f05-cfb7-4478-8385-528382f71b9e-S1 at slave(112)@172.17.0.1:38193 > (maintenance-host-2), starting at 2399.10961820361weeks > I1203 18:20:08.106581 364 replica.cpp:538] Replica received write request > for position 8 from (3846)@172.17.0.1:38193 > I1203 18:20:08.106816 370 hierarchical.cpp:1062] No resources available to > allocate! > I1203 18:20:08.106873 370 hierarchical.cpp:1155] No inverse offers to send > out! > I1203 18:20:08.107069 370 hierarchical.cpp:973] Performed allocation for > slave 78046f05-cfb7-4478-8385-528382f71b9e-S0 in 554269ns > I1203 18:20:08.107333 364 leveldb.cpp:341] Persisting action (16 bytes) to > leveldb took 640014ns > I1203 18:20:08.107363 364 replica.cpp:713] Persisted action at 8 > I1203 18:20:08.107599 370 hierarchical.cpp:1062] No resources available to > allocate! > I1203 18:20:08.107808 370 hierarchical.cpp:1155] No inverse offers to send > out! > I1203 18:20:08.107841 370 hierarchical.cpp:973] Performed allocation for > slave 78046f05-cfb7-4478-8385-528382f71b9e-S1 in 380899ns > I1203 18:20:08.109459 371 replica.cpp:692] Replica received learned notice > for position 8 from @0.0.0.0:0 > I1203 18:20:08.110229 341 scheduler.cpp:154] Version: 0.27.0 > I1203 18:20:08.110628 371 leveldb.cpp:341] Persisting action (18 bytes) to > leveldb took 1.126432ms > I1203 18:20:08.110713 371 leveldb.cpp:399] Deleting ~2 keys from leveldb > took 42772ns > I1203 18:20:08.110736 371 replica.cpp:713] Persisted action at 8 > I1203 18:20:08.110766 371 replica.cpp:698] Replica learned TRUNCATE action > at position 8 > I1203 18:20:08.111073 370 scheduler.cpp:236] New master detected at > master@172.17.0.1:38193 > I1203 18:20:08.121060 370 scheduler.cpp:298] Sending SUBSCRIBE call to > master@172.17.0.1:38193 > I1203 18:20:08.123993 370 process.cpp:3067] Handling HTTP event for process > 'master' with path: '/master/api/v1/scheduler' > I1203 18:20:08.124058 370 http.cpp:336] HTTP POST for > /master/api/v1/scheduler from 172.17.0.1:35705 > I1203 18:20:08.124267 370 master.cpp:1899] Received subscription request > for HTTP framework 'default' > I1203 18:20:08.124351 370 master.cpp:1676] Authorizing framework principal > 'test-principal' to receive offers for role '*' > I1203 18:20:08.124866 360 master.cpp:1991] Subscribing framework 'default' > with checkpointing disabled and capabilities [ ] > I1203 18:20:08.125830 371 master.hpp:1583] Sending heartbeat to > 78046f05-cfb7-4478-8385-528382f71b9e-0000 > I1203 18:20:08.125911 370 hierarchical.cpp:220] Added framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 > I1203 18:20:08.127351 360 scheduler.cpp:457] Enqueuing event SUBSCRIBED > received from master@172.17.0.1:38193 > I1203 18:20:08.127707 370 hierarchical.cpp:957] Performed allocation for 2 > slaves in 1.763005ms > I1203 18:20:08.127928 370 scheduler.cpp:457] Enqueuing event HEARTBEAT > received from master@172.17.0.1:38193 > I1203 18:20:08.128466 370 master_maintenance_tests.cpp:172] Ignoring > HEARTBEAT event > I1203 18:20:08.128676 360 master.cpp:5137] Sending 2 offers to framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 (default) > I1203 18:20:08.129547 360 master.cpp:5227] Sending 2 inverse offers to > framework 78046f05-cfb7-4478-8385-528382f71b9e-0000 (default) > I1203 18:20:08.131640 372 scheduler.cpp:457] Enqueuing event OFFERS > received from master@172.17.0.1:38193 > I1203 18:20:08.132640 372 scheduler.cpp:457] Enqueuing event OFFERS > received from master@172.17.0.1:38193 > I1203 18:20:08.142935 368 hierarchical.cpp:1062] No resources available to > allocate! > I1203 18:20:08.143271 368 hierarchical.cpp:957] Performed allocation for 2 > slaves in 1.280338ms > I1203 18:20:08.154265 363 scheduler.cpp:298] Sending ACCEPT call to > master@172.17.0.1:38193 > I1203 18:20:08.156982 373 process.cpp:3067] Handling HTTP event for process > 'master' with path: '/master/api/v1/scheduler' > I1203 18:20:08.157058 373 http.cpp:336] HTTP POST for > /master/api/v1/scheduler from 172.17.0.1:35706 > I1203 18:20:08.158001 373 master.cpp:3010] Processing ACCEPT call for > offers: [ 78046f05-cfb7-4478-8385-528382f71b9e-O0 ] on slave > 78046f05-cfb7-4478-8385-528382f71b9e-S0 at slave(111)@172.17.0.1:38193 > (maintenance-host) for framework 78046f05-cfb7-4478-8385-528382f71b9e-0000 > (default) > I1203 18:20:08.158068 373 master.cpp:2742] Authorizing framework principal > 'test-principal' to launch task e0957182-29d5-4591-938c-583b94075cac as user > 'mesos' > W1203 18:20:08.160732 373 validation.cpp:420] Executor executor-1 for task > e0957182-29d5-4591-938c-583b94075cac uses less CPUs (None) than the minimum > required (0.01). Please update your executor, as this will be mandatory in > future releases. > W1203 18:20:08.160810 373 validation.cpp:432] Executor executor-1 for task > e0957182-29d5-4591-938c-583b94075cac uses less memory (None) than the minimum > required (32MB). Please update your executor, as this will be mandatory in > future releases. > I1203 18:20:08.161272 373 master.hpp:176] Adding task > e0957182-29d5-4591-938c-583b94075cac with resources cpus(*):2; mem(*):1024; > disk(*):1024; ports(*):[31000-32000] on slave > 78046f05-cfb7-4478-8385-528382f71b9e-S0 (maintenance-host) > I1203 18:20:08.161528 373 master.cpp:3403] Launching task > e0957182-29d5-4591-938c-583b94075cac of framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 (default) with resources cpus(*):2; > mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave > 78046f05-cfb7-4478-8385-528382f71b9e-S0 at slave(111)@172.17.0.1:38193 > (maintenance-host) > I1203 18:20:08.163053 361 slave.cpp:1292] Got assigned task > e0957182-29d5-4591-938c-583b94075cac for framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 > I1203 18:20:08.163275 373 scheduler.cpp:298] Sending ACCEPT call to > master@172.17.0.1:38193 > I1203 18:20:08.165091 361 slave.cpp:1411] Launching task > e0957182-29d5-4591-938c-583b94075cac for framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 > I1203 18:20:08.166036 361 paths.cpp:434] Trying to chown > '/tmp/MasterMaintenanceTest_InverseOffersFilters_t0jUCH/slaves/78046f05-cfb7-4478-8385-528382f71b9e-S0/frameworks/78046f05-cfb7-4478-8385-528382f71b9e-0000/executors/executor-1/runs/21ad7ee3-0cf3-4cba-a600-9a92469c806d' > to user 'mesos' > I1203 18:20:08.169783 365 process.cpp:3067] Handling HTTP event for process > 'master' with path: '/master/api/v1/scheduler' > I1203 18:20:08.170961 365 http.cpp:336] HTTP POST for > /master/api/v1/scheduler from 172.17.0.1:35707 > I1203 18:20:08.172499 365 master.cpp:3010] Processing ACCEPT call for > offers: [ 78046f05-cfb7-4478-8385-528382f71b9e-O1 ] on slave > 78046f05-cfb7-4478-8385-528382f71b9e-S1 at slave(112)@172.17.0.1:38193 > (maintenance-host-2) for framework 78046f05-cfb7-4478-8385-528382f71b9e-0000 > (default) > I1203 18:20:08.172575 365 master.cpp:2742] Authorizing framework principal > 'test-principal' to launch task 124ff0e0-2a13-44e9-930a-3064718f86ae as user > 'mesos' > I1203 18:20:08.173951 361 slave.cpp:5042] Launching executor executor-1 of > framework 78046f05-cfb7-4478-8385-528382f71b9e-0000 with resources in work > directory > '/tmp/MasterMaintenanceTest_InverseOffersFilters_t0jUCH/slaves/78046f05-cfb7-4478-8385-528382f71b9e-S0/frameworks/78046f05-cfb7-4478-8385-528382f71b9e-0000/executors/executor-1/runs/21ad7ee3-0cf3-4cba-a600-9a92469c806d' > I1203 18:20:08.176758 361 exec.cpp:134] Version: 0.27.0 > W1203 18:20:08.178130 362 validation.cpp:420] Executor executor-2 for task > 124ff0e0-2a13-44e9-930a-3064718f86ae uses less CPUs (None) than the minimum > required (0.01). Please update your executor, as this will be mandatory in > future releases. > W1203 18:20:08.178272 362 validation.cpp:432] Executor executor-2 for task > 124ff0e0-2a13-44e9-930a-3064718f86ae uses less memory (None) than the minimum > required (32MB). Please update your executor, as this will be mandatory in > future releases. > I1203 18:20:08.178927 362 master.hpp:176] Adding task > 124ff0e0-2a13-44e9-930a-3064718f86ae with resources cpus(*):2; mem(*):1024; > disk(*):1024; ports(*):[31000-32000] on slave > 78046f05-cfb7-4478-8385-528382f71b9e-S1 (maintenance-host-2) > I1203 18:20:08.179332 362 master.cpp:3403] Launching task > 124ff0e0-2a13-44e9-930a-3064718f86ae of framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 (default) with resources cpus(*):2; > mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave > 78046f05-cfb7-4478-8385-528382f71b9e-S1 at slave(112)@172.17.0.1:38193 > (maintenance-host-2) > I1203 18:20:08.180057 362 slave.cpp:1292] Got assigned task > 124ff0e0-2a13-44e9-930a-3064718f86ae for framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 > I1203 18:20:08.180531 361 slave.cpp:1629] Queuing task > 'e0957182-29d5-4591-938c-583b94075cac' for executor 'executor-1' of framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 > I1203 18:20:08.180651 365 exec.cpp:184] Executor started at: > executor(48)@172.17.0.1:38193 with pid 341 > I1203 18:20:08.181100 362 slave.cpp:1411] Launching task > 124ff0e0-2a13-44e9-930a-3064718f86ae for framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 > I1203 18:20:08.181176 361 slave.cpp:680] Successfully attached file > '/tmp/MasterMaintenanceTest_InverseOffersFilters_t0jUCH/slaves/78046f05-cfb7-4478-8385-528382f71b9e-S0/frameworks/78046f05-cfb7-4478-8385-528382f71b9e-0000/executors/executor-1/runs/21ad7ee3-0cf3-4cba-a600-9a92469c806d' > I1203 18:20:08.181932 361 slave.cpp:2406] Got registration for executor > 'executor-1' of framework 78046f05-cfb7-4478-8385-528382f71b9e-0000 from > executor(48)@172.17.0.1:38193 > I1203 18:20:08.181985 362 paths.cpp:434] Trying to chown > '/tmp/MasterMaintenanceTest_InverseOffersFilters_XSU2vX/slaves/78046f05-cfb7-4478-8385-528382f71b9e-S1/frameworks/78046f05-cfb7-4478-8385-528382f71b9e-0000/executors/executor-2/runs/6104f936-ea54-4f01-a5f9-01dd606a7215' > to user 'mesos' > I1203 18:20:08.185151 374 exec.cpp:208] Executor registered on slave > 78046f05-cfb7-4478-8385-528382f71b9e-S0 > I1203 18:20:08.185253 374 exec.cpp:220] Executor::registered took 50794ns > I1203 18:20:08.185778 361 slave.cpp:1794] Sending queued task > 'e0957182-29d5-4591-938c-583b94075cac' to executor 'executor-1' of framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 at executor(48)@172.17.0.1:38193 > I1203 18:20:08.186409 370 exec.cpp:295] Executor asked to run task > 'e0957182-29d5-4591-938c-583b94075cac' > I1203 18:20:08.186703 370 exec.cpp:304] Executor::launchTask took 265614ns > I1203 18:20:08.187018 370 exec.cpp:517] Executor sending status update > TASK_RUNNING (UUID: a4153a7a-bb32-41cc-9457-841754508d66) for task > e0957182-29d5-4591-938c-583b94075cac of framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 > I1203 18:20:08.187510 370 slave.cpp:2763] Handling status update > TASK_RUNNING (UUID: a4153a7a-bb32-41cc-9457-841754508d66) for task > e0957182-29d5-4591-938c-583b94075cac of framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 from executor(48)@172.17.0.1:38193 > I1203 18:20:08.188098 371 status_update_manager.cpp:320] Received status > update TASK_RUNNING (UUID: a4153a7a-bb32-41cc-9457-841754508d66) for task > e0957182-29d5-4591-938c-583b94075cac of framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 > I1203 18:20:08.188145 371 status_update_manager.cpp:497] Creating > StatusUpdate stream for task e0957182-29d5-4591-938c-583b94075cac of > framework 78046f05-cfb7-4478-8385-528382f71b9e-0000 > I1203 18:20:08.188643 371 status_update_manager.cpp:374] Forwarding update > TASK_RUNNING (UUID: a4153a7a-bb32-41cc-9457-841754508d66) for task > e0957182-29d5-4591-938c-583b94075cac of framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 to the slave > I1203 18:20:08.189015 366 slave.cpp:3115] Forwarding the update > TASK_RUNNING (UUID: a4153a7a-bb32-41cc-9457-841754508d66) for task > e0957182-29d5-4591-938c-583b94075cac of framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 to master@172.17.0.1:38193 > I1203 18:20:08.189395 366 slave.cpp:3009] Status update manager > successfully handled status update TASK_RUNNING (UUID: > a4153a7a-bb32-41cc-9457-841754508d66) for task > e0957182-29d5-4591-938c-583b94075cac of framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 > I1203 18:20:08.189781 372 master.cpp:4572] Status update TASK_RUNNING > (UUID: a4153a7a-bb32-41cc-9457-841754508d66) for task > e0957182-29d5-4591-938c-583b94075cac of framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 from slave > 78046f05-cfb7-4478-8385-528382f71b9e-S0 at slave(111)@172.17.0.1:38193 > (maintenance-host) > I1203 18:20:08.190065 372 master.cpp:4620] Forwarding status update > TASK_RUNNING (UUID: a4153a7a-bb32-41cc-9457-841754508d66) for task > e0957182-29d5-4591-938c-583b94075cac of framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 > I1203 18:20:08.190698 372 master.cpp:6224] Updating the state of task > e0957182-29d5-4591-938c-583b94075cac of framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 (latest state: TASK_RUNNING, status > update state: TASK_RUNNING) > I1203 18:20:08.191265 366 slave.cpp:3025] Sending acknowledgement for > status update TASK_RUNNING (UUID: a4153a7a-bb32-41cc-9457-841754508d66) for > task e0957182-29d5-4591-938c-583b94075cac of framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 to executor(48)@172.17.0.1:38193 > I1203 18:20:08.191725 366 exec.cpp:341] Executor received status update > acknowledgement a4153a7a-bb32-41cc-9457-841754508d66 for task > e0957182-29d5-4591-938c-583b94075cac of framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 > I1203 18:20:08.193317 363 scheduler.cpp:457] Enqueuing event UPDATE > received from master@172.17.0.1:38193 > I1203 18:20:08.194072 362 slave.cpp:5042] Launching executor executor-2 of > framework 78046f05-cfb7-4478-8385-528382f71b9e-0000 with resources in work > directory > '/tmp/MasterMaintenanceTest_InverseOffersFilters_XSU2vX/slaves/78046f05-cfb7-4478-8385-528382f71b9e-S1/frameworks/78046f05-cfb7-4478-8385-528382f71b9e-0000/executors/executor-2/runs/6104f936-ea54-4f01-a5f9-01dd606a7215' > I1203 18:20:08.196590 362 exec.cpp:134] Version: 0.27.0 > I1203 18:20:08.197185 369 exec.cpp:184] Executor started at: > executor(49)@172.17.0.1:38193 with pid 341 > I1203 18:20:08.197547 362 slave.cpp:1629] Queuing task > '124ff0e0-2a13-44e9-930a-3064718f86ae' for executor 'executor-2' of framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 > I1203 18:20:08.197845 362 slave.cpp:680] Successfully attached file > '/tmp/MasterMaintenanceTest_InverseOffersFilters_XSU2vX/slaves/78046f05-cfb7-4478-8385-528382f71b9e-S1/frameworks/78046f05-cfb7-4478-8385-528382f71b9e-0000/executors/executor-2/runs/6104f936-ea54-4f01-a5f9-01dd606a7215' > I1203 18:20:08.198031 362 slave.cpp:2406] Got registration for executor > 'executor-2' of framework 78046f05-cfb7-4478-8385-528382f71b9e-0000 from > executor(49)@172.17.0.1:38193 > I1203 18:20:08.198644 369 exec.cpp:208] Executor registered on slave > 78046f05-cfb7-4478-8385-528382f71b9e-S1 > I1203 18:20:08.198714 369 exec.cpp:220] Executor::registered took 38382ns > I1203 18:20:08.199406 362 slave.cpp:1794] Sending queued task > '124ff0e0-2a13-44e9-930a-3064718f86ae' to executor 'executor-2' of framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 at executor(49)@172.17.0.1:38193 > I1203 18:20:08.199937 369 exec.cpp:295] Executor asked to run task > '124ff0e0-2a13-44e9-930a-3064718f86ae' > I1203 18:20:08.200042 369 exec.cpp:304] Executor::launchTask took 77814ns > I1203 18:20:08.200152 369 exec.cpp:517] Executor sending status update > TASK_RUNNING (UUID: 63ef56ab-2f32-4945-9f6d-f35829c3dc86) for task > 124ff0e0-2a13-44e9-930a-3064718f86ae of framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 > I1203 18:20:08.200451 369 slave.cpp:2763] Handling status update > TASK_RUNNING (UUID: 63ef56ab-2f32-4945-9f6d-f35829c3dc86) for task > 124ff0e0-2a13-44e9-930a-3064718f86ae of framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 from executor(49)@172.17.0.1:38193 > I1203 18:20:08.200881 368 status_update_manager.cpp:320] Received status > update TASK_RUNNING (UUID: 63ef56ab-2f32-4945-9f6d-f35829c3dc86) for task > 124ff0e0-2a13-44e9-930a-3064718f86ae of framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 > I1203 18:20:08.201140 368 status_update_manager.cpp:497] Creating > StatusUpdate stream for task 124ff0e0-2a13-44e9-930a-3064718f86ae of > framework 78046f05-cfb7-4478-8385-528382f71b9e-0000 > I1203 18:20:08.201761 368 status_update_manager.cpp:374] Forwarding update > TASK_RUNNING (UUID: 63ef56ab-2f32-4945-9f6d-f35829c3dc86) for task > 124ff0e0-2a13-44e9-930a-3064718f86ae of framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 to the slave > I1203 18:20:08.202327 371 slave.cpp:3115] Forwarding the update > TASK_RUNNING (UUID: 63ef56ab-2f32-4945-9f6d-f35829c3dc86) for task > 124ff0e0-2a13-44e9-930a-3064718f86ae of framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 to master@172.17.0.1:38193 > I1203 18:20:08.202533 371 slave.cpp:3009] Status update manager > successfully handled status update TASK_RUNNING (UUID: > 63ef56ab-2f32-4945-9f6d-f35829c3dc86) for task > 124ff0e0-2a13-44e9-930a-3064718f86ae of framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 > I1203 18:20:08.202585 371 slave.cpp:3025] Sending acknowledgement for > status update TASK_RUNNING (UUID: 63ef56ab-2f32-4945-9f6d-f35829c3dc86) for > task 124ff0e0-2a13-44e9-930a-3064718f86ae of framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 to executor(49)@172.17.0.1:38193 > I1203 18:20:08.202899 371 master.cpp:4572] Status update TASK_RUNNING > (UUID: 63ef56ab-2f32-4945-9f6d-f35829c3dc86) for task > 124ff0e0-2a13-44e9-930a-3064718f86ae of framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 from slave > 78046f05-cfb7-4478-8385-528382f71b9e-S1 at slave(112)@172.17.0.1:38193 > (maintenance-host-2) > I1203 18:20:08.202953 371 master.cpp:4620] Forwarding status update > TASK_RUNNING (UUID: 63ef56ab-2f32-4945-9f6d-f35829c3dc86) for task > 124ff0e0-2a13-44e9-930a-3064718f86ae of framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 > I1203 18:20:08.203388 371 master.cpp:6224] Updating the state of task > 124ff0e0-2a13-44e9-930a-3064718f86ae of framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 (latest state: TASK_RUNNING, status > update state: TASK_RUNNING) > I1203 18:20:08.203501 371 exec.cpp:341] Executor received status update > acknowledgement 63ef56ab-2f32-4945-9f6d-f35829c3dc86 for task > 124ff0e0-2a13-44e9-930a-3064718f86ae of framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 > I1203 18:20:08.205032 372 scheduler.cpp:457] Enqueuing event UPDATE > received from master@172.17.0.1:38193 > I1203 18:20:08.228276 360 scheduler.cpp:298] Sending ACKNOWLEDGE call to > master@172.17.0.1:38193 > I1203 18:20:08.230792 364 process.cpp:3067] Handling HTTP event for process > 'master' with path: '/master/api/v1/scheduler' > I1203 18:20:08.230885 364 http.cpp:336] HTTP POST for > /master/api/v1/scheduler from 172.17.0.1:35708 > I1203 18:20:08.231041 364 master.cpp:3729] Processing ACKNOWLEDGE call > a4153a7a-bb32-41cc-9457-841754508d66 for task > e0957182-29d5-4591-938c-583b94075cac of framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 (default) on slave > 78046f05-cfb7-4478-8385-528382f71b9e-S0 > I1203 18:20:08.231542 372 status_update_manager.cpp:392] Received status > update acknowledgement (UUID: a4153a7a-bb32-41cc-9457-841754508d66) for task > e0957182-29d5-4591-938c-583b94075cac of framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 > I1203 18:20:08.231957 364 slave.cpp:2346] Status update manager > successfully handled status update acknowledgement (UUID: > a4153a7a-bb32-41cc-9457-841754508d66) for task > e0957182-29d5-4591-938c-583b94075cac of framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 > I1203 18:20:08.239132 372 scheduler.cpp:298] Sending ACKNOWLEDGE call to > master@172.17.0.1:38193 > I1203 18:20:08.241991 360 process.cpp:3067] Handling HTTP event for process > 'master' with path: '/master/api/v1/scheduler' > I1203 18:20:08.242050 360 http.cpp:336] HTTP POST for > /master/api/v1/scheduler from 172.17.0.1:35709 > I1203 18:20:08.242168 360 master.cpp:3729] Processing ACKNOWLEDGE call > 63ef56ab-2f32-4945-9f6d-f35829c3dc86 for task > 124ff0e0-2a13-44e9-930a-3064718f86ae of framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 (default) on slave > 78046f05-cfb7-4478-8385-528382f71b9e-S1 > I1203 18:20:08.242746 360 status_update_manager.cpp:392] Received status > update acknowledgement (UUID: 63ef56ab-2f32-4945-9f6d-f35829c3dc86) for task > 124ff0e0-2a13-44e9-930a-3064718f86ae of framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 > I1203 18:20:08.243091 360 slave.cpp:2346] Status update manager > successfully handled status update acknowledgement (UUID: > 63ef56ab-2f32-4945-9f6d-f35829c3dc86) for task > 124ff0e0-2a13-44e9-930a-3064718f86ae of framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 > I1203 18:20:08.244417 360 scheduler.cpp:298] Sending DECLINE call to > master@172.17.0.1:38193 > I1203 18:20:08.246664 374 process.cpp:3067] Handling HTTP event for process > 'master' with path: '/master/api/v1/scheduler' > I1203 18:20:08.246726 374 http.cpp:336] HTTP POST for > /master/api/v1/scheduler from 172.17.0.1:35710 > I1203 18:20:08.246840 374 master.cpp:3455] Processing DECLINE call for > offers: [ 78046f05-cfb7-4478-8385-528382f71b9e-O3 ] for framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 (default) > I1203 18:20:08.247181 371 hierarchical.cpp:699] Framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 filtered inverse offers from slave > 78046f05-cfb7-4478-8385-528382f71b9e-S0 for 101secs > I1203 18:20:08.248678 364 scheduler.cpp:298] Sending ACCEPT call to > master@172.17.0.1:38193 > I1203 18:20:08.250946 374 process.cpp:3067] Handling HTTP event for process > 'master' with path: '/master/api/v1/scheduler' > I1203 18:20:08.251015 374 http.cpp:336] HTTP POST for > /master/api/v1/scheduler from 172.17.0.1:35711 > W1203 18:20:08.251413 374 master.cpp:2973] ACCEPT call used invalid offers > '[ 78046f05-cfb7-4478-8385-528382f71b9e-O2 ]': Offer > 78046f05-cfb7-4478-8385-528382f71b9e-O2 is no longer valid > I1203 18:20:08.251454 366 hierarchical.cpp:1062] No resources available to > allocate! > I1203 18:20:08.251724 366 hierarchical.cpp:1272] Filtered unavailability on > slave 78046f05-cfb7-4478-8385-528382f71b9e-S0 for framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 > I1203 18:20:08.251934 366 hierarchical.cpp:957] Performed allocation for 2 > slaves in 1.499989ms > 2015-12-03 > 18:20:09,158:341(0x7f61e908c700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:43036] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > 2015-12-03 > 18:20:12,495:341(0x7f61e908c700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:43036] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > 2015-12-03 > 18:20:15,832:341(0x7f61e908c700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:43036] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > 2015-12-03 > 18:20:19,167:341(0x7f61e908c700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:43036] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > 2015-12-03 > 18:20:22,503:341(0x7f61e908c700):ZOO_ERROR@handle_socket_error_msg@1697: > Socket [127.0.0.1:43036] zk retcode=-4, errno=111(Connection refused): server > refused to accept the client > ../../src/tests/master_maintenance_tests.cpp:1559: Failure > Failed to wait 15secs for event > I1203 18:20:23.261693 365 master.cpp:938] Master terminating > W1203 18:20:23.261994 365 master.cpp:6276] Removing task > 124ff0e0-2a13-44e9-930a-3064718f86ae with resources cpus(*):2; mem(*):1024; > disk(*):1024; ports(*):[31000-32000] of framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 on slave > 78046f05-cfb7-4478-8385-528382f71b9e-S1 at slave(112)@172.17.0.1:38193 > (maintenance-host-2) in non-terminal state TASK_RUNNING > I1203 18:20:23.263239 368 hierarchical.cpp:410] Removed slave > 78046f05-cfb7-4478-8385-528382f71b9e-S1 > I1203 18:20:23.263739 365 master.cpp:6319] Removing executor 'executor-2' > with resources of framework 78046f05-cfb7-4478-8385-528382f71b9e-0000 on > slave 78046f05-cfb7-4478-8385-528382f71b9e-S1 at slave(112)@172.17.0.1:38193 > (maintenance-host-2) > W1203 18:20:23.264315 365 master.cpp:6276] Removing task > e0957182-29d5-4591-938c-583b94075cac with resources cpus(*):2; mem(*):1024; > disk(*):1024; ports(*):[31000-32000] of framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 on slave > 78046f05-cfb7-4478-8385-528382f71b9e-S0 at slave(111)@172.17.0.1:38193 > (maintenance-host) in non-terminal state TASK_RUNNING > I1203 18:20:23.264825 367 hierarchical.cpp:410] Removed slave > 78046f05-cfb7-4478-8385-528382f71b9e-S0 > I1203 18:20:23.265086 365 master.cpp:6319] Removing executor 'executor-1' > with resources of framework 78046f05-cfb7-4478-8385-528382f71b9e-0000 on > slave 78046f05-cfb7-4478-8385-528382f71b9e-S0 at slave(111)@172.17.0.1:38193 > (maintenance-host) > I1203 18:20:23.265804 372 hierarchical.cpp:260] Removed framework > 78046f05-cfb7-4478-8385-528382f71b9e-0000 > I1203 18:20:23.267813 367 slave.cpp:3243] master@172.17.0.1:38193 exited > W1203 18:20:23.267844 367 slave.cpp:3246] Master disconnected! Waiting for > a new master to be elected > I1203 18:20:23.267884 365 slave.cpp:3243] master@172.17.0.1:38193 exited > W1203 18:20:23.267940 365 slave.cpp:3246] Master disconnected! Waiting for > a new master to be elected > F1203 18:20:23.267940 341 logging.cpp:55] RAW: Pure virtual method called > @ 0x7f628594a4ae google::LogMessage::Fail() > @ 0x7f628594fa04 google::RawLog__() > @ 0x7f6284b9f030 __cxa_pure_virtual > @ 0x9eb126 mesos::internal::tests::Cluster::Slaves::shutdown() > @ 0xf0fb90 mesos::internal::tests::MesosTest::ShutdownSlaves() > @ 0xf0fb52 mesos::internal::tests::MesosTest::Shutdown() > @ 0xf0c12b mesos::internal::tests::MesosTest::TearDown() > @ 0x15037ca > testing::internal::HandleSehExceptionsInMethodIfSupported<>() > @ 0x14fe6a4 > testing::internal::HandleExceptionsInMethodIfSupported<>() > @ 0x14dfcc6 testing::Test::Run() > @ 0x14e0400 testing::TestInfo::Run() > @ 0x14e0a46 testing::TestCase::Run() > @ 0x14e7320 testing::internal::UnitTestImpl::RunAllTests() > @ 0x15043ef > testing::internal::HandleSehExceptionsInMethodIfSupported<>() > @ 0x14ff21a > testing::internal::HandleExceptionsInMethodIfSupported<>() > @ 0x14e6066 testing::UnitTest::Run() > @ 0xd0eba0 RUN_ALL_TESTS() > @ 0xd0e77e main > @ 0x7f62800d3af5 __libc_start_main > @ 0x939379 (unknown) > > > On Thu, Dec 3, 2015 at 10:20 AM, Apache Jenkins Server < > jenk...@builds.apache.org> wrote: > >> See < >> https://builds.apache.org/job/Mesos/COMPILER=gcc,CONFIGURATION=--verbose%20--enable-libevent%20--enable-ssl,OS=centos%3A7,label_exp=docker%7C%7CHadoop/1315/ >> > >> >> ------------------------------------------ >> [...truncated 65719 lines...] >> I1203 18:20:08.083830 362 leveldb.cpp:341] Persisting action (536 >> bytes) to leveldb took 489932ns >> I1203 18:20:08.083856 362 replica.cpp:713] Persisted action at 5 >> I1203 18:20:08.083878 362 replica.cpp:698] Replica learned APPEND >> action at position 5 >> I1203 18:20:08.086607 365 registrar.cpp:484] Successfully updated the >> 'registry' in 7.361024ms >> I1203 18:20:08.086846 362 log.cpp:702] Attempting to truncate the log >> to 5 >> I1203 18:20:08.087077 362 coordinator.cpp:348] Coordinator attempting >> to write TRUNCATE action at position 6 >> I1203 18:20:08.088059 375 master.cpp:4085] Registered slave >> 78046f05-cfb7-4478-8385-528382f71b9e-S1 at slave(112)@172.17.0.1:38193 >> (maintenance-host-2) with cpus(*):2; mem(*):1024; disk(*):1024; >> ports(*):[31000-32000] >> I1203 18:20:08.088321 362 hierarchical.cpp:380] Added slave >> 78046f05-cfb7-4478-8385-528382f71b9e-S1 (maintenance-host-2) with >> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: ) >> I1203 18:20:08.088524 362 hierarchical.cpp:1062] No resources available >> to allocate! >> I1203 18:20:08.088575 362 hierarchical.cpp:1155] No inverse offers to >> send out! >> I1203 18:20:08.088601 362 hierarchical.cpp:973] Performed allocation >> for slave 78046f05-cfb7-4478-8385-528382f71b9e-S1 in 240968ns >> I1203 18:20:08.088644 360 replica.cpp:538] Replica received write >> request for position 6 from (3844)@172.17.0.1:38193 >> I1203 18:20:08.088717 361 slave.cpp:3197] Received ping from >> slave-observer(115)@172.17.0.1:38193 >> I1203 18:20:08.089000 361 slave.cpp:902] Registered with master >> master@172.17.0.1:38193; given slave ID >> 78046f05-cfb7-4478-8385-528382f71b9e-S1 >> I1203 18:20:08.089025 361 fetcher.cpp:79] Clearing fetcher cache >> I1203 18:20:08.089114 360 leveldb.cpp:341] Persisting action (16 bytes) >> to leveldb took 427596ns >> I1203 18:20:08.089143 360 replica.cpp:713] Persisted action at 6 >> I1203 18:20:08.089632 374 status_update_manager.cpp:181] Resuming >> sending status updates >> I1203 18:20:08.089820 361 slave.cpp:925] Checkpointing SlaveInfo to >> '/tmp/MasterMaintenanceTest_InverseOffersFilters_XSU2vX/meta/slaves/78046f05-cfb7-4478-8385-528382f71b9e-S1/ >> slave.info' >> I1203 18:20:08.090217 361 slave.cpp:961] Forwarding total >> oversubscribed resources >> I1203 18:20:08.090314 360 replica.cpp:692] Replica received learned >> notice for position 6 from @0.0.0.0:0 >> I1203 18:20:08.090492 361 master.cpp:4427] Received update of slave >> 78046f05-cfb7-4478-8385-528382f71b9e-S1 at slave(112)@172.17.0.1:38193 >> (maintenance-host-2) with total oversubscribed resources >> I1203 18:20:08.090750 360 leveldb.cpp:341] Persisting action (18 bytes) >> to leveldb took 402522ns >> I1203 18:20:08.090843 360 leveldb.cpp:399] Deleting ~2 keys from >> leveldb took 64765ns >> I1203 18:20:08.090870 360 replica.cpp:713] Persisted action at 6 >> I1203 18:20:08.090895 360 replica.cpp:698] Replica learned TRUNCATE >> action at position 6 >> I1203 18:20:08.090980 361 hierarchical.cpp:434] Slave >> 78046f05-cfb7-4478-8385-528382f71b9e-S1 (maintenance-host-2) updated with >> oversubscribed resources (total: cpus(*):2; mem(*):1024; disk(*):1024; >> ports(*):[31000-32000], allocated: ) >> I1203 18:20:08.091161 361 hierarchical.cpp:1062] No resources available >> to allocate! >> I1203 18:20:08.091203 361 hierarchical.cpp:1155] No inverse offers to >> send out! >> I1203 18:20:08.091225 361 hierarchical.cpp:973] Performed allocation >> for slave 78046f05-cfb7-4478-8385-528382f71b9e-S1 in 203111ns >> I1203 18:20:08.094625 375 process.cpp:3067] Handling HTTP event for >> process 'master' with path: '/master/maintenance/schedule' >> I1203 18:20:08.094715 375 http.cpp:336] HTTP POST for >> /master/maintenance/schedule from 172.17.0.1:35704 >> I1203 18:20:08.095815 367 registrar.cpp:439] Applied 1 operations in >> 233576ns; attempting to update the 'registry' >> I1203 18:20:08.097347 374 log.cpp:683] Attempting to append 734 bytes >> to the log >> I1203 18:20:08.097617 374 coordinator.cpp:348] Coordinator attempting >> to write APPEND action at position 7 >> I1203 18:20:08.098783 374 replica.cpp:538] Replica received write >> request for position 7 from (3845)@172.17.0.1:38193 >> I1203 18:20:08.099269 374 leveldb.cpp:341] Persisting action (753 >> bytes) to leveldb took 422267ns >> I1203 18:20:08.099300 374 replica.cpp:713] Persisted action at 7 >> I1203 18:20:08.100100 374 replica.cpp:692] Replica received learned >> notice for position 7 from @0.0.0.0:0 >> I1203 18:20:08.100509 374 leveldb.cpp:341] Persisting action (755 >> bytes) to leveldb took 378294ns >> I1203 18:20:08.100538 374 replica.cpp:713] Persisted action at 7 >> I1203 18:20:08.100560 374 replica.cpp:698] Replica learned APPEND >> action at position 7 >> I1203 18:20:08.103358 368 registrar.cpp:484] Successfully updated the >> 'registry' in 7.382784ms >> I1203 18:20:08.103742 374 log.cpp:702] Attempting to truncate the log >> to 7 >> I1203 18:20:08.104044 362 master.cpp:4483] Updating unavailability of >> slave 78046f05-cfb7-4478-8385-528382f71b9e-S1 at slave(112)@ >> 172.17.0.1:38193 (maintenance-host-2), starting at 2399.10961820361weeks >> I1203 18:20:08.104357 374 coordinator.cpp:348] Coordinator attempting >> to write TRUNCATE action at position 8 >> I1203 18:20:08.105026 362 master.cpp:4483] Updating unavailability of >> slave 78046f05-cfb7-4478-8385-528382f71b9e-S0 at slave(111)@ >> 172.17.0.1:38193 (maintenance-host), starting at 2399.10961820361weeks >> I1203 18:20:08.105545 363 hierarchical.cpp:1062] No resources available >> to allocate! >> I1203 18:20:08.105623 363 hierarchical.cpp:1155] No inverse offers to >> send out! >> I1203 18:20:08.105664 363 hierarchical.cpp:973] Performed allocation >> for slave 78046f05-cfb7-4478-8385-528382f71b9e-S1 in 323361ns >> I1203 18:20:08.105907 363 hierarchical.cpp:1062] No resources available >> to allocate! >> I1203 18:20:08.105969 363 hierarchical.cpp:1155] No inverse offers to >> send out! >> I1203 18:20:08.105998 363 hierarchical.cpp:973] Performed allocation >> for slave 78046f05-cfb7-4478-8385-528382f71b9e-S0 in 227967ns >> I1203 18:20:08.106138 362 master.cpp:4483] Updating unavailability of >> slave 78046f05-cfb7-4478-8385-528382f71b9e-S0 at slave(111)@ >> 172.17.0.1:38193 (maintenance-host), starting at 2399.10961820361weeks >> I1203 18:20:08.106348 362 master.cpp:4483] Updating unavailability of >> slave 78046f05-cfb7-4478-8385-528382f71b9e-S1 at slave(112)@ >> 172.17.0.1:38193 (maintenance-host-2), starting at 2399.10961820361weeks >> I1203 18:20:08.106581 364 replica.cpp:538] Replica received write >> request for position 8 from (3846)@172.17.0.1:38193 >> I1203 18:20:08.106816 370 hierarchical.cpp:1062] No resources available >> to allocate! >> I1203 18:20:08.106873 370 hierarchical.cpp:1155] No inverse offers to >> send out! >> I1203 18:20:08.107069 370 hierarchical.cpp:973] Performed allocation >> for slave 78046f05-cfb7-4478-8385-528382f71b9e-S0 in 554269ns >> I1203 18:20:08.107333 364 leveldb.cpp:341] Persisting action (16 bytes) >> to leveldb took 640014ns >> I1203 18:20:08.107363 364 replica.cpp:713] Persisted action at 8 >> I1203 18:20:08.107599 370 hierarchical.cpp:1062] No resources available >> to allocate! >> I1203 18:20:08.107808 370 hierarchical.cpp:1155] No inverse offers to >> send out! >> I1203 18:20:08.107841 370 hierarchical.cpp:973] Performed allocation >> for slave 78046f05-cfb7-4478-8385-528382f71b9e-S1 in 380899ns >> I1203 18:20:08.109459 371 replica.cpp:692] Replica received learned >> notice for position 8 from @0.0.0.0:0 >> I1203 18:20:08.110229 341 scheduler.cpp:154] Version: 0.27.0 >> I1203 18:20:08.110628 371 leveldb.cpp:341] Persisting action (18 bytes) >> to leveldb took 1.126432ms >> I1203 18:20:08.110713 371 leveldb.cpp:399] Deleting ~2 keys from >> leveldb took 42772ns >> I1203 18:20:08.110736 371 replica.cpp:713] Persisted action at 8 >> I1203 18:20:08.110766 371 replica.cpp:698] Replica learned TRUNCATE >> action at position 8 >> I1203 18:20:08.111073 370 scheduler.cpp:236] New master detected at >> master@172.17.0.1:38193 >> I1203 18:20:08.121060 370 scheduler.cpp:298] Sending SUBSCRIBE call to >> master@172.17.0.1:38193 >> I1203 18:20:08.123993 370 process.cpp:3067] Handling HTTP event for >> process 'master' with path: '/master/api/v1/scheduler' >> I1203 18:20:08.124058 370 http.cpp:336] HTTP POST for >> /master/api/v1/scheduler from 172.17.0.1:35705 >> I1203 18:20:08.124267 370 master.cpp:1899] Received subscription >> request for HTTP framework 'default' >> I1203 18:20:08.124351 370 master.cpp:1676] Authorizing framework >> principal 'test-principal' to receive offers for role '*' >> I1203 18:20:08.124866 360 master.cpp:1991] Subscribing framework >> 'default' with checkpointing disabled and capabilities [ ] >> I1203 18:20:08.125830 371 master.hpp:1583] Sending heartbeat to >> 78046f05-cfb7-4478-8385-528382f71b9e-0000 >> I1203 18:20:08.125911 370 hierarchical.cpp:220] Added framework >> 78046f05-cfb7-4478-8385-528382f71b9e-0000 >> I1203 18:20:08.127351 360 scheduler.cpp:457] Enqueuing event SUBSCRIBED >> received from master@172.17.0.1:38193 >> I1203 18:20:08.127707 370 hierarchical.cpp:957] Performed allocation >> for 2 slaves in 1.763005ms >> I1203 18:20:08.127928 370 scheduler.cpp:457] Enqueuing event HEARTBEAT >> received from master@172.17.0.1:38193 >> I1203 18:20:08.128466 370 master_maintenance_tests.cpp:172] Ignoring >> HEARTBEAT event >> I1203 18:20:08.128676 360 master.cpp:5137] Sending 2 offers to >> framework 78046f05-cfb7-4478-8385-528382f71b9e-0000 (default) >> I1203 18:20:08.129547 360 master.cpp:5227] Sending 2 inverse offers to >> framework 78046f05-cfb7-4478-8385-528382f71b9e-0000 (default) >> I1203 18:20:08.131640 372 scheduler.cpp:457] Enqueuing event OFFERS >> received from master@172.17.0.1:38193 >> I1203 18:20:08.132640 372 scheduler.cpp:457] Enqueuing event OFFERS >> received from master@172.17.0.1:38193 >> I1203 18:20:08.142935 368 hierarchical.cpp:1062] No resources available >> to allocate! >> I1203 18:20:08.143271 368 hierarchical.cpp:957] Performed allocation >> for 2 slaves in 1.280338ms >> I1203 18:20:08.154265 363 scheduler.cpp:298] Sending ACCEPT call to >> master@172.17.0.1:38193 >> I1203 18:20:08.156982 373 process.cpp:3067] Handling HTTP event for >> process 'master' with path: '/master/api/v1/scheduler' >> I1203 18:20:08.157058 373 http.cpp:336] HTTP POST for >> /master/api/v1/scheduler from 172.17.0.1:35706 >> I1203 18:20:08.158001 373 master.cpp:3010] Processing ACCEPT call for >> offers: [ 78046f05-cfb7-4478-8385-528382f71b9e-O0 ] on slave >> 78046f05-cfb7-4478-8385-528382f71b9e-S0 at slave(111)@172.17.0.1:38193 >> (maintenance-host) for framework 78046f05-cfb7-4478-8385-528382f71b9e-0000 >> (default) >> I1203 18:20:08.158068 373 master.cpp:2742] Authorizing framework >> principal 'test-principal' to launch task >> e0957182-29d5-4591-938c-583b94075cac as user 'mesos' >> W1203 18:20:08.160732 373 validation.cpp:420] Executor executor-1 for >> task e0957182-29d5-4591-938c-583b94075cac uses less CPUs (None) than the >> minimum required (0.01). Please update your executor, as this will be >> mandatory in future releases. >> W1203 18:20:08.160810 373 validation.cpp:432] Executor executor-1 for >> task e0957182-29d5-4591-938c-583b94075cac uses less memory (None) than the >> minimum required (32MB). Please update your executor, as this will be >> mandatory in future releases. >> I1203 18:20:08.161272 373 master.hpp:176] Adding task >> e0957182-29d5-4591-938c-583b94075cac with resources cpus(*):2; mem(*):1024; >> disk(*):1024; ports(*):[31000-32000] on slave >> 78046f05-cfb7-4478-8385-528382f71b9e-S0 (maintenance-host) >> I1203 18:20:08.161528 373 master.cpp:3403] Launching task >> e0957182-29d5-4591-938c-583b94075cac of framework >> 78046f05-cfb7-4478-8385-528382f71b9e-0000 (default) with resources >> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave >> 78046f05-cfb7-4478-8385-528382f71b9e-S0 at slave(111)@172.17.0.1:38193 >> (maintenance-host) >> I1203 18:20:08.163053 361 slave.cpp:1292] Got assigned task >> e0957182-29d5-4591-938c-583b94075cac for framework >> 78046f05-cfb7-4478-8385-528382f71b9e-0000 >> I1203 18:20:08.163275 373 scheduler.cpp:298] Sending ACCEPT call to >> master@172.17.0.1:38193 >> I1203 18:20:08.165091 361 slave.cpp:1411] Launching task >> e0957182-29d5-4591-938c-583b94075cac for framework >> 78046f05-cfb7-4478-8385-528382f71b9e-0000 >> I1203 18:20:08.166036 361 paths.cpp:434] Trying to chown >> '/tmp/MasterMaintenanceTest_InverseOffersFilters_t0jUCH/slaves/78046f05-cfb7-4478-8385-528382f71b9e-S0/frameworks/78046f05-cfb7-4478-8385-528382f71b9e-0000/executors/executor-1/runs/21ad7ee3-0cf3-4cba-a600-9a92469c806d' >> to user 'mesos' >> I1203 18:20:08.169783 365 process.cpp:3067] Handling HTTP event for >> process 'master' with path: '/master/api/v1/scheduler' >> I1203 18:20:08.170961 365 http.cpp:336] HTTP POST for >> /master/api/v1/scheduler from 172.17.0.1:35707 >> I1203 18:20:08.172499 365 master.cpp:3010] Processing ACCEPT call for >> offers: [ 78046f05-cfb7-4478-8385-528382f71b9e-O1 ] on slave >> 78046f05-cfb7-4478-8385-528382f71b9e-S1 at slave(112)@172.17.0.1:38193 >> (maintenance-host-2) for framework >> 78046f05-cfb7-4478-8385-528382f71b9e-0000 (default) >> I1203 18:20:08.172575 365 master.cpp:2742] Authorizing framework >> principal 'test-principal' to launch task >> 124ff0e0-2a13-44e9-930a-3064718f86ae as user 'mesos' >> I1203 18:20:08.173951 361 slave.cpp:5042] Launching executor executor-1 >> of framework 78046f05-cfb7-4478-8385-528382f71b9e-0000 with resources in >> work directory >> '/tmp/MasterMaintenanceTest_InverseOffersFilters_t0jUCH/slaves/78046f05-cfb7-4478-8385-528382f71b9e-S0/frameworks/78046f05-cfb7-4478-8385-528382f71b9e-0000/executors/executor-1/runs/21ad7ee3-0cf3-4cba-a600-9a92469c806d' >> I1203 18:20:08.176758 361 exec.cpp:134] Version: 0.27.0 >> W1203 18:20:08.178130 362 validation.cpp:420] Executor executor-2 for >> task 124ff0e0-2a13-44e9-930a-3064718f86ae uses less CPUs (None) than the >> minimum required (0.01). Please update your executor, as this will be >> mandatory in future releases. >> W1203 18:20:08.178272 362 validation.cpp:432] Executor executor-2 for >> task 124ff0e0-2a13-44e9-930a-3064718f86ae uses less memory (None) than the >> minimum required (32MB). Please update your executor, as this will be >> mandatory in future releases. >> I1203 18:20:08.178927 362 master.hpp:176] Adding task >> 124ff0e0-2a13-44e9-930a-3064718f86ae with resources cpus(*):2; mem(*):1024; >> disk(*):1024; ports(*):[31000-32000] on slave >> 78046f05-cfb7-4478-8385-528382f71b9e-S1 (maintenance-host-2) >> I1203 18:20:08.179332 362 master.cpp:3403] Launching task >> 124ff0e0-2a13-44e9-930a-3064718f86ae of framework >> 78046f05-cfb7-4478-8385-528382f71b9e-0000 (default) with resources >> cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave >> 78046f05-cfb7-4478-8385-528382f71b9e-S1 at slave(112)@172.17.0.1:38193 >> (maintenance-host-2) >> I1203 18:20:08.180057 362 slave.cpp:1292] Got assigned task >> 124ff0e0-2a13-44e9-930a-3064718f86ae for framework >> 78046f05-cfb7-4478-8385-528382f71b9e-0000 >> I1203 18:20:08.180531 361 slave.cpp:1629] Queuing task >> 'e0957182-29d5-4591-938c-583b94075cac' for executor 'executor-1' of >> framework 78046f05-cfb7-4478-8385-528382f71b9e-0000 >> I1203 18:20:08.180651 365 exec.cpp:184] Executor started at: >> executor(48)@172.17.0.1:38193 with pid 341 >> I1203 18:20:08.181100 362 slave.cpp:1411] Launching task >> 124ff0e0-2a13-44e9-930a-3064718f86ae for framework >> 78046f05-cfb7-4478-8385-528382f71b9e-0000 >> I1203 18:20:08.181176 361 slave.cpp:680] Successfully attached file >> '/tmp/MasterMaintenanceTest_InverseOffersFilters_t0jUCH/slaves/78046f05-cfb7-4478-8385-528382f71b9e-S0/frameworks/78046f05-cfb7-4478-8385-528382f71b9e-0000/executors/executor-1/runs/21ad7ee3-0cf3-4cba-a600-9a92469c806d' >> I1203 18:20:08.181932 361 slave.cpp:2406] Got registration for executor >> 'executor-1' of framework 78046f05-cfb7-4478-8385-528382f71b9e-0000 from >> executor(48)@172.17.0.1:38193 >> I1203 18:20:08.181985 362 paths.cpp:434] Trying to chown >> '/tmp/MasterMaintenanceTest_InverseOffersFilters_XSU2vX/slaves/78046f05-cfb7-4478-8385-528382f71b9e-S1/frameworks/78046f05-cfb7-4478-8385-528382f71b9e-0000/executors/executor-2/runs/6104f936-ea54-4f01-a5f9-01dd606a7215' >> to user 'mesos' >> I1203 18:20:08.185151 374 exec.cpp:208] Executor registered on slave >> 78046f05-cfb7-4478-8385-528382f71b9e-S0 >> I1203 18:20:08.185253 374 exec.cpp:220] Executor::registered took >> 50794ns >> I1203 18:20:08.185778 361 slave.cpp:1794] Sending queued task >> 'e0957182-29d5-4591-938c-583b94075cac' to executor 'executor-1' of >> framework 78046f05-cfb7-4478-8385-528382f71b9e-0000 at executor(48)@ >> 172.17.0.1:38193 >> I1203 18:20:08.186409 370 exec.cpp:295] Executor asked to run task >> 'e0957182-29d5-4591-938c-583b94075cac' >> I1203 18:20:08.186703 370 exec.cpp:304] Executor::launchTask took >> 265614ns >> I1203 18:20:08.187018 370 exec.cpp:517] Executor sending status update >> TASK_RUNNING (UUID: a4153a7a-bb32-41cc-9457-841754508d66) for task >> e0957182-29d5-4591-938c-583b94075cac of framework >> 78046f05-cfb7-4478-8385-528382f71b9e-0000 >> I1203 18:20:08.187510 370 slave.cpp:2763] Handling status update >> TASK_RUNNING (UUID: a4153a7a-bb32-41cc-9457-841754508d66) for task >> e0957182-29d5-4591-938c-583b94075cac of framework >> 78046f05-cfb7-4478-8385-528382f71b9e-0000 from executor(48)@ >> 172.17.0.1:38193 >> I1203 18:20:08.188098 371 status_update_manager.cpp:320] Received >> status update TASK_RUNNING (UUID: a4153a7a-bb32-41cc-9457-841754508d66) for >> task e0957182-29d5-4591-938c-583b94075cac of framework >> 78046f05-cfb7-4478-8385-528382f71b9e-0000 >> I1203 18:20:08.188145 371 status_update_manager.cpp:497] Creating >> StatusUpdate stream for task e0957182-29d5-4591-938c-583b94075cac of >> framework 78046f05-cfb7-4478-8385-528382f71b9e-0000 >> I1203 18:20:08.188643 371 status_update_manager.cpp:374] Forwarding >> update TASK_RUNNING (UUID: a4153a7a-bb32-41cc-9457-841754508d66) for task >> e0957182-29d5-4591-938c-583b94075cac of framework >> 78046f05-cfb7-4478-8385-528382f71b9e-0000 to the slave >> I1203 18:20:08.189015 366 slave.cpp:3115] Forwarding the update >> TASK_RUNNING (UUID: a4153a7a-bb32-41cc-9457-841754508d66) for task >> e0957182-29d5-4591-938c-583b94075cac of framework >> 78046f05-cfb7-4478-8385-528382f71b9e-0000 to master@172.17.0.1:38193 >> I1203 18:20:08.189395 366 slave.cpp:3009] Status update manager >> successfully handled status update TASK_RUNNING (UUID: >> a4153a7a-bb32-41cc-9457-841754508d66) for task >> e0957182-29d5-4591-938c-583b94075cac of framework >> 78046f05-cfb7-4478-8385-528382f71b9e-0000 >> I1203 18:20:08.189781 372 master.cpp:4572] Status update TASK_RUNNING >> (UUID: a4153a7a-bb32-41cc-9457-841754508d66) for task >> e0957182-29d5-4591-938c-583b94075cac of framework >> 78046f05-cfb7-4478-8385-528382f71b9e-0000 from slave >> 78046f05-cfb7-4478-8385-528382f71b9e-S0 at slave(111)@172.17.0.1:38193 >> (maintenance-host) >> I1203 18:20:08.190065 372 master.cpp:4620] Forwarding status update >> TASK_RUNNING (UUID: a4153a7a-bb32-41cc-9457-841754508d66) for task >> e0957182-29d5-4591-938c-583b94075cac of framework >> 78046f05-cfb7-4478-8385-528382f71b9e-0000 >> I1203 18:20:08.190698 372 master.cpp:6224] Updating the state of task >> e0957182-29d5-4591-938c-583b94075cac of framework >> 78046f05-cfb7-4478-8385-528382f71b9e-0000 (latest state: TASK_RUNNING, >> status update state: TASK_RUNNING) >> I1203 18:20:08.191265 366 slave.cpp:3025] Sending acknowledgement for >> status update TASK_RUNNING (UUID: a4153a7a-bb32-41cc-9457-841754508d66) for >> task e0957182-29d5-4591-938c-583b94075cac of framework >> 78046f05-cfb7-4478-8385-528382f71b9e-0000 to executor(48)@ >> 172.17.0.1:38193 >> I1203 18:20:08.191725 366 exec.cpp:341] Executor received status update >> acknowledgement a4153a7a-bb32-41cc-9457-841754508d66 for task >> e0957182-29d5-4591-938c-583b94075cac of framework >> 78046f05-cfb7-4478-8385-528382f71b9e-0000 >> I1203 18:20:08.193317 363 scheduler.cpp:457] Enqueuing event UPDATE >> received from master@172.17.0.1:38193 >> I1203 18:20:08.194072 362 slave.cpp:5042] Launching executor executor-2 >> of framework 78046f05-cfb7-4478-8385-528382f71b9e-0000 with resources in >> work directory >> '/tmp/MasterMaintenanceTest_InverseOffersFilters_XSU2vX/slaves/78046f05-cfb7-4478-8385-528382f71b9e-S1/frameworks/78046f05-cfb7-4478-8385-528382f71b9e-0000/executors/executor-2/runs/6104f936-ea54-4f01-a5f9-01dd606a7215' >> I1203 18:20:08.196590 362 exec.cpp:134] Version: 0.27.0 >> I1203 18:20:08.197185 369 exec.cpp:184] Executor started at: >> executor(49)@172.17.0.1:38193 with pid 341 >> I1203 18:20:08.197547 362 slave.cpp:1629] Queuing task >> '124ff0e0-2a13-44e9-930a-3064718f86ae' for executor 'executor-2' of >> framework 78046f05-cfb7-4478-8385-528382f71b9e-0000 >> I1203 18:20:08.197845 362 slave.cpp:680] Successfully attached file >> '/tmp/MasterMaintenanceTest_InverseOffersFilters_XSU2vX/slaves/78046f05-cfb7-4478-8385-528382f71b9e-S1/frameworks/78046f05-cfb7-4478-8385-528382f71b9e-0000/executors/executor-2/runs/6104f936-ea54-4f01-a5f9-01dd606a7215' >> I1203 18:20:08.198031 362 slave.cpp:2406] Got registration for executor >> 'executor-2' of framework 78046f05-cfb7-4478-8385-528382f71b9e-0000 from >> executor(49)@172.17.0.1:38193 >> I1203 18:20:08.198644 369 exec.cpp:208] Executor registered on slave >> 78046f05-cfb7-4478-8385-528382f71b9e-S1 >> I1203 18:20:08.198714 369 exec.cpp:220] Executor::registered took >> 38382ns >> I1203 18:20:08.199406 362 slave.cpp:1794] Sending queued task >> '124ff0e0-2a13-44e9-930a-3064718f86ae' to executor 'executor-2' of >> framework 78046f05-cfb7-4478-8385-528382f71b9e-0000 at executor(49)@ >> 172.17.0.1:38193 >> I1203 18:20:08.199937 369 exec.cpp:295] Executor asked to run task >> '124ff0e0-2a13-44e9-930a-3064718f86ae' >> I1203 18:20:08.200042 369 exec.cpp:304] Executor::launchTask took >> 77814ns >> I1203 18:20:08.200152 369 exec.cpp:517] Executor sending status update >> TASK_RUNNING (UUID: 63ef56ab-2f32-4945-9f6d-f35829c3dc86) for task >> 124ff0e0-2a13-44e9-930a-3064718f86ae of framework >> 78046f05-cfb7-4478-8385-528382f71b9e-0000 >> I1203 18:20:08.200451 369 slave.cpp:2763] Handling status update >> TASK_RUNNING (UUID: 63ef56ab-2f32-4945-9f6d-f35829c3dc86) for task >> 124ff0e0-2a13-44e9-930a-3064718f86ae of framework >> 78046f05-cfb7-4478-8385-528382f71b9e-0000 from executor(49)@ >> 172.17.0.1:38193 >> I1203 18:20:08.200881 368 status_update_manager.cpp:320] Received >> status update TASK_RUNNING (UUID: 63ef56ab-2f32-4945-9f6d-f35829c3dc86) for >> task 124ff0e0-2a13-44e9-930a-3064718f86ae of framework >> 78046f05-cfb7-4478-8385-528382f71b9e-0000 >> I1203 18:20:08.201140 368 status_update_manager.cpp:497] Creating >> StatusUpdate stream for task 124ff0e0-2a13-44e9-930a-3064718f86ae of >> framework 78046f05-cfb7-4478-8385-528382f71b9e-0000 >> I1203 18:20:08.201761 368 status_update_manager.cpp:374] Forwarding >> update TASK_RUNNING (UUID: 63ef56ab-2f32-4945-9f6d-f35829c3dc86) for task >> 124ff0e0-2a13-44e9-930a-3064718f86ae of framework >> 78046f05-cfb7-4478-8385-528382f71b9e-0000 to the slave >> I1203 18:20:08.202327 371 slave.cpp:3115] Forwarding the update >> TASK_RUNNING (UUID: 63ef56ab-2f32-4945-9f6d-f35829c3dc86) for task >> 124ff0e0-2a13-44e9-930a-3064718f86ae of framework >> 78046f05-cfb7-4478-8385-528382f71b9e-0000 to master@172.17.0.1:38193 >> I1203 18:20:08.202533 371 slave.cpp:3009] Status update manager >> successfully handled status update TASK_RUNNING (UUID: >> 63ef56ab-2f32-4945-9f6d-f35829c3dc86) for task >> 124ff0e0-2a13-44e9-930a-3064718f86ae of framework >> 78046f05-cfb7-4478-8385-528382f71b9e-0000 >> I1203 18:20:08.202585 371 slave.cpp:3025] Sending acknowledgement for >> status update TASK_RUNNING (UUID: 63ef56ab-2f32-4945-9f6d-f35829c3dc86) for >> task 124ff0e0-2a13-44e9-930a-3064718f86ae of framework >> 78046f05-cfb7-4478-8385-528382f71b9e-0000 to executor(49)@ >> 172.17.0.1:38193 >> I1203 18:20:08.202899 371 master.cpp:4572] Status update TASK_RUNNING >> (UUID: 63ef56ab-2f32-4945-9f6d-f35829c3dc86) for task >> 124ff0e0-2a13-44e9-930a-3064718f86ae of framework >> 78046f05-cfb7-4478-8385-528382f71b9e-0000 from slave >> 78046f05-cfb7-4478-8385-528382f71b9e-S1 at slave(112)@172.17.0.1:38193 >> (maintenance-host-2) >> I1203 18:20:08.202953 371 master.cpp:4620] Forwarding status update >> TASK_RUNNING (UUID: 63ef56ab-2f32-4945-9f6d-f35829c3dc86) for task >> 124ff0e0-2a13-44e9-930a-3064718f86ae of framework >> 78046f05-cfb7-4478-8385-528382f71b9e-0000 >> I1203 18:20:08.203388 371 master.cpp:6224] Updating the state of task >> 124ff0e0-2a13-44e9-930a-3064718f86ae of framework >> 78046f05-cfb7-4478-8385-528382f71b9e-0000 (latest state: TASK_RUNNING, >> status update state: TASK_RUNNING) >> I1203 18:20:08.203501 371 exec.cpp:341] Executor received status update >> acknowledgement 63ef56ab-2f32-4945-9f6d-f35829c3dc86 for task >> 124ff0e0-2a13-44e9-930a-3064718f86ae of framework >> 78046f05-cfb7-4478-8385-528382f71b9e-0000 >> I1203 18:20:08.205032 372 scheduler.cpp:457] Enqueuing event UPDATE >> received from master@172.17.0.1:38193 >> I1203 18:20:08.228276 360 scheduler.cpp:298] Sending ACKNOWLEDGE call >> to master@172.17.0.1:38193 >> I1203 18:20:08.230792 364 process.cpp:3067] Handling HTTP event for >> process 'master' with path: '/master/api/v1/scheduler' >> I1203 18:20:08.230885 364 http.cpp:336] HTTP POST for >> /master/api/v1/scheduler from 172.17.0.1:35708 >> I1203 18:20:08.231041 364 master.cpp:3729] Processing ACKNOWLEDGE call >> a4153a7a-bb32-41cc-9457-841754508d66 for task >> e0957182-29d5-4591-938c-583b94075cac of framework >> 78046f05-cfb7-4478-8385-528382f71b9e-0000 (default) on slave >> 78046f05-cfb7-4478-8385-528382f71b9e-S0 >> I1203 18:20:08.231542 372 status_update_manager.cpp:392] Received >> status update acknowledgement (UUID: a4153a7a-bb32-41cc-9457-841754508d66) >> for task e0957182-29d5-4591-938c-583b94075cac of framework >> 78046f05-cfb7-4478-8385-528382f71b9e-0000 >> I1203 18:20:08.231957 364 slave.cpp:2346] Status update manager >> successfully handled status update acknowledgement (UUID: >> a4153a7a-bb32-41cc-9457-841754508d66) for task >> e0957182-29d5-4591-938c-583b94075cac of framework >> 78046f05-cfb7-4478-8385-528382f71b9e-0000 >> I1203 18:20:08.239132 372 scheduler.cpp:298] Sending ACKNOWLEDGE call >> to master@172.17.0.1:38193 >> I1203 18:20:08.241991 360 process.cpp:3067] Handling HTTP event for >> process 'master' with path: '/master/api/v1/scheduler' >> I1203 18:20:08.242050 360 http.cpp:336] HTTP POST for >> /master/api/v1/scheduler from 172.17.0.1:35709 >> I1203 18:20:08.242168 360 master.cpp:3729] Processing ACKNOWLEDGE call >> 63ef56ab-2f32-4945-9f6d-f35829c3dc86 for task >> 124ff0e0-2a13-44e9-930a-3064718f86ae of framework >> 78046f05-cfb7-4478-8385-528382f71b9e-0000 (default) on slave >> 78046f05-cfb7-4478-8385-528382f71b9e-S1 >> I1203 18:20:08.242746 360 status_update_manager.cpp:392] Received >> status update acknowledgement (UUID: 63ef56ab-2f32-4945-9f6d-f35829c3dc86) >> for task 124ff0e0-2a13-44e9-930a-3064718f86ae of framework >> 78046f05-cfb7-4478-8385-528382f71b9e-0000 >> I1203 18:20:08.243091 360 slave.cpp:2346] Status update manager >> successfully handled status update acknowledgement (UUID: >> 63ef56ab-2f32-4945-9f6d-f35829c3dc86) for task >> 124ff0e0-2a13-44e9-930a-3064718f86ae of framework >> 78046f05-cfb7-4478-8385-528382f71b9e-0000 >> I1203 18:20:08.244417 360 scheduler.cpp:298] Sending DECLINE call to >> master@172.17.0.1:38193 >> I1203 18:20:08.246664 374 process.cpp:3067] Handling HTTP event for >> process 'master' with path: '/master/api/v1/scheduler' >> I1203 18:20:08.246726 374 http.cpp:336] HTTP POST for >> /master/api/v1/scheduler from 172.17.0.1:35710 >> I1203 18:20:08.246840 374 master.cpp:3455] Processing DECLINE call for >> offers: [ 78046f05-cfb7-4478-8385-528382f71b9e-O3 ] for framework >> 78046f05-cfb7-4478-8385-528382f71b9e-0000 (default) >> I1203 18:20:08.247181 371 hierarchical.cpp:699] Framework >> 78046f05-cfb7-4478-8385-528382f71b9e-0000 filtered inverse offers from >> slave 78046f05-cfb7-4478-8385-528382f71b9e-S0 for 101secs >> I1203 18:20:08.248678 364 scheduler.cpp:298] Sending ACCEPT call to >> master@172.17.0.1:38193 >> I1203 18:20:08.250946 374 process.cpp:3067] Handling HTTP event for >> process 'master' with path: '/master/api/v1/scheduler' >> I1203 18:20:08.251015 374 http.cpp:336] HTTP POST for >> /master/api/v1/scheduler from 172.17.0.1:35711 >> W1203 18:20:08.251413 374 master.cpp:2973] ACCEPT call used invalid >> offers '[ 78046f05-cfb7-4478-8385-528382f71b9e-O2 ]': Offer >> 78046f05-cfb7-4478-8385-528382f71b9e-O2 is no longer valid >> I1203 18:20:08.251454 366 hierarchical.cpp:1062] No resources available >> to allocate! >> I1203 18:20:08.251724 366 hierarchical.cpp:1272] Filtered >> unavailability on slave 78046f05-cfb7-4478-8385-528382f71b9e-S0 for >> framework 78046f05-cfb7-4478-8385-528382f71b9e-0000 >> I1203 18:20:08.251934 366 hierarchical.cpp:957] Performed allocation >> for 2 slaves in 1.499989ms >> 2015-12-03 >> 18:20:09,158:341(0x7f61e908c700):ZOO_ERROR@handle_socket_error_msg@1697: >> Socket [127.0.0.1:43036] zk retcode=-4, errno=111(Connection refused): >> server refused to accept the client >> 2015-12-03 >> 18:20:12,495:341(0x7f61e908c700):ZOO_ERROR@handle_socket_error_msg@1697: >> Socket [127.0.0.1:43036] zk retcode=-4, errno=111(Connection refused): >> server refused to accept the client >> 2015-12-03 >> 18:20:15,832:341(0x7f61e908c700):ZOO_ERROR@handle_socket_error_msg@1697: >> Socket [127.0.0.1:43036] zk retcode=-4, errno=111(Connection refused): >> server refused to accept the client >> 2015-12-03 >> 18:20:19,167:341(0x7f61e908c700):ZOO_ERROR@handle_socket_error_msg@1697: >> Socket [127.0.0.1:43036] zk retcode=-4, errno=111(Connection refused): >> server refused to accept the client >> 2015-12-03 >> 18:20:22,503:341(0x7f61e908c700):ZOO_ERROR@handle_socket_error_msg@1697: >> Socket [127.0.0.1:43036] zk retcode=-4, errno=111(Connection refused): >> server refused to accept the client >> ../../src/tests/master_maintenance_tests.cpp:1559: Failure >> Failed to wait 15secs for event >> I1203 18:20:23.261693 365 master.cpp:938] Master terminating >> W1203 18:20:23.261994 365 master.cpp:6276] Removing task >> 124ff0e0-2a13-44e9-930a-3064718f86ae with resources cpus(*):2; mem(*):1024; >> disk(*):1024; ports(*):[31000-32000] of framework >> 78046f05-cfb7-4478-8385-528382f71b9e-0000 on slave >> 78046f05-cfb7-4478-8385-528382f71b9e-S1 at slave(112)@172.17.0.1:38193 >> (maintenance-host-2) in non-terminal state TASK_RUNNING >> I1203 18:20:23.263239 368 hierarchical.cpp:410] Removed slave >> 78046f05-cfb7-4478-8385-528382f71b9e-S1 >> I1203 18:20:23.263739 365 master.cpp:6319] Removing executor >> 'executor-2' with resources of framework >> 78046f05-cfb7-4478-8385-528382f71b9e-0000 on slave >> 78046f05-cfb7-4478-8385-528382f71b9e-S1 at slave(112)@172.17.0.1:38193 >> (maintenance-host-2) >> W1203 18:20:23.264315 365 master.cpp:6276] Removing task >> e0957182-29d5-4591-938c-583b94075cac with resources cpus(*):2; mem(*):1024; >> disk(*):1024; ports(*):[31000-32000] of framework >> 78046f05-cfb7-4478-8385-528382f71b9e-0000 on slave >> 78046f05-cfb7-4478-8385-528382f71b9e-S0 at slave(111)@172.17.0.1:38193 >> (maintenance-host) in non-terminal state TASK_RUNNING >> I1203 18:20:23.264825 367 hierarchical.cpp:410] Removed slave >> 78046f05-cfb7-4478-8385-528382f71b9e-S0 >> I1203 18:20:23.265086 365 master.cpp:6319] Removing executor >> 'executor-1' with resources of framework >> 78046f05-cfb7-4478-8385-528382f71b9e-0000 on slave >> 78046f05-cfb7-4478-8385-528382f71b9e-S0 at slave(111)@172.17.0.1:38193 >> (maintenance-host) >> I1203 18:20:23.265804 372 hierarchical.cpp:260] Removed framework >> 78046f05-cfb7-4478-8385-528382f71b9e-0000 >> I1203 18:20:23.267813 367 slave.cpp:3243] master@172.17.0.1:38193 >> exited >> W1203 18:20:23.267844 367 slave.cpp:3246] Master disconnected! Waiting >> for a new master to be elected >> I1203 18:20:23.267884 365 slave.cpp:3243] master@172.17.0.1:38193 >> exited >> W1203 18:20:23.267940 365 slave.cpp:3246] Master disconnected! Waiting >> for a new master to be elected >> F1203 18:20:23.267940 341 logging.cpp:55] RAW: Pure virtual method >> called >> @ 0x7f628594a4ae google::LogMessage::Fail() >> @ 0x7f628594fa04 google::RawLog__() >> @ 0x7f6284b9f030 __cxa_pure_virtual >> @ 0x9eb126 >> mesos::internal::tests::Cluster::Slaves::shutdown() >> @ 0xf0fb90 >> mesos::internal::tests::MesosTest::ShutdownSlaves() >> @ 0xf0fb52 mesos::internal::tests::MesosTest::Shutdown() >> @ 0xf0c12b mesos::internal::tests::MesosTest::TearDown() >> @ 0x15037ca >> testing::internal::HandleSehExceptionsInMethodIfSupported<>() >> @ 0x14fe6a4 >> testing::internal::HandleExceptionsInMethodIfSupported<>() >> @ 0x14dfcc6 testing::Test::Run() >> @ 0x14e0400 testing::TestInfo::Run() >> @ 0x14e0a46 testing::TestCase::Run() >> @ 0x14e7320 testing::internal::UnitTestImpl::RunAllTests() >> @ 0x15043ef >> testing::internal::HandleSehExceptionsInMethodIfSupported<>() >> @ 0x14ff21a >> testing::internal::HandleExceptionsInMethodIfSupported<>() >> @ 0x14e6066 testing::UnitTest::Run() >> @ 0xd0eba0 RUN_ALL_TESTS() >> @ 0xd0e77e main >> @ 0x7f62800d3af5 __libc_start_main >> @ 0x939379 (unknown) >> make[4]: *** [check-local] Aborted >> make[4]: Leaving directory `/mesos/mesos-0.27.0/_build/src' >> make[3]: *** [check-am] Error 2 >> make[3]: Leaving directory `/mesos/mesos-0.27.0/_build/src' >> make[2]: *** [check] Error 2 >> make[2]: Leaving directory `/mesos/mesos-0.27.0/_build/src' >> make[1]: *** [check-recursive] Error 1 >> make[1]: Leaving directory `/mesos/mesos-0.27.0/_build' >> make: *** [distcheck] Error 1 >> + docker rmi mesos-1449165142-11808 >> Untagged: mesos-1449165142-11808:latest >> Deleted: db54fc17d43deb93a90e8fabb7824e24f491aafdfabd44cf81a28768e7498566 >> Deleted: 28ad8a4d4601593fd69c107f55038fb162cb367a553e5cd1c46d59cf898afed6 >> Deleted: a5760177aedb0acea3825781c16f792b06232601577db17da79670a23a8116de >> Deleted: 99bebc3204f26ca4a07830e98ac2c646f4b7188df0674758191a99d8c58d88ad >> Deleted: 9ff79d453151387cfe33d186170f9771af1b94420d5acd2917e642a56a8aa0ba >> Deleted: 406ad7284996fbb203714adaf5e0f71d2b66aaf90bf1f2ddef4983389ae73307 >> Deleted: acfc0dc0a0f449b7471e73c200f401cd5983b972548402d786f366eba1a7f3b1 >> Deleted: 6bfe4589d9179945d0a56ee8e1405f4d2b0dbdbc97d2d80ba41b371fe92bbe63 >> Deleted: 394453c00da5c216f70ec2ea855be7c5881914c5f9e8d6b5ac83aeacf6a9f73b >> Deleted: 3f817f3f0e4d357fb448a08ccf88cf269c41ab6ae2ddebb346ad3c5a1fca2d99 >> Deleted: 5819519622c001b957e40e81e38b8492649b96ab52157f952a28c72b5c716a82 >> Deleted: b5aacb8d1b68aafaba0d668495a0e1c6e61a15c7224f8e667241e2748688ef52 >> Build step 'Execute shell' marked build as failure >> > >