[ https://issues.apache.org/jira/browse/MESOS-5805?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16898791#comment-16898791 ]
Andrei Sekretenko edited comment on MESOS-5805 at 8/2/19 10:55 AM: ------------------------------------------------------------------- Well, this SHOULD be flaky - there is an actual race between this test re-setting expectation on the MOCK_METHOD call and the scheduler driver calling the mock method: https://github.com/apache/mesos/blob/e1176c453d04a8ef8f53cf23928b5bbb09173d78/src/tests/fetcher_cache_tests.cpp#L221 https://github.com/apache/mesos/blob/e1176c453d04a8ef8f53cf23928b5bbb09173d78/src/tests/fetcher_cache_tests.cpp#L453 I would expect all the other tests using this setup to be flaky too. was (Author: asekretenko): Well, this SHOULD be flaky - there is an actual race between this test re-setting expectation on the MOCK_METHOD call and the scheduler driver calling the mock method: https://github.com/apache/mesos/blob/e1176c453d04a8ef8f53cf23928b5bbb09173d78/src/tests/fetcher_cache_tests.cpp#L221 https://github.com/apache/mesos/blob/e1176c453d04a8ef8f53cf23928b5bbb09173d78/src/tests/fetcher_cache_tests.cpp#L453 > FetcherCacheTest.CachedCustomOutputFileWithSubdirectory is flaky > ---------------------------------------------------------------- > > Key: MESOS-5805 > URL: https://issues.apache.org/jira/browse/MESOS-5805 > Project: Mesos > Issue Type: Bug > Reporter: Anand Mazumdar > Priority: Major > Labels: containerization, flaky, flaky-test, tests > > Showed up on ASF CI: > https://builds.apache.org/job/Mesos/BUILDTOOL=autotools,COMPILER=clang,CONFIGURATION=--verbose%20--enable-libevent%20--enable-ssl,ENVIRONMENT=GLOG_v=1%20MESOS_VERBOSE=1,OS=ubuntu%3A14.04,label_exp=(docker%7C%7CHadoop)&&(!ubuntu-us1)&&(!ubuntu-6)/2466/changes > {code} > [ RUN ] FetcherCacheTest.CachedCustomOutputFileWithSubdirectory > I0707 19:32:26.474630 27874 cluster.cpp:155] Creating default 'local' > authorizer > I0707 19:32:26.569936 27874 leveldb.cpp:174] Opened db in 94.192009ms > I0707 19:32:26.612267 27874 leveldb.cpp:181] Compacted db in 42.112514ms > I0707 19:32:26.612556 27874 leveldb.cpp:196] Created db iterator in 53311ns > I0707 19:32:26.612701 27874 leveldb.cpp:202] Seeked to beginning of db in > 16446ns > I0707 19:32:26.612807 27874 leveldb.cpp:271] Iterated through 0 keys in the > db in 22978ns > I0707 19:32:26.612962 27874 replica.cpp:779] Replica recovered with log > positions 0 -> 0 with 1 holes and 0 unlearned > I0707 19:32:26.614738 27900 recover.cpp:451] Starting replica recovery > I0707 19:32:26.615362 27900 recover.cpp:477] Replica is in EMPTY status > I0707 19:32:26.617480 27893 replica.cpp:673] Replica in EMPTY status received > a broadcasted recover request from (2046)@172.17.0.7:47769 > I0707 19:32:26.618697 27903 recover.cpp:197] Received a recover response from > a replica in EMPTY status > I0707 19:32:26.619361 27903 recover.cpp:568] Updating replica status to > STARTING > I0707 19:32:26.641041 27901 master.cpp:382] Master > 27e097c5-33d2-457b-97f7-eafde246f1bb (89b080073abb) started on > 172.17.0.7:47769 > I0707 19:32:26.641352 27901 master.cpp:384] Flags at startup: --acls="" > --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" > --allocation_interval="1secs" --allocator="HierarchicalDRF" > --authenticate_agents="true" --authenticate_frameworks="true" > --authenticate_http="true" --authenticate_http_frameworks="true" > --authenticators="crammd5" --authorizers="local" > --credentials="/tmp/6aq2CX/credentials" --framework_sorter="drf" > --help="false" --hostname_lookup="true" --http_authenticators="basic" > --http_framework_authenticators="basic" --initialize_driver_logging="true" > --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" > --max_agent_ping_timeouts="5" --max_completed_frameworks="50" > --max_completed_tasks_per_framework="1000" --quiet="false" > --recovery_agent_removal_limit="100%" --registry="replicated_log" > --registry_fetch_timeout="1mins" --registry_store_timeout="100secs" > --registry_strict="true" --root_submissions="true" --user_sorter="drf" > --version="false" --webui_dir="/mesos/mesos-1.0.0/_inst/share/mesos/webui" > --work_dir="/tmp/6aq2CX/master" --zk_session_timeout="10secs" > I0707 19:32:26.642398 27901 master.cpp:434] Master only allowing > authenticated frameworks to register > I0707 19:32:26.642501 27901 master.cpp:448] Master only allowing > authenticated agents to register > I0707 19:32:26.642599 27901 master.cpp:461] Master only allowing > authenticated HTTP frameworks to register > I0707 19:32:26.642691 27901 credentials.hpp:37] Loading credentials for > authentication from '/tmp/6aq2CX/credentials' > I0707 19:32:26.643245 27901 master.cpp:506] Using default 'crammd5' > authenticator > I0707 19:32:26.643949 27901 master.cpp:578] Using default 'basic' HTTP > authenticator > I0707 19:32:26.644579 27901 master.cpp:658] Using default 'basic' HTTP > framework authenticator > I0707 19:32:26.645917 27901 master.cpp:705] Authorization enabled > I0707 19:32:26.646328 27897 hierarchical.cpp:151] Initialized hierarchical > allocator process > I0707 19:32:26.647629 27904 leveldb.cpp:304] Persisting metadata (8 bytes) to > leveldb took 27.466685ms > I0707 19:32:26.647743 27905 whitelist_watcher.cpp:77] No whitelist given > I0707 19:32:26.647814 27904 replica.cpp:320] Persisted replica status to > STARTING > I0707 19:32:26.648566 27904 recover.cpp:477] Replica is in STARTING status > I0707 19:32:26.651857 27899 replica.cpp:673] Replica in STARTING status > received a broadcasted recover request from (2050)@172.17.0.7:47769 > I0707 19:32:26.652978 27907 recover.cpp:197] Received a recover response from > a replica in STARTING status > I0707 19:32:26.654054 27907 recover.cpp:568] Updating replica status to VOTING > I0707 19:32:26.660482 27905 master.cpp:1973] The newly elected leader is > master@172.17.0.7:47769 with id 27e097c5-33d2-457b-97f7-eafde246f1bb > I0707 19:32:26.660712 27905 master.cpp:1986] Elected as the leading master! > I0707 19:32:26.660835 27905 master.cpp:1673] Recovering from registrar > I0707 19:32:26.661224 27895 registrar.cpp:332] Recovering registrar > I0707 19:32:26.681769 27892 leveldb.cpp:304] Persisting metadata (8 bytes) to > leveldb took 26.868425ms > I0707 19:32:26.682031 27892 replica.cpp:320] Persisted replica status to > VOTING > I0707 19:32:26.682479 27899 recover.cpp:582] Successfully joined the Paxos > group > I0707 19:32:26.683171 27899 recover.cpp:466] Recover process terminated > I0707 19:32:26.684547 27892 log.cpp:553] Attempting to start the writer > I0707 19:32:26.686614 27897 replica.cpp:493] Replica received implicit > promise request from (2051)@172.17.0.7:47769 with proposal 1 > I0707 19:32:26.709501 27897 leveldb.cpp:304] Persisting metadata (8 bytes) to > leveldb took 22.766332ms > I0707 19:32:26.709594 27897 replica.cpp:342] Persisted promised to 1 > I0707 19:32:26.711184 27897 coordinator.cpp:238] Coordinator attempting to > fill missing positions > I0707 19:32:26.713104 27897 replica.cpp:388] Replica received explicit > promise request from (2052)@172.17.0.7:47769 for position 0 with proposal 2 > I0707 19:32:26.740506 27897 leveldb.cpp:341] Persisting action (8 bytes) to > leveldb took 26.031904ms > I0707 19:32:26.740598 27897 replica.cpp:712] Persisted action at 0 > I0707 19:32:26.742622 27902 replica.cpp:537] Replica received write request > for position 0 from (2053)@172.17.0.7:47769 > I0707 19:32:26.742712 27902 leveldb.cpp:436] Reading position from leveldb > took 57696ns > I0707 19:32:26.768502 27902 leveldb.cpp:341] Persisting action (14 bytes) to > leveldb took 25.768923ms > I0707 19:32:26.768704 27902 replica.cpp:712] Persisted action at 0 > I0707 19:32:26.769994 27895 replica.cpp:691] Replica received learned notice > for position 0 from @0.0.0.0:0 > I0707 19:32:26.793498 27895 leveldb.cpp:341] Persisting action (16 bytes) to > leveldb took 23.061867ms > I0707 19:32:26.793726 27895 replica.cpp:712] Persisted action at 0 > I0707 19:32:26.793859 27895 replica.cpp:697] Replica learned NOP action at > position 0 > I0707 19:32:26.795469 27899 log.cpp:569] Writer started with ending position 0 > I0707 19:32:26.797344 27895 leveldb.cpp:436] Reading position from leveldb > took 73951ns > I0707 19:32:26.806041 27895 registrar.cpp:365] Successfully fetched the > registry (0B) in 144.496128ms > I0707 19:32:26.806359 27895 registrar.cpp:464] Applied 1 operations in > 43069ns; attempting to update the 'registry' > I0707 19:32:26.807682 27904 log.cpp:577] Attempting to append 168 bytes to > the log > I0707 19:32:26.807905 27904 coordinator.cpp:348] Coordinator attempting to > write APPEND action at position 1 > I0707 19:32:26.809219 27904 replica.cpp:537] Replica received write request > for position 1 from (2054)@172.17.0.7:47769 > I0707 19:32:26.835285 27904 leveldb.cpp:341] Persisting action (187 bytes) to > leveldb took 26.051963ms > I0707 19:32:26.835520 27904 replica.cpp:712] Persisted action at 1 > I0707 19:32:26.837309 27904 replica.cpp:691] Replica received learned notice > for position 1 from @0.0.0.0:0 > I0707 19:32:26.860438 27904 leveldb.cpp:341] Persisting action (189 bytes) to > leveldb took 23.040844ms > I0707 19:32:26.860656 27904 replica.cpp:712] Persisted action at 1 > I0707 19:32:26.860785 27904 replica.cpp:697] Replica learned APPEND action at > position 1 > I0707 19:32:26.866220 27899 registrar.cpp:509] Successfully updated the > 'registry' in 59.460096ms > I0707 19:32:26.866374 27898 log.cpp:596] Attempting to truncate the log to 1 > I0707 19:32:26.867024 27898 coordinator.cpp:348] Coordinator attempting to > write TRUNCATE action at position 2 > I0707 19:32:26.868391 27906 replica.cpp:537] Replica received write request > for position 2 from (2055)@172.17.0.7:47769 > I0707 19:32:26.868849 27899 registrar.cpp:395] Successfully recovered > registrar > I0707 19:32:26.869691 27893 master.cpp:1781] Recovered 0 agents from the > Registry (129B) ; allowing 10mins for agents to re-register > I0707 19:32:26.869958 27893 hierarchical.cpp:178] Skipping recovery of > hierarchical allocator: nothing to recover > I0707 19:32:26.893944 27906 leveldb.cpp:341] Persisting action (16 bytes) to > leveldb took 25.434238ms > I0707 19:32:26.894160 27906 replica.cpp:712] Persisted action at 2 > I0707 19:32:26.896083 27906 replica.cpp:691] Replica received learned notice > for position 2 from @0.0.0.0:0 > I0707 19:32:26.919489 27906 leveldb.cpp:341] Persisting action (18 bytes) to > leveldb took 23.328407ms > I0707 19:32:26.919626 27906 leveldb.cpp:399] Deleting ~1 keys from leveldb > took 73119ns > I0707 19:32:26.919653 27906 replica.cpp:712] Persisted action at 2 > I0707 19:32:26.919689 27906 replica.cpp:697] Replica learned TRUNCATE action > at position 2 > I0707 19:32:26.926030 27874 containerizer.cpp:196] Using isolation: > posix/cpu,posix/mem,filesystem/posix,network/cni > W0707 19:32:26.928402 27874 backend.cpp:75] Failed to create 'aufs' backend: > AufsBackend requires root privileges, but is running as user mesos > W0707 19:32:26.929761 27874 backend.cpp:75] Failed to create 'bind' backend: > BindBackend requires root privileges > I0707 19:32:26.940363 27874 cluster.cpp:432] Creating default 'local' > authorizer > I0707 19:32:26.946017 27901 slave.cpp:205] Agent started on > 47)@172.17.0.7:47769 > I0707 19:32:26.946146 27901 slave.cpp:206] Flags at startup: --acls="" > --appc_simple_discovery_uri_prefix="http://" > --appc_store_dir="/tmp/mesos/store/appc" --authenticate_http="true" > --authenticatee="crammd5" --authentication_backoff_factor="1secs" > --authorizer="local" --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_CachedCustomOutputFileWithSubdirectory_YYDf97/credential" > --default_role="*" --disk_watch_interval="1mins" --docker="docker" > --docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io" > --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" > --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" > --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" > --enforce_container_disk_quota="false" > --executor_registration_timeout="1mins" > --executor_shutdown_grace_period="5secs" > --fetcher_cache_dir="/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_YYDf97/fetch" > --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" > --gc_disk_headroom="0.1" --hadoop_home="" --help="false" > --hostname_lookup="true" --http_authenticators="basic" > --http_command_executor="false" > --http_credentials="/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_YYDf97/http_credentials" > --image_provisioner_backend="copy" --initialize_driver_logging="true" > --isolation="posix/cpu,posix/mem" > --launcher_dir="/mesos/mesos-1.0.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:1000;mem:1000" --revocable_cpu_low_priority="true" > --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" > --systemd_enable_support="true" > --systemd_runtime_directory="/run/systemd/system" --version="false" > --work_dir="/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_YYDf97" > I0707 19:32:26.947057 27901 credentials.hpp:86] Loading credential for > authentication from > '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_YYDf97/credential' > I0707 19:32:26.947353 27901 slave.cpp:343] Agent using credential for: > test-principal > I0707 19:32:26.949486 27901 credentials.hpp:37] Loading credentials for > authentication from > '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_YYDf97/http_credentials' > I0707 19:32:26.949837 27901 slave.cpp:395] Using default 'basic' HTTP > authenticator > I0707 19:32:26.951508 27901 resources.cpp:572] Parsing resources as JSON > failed: cpus:1000;mem:1000 > Trying semicolon-delimited string format instead > I0707 19:32:26.951822 27901 resources.cpp:572] Parsing resources as JSON > failed: cpus:1000;mem:1000 > Trying semicolon-delimited string format instead > I0707 19:32:26.952347 27901 slave.cpp:594] Agent resources: cpus(*):1000; > mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] > I0707 19:32:26.955682 27901 slave.cpp:602] Agent attributes: [ ] > I0707 19:32:26.955793 27901 slave.cpp:607] Agent hostname: 89b080073abb > I0707 19:32:26.961683 27901 state.cpp:57] Recovering state from > '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_YYDf97/meta' > I0707 19:32:26.962864 27907 status_update_manager.cpp:200] Recovering status > update manager > I0707 19:32:26.963281 27905 containerizer.cpp:522] Recovering containerizer > I0707 19:32:26.966325 27902 provisioner.cpp:253] Provisioner recovery complete > I0707 19:32:26.968153 27902 slave.cpp:4856] Finished recovery > I0707 19:32:26.969983 27902 slave.cpp:5028] Querying resource estimator for > oversubscribable resources > I0707 19:32:26.971781 27902 slave.cpp:969] New master detected at > master@172.17.0.7:47769 > I0707 19:32:26.972028 27892 status_update_manager.cpp:174] Pausing sending > status updates > I0707 19:32:26.972312 27902 slave.cpp:1028] Authenticating with master > master@172.17.0.7:47769 > I0707 19:32:26.972450 27902 slave.cpp:1039] Using default CRAM-MD5 > authenticatee > I0707 19:32:26.972923 27896 authenticatee.cpp:121] Creating new client SASL > connection > I0707 19:32:26.974572 27904 master.cpp:6006] Authenticating > slave(47)@172.17.0.7:47769 > I0707 19:32:26.974946 27895 authenticator.cpp:414] Starting authentication > session for crammd5_authenticatee(139)@172.17.0.7:47769 > I0707 19:32:26.975589 27895 authenticator.cpp:98] Creating new server SASL > connection > I0707 19:32:26.976150 27895 authenticatee.cpp:213] Received SASL > authentication mechanisms: CRAM-MD5 > I0707 19:32:26.976929 27895 authenticatee.cpp:239] Attempting to authenticate > with mechanism 'CRAM-MD5' > I0707 19:32:26.977274 27895 authenticator.cpp:204] Received SASL > authentication start > I0707 19:32:26.978523 27895 authenticator.cpp:326] Authentication requires > more steps > I0707 19:32:26.978771 27904 authenticatee.cpp:259] Received SASL > authentication step > I0707 19:32:26.978956 27904 authenticator.cpp:232] Received SASL > authentication step > I0707 19:32:26.979115 27904 auxprop.cpp:109] Request to lookup properties for > user: 'test-principal' realm: '89b080073abb' server FQDN: '89b080073abb' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: false > I0707 19:32:26.979269 27904 auxprop.cpp:181] Looking up auxiliary property > '*userPassword' > I0707 19:32:26.979514 27904 auxprop.cpp:181] Looking up auxiliary property > '*cmusaslsecretCRAM-MD5' > I0707 19:32:26.979754 27904 auxprop.cpp:109] Request to lookup properties for > user: 'test-principal' realm: '89b080073abb' server FQDN: '89b080073abb' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: true > I0707 19:32:26.979840 27904 auxprop.cpp:131] Skipping auxiliary property > '*userPassword' since SASL_AUXPROP_AUTHZID == true > I0707 19:32:26.979966 27904 auxprop.cpp:131] Skipping auxiliary property > '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true > I0707 19:32:26.980000 27904 authenticator.cpp:318] Authentication success > I0707 19:32:26.980474 27896 authenticatee.cpp:299] Authentication success > I0707 19:32:26.980962 27904 master.cpp:6036] Successfully authenticated > principal 'test-principal' at slave(47)@172.17.0.7:47769 > I0707 19:32:26.982486 27907 authenticator.cpp:432] Authentication session > cleanup for crammd5_authenticatee(139)@172.17.0.7:47769 > I0707 19:32:26.983160 27902 slave.cpp:1001] Detecting new master > I0707 19:32:26.984596 27902 slave.cpp:5042] Received oversubscribable > resources from the resource estimator > I0707 19:32:26.985185 27902 slave.cpp:1123] Successfully authenticated with > master master@172.17.0.7:47769 > I0707 19:32:26.986740 27902 slave.cpp:1529] Will retry registration in > 5.184254ms if necessary > I0707 19:32:26.987226 27900 master.cpp:4676] Registering agent at > slave(47)@172.17.0.7:47769 (89b080073abb) with id > 27e097c5-33d2-457b-97f7-eafde246f1bb-S0 > I0707 19:32:26.989073 27900 registrar.cpp:464] Applied 1 operations in > 101321ns; attempting to update the 'registry' > I0707 19:32:26.993281 27900 log.cpp:577] Attempting to append 337 bytes to > the log > I0707 19:32:26.994741 27900 coordinator.cpp:348] Coordinator attempting to > write APPEND action at position 3 > I0707 19:32:26.998684 27898 replica.cpp:537] Replica received write request > for position 3 from (2072)@172.17.0.7:47769 > I0707 19:32:27.006036 27901 slave.cpp:1529] Will retry registration in > 32.31224ms if necessary > I0707 19:32:27.006404 27901 master.cpp:4664] Ignoring register agent message > from slave(47)@172.17.0.7:47769 (89b080073abb) as admission is already in > progress > I0707 19:32:27.022506 27898 leveldb.cpp:341] Persisting action (356 bytes) to > leveldb took 23.781478ms > I0707 19:32:27.022605 27898 replica.cpp:712] Persisted action at 3 > I0707 19:32:27.024341 27898 replica.cpp:691] Replica received learned notice > for position 3 from @0.0.0.0:0 > I0707 19:32:27.040745 27900 slave.cpp:1529] Will retry registration in > 64.501962ms if necessary > I0707 19:32:27.041081 27900 master.cpp:4664] Ignoring register agent message > from slave(47)@172.17.0.7:47769 (89b080073abb) as admission is already in > progress > I0707 19:32:27.054486 27898 leveldb.cpp:341] Persisting action (358 bytes) to > leveldb took 30.127114ms > I0707 19:32:27.054553 27898 replica.cpp:712] Persisted action at 3 > I0707 19:32:27.054594 27898 replica.cpp:697] Replica learned APPEND action at > position 3 > I0707 19:32:27.058605 27900 registrar.cpp:509] Successfully updated the > 'registry' in 68.084992ms > I0707 19:32:27.058904 27895 log.cpp:596] Attempting to truncate the log to 3 > I0707 19:32:27.060483 27899 coordinator.cpp:348] Coordinator attempting to > write TRUNCATE action at position 4 > I0707 19:32:27.062862 27892 replica.cpp:537] Replica received write request > for position 4 from (2073)@172.17.0.7:47769 > I0707 19:32:27.064043 27907 master.cpp:4745] Registered agent > 27e097c5-33d2-457b-97f7-eafde246f1bb-S0 at slave(47)@172.17.0.7:47769 > (89b080073abb) with cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; > ports(*):[31000-32000] > I0707 19:32:27.065629 27899 slave.cpp:1169] Registered with master > master@172.17.0.7:47769; given agent ID > 27e097c5-33d2-457b-97f7-eafde246f1bb-S0 > I0707 19:32:27.065661 27899 fetcher.cpp:86] Clearing fetcher cache > I0707 19:32:27.066124 27899 slave.cpp:1192] Checkpointing SlaveInfo to > '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_YYDf97/meta/slaves/27e097c5-33d2-457b-97f7-eafde246f1bb-S0/slave.info' > I0707 19:32:27.066478 27904 status_update_manager.cpp:181] Resuming sending > status updates > I0707 19:32:27.067095 27899 slave.cpp:1229] Forwarding total oversubscribed > resources > I0707 19:32:27.067220 27899 slave.cpp:3760] Received ping from > slave-observer(47)@172.17.0.7:47769 > I0707 19:32:27.068536 27907 hierarchical.cpp:478] Added agent > 27e097c5-33d2-457b-97f7-eafde246f1bb-S0 (89b080073abb) with cpus(*):1000; > mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] (allocated: ) > I0707 19:32:27.068730 27907 hierarchical.cpp:1537] No allocations performed > I0707 19:32:27.068801 27907 hierarchical.cpp:1195] Performed allocation for > agent 27e097c5-33d2-457b-97f7-eafde246f1bb-S0 in 218556ns > I0707 19:32:27.068866 27899 master.cpp:5128] Received update of agent > 27e097c5-33d2-457b-97f7-eafde246f1bb-S0 at slave(47)@172.17.0.7:47769 > (89b080073abb) with total oversubscribed resources > I0707 19:32:27.069129 27899 hierarchical.cpp:542] Agent > 27e097c5-33d2-457b-97f7-eafde246f1bb-S0 (89b080073abb) updated with > oversubscribed resources (total: cpus(*):1000; mem(*):1000; > disk(*):3.70122e+06; ports(*):[31000-32000], allocated: ) > I0707 19:32:27.069268 27899 hierarchical.cpp:1537] No allocations performed > I0707 19:32:27.069330 27899 hierarchical.cpp:1195] Performed allocation for > agent 27e097c5-33d2-457b-97f7-eafde246f1bb-S0 in 157467ns > I0707 19:32:27.071974 27874 sched.cpp:226] Version: 1.0.0 > I0707 19:32:27.073761 27906 sched.cpp:330] New master detected at > master@172.17.0.7:47769 > I0707 19:32:27.073868 27906 sched.cpp:396] Authenticating with master > master@172.17.0.7:47769 > I0707 19:32:27.073897 27906 sched.cpp:403] Using default CRAM-MD5 > authenticatee > I0707 19:32:27.074276 27906 authenticatee.cpp:121] Creating new client SASL > connection > I0707 19:32:27.074748 27906 master.cpp:6006] Authenticating > scheduler-b12d469c-0d02-4585-91e4-2029dab1fa4e@172.17.0.7:47769 > I0707 19:32:27.074947 27906 authenticator.cpp:414] Starting authentication > session for crammd5_authenticatee(140)@172.17.0.7:47769 > I0707 19:32:27.075307 27906 authenticator.cpp:98] Creating new server SASL > connection > I0707 19:32:27.076591 27906 authenticatee.cpp:213] Received SASL > authentication mechanisms: CRAM-MD5 > I0707 19:32:27.076633 27906 authenticatee.cpp:239] Attempting to authenticate > with mechanism 'CRAM-MD5' > I0707 19:32:27.076732 27906 authenticator.cpp:204] Received SASL > authentication start > I0707 19:32:27.076798 27906 authenticator.cpp:326] Authentication requires > more steps > I0707 19:32:27.076896 27906 authenticatee.cpp:259] Received SASL > authentication step > I0707 19:32:27.077006 27906 authenticator.cpp:232] Received SASL > authentication step > I0707 19:32:27.077044 27906 auxprop.cpp:109] Request to lookup properties for > user: 'test-principal' realm: '89b080073abb' server FQDN: '89b080073abb' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: false > I0707 19:32:27.077070 27906 auxprop.cpp:181] Looking up auxiliary property > '*userPassword' > I0707 19:32:27.077122 27906 auxprop.cpp:181] Looking up auxiliary property > '*cmusaslsecretCRAM-MD5' > I0707 19:32:27.077162 27906 auxprop.cpp:109] Request to lookup properties for > user: 'test-principal' realm: '89b080073abb' server FQDN: '89b080073abb' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: true > I0707 19:32:27.077186 27906 auxprop.cpp:131] Skipping auxiliary property > '*userPassword' since SASL_AUXPROP_AUTHZID == true > I0707 19:32:27.077201 27906 auxprop.cpp:131] Skipping auxiliary property > '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true > I0707 19:32:27.077224 27906 authenticator.cpp:318] Authentication success > I0707 19:32:27.077405 27906 authenticatee.cpp:299] Authentication success > I0707 19:32:27.077901 27906 sched.cpp:502] Successfully authenticated with > master master@172.17.0.7:47769 > I0707 19:32:27.077930 27906 sched.cpp:820] Sending SUBSCRIBE call to > master@172.17.0.7:47769 > I0707 19:32:27.078029 27906 sched.cpp:853] Will retry registration in > 1.38078506secs if necessary > I0707 19:32:27.077478 27894 master.cpp:6036] Successfully authenticated > principal 'test-principal' at > scheduler-b12d469c-0d02-4585-91e4-2029dab1fa4e@172.17.0.7:47769 > I0707 19:32:27.078367 27894 master.cpp:2550] Received SUBSCRIBE call for > framework 'default' at > scheduler-b12d469c-0d02-4585-91e4-2029dab1fa4e@172.17.0.7:47769 > I0707 19:32:27.077536 27893 authenticator.cpp:432] Authentication session > cleanup for crammd5_authenticatee(140)@172.17.0.7:47769 > W0707 19:32:27.079169 27894 master.cpp:2558] Setting 'principal' in > FrameworkInfo to 'test-principal' because the framework authenticated with > that principal but did not set it in FrameworkInfo > I0707 19:32:27.079267 27894 master.cpp:2012] Authorizing framework principal > 'test-principal' to receive offers for role '*' > I0707 19:32:27.079823 27894 master.cpp:2626] Subscribing framework default > with checkpointing enabled and capabilities [ ] > I0707 19:32:27.080744 27894 hierarchical.cpp:271] Added framework > 27e097c5-33d2-457b-97f7-eafde246f1bb-0000 > I0707 19:32:27.081712 27894 hierarchical.cpp:1632] No inverse offers to send > out! > I0707 19:32:27.081866 27894 hierarchical.cpp:1172] Performed allocation for 1 > agents in 1.013733ms > I0707 19:32:27.082243 27894 sched.cpp:743] Framework registered with > 27e097c5-33d2-457b-97f7-eafde246f1bb-0000 > I0707 19:32:27.082551 27894 sched.cpp:757] Scheduler::registered took 36098ns > I0707 19:32:27.082960 27893 master.cpp:5835] Sending 1 offers to framework > 27e097c5-33d2-457b-97f7-eafde246f1bb-0000 (default) at > scheduler-b12d469c-0d02-4585-91e4-2029dab1fa4e@172.17.0.7:47769 > I0707 19:32:27.083443 27893 sched.cpp:917] Scheduler::resourceOffers took > 56308ns > I0707 19:32:27.098503 27892 leveldb.cpp:341] Persisting action (16 bytes) to > leveldb took 35.618891ms > I0707 19:32:27.098595 27892 replica.cpp:712] Persisted action at 4 > I0707 19:32:27.102179 27892 replica.cpp:691] Replica received learned notice > for position 4 from @0.0.0.0:0 > I0707 19:32:27.131503 27892 leveldb.cpp:341] Persisting action (18 bytes) to > leveldb took 29.315235ms > I0707 19:32:27.131675 27892 leveldb.cpp:399] Deleting ~2 keys from leveldb > took 96863ns > I0707 19:32:27.131713 27892 replica.cpp:712] Persisted action at 4 > I0707 19:32:27.131757 27892 replica.cpp:697] Replica learned TRUNCATE action > at position 4 > I0707 19:32:27.647403 27903 hierarchical.cpp:1537] No allocations performed > I0707 19:32:27.647547 27903 hierarchical.cpp:1632] No inverse offers to send > out! > I0707 19:32:27.647682 27903 hierarchical.cpp:1172] Performed allocation for 1 > agents in 516669ns > I0707 19:32:28.648784 27902 hierarchical.cpp:1537] No allocations performed > I0707 19:32:28.648861 27902 hierarchical.cpp:1632] No inverse offers to send > out! > I0707 19:32:28.648948 27902 hierarchical.cpp:1172] Performed allocation for 1 > agents in 401012ns > I0707 19:32:29.650446 27895 hierarchical.cpp:1537] No allocations performed > I0707 19:32:29.650642 27895 hierarchical.cpp:1632] No inverse offers to send > out! > I0707 19:32:29.650847 27895 hierarchical.cpp:1172] Performed allocation for 1 > agents in 657345ns > I0707 19:32:30.651702 27898 hierarchical.cpp:1537] No allocations performed > I0707 19:32:30.651906 27898 hierarchical.cpp:1632] No inverse offers to send > out! > I0707 19:32:30.664597 27898 hierarchical.cpp:1172] Performed allocation for 1 > agents in 13.162927ms > I0707 19:32:31.665630 27893 hierarchical.cpp:1537] No allocations performed > I0707 19:32:31.665824 27893 hierarchical.cpp:1632] No inverse offers to send > out! > I0707 19:32:31.666036 27893 hierarchical.cpp:1172] Performed allocation for 1 > agents in 662365ns > I0707 19:32:32.670071 27897 hierarchical.cpp:1537] No allocations performed > I0707 19:32:32.670270 27897 hierarchical.cpp:1632] No inverse offers to send > out! > I0707 19:32:32.670495 27897 hierarchical.cpp:1172] Performed allocation for 1 > agents in 674425ns > I0707 19:32:33.672061 27905 hierarchical.cpp:1537] No allocations performed > I0707 19:32:33.672142 27905 hierarchical.cpp:1632] No inverse offers to send > out! > I0707 19:32:33.672230 27905 hierarchical.cpp:1172] Performed allocation for 1 > agents in 409318ns > I0707 19:32:34.674059 27898 hierarchical.cpp:1537] No allocations performed > I0707 19:32:34.674139 27898 hierarchical.cpp:1632] No inverse offers to send > out! > I0707 19:32:34.674226 27898 hierarchical.cpp:1172] Performed allocation for 1 > agents in 401379ns > I0707 19:32:35.676055 27893 hierarchical.cpp:1537] No allocations performed > I0707 19:32:35.676136 27893 hierarchical.cpp:1632] No inverse offers to send > out! > I0707 19:32:35.676223 27893 hierarchical.cpp:1172] Performed allocation for 1 > agents in 404615ns > I0707 19:32:36.677132 27903 hierarchical.cpp:1537] No allocations performed > I0707 19:32:36.677203 27903 hierarchical.cpp:1632] No inverse offers to send > out! > I0707 19:32:36.677285 27903 hierarchical.cpp:1172] Performed allocation for 1 > agents in 373906ns > I0707 19:32:37.678169 27894 hierarchical.cpp:1537] No allocations performed > I0707 19:32:37.678241 27894 hierarchical.cpp:1632] No inverse offers to send > out! > I0707 19:32:37.678328 27894 hierarchical.cpp:1172] Performed allocation for 1 > agents in 390602ns > I0707 19:32:38.683040 27893 hierarchical.cpp:1537] No allocations performed > I0707 19:32:38.683117 27893 hierarchical.cpp:1632] No inverse offers to send > out! > I0707 19:32:38.683199 27893 hierarchical.cpp:1172] Performed allocation for 1 > agents in 385950ns > I0707 19:32:39.684876 27907 hierarchical.cpp:1537] No allocations performed > I0707 19:32:39.684948 27907 hierarchical.cpp:1632] No inverse offers to send > out! > I0707 19:32:39.685032 27907 hierarchical.cpp:1172] Performed allocation for 1 > agents in 382509ns > I0707 19:32:40.686470 27894 hierarchical.cpp:1537] No allocations performed > I0707 19:32:40.686542 27894 hierarchical.cpp:1632] No inverse offers to send > out! > I0707 19:32:40.686628 27894 hierarchical.cpp:1172] Performed allocation for 1 > agents in 393049ns > I0707 19:32:41.687438 27900 hierarchical.cpp:1537] No allocations performed > I0707 19:32:41.687513 27900 hierarchical.cpp:1632] No inverse offers to send > out! > I0707 19:32:41.687610 27900 hierarchical.cpp:1172] Performed allocation for 1 > agents in 443146ns > I0707 19:32:41.986075 27898 slave.cpp:5028] Querying resource estimator for > oversubscribable resources > I0707 19:32:41.986361 27898 slave.cpp:5042] Received oversubscribable > resources from the resource estimator > I0707 19:32:42.064714 27897 slave.cpp:3760] Received ping from > slave-observer(47)@172.17.0.7:47769 > ../../src/tests/fetcher_cache_tests.cpp:725: Failure > task: Failed to wait for resource offers: discarded > Begin listing sandboxes > End sandboxes > I0707 19:32:42.100826 27874 sched.cpp:1987] Asked to stop the driver > I0707 19:32:42.101096 27892 sched.cpp:1187] Stopping framework > '27e097c5-33d2-457b-97f7-eafde246f1bb-0000' > I0707 19:32:42.101379 27900 master.cpp:6410] Processing TEARDOWN call for > framework 27e097c5-33d2-457b-97f7-eafde246f1bb-0000 (default) at > scheduler-b12d469c-0d02-4585-91e4-2029dab1fa4e@172.17.0.7:47769 > I0707 19:32:42.101488 27900 master.cpp:6422] Removing framework > 27e097c5-33d2-457b-97f7-eafde246f1bb-0000 (default) at > scheduler-b12d469c-0d02-4585-91e4-2029dab1fa4e@172.17.0.7:47769 > I0707 19:32:42.102313 27900 hierarchical.cpp:382] Deactivated framework > 27e097c5-33d2-457b-97f7-eafde246f1bb-0000 > I0707 19:32:42.102485 27895 slave.cpp:2292] Asked to shut down framework > 27e097c5-33d2-457b-97f7-eafde246f1bb-0000 by master@172.17.0.7:47769 > W0707 19:32:42.102519 27895 slave.cpp:2307] Cannot shut down unknown > framework 27e097c5-33d2-457b-97f7-eafde246f1bb-0000 > I0707 19:32:42.103277 27900 hierarchical.cpp:924] 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 agent 27e097c5-33d2-457b-97f7-eafde246f1bb-S0 from framework > 27e097c5-33d2-457b-97f7-eafde246f1bb-0000 > I0707 19:32:42.103543 27900 hierarchical.cpp:333] Removed framework > 27e097c5-33d2-457b-97f7-eafde246f1bb-0000 > I0707 19:32:42.104722 27904 master.cpp:1218] Master terminating > I0707 19:32:42.105665 27903 hierarchical.cpp:510] Removed agent > 27e097c5-33d2-457b-97f7-eafde246f1bb-S0 > I0707 19:32:42.112759 27905 slave.cpp:3806] master@172.17.0.7:47769 exited > W0707 19:32:42.112814 27905 slave.cpp:3811] Master disconnected! Waiting for > a new master to be elected > I0707 19:32:42.227802 27874 slave.cpp:841] Agent terminating > [ FAILED ] FetcherCacheTest.CachedCustomOutputFileWithSubdirectory (15871 > ms) > {code} > Logs from a good run: > {code} > [ RUN ] FetcherCacheTest.CachedCustomOutputFileWithSubdirectory > I0707 18:08:20.581107 29421 cluster.cpp:155] Creating default 'local' > authorizer > I0707 18:08:20.666667 29421 leveldb.cpp:174] Opened db in 85.116942ms > I0707 18:08:20.692816 29421 leveldb.cpp:181] Compacted db in 26.071143ms > I0707 18:08:20.692908 29421 leveldb.cpp:196] Created db iterator in 24163ns > I0707 18:08:20.692925 29421 leveldb.cpp:202] Seeked to beginning of db in > 2922ns > I0707 18:08:20.692937 29421 leveldb.cpp:271] Iterated through 0 keys in the > db in 335ns > I0707 18:08:20.692993 29421 replica.cpp:779] Replica recovered with log > positions 0 -> 0 with 1 holes and 0 unlearned > I0707 18:08:20.694229 29454 recover.cpp:451] Starting replica recovery > I0707 18:08:20.694669 29451 recover.cpp:477] Replica is in EMPTY status > I0707 18:08:20.697399 29443 replica.cpp:673] Replica in EMPTY status received > a broadcasted recover request from (2049)@172.17.0.7:43512 > I0707 18:08:20.698287 29443 recover.cpp:197] Received a recover response from > a replica in EMPTY status > I0707 18:08:20.699291 29443 recover.cpp:568] Updating replica status to > STARTING > I0707 18:08:20.714786 29444 master.cpp:382] Master > 2d32adef-7b13-4aff-b8ed-363a2e14655f (753c2ae3a486) started on > 172.17.0.7:43512 > I0707 18:08:20.715103 29444 master.cpp:384] Flags at startup: --acls="" > --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" > --allocation_interval="1secs" --allocator="HierarchicalDRF" > --authenticate_agents="true" --authenticate_frameworks="true" > --authenticate_http="true" --authenticate_http_frameworks="true" > --authenticators="crammd5" --authorizers="local" > --credentials="/tmp/g9jQAg/credentials" --framework_sorter="drf" > --help="false" --hostname_lookup="true" --http_authenticators="basic" > --http_framework_authenticators="basic" --initialize_driver_logging="true" > --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" > --max_agent_ping_timeouts="5" --max_completed_frameworks="50" > --max_completed_tasks_per_framework="1000" --quiet="false" > --recovery_agent_removal_limit="100%" --registry="replicated_log" > --registry_fetch_timeout="1mins" --registry_store_timeout="100secs" > --registry_strict="true" --root_submissions="true" --user_sorter="drf" > --version="false" --webui_dir="/mesos/mesos-1.0.0/_inst/share/mesos/webui" > --work_dir="/tmp/g9jQAg/master" --zk_session_timeout="10secs" > I0707 18:08:20.715935 29444 master.cpp:434] Master only allowing > authenticated frameworks to register > I0707 18:08:20.716097 29444 master.cpp:448] Master only allowing > authenticated agents to register > I0707 18:08:20.716236 29444 master.cpp:461] Master only allowing > authenticated HTTP frameworks to register > I0707 18:08:20.716428 29444 credentials.hpp:37] Loading credentials for > authentication from '/tmp/g9jQAg/credentials' > I0707 18:08:20.731957 29444 master.cpp:506] Using default 'crammd5' > authenticator > I0707 18:08:20.732342 29444 master.cpp:578] Using default 'basic' HTTP > authenticator > I0707 18:08:20.732915 29444 master.cpp:658] Using default 'basic' HTTP > framework authenticator > I0707 18:08:20.733528 29444 master.cpp:705] Authorization enabled > I0707 18:08:20.734544 29441 hierarchical.cpp:151] Initialized hierarchical > allocator process > I0707 18:08:20.734659 29454 whitelist_watcher.cpp:77] No whitelist given > I0707 18:08:20.739863 29446 leveldb.cpp:304] Persisting metadata (8 bytes) to > leveldb took 39.990221ms > I0707 18:08:20.740063 29446 replica.cpp:320] Persisted replica status to > STARTING > I0707 18:08:20.740602 29446 recover.cpp:477] Replica is in STARTING status > I0707 18:08:20.742774 29446 replica.cpp:673] Replica in STARTING status > received a broadcasted recover request from (2052)@172.17.0.7:43512 > I0707 18:08:20.743501 29446 recover.cpp:197] Received a recover response from > a replica in STARTING status > I0707 18:08:20.744494 29451 recover.cpp:568] Updating replica status to VOTING > I0707 18:08:20.746140 29444 master.cpp:1973] The newly elected leader is > master@172.17.0.7:43512 with id 2d32adef-7b13-4aff-b8ed-363a2e14655f > I0707 18:08:20.746523 29444 master.cpp:1986] Elected as the leading master! > I0707 18:08:20.746713 29444 master.cpp:1673] Recovering from registrar > I0707 18:08:20.747117 29443 registrar.cpp:332] Recovering registrar > I0707 18:08:20.780143 29445 leveldb.cpp:304] Persisting metadata (8 bytes) to > leveldb took 34.654414ms > I0707 18:08:20.780215 29445 replica.cpp:320] Persisted replica status to > VOTING > I0707 18:08:20.780552 29445 recover.cpp:582] Successfully joined the Paxos > group > I0707 18:08:20.781373 29444 log.cpp:553] Attempting to start the writer > I0707 18:08:20.781486 29445 recover.cpp:466] Recover process terminated > I0707 18:08:20.783949 29446 replica.cpp:493] Replica received implicit > promise request from (2053)@172.17.0.7:43512 with proposal 1 > I0707 18:08:20.807478 29446 leveldb.cpp:304] Persisting metadata (8 bytes) to > leveldb took 23.302934ms > I0707 18:08:20.807561 29446 replica.cpp:342] Persisted promised to 1 > I0707 18:08:20.810058 29451 coordinator.cpp:238] Coordinator attempting to > fill missing positions > I0707 18:08:20.812877 29451 replica.cpp:388] Replica received explicit > promise request from (2054)@172.17.0.7:43512 for position 0 with proposal 2 > I0707 18:08:20.838755 29451 leveldb.cpp:341] Persisting action (8 bytes) to > leveldb took 25.80638ms > I0707 18:08:20.838837 29451 replica.cpp:712] Persisted action at 0 > I0707 18:08:20.841653 29440 replica.cpp:537] Replica received write request > for position 0 from (2055)@172.17.0.7:43512 > I0707 18:08:20.841735 29440 leveldb.cpp:436] Reading position from leveldb > took 38136ns > I0707 18:08:20.863855 29440 leveldb.cpp:341] Persisting action (14 bytes) to > leveldb took 22.056724ms > I0707 18:08:20.863939 29440 replica.cpp:712] Persisted action at 0 > I0707 18:08:20.864995 29440 replica.cpp:691] Replica received learned notice > for position 0 from @0.0.0.0:0 > I0707 18:08:20.888983 29440 leveldb.cpp:341] Persisting action (16 bytes) to > leveldb took 23.93767ms > I0707 18:08:20.889062 29440 replica.cpp:712] Persisted action at 0 > I0707 18:08:20.889097 29440 replica.cpp:697] Replica learned NOP action at > position 0 > I0707 18:08:20.890658 29454 log.cpp:569] Writer started with ending position 0 > I0707 18:08:20.892063 29441 leveldb.cpp:436] Reading position from leveldb > took 51724ns > I0707 18:08:20.893506 29441 registrar.cpp:365] Successfully fetched the > registry (0B) in 146.110976ms > I0707 18:08:20.893682 29441 registrar.cpp:464] Applied 1 operations in > 27053ns; attempting to update the 'registry' > I0707 18:08:20.894632 29453 log.cpp:577] Attempting to append 168 bytes to > the log > I0707 18:08:20.894870 29452 coordinator.cpp:348] Coordinator attempting to > write APPEND action at position 1 > I0707 18:08:20.895822 29450 replica.cpp:537] Replica received write request > for position 1 from (2056)@172.17.0.7:43512 > I0707 18:08:20.922474 29450 leveldb.cpp:341] Persisting action (187 bytes) to > leveldb took 26.593514ms > I0707 18:08:20.922554 29450 replica.cpp:712] Persisted action at 1 > I0707 18:08:20.923375 29450 replica.cpp:691] Replica received learned notice > for position 1 from @0.0.0.0:0 > I0707 18:08:20.947584 29450 leveldb.cpp:341] Persisting action (189 bytes) to > leveldb took 24.082326ms > I0707 18:08:20.947877 29450 replica.cpp:712] Persisted action at 1 > I0707 18:08:20.948094 29450 replica.cpp:697] Replica learned APPEND action at > position 1 > I0707 18:08:20.950374 29455 registrar.cpp:509] Successfully updated the > 'registry' in 56.603136ms > I0707 18:08:20.950639 29445 log.cpp:596] Attempting to truncate the log to 1 > I0707 18:08:20.950664 29455 registrar.cpp:395] Successfully recovered > registrar > I0707 18:08:20.950953 29455 coordinator.cpp:348] Coordinator attempting to > write TRUNCATE action at position 2 > I0707 18:08:20.951706 29445 master.cpp:1781] Recovered 0 agents from the > Registry (129B) ; allowing 10mins for agents to re-register > I0707 18:08:20.951740 29455 hierarchical.cpp:178] Skipping recovery of > hierarchical allocator: nothing to recover > I0707 18:08:20.952482 29455 replica.cpp:537] Replica received write request > for position 2 from (2057)@172.17.0.7:43512 > I0707 18:08:20.972702 29455 leveldb.cpp:341] Persisting action (16 bytes) to > leveldb took 20.161143ms > I0707 18:08:20.972781 29455 replica.cpp:712] Persisted action at 2 > I0707 18:08:20.973821 29447 replica.cpp:691] Replica received learned notice > for position 2 from @0.0.0.0:0 > I0707 18:08:20.997858 29447 leveldb.cpp:341] Persisting action (18 bytes) to > leveldb took 23.980235ms > I0707 18:08:20.998198 29447 leveldb.cpp:399] Deleting ~1 keys from leveldb > took 260069ns > I0707 18:08:20.998241 29447 replica.cpp:712] Persisted action at 2 > I0707 18:08:20.998284 29447 replica.cpp:697] Replica learned TRUNCATE action > at position 2 > I0707 18:08:21.003728 29421 containerizer.cpp:196] Using isolation: > posix/cpu,posix/mem,filesystem/posix,network/cni > W0707 18:08:21.004771 29421 backend.cpp:75] Failed to create 'aufs' backend: > AufsBackend requires root privileges, but is running as user mesos > W0707 18:08:21.005142 29421 backend.cpp:75] Failed to create 'bind' backend: > BindBackend requires root privileges > I0707 18:08:21.009625 29421 cluster.cpp:432] Creating default 'local' > authorizer > I0707 18:08:21.019762 29454 slave.cpp:205] Agent started on > 47)@172.17.0.7:43512 > I0707 18:08:21.019804 29454 slave.cpp:206] Flags at startup: --acls="" > --appc_simple_discovery_uri_prefix="http://" > --appc_store_dir="/tmp/mesos/store/appc" --authenticate_http="true" > --authenticatee="crammd5" --authentication_backoff_factor="1secs" > --authorizer="local" --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_CachedCustomOutputFileWithSubdirectory_lg5t7d/credential" > --default_role="*" --disk_watch_interval="1mins" --docker="docker" > --docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io" > --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" > --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" > --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" > --enforce_container_disk_quota="false" > --executor_registration_timeout="1mins" > --executor_shutdown_grace_period="5secs" > --fetcher_cache_dir="/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/fetch" > --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" > --gc_disk_headroom="0.1" --hadoop_home="" --help="false" > --hostname_lookup="true" --http_authenticators="basic" > --http_command_executor="false" > --http_credentials="/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/http_credentials" > --image_provisioner_backend="copy" --initialize_driver_logging="true" > --isolation="posix/cpu,posix/mem" > --launcher_dir="/mesos/mesos-1.0.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:1000;mem:1000" --revocable_cpu_low_priority="true" > --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" > --systemd_enable_support="true" > --systemd_runtime_directory="/run/systemd/system" --version="false" > --work_dir="/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d" > I0707 18:08:21.020503 29454 credentials.hpp:86] Loading credential for > authentication from > '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/credential' > I0707 18:08:21.020758 29454 slave.cpp:343] Agent using credential for: > test-principal > I0707 18:08:21.020795 29454 credentials.hpp:37] Loading credentials for > authentication from > '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/http_credentials' > I0707 18:08:21.021077 29454 slave.cpp:395] Using default 'basic' HTTP > authenticator > I0707 18:08:21.021381 29454 resources.cpp:572] Parsing resources as JSON > failed: cpus:1000;mem:1000 > Trying semicolon-delimited string format instead > I0707 18:08:21.021611 29454 resources.cpp:572] Parsing resources as JSON > failed: cpus:1000;mem:1000 > Trying semicolon-delimited string format instead > I0707 18:08:21.022073 29454 slave.cpp:594] Agent resources: cpus(*):1000; > mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] > I0707 18:08:21.022148 29454 slave.cpp:602] Agent attributes: [ ] > I0707 18:08:21.022162 29454 slave.cpp:607] Agent hostname: 753c2ae3a486 > I0707 18:08:21.023818 29440 state.cpp:57] Recovering state from > '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/meta' > I0707 18:08:21.024276 29448 status_update_manager.cpp:200] Recovering status > update manager > I0707 18:08:21.024487 29448 containerizer.cpp:522] Recovering containerizer > I0707 18:08:21.026320 29453 provisioner.cpp:253] Provisioner recovery complete > I0707 18:08:21.026952 29452 slave.cpp:4856] Finished recovery > I0707 18:08:21.027668 29452 slave.cpp:5028] Querying resource estimator for > oversubscribable resources > I0707 18:08:21.028062 29452 slave.cpp:5042] Received oversubscribable > resources from the resource estimator > I0707 18:08:21.028357 29452 slave.cpp:969] New master detected at > master@172.17.0.7:43512 > I0707 18:08:21.028640 29452 slave.cpp:1028] Authenticating with master > master@172.17.0.7:43512 > I0707 18:08:21.028800 29452 slave.cpp:1039] Using default CRAM-MD5 > authenticatee > I0707 18:08:21.029043 29452 slave.cpp:1001] Detecting new master > I0707 18:08:21.028524 29449 status_update_manager.cpp:174] Pausing sending > status updates > I0707 18:08:21.029203 29442 authenticatee.cpp:121] Creating new client SASL > connection > I0707 18:08:21.029804 29442 master.cpp:6006] Authenticating > slave(47)@172.17.0.7:43512 > I0707 18:08:21.030040 29442 authenticator.cpp:414] Starting authentication > session for crammd5_authenticatee(139)@172.17.0.7:43512 > I0707 18:08:21.030367 29449 authenticator.cpp:98] Creating new server SASL > connection > I0707 18:08:21.030680 29449 authenticatee.cpp:213] Received SASL > authentication mechanisms: CRAM-MD5 > I0707 18:08:21.030711 29449 authenticatee.cpp:239] Attempting to authenticate > with mechanism 'CRAM-MD5' > I0707 18:08:21.030793 29449 authenticator.cpp:204] Received SASL > authentication start > I0707 18:08:21.030849 29449 authenticator.cpp:326] Authentication requires > more steps > I0707 18:08:21.030926 29449 authenticatee.cpp:259] Received SASL > authentication step > I0707 18:08:21.031011 29449 authenticator.cpp:232] Received SASL > authentication step > I0707 18:08:21.031041 29449 auxprop.cpp:109] Request to lookup properties for > user: 'test-principal' realm: '753c2ae3a486' server FQDN: '753c2ae3a486' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: false > I0707 18:08:21.031056 29449 auxprop.cpp:181] Looking up auxiliary property > '*userPassword' > I0707 18:08:21.031095 29449 auxprop.cpp:181] Looking up auxiliary property > '*cmusaslsecretCRAM-MD5' > I0707 18:08:21.031117 29449 auxprop.cpp:109] Request to lookup properties for > user: 'test-principal' realm: '753c2ae3a486' server FQDN: '753c2ae3a486' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: true > I0707 18:08:21.031131 29449 auxprop.cpp:131] Skipping auxiliary property > '*userPassword' since SASL_AUXPROP_AUTHZID == true > I0707 18:08:21.031141 29449 auxprop.cpp:131] Skipping auxiliary property > '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true > I0707 18:08:21.031158 29449 authenticator.cpp:318] Authentication success > I0707 18:08:21.031272 29449 authenticatee.cpp:299] Authentication success > I0707 18:08:21.031570 29442 authenticator.cpp:432] Authentication session > cleanup for crammd5_authenticatee(139)@172.17.0.7:43512 > I0707 18:08:21.031811 29449 slave.cpp:1123] Successfully authenticated with > master master@172.17.0.7:43512 > I0707 18:08:21.031975 29449 slave.cpp:1529] Will retry registration in > 5.31021ms if necessary > I0707 18:08:21.032245 29451 master.cpp:6036] Successfully authenticated > principal 'test-principal' at slave(47)@172.17.0.7:43512 > I0707 18:08:21.032536 29451 master.cpp:4676] Registering agent at > slave(47)@172.17.0.7:43512 (753c2ae3a486) with id > 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 > I0707 18:08:21.033066 29451 registrar.cpp:464] Applied 1 operations in > 69145ns; attempting to update the 'registry' > I0707 18:08:21.033982 29440 log.cpp:577] Attempting to append 337 bytes to > the log > I0707 18:08:21.034283 29440 coordinator.cpp:348] Coordinator attempting to > write APPEND action at position 3 > I0707 18:08:21.035542 29444 replica.cpp:537] Replica received write request > for position 3 from (2074)@172.17.0.7:43512 > I0707 18:08:21.038626 29441 slave.cpp:1529] Will retry registration in > 15.12588ms if necessary > I0707 18:08:21.038935 29445 master.cpp:4664] Ignoring register agent message > from slave(47)@172.17.0.7:43512 (753c2ae3a486) as admission is already in > progress > I0707 18:08:21.054829 29442 slave.cpp:1529] Will retry registration in > 764229ns if necessary > I0707 18:08:21.055054 29443 master.cpp:4664] Ignoring register agent message > from slave(47)@172.17.0.7:43512 (753c2ae3a486) as admission is already in > progress > I0707 18:08:21.056470 29447 slave.cpp:1529] Will retry registration in > 107.24051ms if necessary > I0707 18:08:21.056874 29447 master.cpp:4664] Ignoring register agent message > from slave(47)@172.17.0.7:43512 (753c2ae3a486) as admission is already in > progress > I0707 18:08:21.067499 29444 leveldb.cpp:341] Persisting action (356 bytes) to > leveldb took 31.803841ms > I0707 18:08:21.067585 29444 replica.cpp:712] Persisted action at 3 > I0707 18:08:21.068524 29448 replica.cpp:691] Replica received learned notice > for position 3 from @0.0.0.0:0 > I0707 18:08:21.083830 29448 leveldb.cpp:341] Persisting action (358 bytes) to > leveldb took 15.184375ms > I0707 18:08:21.083922 29448 replica.cpp:712] Persisted action at 3 > I0707 18:08:21.083961 29448 replica.cpp:697] Replica learned APPEND action at > position 3 > I0707 18:08:21.086673 29448 registrar.cpp:509] Successfully updated the > 'registry' in 53.527808ms > I0707 18:08:21.087697 29447 log.cpp:596] Attempting to truncate the log to 3 > I0707 18:08:21.087909 29447 coordinator.cpp:348] Coordinator attempting to > write TRUNCATE action at position 4 > I0707 18:08:21.089154 29451 replica.cpp:537] Replica received write request > for position 4 from (2075)@172.17.0.7:43512 > I0707 18:08:21.089615 29448 master.cpp:4745] Registered agent > 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 at slave(47)@172.17.0.7:43512 > (753c2ae3a486) with cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; > ports(*):[31000-32000] > I0707 18:08:21.089970 29448 hierarchical.cpp:478] Added agent > 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 (753c2ae3a486) with cpus(*):1000; > mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] (allocated: ) > I0707 18:08:21.090132 29448 hierarchical.cpp:1537] No allocations performed > I0707 18:08:21.090188 29448 hierarchical.cpp:1195] Performed allocation for > agent 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 in 177083ns > I0707 18:08:21.090397 29448 slave.cpp:1169] Registered with master > master@172.17.0.7:43512; given agent ID > 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 > I0707 18:08:21.090903 29448 fetcher.cpp:86] Clearing fetcher cache > I0707 18:08:21.091346 29448 slave.cpp:1192] Checkpointing SlaveInfo to > '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/meta/slaves/2d32adef-7b13-4aff-b8ed-363a2e14655f-S0/slave.info' > I0707 18:08:21.091488 29454 status_update_manager.cpp:181] Resuming sending > status updates > I0707 18:08:21.091950 29448 slave.cpp:1229] Forwarding total oversubscribed > resources > I0707 18:08:21.092053 29448 slave.cpp:3760] Received ping from > slave-observer(45)@172.17.0.7:43512 > I0707 18:08:21.092229 29448 master.cpp:5128] Received update of agent > 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 at slave(47)@172.17.0.7:43512 > (753c2ae3a486) with total oversubscribed resources > I0707 18:08:21.092576 29448 hierarchical.cpp:542] Agent > 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 (753c2ae3a486) updated with > oversubscribed resources (total: cpus(*):1000; mem(*):1000; > disk(*):3.70122e+06; ports(*):[31000-32000], allocated: ) > I0707 18:08:21.092691 29448 hierarchical.cpp:1537] No allocations performed > I0707 18:08:21.092743 29448 hierarchical.cpp:1195] Performed allocation for > agent 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 in 126981ns > I0707 18:08:21.094138 29421 sched.cpp:226] Version: 1.0.0 > I0707 18:08:21.094784 29440 sched.cpp:330] New master detected at > master@172.17.0.7:43512 > I0707 18:08:21.094863 29440 sched.cpp:396] Authenticating with master > master@172.17.0.7:43512 > I0707 18:08:21.094884 29440 sched.cpp:403] Using default CRAM-MD5 > authenticatee > I0707 18:08:21.095202 29440 authenticatee.cpp:121] Creating new client SASL > connection > I0707 18:08:21.095528 29441 master.cpp:6006] Authenticating > scheduler-de5e7f7e-b553-4d96-b7e5-b9ecf8146498@172.17.0.7:43512 > I0707 18:08:21.095715 29441 authenticator.cpp:414] Starting authentication > session for crammd5_authenticatee(140)@172.17.0.7:43512 > I0707 18:08:21.096050 29441 authenticator.cpp:98] Creating new server SASL > connection > I0707 18:08:21.096276 29441 authenticatee.cpp:213] Received SASL > authentication mechanisms: CRAM-MD5 > I0707 18:08:21.096307 29441 authenticatee.cpp:239] Attempting to authenticate > with mechanism 'CRAM-MD5' > I0707 18:08:21.096530 29441 authenticator.cpp:204] Received SASL > authentication start > I0707 18:08:21.096591 29441 authenticator.cpp:326] Authentication requires > more steps > I0707 18:08:21.096679 29441 authenticatee.cpp:259] Received SASL > authentication step > I0707 18:08:21.096771 29441 authenticator.cpp:232] Received SASL > authentication step > I0707 18:08:21.096803 29441 auxprop.cpp:109] Request to lookup properties for > user: 'test-principal' realm: '753c2ae3a486' server FQDN: '753c2ae3a486' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: false > I0707 18:08:21.096818 29441 auxprop.cpp:181] Looking up auxiliary property > '*userPassword' > I0707 18:08:21.096859 29441 auxprop.cpp:181] Looking up auxiliary property > '*cmusaslsecretCRAM-MD5' > I0707 18:08:21.096885 29441 auxprop.cpp:109] Request to lookup properties for > user: 'test-principal' realm: '753c2ae3a486' server FQDN: '753c2ae3a486' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: true > I0707 18:08:21.096899 29441 auxprop.cpp:131] Skipping auxiliary property > '*userPassword' since SASL_AUXPROP_AUTHZID == true > I0707 18:08:21.096909 29441 auxprop.cpp:131] Skipping auxiliary property > '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true > I0707 18:08:21.096928 29441 authenticator.cpp:318] Authentication success > I0707 18:08:21.097080 29441 authenticatee.cpp:299] Authentication success > I0707 18:08:21.097163 29441 master.cpp:6036] Successfully authenticated > principal 'test-principal' at > scheduler-de5e7f7e-b553-4d96-b7e5-b9ecf8146498@172.17.0.7:43512 > I0707 18:08:21.097249 29441 authenticator.cpp:432] Authentication session > cleanup for crammd5_authenticatee(140)@172.17.0.7:43512 > I0707 18:08:21.097561 29445 sched.cpp:502] Successfully authenticated with > master master@172.17.0.7:43512 > I0707 18:08:21.097592 29445 sched.cpp:820] Sending SUBSCRIBE call to > master@172.17.0.7:43512 > I0707 18:08:21.097674 29445 sched.cpp:853] Will retry registration in > 1.44767632secs if necessary > I0707 18:08:21.097885 29445 master.cpp:2550] Received SUBSCRIBE call for > framework 'default' at > scheduler-de5e7f7e-b553-4d96-b7e5-b9ecf8146498@172.17.0.7:43512 > W0707 18:08:21.097920 29445 master.cpp:2558] Setting 'principal' in > FrameworkInfo to 'test-principal' because the framework authenticated with > that principal but did not set it in FrameworkInfo > I0707 18:08:21.097973 29445 master.cpp:2012] Authorizing framework principal > 'test-principal' to receive offers for role '*' > I0707 18:08:21.098445 29445 master.cpp:2626] Subscribing framework default > with checkpointing enabled and capabilities [ ] > I0707 18:08:21.099176 29445 hierarchical.cpp:271] Added framework > 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 > I0707 18:08:21.100005 29445 hierarchical.cpp:1632] No inverse offers to send > out! > I0707 18:08:21.100078 29445 hierarchical.cpp:1172] Performed allocation for 1 > agents in 874090ns > I0707 18:08:21.100342 29445 sched.cpp:743] Framework registered with > 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 > I0707 18:08:21.100389 29445 sched.cpp:757] Scheduler::registered took 22486ns > I0707 18:08:21.100822 29445 master.cpp:5835] Sending 1 offers to framework > 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 (default) at > scheduler-de5e7f7e-b553-4d96-b7e5-b9ecf8146498@172.17.0.7:43512 > I0707 18:08:21.101421 29445 sched.cpp:917] Scheduler::resourceOffers took > 258437ns > I0707 18:08:21.101763 29445 master.cpp:4077] Processing DECLINE call for > offers: [ 2d32adef-7b13-4aff-b8ed-363a2e14655f-O0 ] for framework > 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 (default) at > scheduler-de5e7f7e-b553-4d96-b7e5-b9ecf8146498@172.17.0.7:43512 > I0707 18:08:21.102890 29445 hierarchical.cpp:924] 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 agent 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 from framework > 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 > I0707 18:08:21.102955 29445 hierarchical.cpp:961] Framework > 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 filtered agent > 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 for 5secs > I0707 18:08:21.128569 29451 leveldb.cpp:341] Persisting action (16 bytes) to > leveldb took 39.364122ms > I0707 18:08:21.128710 29451 replica.cpp:712] Persisted action at 4 > I0707 18:08:21.130101 29451 replica.cpp:691] Replica received learned notice > for position 4 from @0.0.0.0:0 > I0707 18:08:21.170497 29451 leveldb.cpp:341] Persisting action (18 bytes) to > leveldb took 40.264167ms > I0707 18:08:21.170656 29451 leveldb.cpp:399] Deleting ~2 keys from leveldb > took 81667ns > I0707 18:08:21.170687 29451 replica.cpp:712] Persisted action at 4 > I0707 18:08:21.170724 29451 replica.cpp:697] Replica learned TRUNCATE action > at position 4 > I0707 18:08:21.735710 29442 hierarchical.cpp:1723] Filtered offer with > cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] on > agent 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 for framework > 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 > I0707 18:08:21.735790 29442 hierarchical.cpp:1537] No allocations performed > I0707 18:08:21.735828 29442 hierarchical.cpp:1632] No inverse offers to send > out! > I0707 18:08:21.735908 29442 hierarchical.cpp:1172] Performed allocation for 1 > agents in 647442ns > I0707 18:08:22.737726 29444 hierarchical.cpp:1723] Filtered offer with > cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] on > agent 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 for framework > 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 > I0707 18:08:22.737809 29444 hierarchical.cpp:1537] No allocations performed > I0707 18:08:22.737846 29444 hierarchical.cpp:1632] No inverse offers to send > out! > I0707 18:08:22.737920 29444 hierarchical.cpp:1172] Performed allocation for 1 > agents in 720313ns > I0707 18:08:23.739508 29448 hierarchical.cpp:1723] Filtered offer with > cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] on > agent 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 for framework > 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 > I0707 18:08:23.739596 29448 hierarchical.cpp:1537] No allocations performed > I0707 18:08:23.739634 29448 hierarchical.cpp:1632] No inverse offers to send > out! > I0707 18:08:23.739708 29448 hierarchical.cpp:1172] Performed allocation for 1 > agents in 733422ns > I0707 18:08:24.741200 29449 hierarchical.cpp:1723] Filtered offer with > cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] on > agent 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 for framework > 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 > I0707 18:08:24.741292 29449 hierarchical.cpp:1537] No allocations performed > I0707 18:08:24.741333 29449 hierarchical.cpp:1632] No inverse offers to send > out! > I0707 18:08:24.741431 29449 hierarchical.cpp:1172] Performed allocation for 1 > agents in 767509ns > I0707 18:08:25.743439 29448 hierarchical.cpp:1723] Filtered offer with > cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; ports(*):[31000-32000] on > agent 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 for framework > 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 > I0707 18:08:25.743540 29448 hierarchical.cpp:1537] No allocations performed > I0707 18:08:25.743582 29448 hierarchical.cpp:1632] No inverse offers to send > out! > I0707 18:08:25.743664 29448 hierarchical.cpp:1172] Performed allocation for 1 > agents in 812917ns > I0707 18:08:26.745857 29448 hierarchical.cpp:1632] No inverse offers to send > out! > I0707 18:08:26.746567 29445 master.cpp:5835] Sending 1 offers to framework > 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 (default) at > scheduler-de5e7f7e-b553-4d96-b7e5-b9ecf8146498@172.17.0.7:43512 > I0707 18:08:26.747846 29445 sched.cpp:917] Scheduler::resourceOffers took > 119209ns > I0707 18:08:26.748867 29448 hierarchical.cpp:1172] Performed allocation for 1 > agents in 3.93405ms > I0707 18:08:26.748996 29421 resources.cpp:572] Parsing resources as JSON > failed: cpus:1;mem:1 > Trying semicolon-delimited string format instead > I0707 18:08:26.752707 29454 master.cpp:3468] Processing ACCEPT call for > offers: [ 2d32adef-7b13-4aff-b8ed-363a2e14655f-O1 ] on agent > 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 at slave(47)@172.17.0.7:43512 > (753c2ae3a486) for framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 > (default) at scheduler-de5e7f7e-b553-4d96-b7e5-b9ecf8146498@172.17.0.7:43512 > I0707 18:08:26.752810 29454 master.cpp:3106] Authorizing framework principal > 'test-principal' to launch task 0 > I0707 18:08:26.754878 29445 master.cpp:7565] Adding task 0 with resources > cpus(*):1; mem(*):1 on agent 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 > (753c2ae3a486) > I0707 18:08:26.754997 29445 master.cpp:3957] Launching task 0 of framework > 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 (default) at > scheduler-de5e7f7e-b553-4d96-b7e5-b9ecf8146498@172.17.0.7:43512 with > resources cpus(*):1; mem(*):1 on agent > 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 at slave(47)@172.17.0.7:43512 > (753c2ae3a486) > I0707 18:08:26.756191 29443 hierarchical.cpp:924] 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 agent 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 from > framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 > I0707 18:08:26.756541 29443 hierarchical.cpp:961] Framework > 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 filtered agent > 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 for 5secs > I0707 18:08:26.756454 29451 slave.cpp:1569] Got assigned task 0 for framework > 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 > I0707 18:08:26.757066 29451 slave.cpp:5668] Checkpointing FrameworkInfo to > '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/meta/slaves/2d32adef-7b13-4aff-b8ed-363a2e14655f-S0/frameworks/2d32adef-7b13-4aff-b8ed-363a2e14655f-0000/framework.info' > I0707 18:08:26.757915 29451 slave.cpp:5679] Checkpointing framework pid > 'scheduler-de5e7f7e-b553-4d96-b7e5-b9ecf8146498@172.17.0.7:43512' to > '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/meta/slaves/2d32adef-7b13-4aff-b8ed-363a2e14655f-S0/frameworks/2d32adef-7b13-4aff-b8ed-363a2e14655f-0000/framework.pid' > I0707 18:08:26.758503 29451 resources.cpp:572] Parsing resources as JSON > failed: cpus:0.1;mem:32 > Trying semicolon-delimited string format instead > I0707 18:08:26.759313 29451 slave.cpp:1688] Launching task 0 for framework > 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 > I0707 18:08:26.759589 29451 resources.cpp:572] Parsing resources as JSON > failed: cpus:0.1;mem:32 > Trying semicolon-delimited string format instead > I0707 18:08:26.760591 29451 paths.cpp:528] Trying to chown > '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/slaves/2d32adef-7b13-4aff-b8ed-363a2e14655f-S0/frameworks/2d32adef-7b13-4aff-b8ed-363a2e14655f-0000/executors/0/runs/3cb609be-9171-4cc1-bd76-393eb055af18' > to user 'mesos' > I0707 18:08:26.766592 29451 slave.cpp:6150] Checkpointing ExecutorInfo to > '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/meta/slaves/2d32adef-7b13-4aff-b8ed-363a2e14655f-S0/frameworks/2d32adef-7b13-4aff-b8ed-363a2e14655f-0000/executors/0/executor.info' > I0707 18:08:26.767770 29451 slave.cpp:5748] Launching executor 0 of framework > 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 with resources cpus(*):0.1; > mem(*):32 in work directory > '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/slaves/2d32adef-7b13-4aff-b8ed-363a2e14655f-S0/frameworks/2d32adef-7b13-4aff-b8ed-363a2e14655f-0000/executors/0/runs/3cb609be-9171-4cc1-bd76-393eb055af18' > I0707 18:08:26.768576 29444 containerizer.cpp:781] Starting container > '3cb609be-9171-4cc1-bd76-393eb055af18' for executor '0' of framework > '2d32adef-7b13-4aff-b8ed-363a2e14655f-0000' > I0707 18:08:26.768690 29451 slave.cpp:6173] Checkpointing TaskInfo to > '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/meta/slaves/2d32adef-7b13-4aff-b8ed-363a2e14655f-S0/frameworks/2d32adef-7b13-4aff-b8ed-363a2e14655f-0000/executors/0/runs/3cb609be-9171-4cc1-bd76-393eb055af18/tasks/0/task.info' > I0707 18:08:26.769353 29451 slave.cpp:1914] Queuing task '0' for executor '0' > of framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 > I0707 18:08:26.769631 29451 slave.cpp:922] Successfully attached file > '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/slaves/2d32adef-7b13-4aff-b8ed-363a2e14655f-S0/frameworks/2d32adef-7b13-4aff-b8ed-363a2e14655f-0000/executors/0/runs/3cb609be-9171-4cc1-bd76-393eb055af18' > I0707 18:08:26.774013 29453 containerizer.cpp:1284] Launching > 'mesos-containerizer' with flags > '--command="{"arguments":["mesos-executor","--launcher_dir=\/mesos\/mesos-1.0.0\/_build\/src"],"shell":false,"uris":[{"cache":true,"executable":true,"extract":true,"output_file":"subdir\/my-command","value":"\/tmp\/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d\/mesos-fetcher-test-assets\/mesos-fetcher-test-cmd"}],"value":"\/mesos\/mesos-1.0.0\/_build\/src\/mesos-executor"}" > --help="false" --pipe_read="9" --pipe_write="12" --pre_exec_commands="[]" > --unshare_namespace_mnt="false" --user="mesos" > --working_directory="/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/slaves/2d32adef-7b13-4aff-b8ed-363a2e14655f-S0/frameworks/2d32adef-7b13-4aff-b8ed-363a2e14655f-0000/executors/0/runs/3cb609be-9171-4cc1-bd76-393eb055af18"' > I0707 18:08:26.775884 29453 launcher.cpp:126] Forked child with pid '342' for > container '3cb609be-9171-4cc1-bd76-393eb055af18' > I0707 18:08:26.776357 29453 containerizer.cpp:1319] Checkpointing executor's > forked pid 342 to > '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/meta/slaves/2d32adef-7b13-4aff-b8ed-363a2e14655f-S0/frameworks/2d32adef-7b13-4aff-b8ed-363a2e14655f-0000/executors/0/runs/3cb609be-9171-4cc1-bd76-393eb055af18/pids/forked.pid' > I0707 18:08:26.779757 29441 fetcher.cpp:348] Starting to fetch URIs for > container: 3cb609be-9171-4cc1-bd76-393eb055af18, directory: > /tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/slaves/2d32adef-7b13-4aff-b8ed-363a2e14655f-S0/frameworks/2d32adef-7b13-4aff-b8ed-363a2e14655f-0000/executors/0/runs/3cb609be-9171-4cc1-bd76-393eb055af18 > I0707 18:08:26.784481 29441 fetcher.cpp:949] Created cache entry > 'mesos@/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/mesos-fetcher-test-assets/mesos-fetcher-test-cmd' > with file: c1-mesos-fetc_r-test-cmd > I0707 18:08:26.785914 29442 fetcher.cpp:290] Fetching size for URI: > /tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/mesos-fetcher-test-assets/mesos-fetcher-test-cmd > I0707 18:08:26.789315 29441 fetcher.cpp:719] Claiming fetcher cache space > for: > mesos@/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/mesos-fetcher-test-assets/mesos-fetcher-test-cmd > I0707 18:08:26.789444 29441 fetcher.cpp:1170] Claimed cache space: 30B, now > using: 30B > I0707 18:08:26.799283 29441 fetcher.cpp:821] Fetching URIs using command > '/mesos/mesos-1.0.0/_build/src/mesos-fetcher' > I0707 18:08:27.003576 29440 fetcher.cpp:1182] Released cache space: 0B, now > using: 30B > I0707 18:08:27.140242 342 exec.cpp:161] Version: 1.0.0 > I0707 18:08:27.144256 29440 slave.cpp:2902] Got registration for executor '0' > of framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 from > executor(1)@172.17.0.7:54683 > I0707 18:08:27.145002 29440 slave.cpp:2988] Checkpointing executor pid > 'executor(1)@172.17.0.7:54683' to > '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/meta/slaves/2d32adef-7b13-4aff-b8ed-363a2e14655f-S0/frameworks/2d32adef-7b13-4aff-b8ed-363a2e14655f-0000/executors/0/runs/3cb609be-9171-4cc1-bd76-393eb055af18/pids/libprocess.pid' > I0707 18:08:27.147004 401 exec.cpp:236] Executor registered on agent > 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 > I0707 18:08:27.147676 29451 slave.cpp:2079] Sending queued task '0' to > executor '0' of framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 at > executor(1)@172.17.0.7:54683 > Received SUBSCRIBED event > Subscribed executor on 753c2ae3a486 > Received LAUNCH event > Starting task 0 > /mesos/mesos-1.0.0/_build/src/mesos-containerizer launch > --command="{"shell":true,"uris":[{"cache":true,"executable":true,"extract":true,"output_file":"subdir\/my-command","value":"\/tmp\/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d\/mesos-fetcher-test-assets\/mesos-fetcher-test-cmd"}],"value":".\/subdir\/my-command > 0"}" --help="false" --unshare_namespace_mnt="false" > Forked command at 411 > I0707 18:08:27.176249 29450 slave.cpp:3285] Handling status update > TASK_RUNNING (UUID: ac92d492-3e51-4f07-8753-b0f8bc99afcc) for task 0 of > framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 from > executor(1)@172.17.0.7:54683 > I0707 18:08:27.179903 29450 status_update_manager.cpp:320] Received status > update TASK_RUNNING (UUID: ac92d492-3e51-4f07-8753-b0f8bc99afcc) for task 0 > of framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 > I0707 18:08:27.179950 29450 status_update_manager.cpp:497] Creating > StatusUpdate stream for task 0 of framework > 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 > I0707 18:08:27.180871 29450 status_update_manager.cpp:825] Checkpointing > UPDATE for status update TASK_RUNNING (UUID: > ac92d492-3e51-4f07-8753-b0f8bc99afcc) for task 0 of framework > 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 > I0707 18:08:27.283306 29450 status_update_manager.cpp:374] Forwarding update > TASK_RUNNING (UUID: ac92d492-3e51-4f07-8753-b0f8bc99afcc) for task 0 of > framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 to the agent > I0707 18:08:27.284230 29450 slave.cpp:3678] Forwarding the update > TASK_RUNNING (UUID: ac92d492-3e51-4f07-8753-b0f8bc99afcc) for task 0 of > framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 to master@172.17.0.7:43512 > I0707 18:08:27.284757 29450 slave.cpp:3572] Status update manager > successfully handled status update TASK_RUNNING (UUID: > ac92d492-3e51-4f07-8753-b0f8bc99afcc) for task 0 of framework > 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 > I0707 18:08:27.285354 29450 slave.cpp:3588] Sending acknowledgement for > status update TASK_RUNNING (UUID: ac92d492-3e51-4f07-8753-b0f8bc99afcc) for > task 0 of framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 to > executor(1)@172.17.0.7:54683 > I0707 18:08:27.285240 29444 master.cpp:5273] Status update TASK_RUNNING > (UUID: ac92d492-3e51-4f07-8753-b0f8bc99afcc) for task 0 of framework > 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 from agent > 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 at slave(47)@172.17.0.7:43512 > (753c2ae3a486) > I0707 18:08:27.288682 29444 master.cpp:5321] Forwarding status update > TASK_RUNNING (UUID: ac92d492-3e51-4f07-8753-b0f8bc99afcc) for task 0 of > framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 > I0707 18:08:27.290532 29443 sched.cpp:1025] Scheduler::statusUpdate took > 1.319302ms > I0707 18:08:27.290921 29444 master.cpp:6959] Updating the state of task 0 of > framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 (latest state: > TASK_RUNNING, status update state: TASK_RUNNING) > I0707 18:08:27.291749 29444 master.cpp:4388] Processing ACKNOWLEDGE call > ac92d492-3e51-4f07-8753-b0f8bc99afcc for task 0 of framework > 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 (default) at > scheduler-de5e7f7e-b553-4d96-b7e5-b9ecf8146498@172.17.0.7:43512 on agent > 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 > I0707 18:08:27.293953 29450 status_update_manager.cpp:392] Received status > update acknowledgement (UUID: ac92d492-3e51-4f07-8753-b0f8bc99afcc) for task > 0 of framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 > I0707 18:08:27.296530 29450 status_update_manager.cpp:825] Checkpointing ACK > for status update TASK_RUNNING (UUID: ac92d492-3e51-4f07-8753-b0f8bc99afcc) > for task 0 of framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 > I0707 18:08:27.361351 29447 slave.cpp:2671] Status update manager > successfully handled status update acknowledgement (UUID: > ac92d492-3e51-4f07-8753-b0f8bc99afcc) for task 0 of framework > 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 > Command exited with status 0 (pid: 411) > I0707 18:08:27.375931 29450 slave.cpp:3285] Handling status update > TASK_FINISHED (UUID: a778fb07-07e1-47e5-a5a4-01987fe6f8c8) for task 0 of > framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 from > executor(1)@172.17.0.7:54683 > I0707 18:08:27.378550 29447 slave.cpp:6088] Terminating task 0 > I0707 18:08:27.380687 29447 status_update_manager.cpp:320] Received status > update TASK_FINISHED (UUID: a778fb07-07e1-47e5-a5a4-01987fe6f8c8) for task 0 > of framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 > I0707 18:08:27.380910 29447 status_update_manager.cpp:825] Checkpointing > UPDATE for status update TASK_FINISHED (UUID: > a778fb07-07e1-47e5-a5a4-01987fe6f8c8) for task 0 of framework > 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 > I0707 18:08:27.428735 29447 status_update_manager.cpp:374] Forwarding update > TASK_FINISHED (UUID: a778fb07-07e1-47e5-a5a4-01987fe6f8c8) for task 0 of > framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 to the agent > I0707 18:08:27.429576 29448 slave.cpp:3678] Forwarding the update > TASK_FINISHED (UUID: a778fb07-07e1-47e5-a5a4-01987fe6f8c8) for task 0 of > framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 to master@172.17.0.7:43512 > I0707 18:08:27.430321 29448 master.cpp:5273] Status update TASK_FINISHED > (UUID: a778fb07-07e1-47e5-a5a4-01987fe6f8c8) for task 0 of framework > 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 from agent > 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 at slave(47)@172.17.0.7:43512 > (753c2ae3a486) > I0707 18:08:27.430564 29448 master.cpp:5321] Forwarding status update > TASK_FINISHED (UUID: a778fb07-07e1-47e5-a5a4-01987fe6f8c8) for task 0 of > framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 > I0707 18:08:27.431305 29449 sched.cpp:1025] Scheduler::statusUpdate took > 212137ns > I0707 18:08:27.433158 29448 master.cpp:6959] Updating the state of task 0 of > framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 (latest state: > TASK_FINISHED, status update state: TASK_FINISHED) > I0707 18:08:27.433796 29448 master.cpp:4388] Processing ACKNOWLEDGE call > a778fb07-07e1-47e5-a5a4-01987fe6f8c8 for task 0 of framework > 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 (default) at > scheduler-de5e7f7e-b553-4d96-b7e5-b9ecf8146498@172.17.0.7:43512 on agent > 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 > I0707 18:08:27.434646 29448 master.cpp:7025] Removing task 0 with resources > cpus(*):1; mem(*):1 of framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 on > agent 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 at slave(47)@172.17.0.7:43512 > (753c2ae3a486) > I0707 18:08:27.434487 29441 hierarchical.cpp:924] Recovered cpus(*):1; > mem(*):1 (total: cpus(*):1000; mem(*):1000; disk(*):3.70122e+06; > ports(*):[31000-32000], allocated: ) on agent > 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 from framework > 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 > I0707 18:08:27.434103 29421 sched.cpp:1987] Asked to stop the driver > I0707 18:08:27.435642 29446 sched.cpp:1187] Stopping framework > '2d32adef-7b13-4aff-b8ed-363a2e14655f-0000' > I0707 18:08:27.436372 29442 master.cpp:6410] Processing TEARDOWN call for > framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 (default) at > scheduler-de5e7f7e-b553-4d96-b7e5-b9ecf8146498@172.17.0.7:43512 > I0707 18:08:27.436658 29442 master.cpp:6422] Removing framework > 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 (default) at > scheduler-de5e7f7e-b553-4d96-b7e5-b9ecf8146498@172.17.0.7:43512 > I0707 18:08:27.437214 29442 master.cpp:1218] Master terminating > I0707 18:08:27.437697 29449 hierarchical.cpp:382] Deactivated framework > 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 > I0707 18:08:27.437919 29451 slave.cpp:2292] Asked to shut down framework > 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 by master@172.17.0.7:43512 > I0707 18:08:27.439893 29451 slave.cpp:2317] Shutting down framework > 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 > I0707 18:08:27.440057 29451 slave.cpp:4481] Shutting down executor '0' of > framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 at > executor(1)@172.17.0.7:54683 > I0707 18:08:27.440824 29449 hierarchical.cpp:333] Removed framework > 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 > I0707 18:08:27.441685 29449 hierarchical.cpp:510] Removed agent > 2d32adef-7b13-4aff-b8ed-363a2e14655f-S0 > I0707 18:08:27.442066 29442 slave.cpp:3806] master@172.17.0.7:43512 exited > W0707 18:08:27.442292 29442 slave.cpp:3811] Master disconnected! Waiting for > a new master to be elected > I0707 18:08:27.444540 394 exec.cpp:413] Executor asked to shutdown > I0707 18:08:27.445024 29447 status_update_manager.cpp:392] Received status > update acknowledgement (UUID: a778fb07-07e1-47e5-a5a4-01987fe6f8c8) for task > 0 of framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 > I0707 18:08:27.445197 29454 slave.cpp:3572] Status update manager > successfully handled status update TASK_FINISHED (UUID: > a778fb07-07e1-47e5-a5a4-01987fe6f8c8) for task 0 of framework > 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 > I0707 18:08:27.446210 29454 slave.cpp:3588] Sending acknowledgement for > status update TASK_FINISHED (UUID: a778fb07-07e1-47e5-a5a4-01987fe6f8c8) for > task 0 of framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 to > executor(1)@172.17.0.7:54683 > I0707 18:08:27.446987 29447 status_update_manager.cpp:825] Checkpointing ACK > for status update TASK_FINISHED (UUID: a778fb07-07e1-47e5-a5a4-01987fe6f8c8) > for task 0 of framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 > I0707 18:08:27.454666 29455 containerizer.cpp:1622] Destroying container > '3cb609be-9171-4cc1-bd76-393eb055af18' > I0707 18:08:27.469662 29454 slave.cpp:3806] executor(1)@172.17.0.7:54683 > exited > I0707 18:08:27.510895 29442 containerizer.cpp:1863] Executor for container > '3cb609be-9171-4cc1-bd76-393eb055af18' has exited > I0707 18:08:27.511548 29447 status_update_manager.cpp:528] Cleaning up status > update stream for task 0 of framework > 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 > I0707 18:08:27.512651 29442 containerizer.cpp:1618] Destroy has already been > initiated for '3cb609be-9171-4cc1-bd76-393eb055af18' > I0707 18:08:27.513653 29453 provisioner.cpp:411] Ignoring destroy request for > unknown container 3cb609be-9171-4cc1-bd76-393eb055af18 > I0707 18:08:27.513283 29452 slave.cpp:2671] Status update manager > successfully handled status update acknowledgement (UUID: > a778fb07-07e1-47e5-a5a4-01987fe6f8c8) for task 0 of framework > 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 > I0707 18:08:27.513978 29452 slave.cpp:6129] Completing task 0 > I0707 18:08:27.514606 29452 slave.cpp:4163] Executor '0' of framework > 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 terminated with signal Killed > I0707 18:08:27.514744 29452 slave.cpp:4267] Cleaning up executor '0' of > framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 at > executor(1)@172.17.0.7:54683 > I0707 18:08:27.515455 29453 gc.cpp:55] Scheduling > '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/slaves/2d32adef-7b13-4aff-b8ed-363a2e14655f-S0/frameworks/2d32adef-7b13-4aff-b8ed-363a2e14655f-0000/executors/0/runs/3cb609be-9171-4cc1-bd76-393eb055af18' > for gc 6.99999403632days in the future > I0707 18:08:27.515810 29442 gc.cpp:55] Scheduling > '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/slaves/2d32adef-7b13-4aff-b8ed-363a2e14655f-S0/frameworks/2d32adef-7b13-4aff-b8ed-363a2e14655f-0000/executors/0' > for gc 6.9999940309363days in the future > I0707 18:08:27.516185 29452 slave.cpp:4355] Cleaning up framework > 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 > I0707 18:08:27.516422 29440 status_update_manager.cpp:282] Closing status > update streams for framework 2d32adef-7b13-4aff-b8ed-363a2e14655f-0000 > I0707 18:08:27.516657 29442 gc.cpp:55] Scheduling > '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/meta/slaves/2d32adef-7b13-4aff-b8ed-363a2e14655f-S0/frameworks/2d32adef-7b13-4aff-b8ed-363a2e14655f-0000/executors/0/runs/3cb609be-9171-4cc1-bd76-393eb055af18' > for gc 6.99999402774222days in the future > I0707 18:08:27.517086 29442 gc.cpp:55] Scheduling > '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/meta/slaves/2d32adef-7b13-4aff-b8ed-363a2e14655f-S0/frameworks/2d32adef-7b13-4aff-b8ed-363a2e14655f-0000/executors/0' > for gc 6.99999402624889days in the future > I0707 18:08:27.517400 29442 gc.cpp:55] Scheduling > '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/slaves/2d32adef-7b13-4aff-b8ed-363a2e14655f-S0/frameworks/2d32adef-7b13-4aff-b8ed-363a2e14655f-0000' > for gc 6.99999402189926days in the future > I0707 18:08:27.517514 29421 slave.cpp:841] Agent terminating > I0707 18:08:27.517562 29442 gc.cpp:55] Scheduling > '/tmp/FetcherCacheTest_CachedCustomOutputFileWithSubdirectory_lg5t7d/meta/slaves/2d32adef-7b13-4aff-b8ed-363a2e14655f-S0/frameworks/2d32adef-7b13-4aff-b8ed-363a2e14655f-0000' > for gc 6.99999402084444days in the future > [ OK ] FetcherCacheTest.CachedCustomOutputFileWithSubdirectory (6966 ms) > {code} -- This message was sent by Atlassian JIRA (v7.6.14#76016)