You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@mesos.apache.org by "Benjamin Bannier (JIRA)" <ji...@apache.org> on 2015/11/23 15:41:11 UTC
[jira] [Commented] (MESOS-3579)
FetcherCacheTest.LocalUncachedExtract is flaky
[ https://issues.apache.org/jira/browse/MESOS-3579?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15022170#comment-15022170 ]
Benjamin Bannier commented on MESOS-3579:
-----------------------------------------
Some extra code was added middle of October to log additional information on the fetcher (who looks like the culprit here) in case of failure. We should add more information once it fails again.
> FetcherCacheTest.LocalUncachedExtract is flaky
> ----------------------------------------------
>
> Key: MESOS-3579
> URL: https://issues.apache.org/jira/browse/MESOS-3579
> Project: Mesos
> Issue Type: Bug
> Components: fetcher, test
> Reporter: Anand Mazumdar
> Assignee: Benjamin Bannier
> Labels: flaky-test, mesosphere
>
> From ASF CI:
> https://builds.apache.org/job/Mesos/866/COMPILER=clang,CONFIGURATION=--verbose,OS=ubuntu:14.04,label_exp=docker%7C%7CHadoop/console
> {code}
> [ RUN ] FetcherCacheTest.LocalUncachedExtract
> Using temporary directory '/tmp/FetcherCacheTest_LocalUncachedExtract_jHBfeA'
> I0925 19:15:39.541198 27410 leveldb.cpp:176] Opened db in 3.43934ms
> I0925 19:15:39.542362 27410 leveldb.cpp:183] Compacted db in 1.136184ms
> I0925 19:15:39.542428 27410 leveldb.cpp:198] Created db iterator in 35866ns
> I0925 19:15:39.542448 27410 leveldb.cpp:204] Seeked to beginning of db in 8807ns
> I0925 19:15:39.542459 27410 leveldb.cpp:273] Iterated through 0 keys in the db in 6325ns
> I0925 19:15:39.542505 27410 replica.cpp:744] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> I0925 19:15:39.543143 27438 recover.cpp:449] Starting replica recovery
> I0925 19:15:39.543393 27438 recover.cpp:475] Replica is in EMPTY status
> I0925 19:15:39.544373 27436 replica.cpp:641] Replica in EMPTY status received a broadcasted recover request
> I0925 19:15:39.544791 27433 recover.cpp:195] Received a recover response from a replica in EMPTY status
> I0925 19:15:39.545284 27433 recover.cpp:566] Updating replica status to STARTING
> I0925 19:15:39.546155 27436 master.cpp:376] Master c8bf1c95-50f4-4832-a570-c560f0b466ae (f57fd4291168) started on 172.17.1.195:41781
> I0925 19:15:39.546257 27433 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 747249ns
> I0925 19:15:39.546288 27433 replica.cpp:323] Persisted replica status to STARTING
> I0925 19:15:39.546483 27434 recover.cpp:475] Replica is in STARTING status
> I0925 19:15:39.546187 27436 master.cpp:378] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="true" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/FetcherCacheTest_LocalUncachedExtract_jHBfeA/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.26.0/_inst/share/mesos/webui" --work_dir="/tmp/FetcherCacheTest_LocalUncachedExtract_jHBfeA/master" --zk_session_timeout="10secs"
> I0925 19:15:39.546567 27436 master.cpp:423] Master only allowing authenticated frameworks to register
> I0925 19:15:39.546617 27436 master.cpp:428] Master only allowing authenticated slaves to register
> I0925 19:15:39.546632 27436 credentials.hpp:37] Loading credentials for authentication from '/tmp/FetcherCacheTest_LocalUncachedExtract_jHBfeA/credentials'
> I0925 19:15:39.546931 27436 master.cpp:467] Using default 'crammd5' authenticator
> I0925 19:15:39.547044 27436 master.cpp:504] Authorization enabled
> I0925 19:15:39.547276 27441 whitelist_watcher.cpp:79] No whitelist given
> I0925 19:15:39.547320 27434 hierarchical.hpp:468] Initialized hierarchical allocator process
> I0925 19:15:39.547471 27438 replica.cpp:641] Replica in STARTING status received a broadcasted recover request
> I0925 19:15:39.548318 27443 recover.cpp:195] Received a recover response from a replica in STARTING status
> I0925 19:15:39.549067 27435 recover.cpp:566] Updating replica status to VOTING
> I0925 19:15:39.549115 27440 master.cpp:1603] The newly elected leader is master@172.17.1.195:41781 with id c8bf1c95-50f4-4832-a570-c560f0b466ae
> I0925 19:15:39.549162 27440 master.cpp:1616] Elected as the leading master!
> I0925 19:15:39.549190 27440 master.cpp:1376] Recovering from registrar
> I0925 19:15:39.549342 27434 registrar.cpp:309] Recovering registrar
> I0925 19:15:39.549666 27430 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 418187ns
> I0925 19:15:39.549753 27430 replica.cpp:323] Persisted replica status to VOTING
> I0925 19:15:39.550089 27442 recover.cpp:580] Successfully joined the Paxos group
> I0925 19:15:39.550320 27442 recover.cpp:464] Recover process terminated
> I0925 19:15:39.550904 27430 log.cpp:661] Attempting to start the writer
> I0925 19:15:39.551955 27434 replica.cpp:477] Replica received implicit promise request with proposal 1
> I0925 19:15:39.552351 27434 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 380746ns
> I0925 19:15:39.552372 27434 replica.cpp:345] Persisted promised to 1
> I0925 19:15:39.552896 27436 coordinator.cpp:231] Coordinator attemping to fill missing position
> I0925 19:15:39.554003 27432 replica.cpp:378] Replica received explicit promise request for position 0 with proposal 2
> I0925 19:15:39.554534 27432 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 510572ns
> I0925 19:15:39.554558 27432 replica.cpp:679] Persisted action at 0
> I0925 19:15:39.555516 27443 replica.cpp:511] Replica received write request for position 0
> I0925 19:15:39.555595 27443 leveldb.cpp:438] Reading position from leveldb took 65355ns
> I0925 19:15:39.556177 27443 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 542757ns
> I0925 19:15:39.556200 27443 replica.cpp:679] Persisted action at 0
> I0925 19:15:39.556813 27429 replica.cpp:658] Replica received learned notice for position 0
> I0925 19:15:39.557251 27429 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 422272ns
> I0925 19:15:39.557281 27429 replica.cpp:679] Persisted action at 0
> I0925 19:15:39.557315 27429 replica.cpp:664] Replica learned NOP action at position 0
> I0925 19:15:39.558061 27442 log.cpp:677] Writer started with ending position 0
> I0925 19:15:39.559294 27434 leveldb.cpp:438] Reading position from leveldb took 56536ns
> I0925 19:15:39.560333 27432 registrar.cpp:342] Successfully fetched the registry (0B) in 10.936064ms
> I0925 19:15:39.560469 27432 registrar.cpp:441] Applied 1 operations in 41340ns; attempting to update the 'registry'
> I0925 19:15:39.561244 27441 log.cpp:685] Attempting to append 176 bytes to the log
> I0925 19:15:39.561378 27436 coordinator.cpp:341] Coordinator attempting to write APPEND action at position 1
> I0925 19:15:39.562126 27439 replica.cpp:511] Replica received write request for position 1
> I0925 19:15:39.562515 27439 leveldb.cpp:343] Persisting action (195 bytes) to leveldb took 364968ns
> I0925 19:15:39.562539 27439 replica.cpp:679] Persisted action at 1
> I0925 19:15:39.563160 27438 replica.cpp:658] Replica received learned notice for position 1
> I0925 19:15:39.563699 27438 leveldb.cpp:343] Persisting action (197 bytes) to leveldb took 455933ns
> I0925 19:15:39.563730 27438 replica.cpp:679] Persisted action at 1
> I0925 19:15:39.563753 27438 replica.cpp:664] Replica learned APPEND action at position 1
> I0925 19:15:39.564749 27434 registrar.cpp:486] Successfully updated the 'registry' in 4.214016ms
> I0925 19:15:39.564893 27434 registrar.cpp:372] Successfully recovered registrar
> I0925 19:15:39.564950 27442 log.cpp:704] Attempting to truncate the log to 1
> I0925 19:15:39.565039 27429 coordinator.cpp:341] Coordinator attempting to write TRUNCATE action at position 2
> I0925 19:15:39.565172 27430 master.cpp:1413] Recovered 0 slaves from the Registry (137B) ; allowing 10mins for slaves to re-register
> I0925 19:15:39.565946 27429 replica.cpp:511] Replica received write request for position 2
> I0925 19:15:39.566349 27429 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 375473ns
> I0925 19:15:39.566371 27429 replica.cpp:679] Persisted action at 2
> I0925 19:15:39.566994 27431 replica.cpp:658] Replica received learned notice for position 2
> I0925 19:15:39.567440 27431 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 437095ns
> I0925 19:15:39.567483 27431 leveldb.cpp:401] Deleting ~1 keys from leveldb took 31954ns
> I0925 19:15:39.567498 27431 replica.cpp:679] Persisted action at 2
> I0925 19:15:39.567514 27431 replica.cpp:664] Replica learned TRUNCATE action at position 2
> I0925 19:15:39.576660 27410 containerizer.cpp:143] Using isolation: posix/cpu,posix/mem,filesystem/posix
> W0925 19:15:39.577055 27410 backend.cpp:50] Failed to create 'bind' backend: BindBackend requires root privileges
> I0925 19:15:39.583020 27443 slave.cpp:190] Slave started on 46)@172.17.1.195:41781
> I0925 19:15:39.583062 27443 slave.cpp:191] 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/FetcherCacheTest_LocalUncachedExtract_LwfzK4/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_local_archives_dir="/tmp/mesos/images/docker" --docker_puller="local" --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/FetcherCacheTest_LocalUncachedExtract_LwfzK4/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/mesos/mesos-0.26.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" --resource_monitoring_interval="1secs" --resources="cpus(*):1000; mem(*):1000" --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/FetcherCacheTest_LocalUncachedExtract_LwfzK4"
> I0925 19:15:39.583472 27443 credentials.hpp:85] Loading credential for authentication from '/tmp/FetcherCacheTest_LocalUncachedExtract_LwfzK4/credential'
> I0925 19:15:39.583752 27443 slave.cpp:321] Slave using credential for: test-principal
> I0925 19:15:39.584249 27443 slave.cpp:354] Slave resources: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0925 19:15:39.584344 27443 slave.cpp:390] Slave hostname: f57fd4291168
> I0925 19:15:39.584362 27443 slave.cpp:395] Slave checkpoint: true
> I0925 19:15:39.585180 27428 state.cpp:54] Recovering state from '/tmp/FetcherCacheTest_LocalUncachedExtract_LwfzK4/meta'
> I0925 19:15:39.585383 27440 status_update_manager.cpp:202] Recovering status update manager
> I0925 19:15:39.585636 27435 containerizer.cpp:386] Recovering containerizer
> I0925 19:15:39.586380 27438 slave.cpp:4110] Finished recovery
> I0925 19:15:39.586845 27438 slave.cpp:4267] Querying resource estimator for oversubscribable resources
> I0925 19:15:39.587059 27430 status_update_manager.cpp:176] Pausing sending status updates
> I0925 19:15:39.587064 27438 slave.cpp:705] New master detected at master@172.17.1.195:41781
> I0925 19:15:39.587139 27438 slave.cpp:768] Authenticating with master master@172.17.1.195:41781
> I0925 19:15:39.587163 27438 slave.cpp:773] Using default CRAM-MD5 authenticatee
> I0925 19:15:39.587321 27438 slave.cpp:741] Detecting new master
> I0925 19:15:39.587357 27434 authenticatee.cpp:115] Creating new client SASL connection
> I0925 19:15:39.587574 27438 slave.cpp:4281] Received oversubscribable resources from the resource estimator
> I0925 19:15:39.587739 27442 master.cpp:5138] Authenticating slave(46)@172.17.1.195:41781
> I0925 19:15:39.587853 27441 authenticator.cpp:407] Starting authentication session for crammd5_authenticatee(139)@172.17.1.195:41781
> I0925 19:15:39.588052 27439 authenticator.cpp:92] Creating new server SASL connection
> I0925 19:15:39.588248 27431 authenticatee.cpp:206] Received SASL authentication mechanisms: CRAM-MD5
> I0925 19:15:39.588297 27431 authenticatee.cpp:232] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0925 19:15:39.588443 27437 authenticator.cpp:197] Received SASL authentication start
> I0925 19:15:39.588506 27437 authenticator.cpp:319] Authentication requires more steps
> I0925 19:15:39.588677 27443 authenticatee.cpp:252] Received SASL authentication step
> I0925 19:15:39.588814 27436 authenticator.cpp:225] Received SASL authentication step
> I0925 19:15:39.588855 27436 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: 'f57fd4291168' server FQDN: 'f57fd4291168' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0925 19:15:39.588876 27436 auxprop.cpp:174] Looking up auxiliary property '*userPassword'
> I0925 19:15:39.588937 27436 auxprop.cpp:174] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0925 19:15:39.588979 27436 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: 'f57fd4291168' server FQDN: 'f57fd4291168' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0925 19:15:39.588997 27436 auxprop.cpp:124] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0925 19:15:39.589011 27436 auxprop.cpp:124] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0925 19:15:39.589036 27436 authenticator.cpp:311] Authentication success
> I0925 19:15:39.589126 27443 authenticatee.cpp:292] Authentication success
> I0925 19:15:39.589192 27437 master.cpp:5168] Successfully authenticated principal 'test-principal' at slave(46)@172.17.1.195:41781
> I0925 19:15:39.589238 27433 authenticator.cpp:425] Authentication session cleanup for crammd5_authenticatee(139)@172.17.1.195:41781
> I0925 19:15:39.589412 27440 slave.cpp:836] Successfully authenticated with master master@172.17.1.195:41781
> I0925 19:15:39.589540 27440 slave.cpp:1230] Will retry registration in 13.562027ms if necessary
> I0925 19:15:39.589745 27436 master.cpp:3862] Registering slave at slave(46)@172.17.1.195:41781 (f57fd4291168) with id c8bf1c95-50f4-4832-a570-c560f0b466ae-S0
> I0925 19:15:39.590121 27438 registrar.cpp:441] Applied 1 operations in 70627ns; attempting to update the 'registry'
> I0925 19:15:39.590831 27430 log.cpp:685] Attempting to append 345 bytes to the log
> I0925 19:15:39.590927 27439 coordinator.cpp:341] Coordinator attempting to write APPEND action at position 3
> I0925 19:15:39.591809 27430 replica.cpp:511] Replica received write request for position 3
> I0925 19:15:39.592072 27430 leveldb.cpp:343] Persisting action (364 bytes) to leveldb took 221734ns
> I0925 19:15:39.592099 27430 replica.cpp:679] Persisted action at 3
> I0925 19:15:39.592643 27442 replica.cpp:658] Replica received learned notice for position 3
> I0925 19:15:39.593215 27442 leveldb.cpp:343] Persisting action (366 bytes) to leveldb took 560946ns
> I0925 19:15:39.593237 27442 replica.cpp:679] Persisted action at 3
> I0925 19:15:39.593255 27442 replica.cpp:664] Replica learned APPEND action at position 3
> I0925 19:15:39.594663 27433 registrar.cpp:486] Successfully updated the 'registry' in 4.472832ms
> I0925 19:15:39.594874 27431 log.cpp:704] Attempting to truncate the log to 3
> I0925 19:15:39.595407 27429 slave.cpp:3138] Received ping from slave-observer(45)@172.17.1.195:41781
> I0925 19:15:39.595450 27433 coordinator.cpp:341] Coordinator attempting to write TRUNCATE action at position 4
> I0925 19:15:39.596017 27442 replica.cpp:511] Replica received write request for position 4
> I0925 19:15:39.596029 27429 hierarchical.hpp:675] Added slave c8bf1c95-50f4-4832-a570-c560f0b466ae-S0 (f57fd4291168) with cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] (allocated: )
> I0925 19:15:39.595952 27441 master.cpp:3930] Registered slave c8bf1c95-50f4-4832-a570-c560f0b466ae-S0 at slave(46)@172.17.1.195:41781 (f57fd4291168) with cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000]
> I0925 19:15:39.596240 27429 hierarchical.hpp:1326] No resources available to allocate!
> I0925 19:15:39.596263 27439 slave.cpp:880] Registered with master master@172.17.1.195:41781; given slave ID c8bf1c95-50f4-4832-a570-c560f0b466ae-S0
> I0925 19:15:39.596341 27439 fetcher.cpp:77] Clearing fetcher cache
> I0925 19:15:39.596345 27429 hierarchical.hpp:1421] No inverse offers to send out!
> I0925 19:15:39.596367 27429 hierarchical.hpp:1239] Performed allocation for slave c8bf1c95-50f4-4832-a570-c560f0b466ae-S0 in 299337ns
> I0925 19:15:39.596524 27434 status_update_manager.cpp:183] Resuming sending status updates
> I0925 19:15:39.596571 27442 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 575374ns
> I0925 19:15:39.596662 27442 replica.cpp:679] Persisted action at 4
> I0925 19:15:39.596984 27439 slave.cpp:903] Checkpointing SlaveInfo to '/tmp/FetcherCacheTest_LocalUncachedExtract_LwfzK4/meta/slaves/c8bf1c95-50f4-4832-a570-c560f0b466ae-S0/slave.info'
> I0925 19:15:39.597522 27434 replica.cpp:658] Replica received learned notice for position 4
> I0925 19:15:39.597553 27410 sched.cpp:164] Version: 0.26.0
> I0925 19:15:39.597746 27439 slave.cpp:939] Forwarding total oversubscribed resources
> I0925 19:15:39.598021 27429 master.cpp:4272] Received update of slave c8bf1c95-50f4-4832-a570-c560f0b466ae-S0 at slave(46)@172.17.1.195:41781 (f57fd4291168) with total oversubscribed resources
> I0925 19:15:39.598070 27434 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 531503ns
> I0925 19:15:39.598162 27434 leveldb.cpp:401] Deleting ~2 keys from leveldb took 79081ns
> I0925 19:15:39.598170 27428 sched.cpp:262] New master detected at master@172.17.1.195:41781
> I0925 19:15:39.598206 27434 replica.cpp:679] Persisted action at 4
> I0925 19:15:39.598238 27434 replica.cpp:664] Replica learned TRUNCATE action at position 4
> I0925 19:15:39.598276 27428 sched.cpp:318] Authenticating with master master@172.17.1.195:41781
> I0925 19:15:39.598296 27428 sched.cpp:325] Using default CRAM-MD5 authenticatee
> I0925 19:15:39.598950 27430 hierarchical.hpp:735] Slave c8bf1c95-50f4-4832-a570-c560f0b466ae-S0 (f57fd4291168) updated with oversubscribed resources (total: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: )
> I0925 19:15:39.599242 27430 hierarchical.hpp:1326] No resources available to allocate!
> I0925 19:15:39.599282 27430 hierarchical.hpp:1421] No inverse offers to send out!
> I0925 19:15:39.599341 27430 hierarchical.hpp:1239] Performed allocation for slave c8bf1c95-50f4-4832-a570-c560f0b466ae-S0 in 327742ns
> I0925 19:15:39.599632 27437 authenticatee.cpp:115] Creating new client SASL connection
> I0925 19:15:39.600005 27428 master.cpp:5138] Authenticating scheduler-dda30e8e-47b7-4b1d-9a96-32364754be63@172.17.1.195:41781
> I0925 19:15:39.600170 27435 authenticator.cpp:407] Starting authentication session for crammd5_authenticatee(140)@172.17.1.195:41781
> I0925 19:15:39.600518 27433 authenticator.cpp:92] Creating new server SASL connection
> I0925 19:15:39.600788 27436 authenticatee.cpp:206] Received SASL authentication mechanisms: CRAM-MD5
> I0925 19:15:39.600831 27436 authenticatee.cpp:232] Attempting to authenticate with mechanism 'CRAM-MD5'
> I0925 19:15:39.600944 27433 authenticator.cpp:197] Received SASL authentication start
> I0925 19:15:39.601019 27433 authenticator.cpp:319] Authentication requires more steps
> I0925 19:15:39.601150 27436 authenticatee.cpp:252] Received SASL authentication step
> I0925 19:15:39.601284 27436 authenticator.cpp:225] Received SASL authentication step
> I0925 19:15:39.601326 27436 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: 'f57fd4291168' server FQDN: 'f57fd4291168' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
> I0925 19:15:39.601341 27436 auxprop.cpp:174] Looking up auxiliary property '*userPassword'
> I0925 19:15:39.601387 27436 auxprop.cpp:174] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> I0925 19:15:39.601413 27436 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: 'f57fd4291168' server FQDN: 'f57fd4291168' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
> I0925 19:15:39.601421 27436 auxprop.cpp:124] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0925 19:15:39.601428 27436 auxprop.cpp:124] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0925 19:15:39.601439 27436 authenticator.cpp:311] Authentication success
> I0925 19:15:39.601508 27433 authenticatee.cpp:292] Authentication success
> I0925 19:15:39.601644 27433 master.cpp:5168] Successfully authenticated principal 'test-principal' at scheduler-dda30e8e-47b7-4b1d-9a96-32364754be63@172.17.1.195:41781
> I0925 19:15:39.601671 27436 authenticator.cpp:425] Authentication session cleanup for crammd5_authenticatee(140)@172.17.1.195:41781
> I0925 19:15:39.601842 27434 sched.cpp:407] Successfully authenticated with master master@172.17.1.195:41781
> I0925 19:15:39.601869 27434 sched.cpp:714] Sending SUBSCRIBE call to master@172.17.1.195:41781
> I0925 19:15:39.601955 27434 sched.cpp:747] Will retry registration in 749.975107ms if necessary
> I0925 19:15:39.602046 27443 master.cpp:2179] Received SUBSCRIBE call for framework 'default' at scheduler-dda30e8e-47b7-4b1d-9a96-32364754be63@172.17.1.195:41781
> W0925 19:15:39.602128 27443 master.cpp:2186] Framework at scheduler-dda30e8e-47b7-4b1d-9a96-32364754be63@172.17.1.195:41781 (authenticated as 'test-principal') does not set 'principal' in FrameworkInfo
> I0925 19:15:39.602149 27443 master.cpp:1642] Authorizing framework principal '' to receive offers for role '*'
> I0925 19:15:39.602375 27437 master.cpp:2250] Subscribing framework default with checkpointing enabled and capabilities [ ]
> I0925 19:15:39.602712 27429 hierarchical.hpp:515] Added framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000
> I0925 19:15:39.602859 27437 sched.cpp:641] Framework registered with c8bf1c95-50f4-4832-a570-c560f0b466ae-0000
> I0925 19:15:39.602905 27437 sched.cpp:655] Scheduler::registered took 30086ns
> I0925 19:15:39.603204 27429 hierarchical.hpp:1421] No inverse offers to send out!
> I0925 19:15:39.603234 27429 hierarchical.hpp:1221] Performed allocation for 1 slaves in 506104ns
> I0925 19:15:39.603520 27438 master.cpp:4967] Sending 1 offers to framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000 (default) at scheduler-dda30e8e-47b7-4b1d-9a96-32364754be63@172.17.1.195:41781
> I0925 19:15:39.603962 27431 sched.cpp:811] Scheduler::resourceOffers took 123790ns
> I0925 19:15:39.605443 27432 master.cpp:2918] Processing ACCEPT call for offers: [ c8bf1c95-50f4-4832-a570-c560f0b466ae-O0 ] on slave c8bf1c95-50f4-4832-a570-c560f0b466ae-S0 at slave(46)@172.17.1.195:41781 (f57fd4291168) for framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000 (default) at scheduler-dda30e8e-47b7-4b1d-9a96-32364754be63@172.17.1.195:41781
> I0925 19:15:39.605485 27432 master.cpp:2714] Authorizing framework principal '' to launch task 0 as user 'mesos'
> I0925 19:15:39.606487 27432 master.hpp:176] Adding task 0 with resources cpus(*):1; mem(*):1 on slave c8bf1c95-50f4-4832-a570-c560f0b466ae-S0 (f57fd4291168)
> I0925 19:15:39.606586 27432 master.cpp:3248] Launching task 0 of framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000 (default) at scheduler-dda30e8e-47b7-4b1d-9a96-32364754be63@172.17.1.195:41781 with resources cpus(*):1; mem(*):1 on slave c8bf1c95-50f4-4832-a570-c560f0b466ae-S0 at slave(46)@172.17.1.195:41781 (f57fd4291168)
> I0925 19:15:39.606875 27440 slave.cpp:1270] Got assigned task 0 for framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000
> I0925 19:15:39.607050 27439 hierarchical.hpp:1103] Recovered cpus(*):999; mem(*):999; disk(*):3.70122e+06; ports(*):[31000-32000] (total: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: cpus(*):1; mem(*):1) on slave c8bf1c95-50f4-4832-a570-c560f0b466ae-S0 from framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000
> I0925 19:15:39.607087 27440 slave.cpp:4773] Checkpointing FrameworkInfo to '/tmp/FetcherCacheTest_LocalUncachedExtract_LwfzK4/meta/slaves/c8bf1c95-50f4-4832-a570-c560f0b466ae-S0/frameworks/c8bf1c95-50f4-4832-a570-c560f0b466ae-0000/framework.info'
> I0925 19:15:39.607103 27439 hierarchical.hpp:1140] Framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000 filtered slave c8bf1c95-50f4-4832-a570-c560f0b466ae-S0 for 5secs
> I0925 19:15:39.607573 27440 slave.cpp:4784] Checkpointing framework pid 'scheduler-dda30e8e-47b7-4b1d-9a96-32364754be63@172.17.1.195:41781' to '/tmp/FetcherCacheTest_LocalUncachedExtract_LwfzK4/meta/slaves/c8bf1c95-50f4-4832-a570-c560f0b466ae-S0/frameworks/c8bf1c95-50f4-4832-a570-c560f0b466ae-0000/framework.pid'
> I0925 19:15:39.608544 27440 slave.cpp:1386] Launching task 0 for framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000
> I0925 19:15:39.615109 27440 slave.cpp:5209] Checkpointing ExecutorInfo to '/tmp/FetcherCacheTest_LocalUncachedExtract_LwfzK4/meta/slaves/c8bf1c95-50f4-4832-a570-c560f0b466ae-S0/frameworks/c8bf1c95-50f4-4832-a570-c560f0b466ae-0000/executors/0/executor.info'
> I0925 19:15:39.616000 27440 slave.cpp:4852] Launching executor 0 of framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000 with resources cpus(*):0.1; mem(*):32 in work directory '/tmp/FetcherCacheTest_LocalUncachedExtract_LwfzK4/slaves/c8bf1c95-50f4-4832-a570-c560f0b466ae-S0/frameworks/c8bf1c95-50f4-4832-a570-c560f0b466ae-0000/executors/0/runs/4bc31eb2-709b-4b09-a5a9-21a8387e355a'
> I0925 19:15:39.616510 27441 containerizer.cpp:640] Starting container '4bc31eb2-709b-4b09-a5a9-21a8387e355a' for executor '0' of framework 'c8bf1c95-50f4-4832-a570-c560f0b466ae-0000'
> I0925 19:15:39.616612 27440 slave.cpp:5232] Checkpointing TaskInfo to '/tmp/FetcherCacheTest_LocalUncachedExtract_LwfzK4/meta/slaves/c8bf1c95-50f4-4832-a570-c560f0b466ae-S0/frameworks/c8bf1c95-50f4-4832-a570-c560f0b466ae-0000/executors/0/runs/4bc31eb2-709b-4b09-a5a9-21a8387e355a/tasks/0/task.info'
> I0925 19:15:39.617144 27440 slave.cpp:1604] Queuing task '0' for executor 0 of framework 'c8bf1c95-50f4-4832-a570-c560f0b466ae-0000
> I0925 19:15:39.617277 27440 slave.cpp:658] Successfully attached file '/tmp/FetcherCacheTest_LocalUncachedExtract_LwfzK4/slaves/c8bf1c95-50f4-4832-a570-c560f0b466ae-S0/frameworks/c8bf1c95-50f4-4832-a570-c560f0b466ae-0000/executors/0/runs/4bc31eb2-709b-4b09-a5a9-21a8387e355a'
> I0925 19:15:39.619359 27437 launcher.cpp:132] Forked child with pid '30069' for container '4bc31eb2-709b-4b09-a5a9-21a8387e355a'
> I0925 19:15:39.619583 27437 containerizer.cpp:873] Checkpointing executor's forked pid 30069 to '/tmp/FetcherCacheTest_LocalUncachedExtract_LwfzK4/meta/slaves/c8bf1c95-50f4-4832-a570-c560f0b466ae-S0/frameworks/c8bf1c95-50f4-4832-a570-c560f0b466ae-0000/executors/0/runs/4bc31eb2-709b-4b09-a5a9-21a8387e355a/pids/forked.pid'
> I0925 19:15:39.622011 27441 fetcher.cpp:299] Starting to fetch URIs for container: 4bc31eb2-709b-4b09-a5a9-21a8387e355a, directory: /tmp/FetcherCacheTest_LocalUncachedExtract_LwfzK4/slaves/c8bf1c95-50f4-4832-a570-c560f0b466ae-S0/frameworks/c8bf1c95-50f4-4832-a570-c560f0b466ae-0000/executors/0/runs/4bc31eb2-709b-4b09-a5a9-21a8387e355a
> I0925 19:15:39.633872 27441 fetcher.cpp:756] Fetching URIs using command '/mesos/mesos-0.26.0/_build/src/mesos-fetcher'
> E0925 19:15:39.724884 27430 fetcher.cpp:515] Failed to run mesos-fetcher: Failed to fetch all URIs for container '4bc31eb2-709b-4b09-a5a9-21a8387e355a' with exit status: 256
> Failed to synchronize with slave (it's probably exited)
> E0925 19:15:39.725486 27443 slave.cpp:3342] Container '4bc31eb2-709b-4b09-a5a9-21a8387e355a' for executor '0' of framework 'c8bf1c95-50f4-4832-a570-c560f0b466ae-0000' failed to start: Failed to fetch all URIs for container '4bc31eb2-709b-4b09-a5a9-21a8387e355a' with exit status: 256
> I0925 19:15:39.725620 27430 containerizer.cpp:1097] Destroying container '4bc31eb2-709b-4b09-a5a9-21a8387e355a'
> I0925 19:15:39.725651 27430 containerizer.cpp:1126] Waiting for the isolators to complete for container '4bc31eb2-709b-4b09-a5a9-21a8387e355a'
> I0925 19:15:39.825744 27443 containerizer.cpp:1284] Executor for container '4bc31eb2-709b-4b09-a5a9-21a8387e355a' has exited
> I0925 19:15:39.827075 27429 slave.cpp:3440] Executor '0' of framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000 exited with status 1
> I0925 19:15:39.827324 27429 slave.cpp:2717] Handling status update TASK_FAILED (UUID: 6bb8651c-0668-4724-8fbd-76db8a91adb7) for task 0 of framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000 from @0.0.0.0:0
> I0925 19:15:39.827514 27429 slave.cpp:5147] Terminating task 0
> W0925 19:15:39.827745 27436 containerizer.cpp:988] Ignoring update for unknown container: 4bc31eb2-709b-4b09-a5a9-21a8387e355a
> I0925 19:15:39.828073 27440 status_update_manager.cpp:322] Received status update TASK_FAILED (UUID: 6bb8651c-0668-4724-8fbd-76db8a91adb7) for task 0 of framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000
> I0925 19:15:39.828168 27440 status_update_manager.cpp:499] Creating StatusUpdate stream for task 0 of framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000
> I0925 19:15:39.828661 27440 status_update_manager.cpp:826] Checkpointing UPDATE for status update TASK_FAILED (UUID: 6bb8651c-0668-4724-8fbd-76db8a91adb7) for task 0 of framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000
> I0925 19:15:39.830041 27440 status_update_manager.cpp:376] Forwarding update TASK_FAILED (UUID: 6bb8651c-0668-4724-8fbd-76db8a91adb7) for task 0 of framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000 to the slave
> I0925 19:15:39.830292 27434 slave.cpp:3016] Forwarding the update TASK_FAILED (UUID: 6bb8651c-0668-4724-8fbd-76db8a91adb7) for task 0 of framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000 to master@172.17.1.195:41781
> I0925 19:15:39.830492 27434 slave.cpp:2940] Status update manager successfully handled status update TASK_FAILED (UUID: 6bb8651c-0668-4724-8fbd-76db8a91adb7) for task 0 of framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000
> I0925 19:15:39.830641 27432 master.cpp:4415] Status update TASK_FAILED (UUID: 6bb8651c-0668-4724-8fbd-76db8a91adb7) for task 0 of framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000 from slave c8bf1c95-50f4-4832-a570-c560f0b466ae-S0 at slave(46)@172.17.1.195:41781 (f57fd4291168)
> I0925 19:15:39.830682 27432 master.cpp:4454] Forwarding status update TASK_FAILED (UUID: 6bb8651c-0668-4724-8fbd-76db8a91adb7) for task 0 of framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000
> I0925 19:15:39.830842 27432 master.cpp:6081] Updating the latest state of task 0 of framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000 to TASK_FAILED
> I0925 19:15:39.831075 27431 sched.cpp:918] Scheduler::statusUpdate took 176815ns
> I0925 19:15:39.831204 27439 hierarchical.hpp:1103] Recovered cpus(*):1; mem(*):1 (total: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: ) on slave c8bf1c95-50f4-4832-a570-c560f0b466ae-S0 from framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000
> I0925 19:15:39.831357 27432 master.cpp:6149] Removing task 0 with resources cpus(*):1; mem(*):1 of framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000 on slave c8bf1c95-50f4-4832-a570-c560f0b466ae-S0 at slave(46)@172.17.1.195:41781 (f57fd4291168)
> I0925 19:15:39.831491 27432 master.cpp:3606] Processing ACKNOWLEDGE call 6bb8651c-0668-4724-8fbd-76db8a91adb7 for task 0 of framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000 (default) at scheduler-dda30e8e-47b7-4b1d-9a96-32364754be63@172.17.1.195:41781 on slave c8bf1c95-50f4-4832-a570-c560f0b466ae-S0
> I0925 19:15:39.831763 27437 status_update_manager.cpp:394] Received status update acknowledgement (UUID: 6bb8651c-0668-4724-8fbd-76db8a91adb7) for task 0 of framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000
> I0925 19:15:39.831957 27437 status_update_manager.cpp:826] Checkpointing ACK for status update TASK_FAILED (UUID: 6bb8651c-0668-4724-8fbd-76db8a91adb7) for task 0 of framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000
> I0925 19:15:39.833057 27437 status_update_manager.cpp:530] Cleaning up status update stream for task 0 of framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000
> I0925 19:15:39.833407 27432 slave.cpp:2319] Status update manager successfully handled status update acknowledgement (UUID: 6bb8651c-0668-4724-8fbd-76db8a91adb7) for task 0 of framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000
> I0925 19:15:39.833447 27432 slave.cpp:5188] Completing task 0
> I0925 19:15:39.833470 27432 slave.cpp:3544] Cleaning up executor '0' of framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000
> I0925 19:15:39.833768 27437 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_LocalUncachedExtract_LwfzK4/slaves/c8bf1c95-50f4-4832-a570-c560f0b466ae-S0/frameworks/c8bf1c95-50f4-4832-a570-c560f0b466ae-0000/executors/0/runs/4bc31eb2-709b-4b09-a5a9-21a8387e355a' for gc 6.99999035100741days in the future
> I0925 19:15:39.833933 27437 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_LocalUncachedExtract_LwfzK4/slaves/c8bf1c95-50f4-4832-a570-c560f0b466ae-S0/frameworks/c8bf1c95-50f4-4832-a570-c560f0b466ae-0000/executors/0' for gc 6.99999034949333days in the future
> I0925 19:15:39.834005 27432 slave.cpp:3633] Cleaning up framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000
> I0925 19:15:39.834031 27437 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_LocalUncachedExtract_LwfzK4/meta/slaves/c8bf1c95-50f4-4832-a570-c560f0b466ae-S0/frameworks/c8bf1c95-50f4-4832-a570-c560f0b466ae-0000/executors/0/runs/4bc31eb2-709b-4b09-a5a9-21a8387e355a' for gc 6.99999034847111days in the future
> I0925 19:15:39.834106 27430 status_update_manager.cpp:284] Closing status update streams for framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000
> I0925 19:15:39.834121 27437 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_LocalUncachedExtract_LwfzK4/meta/slaves/c8bf1c95-50f4-4832-a570-c560f0b466ae-S0/frameworks/c8bf1c95-50f4-4832-a570-c560f0b466ae-0000/executors/0' for gc 6.99999034757926days in the future
> I0925 19:15:39.834266 27437 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_LocalUncachedExtract_LwfzK4/slaves/c8bf1c95-50f4-4832-a570-c560f0b466ae-S0/frameworks/c8bf1c95-50f4-4832-a570-c560f0b466ae-0000' for gc 6.99999034594963days in the future
> I0925 19:15:39.834360 27437 gc.cpp:56] Scheduling '/tmp/FetcherCacheTest_LocalUncachedExtract_LwfzK4/meta/slaves/c8bf1c95-50f4-4832-a570-c560f0b466ae-S0/frameworks/c8bf1c95-50f4-4832-a570-c560f0b466ae-0000' for gc 6.99999034517333days in the future
> I0925 19:15:40.549545 27428 hierarchical.hpp:1421] No inverse offers to send out!
> I0925 19:15:40.549640 27428 hierarchical.hpp:1221] Performed allocation for 1 slaves in 849712ns
> I0925 19:15:40.550092 27442 master.cpp:4967] Sending 1 offers to framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000 (default) at scheduler-dda30e8e-47b7-4b1d-9a96-32364754be63@172.17.1.195:41781
> I0925 19:15:40.550679 27442 sched.cpp:811] Scheduler::resourceOffers took 157498ns
> I0925 19:15:40.551633 27432 master.cpp:2918] Processing ACCEPT call for offers: [ c8bf1c95-50f4-4832-a570-c560f0b466ae-O1 ] on slave c8bf1c95-50f4-4832-a570-c560f0b466ae-S0 at slave(46)@172.17.1.195:41781 (f57fd4291168) for framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000 (default) at scheduler-dda30e8e-47b7-4b1d-9a96-32364754be63@172.17.1.195:41781
> I0925 19:15:40.552602 27432 hierarchical.hpp:1103] Recovered cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] (total: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: ) on slave c8bf1c95-50f4-4832-a570-c560f0b466ae-S0 from framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000
> I0925 19:15:40.552672 27432 hierarchical.hpp:1140] Framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000 filtered slave c8bf1c95-50f4-4832-a570-c560f0b466ae-S0 for 5secs
> I0925 19:15:41.551115 27428 hierarchical.hpp:1521] Filtered offer with cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] on slave c8bf1c95-50f4-4832-a570-c560f0b466ae-S0 for framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000
> I0925 19:15:41.551200 27428 hierarchical.hpp:1326] No resources available to allocate!
> I0925 19:15:41.551224 27428 hierarchical.hpp:1421] No inverse offers to send out!
> I0925 19:15:41.551239 27428 hierarchical.hpp:1221] Performed allocation for 1 slaves in 595589ns
> I0925 19:15:42.552183 27433 hierarchical.hpp:1521] Filtered offer with cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] on slave c8bf1c95-50f4-4832-a570-c560f0b466ae-S0 for framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000
> I0925 19:15:42.552254 27433 hierarchical.hpp:1326] No resources available to allocate!
> I0925 19:15:42.552271 27433 hierarchical.hpp:1421] No inverse offers to send out!
> I0925 19:15:42.552281 27433 hierarchical.hpp:1221] Performed allocation for 1 slaves in 496429ns
> I0925 19:15:43.553062 27442 hierarchical.hpp:1521] Filtered offer with cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] on slave c8bf1c95-50f4-4832-a570-c560f0b466ae-S0 for framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000
> I0925 19:15:43.553134 27442 hierarchical.hpp:1326] No resources available to allocate!
> I0925 19:15:43.553151 27442 hierarchical.hpp:1421] No inverse offers to send out!
> I0925 19:15:43.553163 27442 hierarchical.hpp:1221] Performed allocation for 1 slaves in 482544ns
> I0925 19:15:44.554844 27443 hierarchical.hpp:1521] Filtered offer with cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] on slave c8bf1c95-50f4-4832-a570-c560f0b466ae-S0 for framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000
> I0925 19:15:44.554930 27443 hierarchical.hpp:1326] No resources available to allocate!
> I0925 19:15:44.554954 27443 hierarchical.hpp:1421] No inverse offers to send out!
> I0925 19:15:44.554970 27443 hierarchical.hpp:1221] Performed allocation for 1 slaves in 699469ns
> I0925 19:15:45.556754 27442 hierarchical.hpp:1421] No inverse offers to send out!
> I0925 19:15:45.556805 27442 hierarchical.hpp:1221] Performed allocation for 1 slaves in 702577ns
> I0925 19:15:45.557119 27437 master.cpp:4967] Sending 1 offers to framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000 (default) at scheduler-dda30e8e-47b7-4b1d-9a96-32364754be63@172.17.1.195:41781
> I0925 19:15:45.557569 27435 sched.cpp:811] Scheduler::resourceOffers took 122887ns
> I0925 19:15:45.558279 27433 master.cpp:2918] Processing ACCEPT call for offers: [ c8bf1c95-50f4-4832-a570-c560f0b466ae-O2 ] on slave c8bf1c95-50f4-4832-a570-c560f0b466ae-S0 at slave(46)@172.17.1.195:41781 (f57fd4291168) for framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000 (default) at scheduler-dda30e8e-47b7-4b1d-9a96-32364754be63@172.17.1.195:41781
> I0925 19:15:45.559015 27441 hierarchical.hpp:1103] Recovered cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] (total: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: ) on slave c8bf1c95-50f4-4832-a570-c560f0b466ae-S0 from framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000
> I0925 19:15:45.559070 27441 hierarchical.hpp:1140] Framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000 filtered slave c8bf1c95-50f4-4832-a570-c560f0b466ae-S0 for 5secs
> I0925 19:15:46.558176 27439 hierarchical.hpp:1521] Filtered offer with cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] on slave c8bf1c95-50f4-4832-a570-c560f0b466ae-S0 for framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000
> I0925 19:15:46.558245 27439 hierarchical.hpp:1326] No resources available to allocate!
> I0925 19:15:46.558262 27439 hierarchical.hpp:1421] No inverse offers to send out!
> I0925 19:15:46.558274 27439 hierarchical.hpp:1221] Performed allocation for 1 slaves in 509658ns
> I0925 19:15:47.559289 27429 hierarchical.hpp:1521] Filtered offer with cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] on slave c8bf1c95-50f4-4832-a570-c560f0b466ae-S0 for framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000
> I0925 19:15:47.559360 27429 hierarchical.hpp:1326] No resources available to allocate!
> I0925 19:15:47.559376 27429 hierarchical.hpp:1421] No inverse offers to send out!
> I0925 19:15:47.559386 27429 hierarchical.hpp:1221] Performed allocation for 1 slaves in 495131ns
> I0925 19:15:48.560979 27442 hierarchical.hpp:1521] Filtered offer with cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] on slave c8bf1c95-50f4-4832-a570-c560f0b466ae-S0 for framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000
> I0925 19:15:48.561064 27442 hierarchical.hpp:1326] No resources available to allocate!
> I0925 19:15:48.561087 27442 hierarchical.hpp:1421] No inverse offers to send out!
> I0925 19:15:48.561101 27442 hierarchical.hpp:1221] Performed allocation for 1 slaves in 710782ns
> I0925 19:15:49.562594 27431 hierarchical.hpp:1521] Filtered offer with cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] on slave c8bf1c95-50f4-4832-a570-c560f0b466ae-S0 for framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000
> I0925 19:15:49.562666 27431 hierarchical.hpp:1326] No resources available to allocate!
> I0925 19:15:49.562683 27431 hierarchical.hpp:1421] No inverse offers to send out!
> I0925 19:15:49.562695 27431 hierarchical.hpp:1221] Performed allocation for 1 slaves in 525867ns
> I0925 19:15:50.564564 27428 hierarchical.hpp:1421] No inverse offers to send out!
> I0925 19:15:50.564620 27428 hierarchical.hpp:1221] Performed allocation for 1 slaves in 621850ns
> I0925 19:15:50.565004 27432 master.cpp:4967] Sending 1 offers to framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000 (default) at scheduler-dda30e8e-47b7-4b1d-9a96-32364754be63@172.17.1.195:41781
> I0925 19:15:50.565457 27428 sched.cpp:811] Scheduler::resourceOffers took 110220ns
> I0925 19:15:50.566159 27437 master.cpp:2918] Processing ACCEPT call for offers: [ c8bf1c95-50f4-4832-a570-c560f0b466ae-O3 ] on slave c8bf1c95-50f4-4832-a570-c560f0b466ae-S0 at slave(46)@172.17.1.195:41781 (f57fd4291168) for framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000 (default) at scheduler-dda30e8e-47b7-4b1d-9a96-32364754be63@172.17.1.195:41781
> I0925 19:15:50.566815 27428 hierarchical.hpp:1103] Recovered cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] (total: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000], allocated: ) on slave c8bf1c95-50f4-4832-a570-c560f0b466ae-S0 from framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000
> I0925 19:15:50.566869 27428 hierarchical.hpp:1140] Framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000 filtered slave c8bf1c95-50f4-4832-a570-c560f0b466ae-S0 for 5secs
> I0925 19:15:51.565913 27433 hierarchical.hpp:1521] Filtered offer with cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] on slave c8bf1c95-50f4-4832-a570-c560f0b466ae-S0 for framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000
> I0925 19:15:51.565981 27433 hierarchical.hpp:1326] No resources available to allocate!
> I0925 19:15:51.565999 27433 hierarchical.hpp:1421] No inverse offers to send out!
> I0925 19:15:51.566009 27433 hierarchical.hpp:1221] Performed allocation for 1 slaves in 504883ns
> I0925 19:15:52.567260 27432 hierarchical.hpp:1521] Filtered offer with cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] on slave c8bf1c95-50f4-4832-a570-c560f0b466ae-S0 for framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000
> I0925 19:15:52.567333 27432 hierarchical.hpp:1326] No resources available to allocate!
> I0925 19:15:52.567350 27432 hierarchical.hpp:1421] No inverse offers to send out!
> I0925 19:15:52.567361 27432 hierarchical.hpp:1221] Performed allocation for 1 slaves in 513500ns
> I0925 19:15:53.568176 27438 hierarchical.hpp:1521] Filtered offer with cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] on slave c8bf1c95-50f4-4832-a570-c560f0b466ae-S0 for framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000
> I0925 19:15:53.568248 27438 hierarchical.hpp:1326] No resources available to allocate!
> I0925 19:15:53.568266 27438 hierarchical.hpp:1421] No inverse offers to send out!
> I0925 19:15:53.568281 27438 hierarchical.hpp:1221] Performed allocation for 1 slaves in 522293ns
> I0925 19:15:54.570142 27430 hierarchical.hpp:1521] Filtered offer with cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] on slave c8bf1c95-50f4-4832-a570-c560f0b466ae-S0 for framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000
> I0925 19:15:54.570226 27430 hierarchical.hpp:1326] No resources available to allocate!
> I0925 19:15:54.570250 27430 hierarchical.hpp:1421] No inverse offers to send out!
> I0925 19:15:54.570264 27430 hierarchical.hpp:1221] Performed allocation for 1 slaves in 626798ns
> I0925 19:15:54.588251 27442 slave.cpp:4267] Querying resource estimator for oversubscribable resources
> I0925 19:15:54.588673 27443 slave.cpp:4281] Received oversubscribable resources from the resource estimator
> I0925 19:15:54.596678 27428 slave.cpp:3138] Received ping from slave-observer(45)@172.17.1.195:41781
> ../../src/tests/fetcher_cache_tests.cpp:681: Failure
> Failed to wait 15secs for awaitFinished(task.get())
> I0925 19:15:54.606274 27410 sched.cpp:1771] Asked to stop the driver
> I0925 19:15:54.606623 27439 master.cpp:1119] Framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000 (default) at scheduler-dda30e8e-47b7-4b1d-9a96-32364754be63@172.17.1.195:41781 disconnected
> I0925 19:15:54.606679 27439 master.cpp:2475] Disconnecting framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000 (default) at scheduler-dda30e8e-47b7-4b1d-9a96-32364754be63@172.17.1.195:41781
> I0925 19:15:54.606855 27439 master.cpp:2499] Deactivating framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000 (default) at scheduler-dda30e8e-47b7-4b1d-9a96-32364754be63@172.17.1.195:41781
> I0925 19:15:54.607441 27439 master.cpp:1143] Giving framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000 (default) at scheduler-dda30e8e-47b7-4b1d-9a96-32364754be63@172.17.1.195:41781 0ns to failover
> I0925 19:15:54.607770 27433 hierarchical.hpp:599] Deactivated framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000
> I0925 19:15:54.609256 27432 master.cpp:4815] Framework failover timeout, removing framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000 (default) at scheduler-dda30e8e-47b7-4b1d-9a96-32364754be63@172.17.1.195:41781
> I0925 19:15:54.609297 27432 master.cpp:5571] Removing framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000 (default) at scheduler-dda30e8e-47b7-4b1d-9a96-32364754be63@172.17.1.195:41781
> I0925 19:15:54.609501 27433 slave.cpp:1980] Asked to shut down framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000 by master@172.17.1.195:41781
> W0925 19:15:54.609549 27433 slave.cpp:1995] Cannot shut down unknown framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000
> I0925 19:15:54.609881 27432 master.cpp:919] Master terminating
> I0925 19:15:54.610255 27440 hierarchical.hpp:552] Removed framework c8bf1c95-50f4-4832-a570-c560f0b466ae-0000
> I0925 19:15:54.610627 27440 hierarchical.hpp:706] Removed slave c8bf1c95-50f4-4832-a570-c560f0b466ae-S0
> I0925 19:15:54.611197 27436 slave.cpp:3184] master@172.17.1.195:41781 exited
> W0925 19:15:54.611233 27436 slave.cpp:3187] Master disconnected! Waiting for a new master to be elected
> I0925 19:15:54.616207 27410 slave.cpp:585] Slave terminating
> [ FAILED ] FetcherCacheTest.LocalUncachedExtract (15091 ms)
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)