[
https://issues.apache.org/jira/browse/MESOS-5177?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Gilbert Song updated MESOS-5177:
--------------------------------
Assignee: Gilbert Song
Sprint: Mesosphere Sprint 37
Labels: filesystem isolation mesosphere (was: mesosphere)
> LinuxFilesystemIsolatorTest.ROOT_ChangeRootFilesystemCommandExecutorWithVolumes
> is flaky
> ----------------------------------------------------------------------------------------
>
> Key: MESOS-5177
> URL: https://issues.apache.org/jira/browse/MESOS-5177
> Project: Mesos
> Issue Type: Bug
> Components: isolation, tests
> Affects Versions: 0.28.0
> Environment: CentOS 7, with libevent and SSL enabled
> Reporter: Greg Mann
> Assignee: Gilbert Song
> Labels: filesystem, isolation, mesosphere
>
> Observed on the internal Mesosphere CI:
> {code}
> [19:35:11] : [Step 11/11] [ RUN ]
> LinuxFilesystemIsolatorTest.ROOT_ChangeRootFilesystemCommandExecutorWithVolumes
> [19:35:11]W: [Step 11/11] I0411 19:35:11.907374 31187 cluster.cpp:149]
> Creating default 'local' authorizer
> [19:35:11]W: [Step 11/11] I0411 19:35:11.912621 31187 leveldb.cpp:174]
> Opened db in 5.045872ms
> [19:35:11]W: [Step 11/11] I0411 19:35:11.914330 31187 leveldb.cpp:181]
> Compacted db in 1.6835ms
> [19:35:11]W: [Step 11/11] I0411 19:35:11.914373 31187 leveldb.cpp:196]
> Created db iterator in 17681ns
> [19:35:11]W: [Step 11/11] I0411 19:35:11.914386 31187 leveldb.cpp:202]
> Seeked to beginning of db in 1769ns
> [19:35:11]W: [Step 11/11] I0411 19:35:11.914393 31187 leveldb.cpp:271]
> Iterated through 0 keys in the db in 306ns
> [19:35:11]W: [Step 11/11] I0411 19:35:11.914429 31187 replica.cpp:779]
> Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> [19:35:11]W: [Step 11/11] I0411 19:35:11.914922 31206 recover.cpp:447]
> Starting replica recovery
> [19:35:11]W: [Step 11/11] I0411 19:35:11.915133 31206 recover.cpp:473]
> Replica is in EMPTY status
> [19:35:11]W: [Step 11/11] I0411 19:35:11.916041 31203 replica.cpp:673]
> Replica in EMPTY status received a broadcasted recover request from
> (16968)@172.30.2.184:40532
> [19:35:11]W: [Step 11/11] I0411 19:35:11.916425 31202 recover.cpp:193]
> Received a recover response from a replica in EMPTY status
> [19:35:11]W: [Step 11/11] I0411 19:35:11.916898 31201 recover.cpp:564]
> Updating replica status to STARTING
> [19:35:11]W: [Step 11/11] I0411 19:35:11.917946 31207 master.cpp:382]
> Master abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b (ip-172-30-2-184.mesosphere.io)
> started on 172.30.2.184:40532
> [19:35:11]W: [Step 11/11] I0411 19:35:11.917966 31207 master.cpp:384] Flags
> at startup: --acls="" --allocation_interval="1secs"
> --allocator="HierarchicalDRF" --authenticate="true"
> --authenticate_http="true" --authenticate_slaves="true"
> --authenticators="crammd5" --authorizers="local"
> --credentials="/tmp/0PzkwC/credentials" --framework_sorter="drf"
> --help="false" --hostname_lookup="true" --http_authenticators="basic"
> --initialize_driver_logging="true" --log_auto_initialize="true"
> --logbufsecs="0" --logging_level="INFO" --max_completed_frameworks="50"
> --max_completed_tasks_per_framework="1000" --max_slave_ping_timeouts="5"
> --quiet="false" --recovery_slave_removal_limit="100%"
> --registry="replicated_log" --registry_fetch_timeout="1mins"
> --registry_store_timeout="100secs" --registry_strict="true"
> --root_submissions="true" --slave_ping_timeout="15secs"
> --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false"
> --webui_dir="/usr/local/share/mesos/webui" --work_dir="/tmp/0PzkwC/master"
> --zk_session_timeout="10secs"
> [19:35:11]W: [Step 11/11] I0411 19:35:11.918198 31207 master.cpp:433]
> Master only allowing authenticated frameworks to register
> [19:35:11]W: [Step 11/11] I0411 19:35:11.918207 31207 master.cpp:438]
> Master only allowing authenticated agents to register
> [19:35:11]W: [Step 11/11] I0411 19:35:11.918213 31207 credentials.hpp:37]
> Loading credentials for authentication from '/tmp/0PzkwC/credentials'
> [19:35:11]W: [Step 11/11] I0411 19:35:11.918454 31207 master.cpp:480] Using
> default 'crammd5' authenticator
> [19:35:11]W: [Step 11/11] I0411 19:35:11.918587 31207 master.cpp:551] Using
> default 'basic' HTTP authenticator
> [19:35:11]W: [Step 11/11] I0411 19:35:11.918615 31205 leveldb.cpp:304]
> Persisting metadata (8 bytes) to leveldb took 1.524112ms
> [19:35:11]W: [Step 11/11] I0411 19:35:11.918644 31205 replica.cpp:320]
> Persisted replica status to STARTING
> [19:35:11]W: [Step 11/11] I0411 19:35:11.918750 31207 master.cpp:589]
> Authorization enabled
> [19:35:11]W: [Step 11/11] I0411 19:35:11.918856 31204 recover.cpp:473]
> Replica is in STARTING status
> [19:35:11]W: [Step 11/11] I0411 19:35:11.918908 31201 hierarchical.cpp:142]
> Initialized hierarchical allocator process
> [19:35:11]W: [Step 11/11] I0411 19:35:11.918912 31208
> whitelist_watcher.cpp:77] No whitelist given
> [19:35:11]W: [Step 11/11] I0411 19:35:11.919694 31202 replica.cpp:673]
> Replica in STARTING status received a broadcasted recover request from
> (16970)@172.30.2.184:40532
> [19:35:11]W: [Step 11/11] I0411 19:35:11.920127 31205 recover.cpp:193]
> Received a recover response from a replica in STARTING status
> [19:35:11]W: [Step 11/11] I0411 19:35:11.920688 31201 recover.cpp:564]
> Updating replica status to VOTING
> [19:35:11]W: [Step 11/11] I0411 19:35:11.921149 31205 master.cpp:1832] The
> newly elected leader is [email protected]:40532 with id
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b
> [19:35:11]W: [Step 11/11] I0411 19:35:11.921180 31205 master.cpp:1845]
> Elected as the leading master!
> [19:35:11]W: [Step 11/11] I0411 19:35:11.921198 31205 master.cpp:1532]
> Recovering from registrar
> [19:35:11]W: [Step 11/11] I0411 19:35:11.921350 31203 registrar.cpp:331]
> Recovering registrar
> [19:35:11]W: [Step 11/11] I0411 19:35:11.922122 31202 leveldb.cpp:304]
> Persisting metadata (8 bytes) to leveldb took 1.235397ms
> [19:35:11]W: [Step 11/11] I0411 19:35:11.922144 31202 replica.cpp:320]
> Persisted replica status to VOTING
> [19:35:11]W: [Step 11/11] I0411 19:35:11.922240 31204 recover.cpp:578]
> Successfully joined the Paxos group
> [19:35:11]W: [Step 11/11] I0411 19:35:11.922380 31204 recover.cpp:462]
> Recover process terminated
> [19:35:11]W: [Step 11/11] I0411 19:35:11.922794 31206 log.cpp:659]
> Attempting to start the writer
> [19:35:11]W: [Step 11/11] I0411 19:35:11.923794 31204 replica.cpp:493]
> Replica received implicit promise request from (16971)@172.30.2.184:40532
> with proposal 1
> [19:35:11]W: [Step 11/11] I0411 19:35:11.924968 31204 leveldb.cpp:304]
> Persisting metadata (8 bytes) to leveldb took 1.149194ms
> [19:35:11]W: [Step 11/11] I0411 19:35:11.924990 31204 replica.cpp:342]
> Persisted promised to 1
> [19:35:11]W: [Step 11/11] I0411 19:35:11.925490 31205 coordinator.cpp:238]
> Coordinator attempting to fill missing positions
> [19:35:11]W: [Step 11/11] I0411 19:35:11.926537 31202 replica.cpp:388]
> Replica received explicit promise request from (16972)@172.30.2.184:40532 for
> position 0 with proposal 2
> [19:35:11]W: [Step 11/11] I0411 19:35:11.927678 31202 leveldb.cpp:341]
> Persisting action (8 bytes) to leveldb took 1.107062ms
> [19:35:11]W: [Step 11/11] I0411 19:35:11.927700 31202 replica.cpp:712]
> Persisted action at 0
> [19:35:11]W: [Step 11/11] I0411 19:35:11.928498 31203 replica.cpp:537]
> Replica received write request for position 0 from (16973)@172.30.2.184:40532
> [19:35:11]W: [Step 11/11] I0411 19:35:11.928546 31203 leveldb.cpp:436]
> Reading position from leveldb took 25316ns
> [19:35:11]W: [Step 11/11] I0411 19:35:11.929805 31203 leveldb.cpp:341]
> Persisting action (14 bytes) to leveldb took 1.227605ms
> [19:35:11]W: [Step 11/11] I0411 19:35:11.929828 31203 replica.cpp:712]
> Persisted action at 0
> [19:35:11]W: [Step 11/11] I0411 19:35:11.930327 31201 replica.cpp:691]
> Replica received learned notice for position 0 from @0.0.0.0:0
> [19:35:11]W: [Step 11/11] I0411 19:35:11.931480 31201 leveldb.cpp:341]
> Persisting action (16 bytes) to leveldb took 1.126326ms
> [19:35:11]W: [Step 11/11] I0411 19:35:11.931504 31201 replica.cpp:712]
> Persisted action at 0
> [19:35:11]W: [Step 11/11] I0411 19:35:11.931517 31201 replica.cpp:697]
> Replica learned NOP action at position 0
> [19:35:11]W: [Step 11/11] I0411 19:35:11.932049 31204 log.cpp:675] Writer
> started with ending position 0
> [19:35:11]W: [Step 11/11] I0411 19:35:11.932972 31201 leveldb.cpp:436]
> Reading position from leveldb took 28445ns
> [19:35:11]W: [Step 11/11] I0411 19:35:11.933792 31201 registrar.cpp:364]
> Successfully fetched the registry (0B) in 12.404992ms
> [19:35:11]W: [Step 11/11] I0411 19:35:11.933892 31201 registrar.cpp:463]
> Applied 1 operations in 26869ns; attempting to update the 'registry'
> [19:35:11]W: [Step 11/11] I0411 19:35:11.934489 31205 log.cpp:683]
> Attempting to append 210 bytes to the log
> [19:35:11]W: [Step 11/11] I0411 19:35:11.934592 31201 coordinator.cpp:348]
> Coordinator attempting to write APPEND action at position 1
> [19:35:11]W: [Step 11/11] I0411 19:35:11.935245 31207 replica.cpp:537]
> Replica received write request for position 1 from (16974)@172.30.2.184:40532
> [19:35:11]W: [Step 11/11] I0411 19:35:11.936398 31207 leveldb.cpp:341]
> Persisting action (229 bytes) to leveldb took 1.125503ms
> [19:35:11]W: [Step 11/11] I0411 19:35:11.936421 31207 replica.cpp:712]
> Persisted action at 1
> [19:35:11]W: [Step 11/11] I0411 19:35:11.936930 31202 replica.cpp:691]
> Replica received learned notice for position 1 from @0.0.0.0:0
> [19:35:11]W: [Step 11/11] I0411 19:35:11.938161 31202 leveldb.cpp:341]
> Persisting action (231 bytes) to leveldb took 1.202858ms
> [19:35:11]W: [Step 11/11] I0411 19:35:11.938184 31202 replica.cpp:712]
> Persisted action at 1
> [19:35:11]W: [Step 11/11] I0411 19:35:11.938197 31202 replica.cpp:697]
> Replica learned APPEND action at position 1
> [19:35:11]W: [Step 11/11] I0411 19:35:11.939043 31204 registrar.cpp:508]
> Successfully updated the 'registry' in 5.092096ms
> [19:35:11]W: [Step 11/11] I0411 19:35:11.939184 31204 registrar.cpp:394]
> Successfully recovered registrar
> [19:35:11]W: [Step 11/11] I0411 19:35:11.939304 31202 log.cpp:702]
> Attempting to truncate the log to 1
> [19:35:11]W: [Step 11/11] I0411 19:35:11.939486 31206 coordinator.cpp:348]
> Coordinator attempting to write TRUNCATE action at position 2
> [19:35:11]W: [Step 11/11] I0411 19:35:11.939679 31201 master.cpp:1640]
> Recovered 0 agents from the Registry (171B) ; allowing 10mins for agents to
> re-register
> [19:35:11]W: [Step 11/11] I0411 19:35:11.939693 31207 hierarchical.cpp:169]
> Skipping recovery of hierarchical allocator: nothing to recover
> [19:35:11]W: [Step 11/11] I0411 19:35:11.940212 31201 replica.cpp:537]
> Replica received write request for position 2 from (16975)@172.30.2.184:40532
> [19:35:11]W: [Step 11/11] I0411 19:35:11.941376 31201 leveldb.cpp:341]
> Persisting action (16 bytes) to leveldb took 1.136471ms
> [19:35:11]W: [Step 11/11] I0411 19:35:11.941398 31201 replica.cpp:712]
> Persisted action at 2
> [19:35:11]W: [Step 11/11] I0411 19:35:11.941915 31204 replica.cpp:691]
> Replica received learned notice for position 2 from @0.0.0.0:0
> [19:35:11]W: [Step 11/11] I0411 19:35:11.943048 31204 leveldb.cpp:341]
> Persisting action (18 bytes) to leveldb took 1.107167ms
> [19:35:11]W: [Step 11/11] I0411 19:35:11.943097 31204 leveldb.cpp:399]
> Deleting ~1 keys from leveldb took 27032ns
> [19:35:11]W: [Step 11/11] I0411 19:35:11.943112 31204 replica.cpp:712]
> Persisted action at 2
> [19:35:11]W: [Step 11/11] I0411 19:35:11.943127 31204 replica.cpp:697]
> Replica learned TRUNCATE action at position 2
> [19:35:12]W: [Step 11/11] I0411 19:35:12.919821 31202
> hierarchical.cpp:1488] No resources available to allocate!
> [19:35:12]W: [Step 11/11] I0411 19:35:12.919903 31202
> hierarchical.cpp:1139] Performed allocation for 0 agents in 184040ns
> [19:35:13]W: [Step 11/11] I0411 19:35:13.638777 31187 linux.cpp:81] Making
> '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutorWithVolumes_gPh4rA'
> a shared mount
> [19:35:13]W: [Step 11/11] I0411 19:35:13.653728 31187
> linux_launcher.cpp:101] Using /sys/fs/cgroup/freezer as the freezer hierarchy
> for the Linux launcher
> [19:35:13]W: [Step 11/11] I0411 19:35:13.656819 31203 slave.cpp:201] Agent
> started on 454)@172.30.2.184:40532
> [19:35:13]W: [Step 11/11] I0411 19:35:13.656842 31203 slave.cpp:202] Flags
> at startup: --appc_simple_discovery_uri_prefix="http://";
> --appc_store_dir="/tmp/mesos/store/appc" --authenticate_http="true"
> --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="/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutorWithVolumes_gPh4rA/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"
> --enforce_container_disk_quota="false"
> --executor_registration_timeout="1mins"
> --executor_shutdown_grace_period="5secs"
> --fetcher_cache_dir="/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutorWithVolumes_gPh4rA/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_credentials="/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutorWithVolumes_gPh4rA/http_credentials"
> --image_provisioner_backend="copy" --initialize_driver_logging="true"
> --isolation="posix/cpu,posix/mem"
> --launcher_dir="/mnt/teamcity/work/4240ba9ddd0997c3/build/src"
> --logbufsecs="0" --logging_level="INFO"
> --oversubscribed_resources_interval="15secs" --perf_duration="10secs"
> --perf_interval="1mins" --qos_correction_interval_min="0ns" --quiet="false"
> --recover="reconnect" --recovery_timeout="15mins"
> --registration_backoff_factor="10ms"
> --resources="cpus:2;mem:1024;disk:1024;ports:[31000-32000]"
> --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox"
> --strict="true" --switch_user="true" --systemd_enable_support="true"
> --systemd_runtime_directory="/run/systemd/system" --version="false"
> --work_dir="/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutorWithVolumes_gPh4rA"
> [19:35:13]W: [Step 11/11] I0411 19:35:13.657383 31203 credentials.hpp:86]
> Loading credential for authentication from
> '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutorWithVolumes_gPh4rA/credential'
> [19:35:13]W: [Step 11/11] I0411 19:35:13.657613 31203 slave.cpp:339] Agent
> using credential for: test-principal
> [19:35:13]W: [Step 11/11] I0411 19:35:13.657644 31203 credentials.hpp:37]
> Loading credentials for authentication from
> '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutorWithVolumes_gPh4rA/http_credentials'
> [19:35:13]W: [Step 11/11] I0411 19:35:13.657941 31203 slave.cpp:391] Using
> default 'basic' HTTP authenticator
> [19:35:13]W: [Step 11/11] I0411 19:35:13.658262 31203 resources.cpp:572]
> Parsing resources as JSON failed:
> cpus:2;mem:1024;disk:1024;ports:[31000-32000]
> [19:35:13]W: [Step 11/11] Trying semicolon-delimited string format instead
> [19:35:13]W: [Step 11/11] I0411 19:35:13.658397 31187 sched.cpp:224]
> Version: 0.29.0
> [19:35:13]W: [Step 11/11] I0411 19:35:13.658759 31203 slave.cpp:590] Agent
> resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> [19:35:13]W: [Step 11/11] I0411 19:35:13.658818 31203 slave.cpp:598] Agent
> attributes: [ ]
> [19:35:13]W: [Step 11/11] I0411 19:35:13.658828 31203 slave.cpp:603] Agent
> hostname: ip-172-30-2-184.mesosphere.io
> [19:35:13]W: [Step 11/11] I0411 19:35:13.659019 31204 sched.cpp:328] New
> master detected at [email protected]:40532
> [19:35:13]W: [Step 11/11] I0411 19:35:13.659096 31204 sched.cpp:384]
> Authenticating with master [email protected]:40532
> [19:35:13]W: [Step 11/11] I0411 19:35:13.659108 31204 sched.cpp:391] Using
> default CRAM-MD5 authenticatee
> [19:35:13]W: [Step 11/11] I0411 19:35:13.659333 31202
> authenticatee.cpp:121] Creating new client SASL connection
> [19:35:13]W: [Step 11/11] I0411 19:35:13.659718 31208 master.cpp:5695]
> Authenticating
> [email protected]:40532
> [19:35:13]W: [Step 11/11] I0411 19:35:13.659885 31201
> authenticator.cpp:413] Starting authentication session for
> crammd5_authenticatee(926)@172.30.2.184:40532
> [19:35:13]W: [Step 11/11] I0411 19:35:13.660116 31207 authenticator.cpp:98]
> Creating new server SASL connection
> [19:35:13]W: [Step 11/11] I0411 19:35:13.660226 31201 state.cpp:57]
> Recovering state from
> '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutorWithVolumes_gPh4rA/meta'
> [19:35:13]W: [Step 11/11] I0411 19:35:13.660459 31208
> status_update_manager.cpp:200] Recovering status update manager
> [19:35:13]W: [Step 11/11] I0411 19:35:13.660513 31205
> authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
> [19:35:13]W: [Step 11/11] I0411 19:35:13.660543 31205
> authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
> [19:35:13]W: [Step 11/11] I0411 19:35:13.660646 31202
> containerizer.cpp:423] Recovering containerizer
> [19:35:13]W: [Step 11/11] I0411 19:35:13.660679 31205
> authenticator.cpp:203] Received SASL authentication start
> [19:35:13]W: [Step 11/11] I0411 19:35:13.660717 31205
> authenticator.cpp:325] Authentication requires more steps
> [19:35:13]W: [Step 11/11] I0411 19:35:13.660797 31205
> authenticatee.cpp:258] Received SASL authentication step
> [19:35:13]W: [Step 11/11] I0411 19:35:13.660892 31205
> authenticator.cpp:231] Received SASL authentication step
> [19:35:13]W: [Step 11/11] I0411 19:35:13.660923 31205 auxprop.cpp:107]
> Request to lookup properties for user: 'test-principal' realm:
> 'ip-172-30-2-184.mesosphere.io' server FQDN: 'ip-172-30-2-184.mesosphere.io'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> [19:35:13]W: [Step 11/11] I0411 19:35:13.660936 31205 auxprop.cpp:179]
> Looking up auxiliary property '*userPassword'
> [19:35:13]W: [Step 11/11] I0411 19:35:13.660972 31205 auxprop.cpp:179]
> Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> [19:35:13]W: [Step 11/11] I0411 19:35:13.660990 31205 auxprop.cpp:107]
> Request to lookup properties for user: 'test-principal' realm:
> 'ip-172-30-2-184.mesosphere.io' server FQDN: 'ip-172-30-2-184.mesosphere.io'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> [19:35:13]W: [Step 11/11] I0411 19:35:13.660998 31205 auxprop.cpp:129]
> Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> [19:35:13]W: [Step 11/11] I0411 19:35:13.661005 31205 auxprop.cpp:129]
> Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since
> SASL_AUXPROP_AUTHZID == true
> [19:35:13]W: [Step 11/11] I0411 19:35:13.661015 31205
> authenticator.cpp:317] Authentication success
> [19:35:13]W: [Step 11/11] I0411 19:35:13.661104 31206
> authenticatee.cpp:298] Authentication success
> [19:35:13]W: [Step 11/11] I0411 19:35:13.661136 31204 master.cpp:5725]
> Successfully authenticated principal 'test-principal' at
> [email protected]:40532
> [19:35:13]W: [Step 11/11] I0411 19:35:13.661202 31203
> authenticator.cpp:431] Authentication session cleanup for
> crammd5_authenticatee(926)@172.30.2.184:40532
> [19:35:13]W: [Step 11/11] I0411 19:35:13.661494 31206 sched.cpp:474]
> Successfully authenticated with master [email protected]:40532
> [19:35:13]W: [Step 11/11] I0411 19:35:13.661509 31206 sched.cpp:779]
> Sending SUBSCRIBE call to [email protected]:40532
> [19:35:13]W: [Step 11/11] I0411 19:35:13.661582 31206 sched.cpp:812] Will
> retry registration in 529.989629ms if necessary
> [19:35:13]W: [Step 11/11] I0411 19:35:13.661708 31204 master.cpp:2362]
> Received SUBSCRIBE call for framework 'default' at
> [email protected]:40532
> [19:35:13]W: [Step 11/11] I0411 19:35:13.661789 31204 master.cpp:1871]
> Authorizing framework principal 'test-principal' to receive offers for role
> '*'
> [19:35:13]W: [Step 11/11] I0411 19:35:13.662065 31206 master.cpp:2433]
> Subscribing framework default with checkpointing disabled and capabilities [
> ]
> [19:35:13]W: [Step 11/11] I0411 19:35:13.662518 31208 sched.cpp:706]
> Framework registered with abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000
> [19:35:13]W: [Step 11/11] I0411 19:35:13.662585 31208 sched.cpp:720]
> Scheduler::registered took 47891ns
> [19:35:13]W: [Step 11/11] I0411 19:35:13.662590 31201 hierarchical.cpp:264]
> Added framework abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000
> [19:35:13]W: [Step 11/11] I0411 19:35:13.662668 31201
> hierarchical.cpp:1488] No resources available to allocate!
> [19:35:13]W: [Step 11/11] I0411 19:35:13.662715 31201
> hierarchical.cpp:1583] No inverse offers to send out!
> [19:35:13]W: [Step 11/11] I0411 19:35:13.662778 31201
> hierarchical.cpp:1139] Performed allocation for 0 agents in 168797ns
> [19:35:13]W: [Step 11/11] I0411 19:35:13.663818 31207 provisioner.cpp:245]
> Provisioner recovery complete
> [19:35:13]W: [Step 11/11] I0411 19:35:13.664186 31206 slave.cpp:4784]
> Finished recovery
> [19:35:13]W: [Step 11/11] I0411 19:35:13.664489 31206 slave.cpp:4956]
> Querying resource estimator for oversubscribable resources
> [19:35:13]W: [Step 11/11] I0411 19:35:13.664685 31202
> status_update_manager.cpp:174] Pausing sending status updates
> [19:35:13]W: [Step 11/11] I0411 19:35:13.664681 31206 slave.cpp:939] New
> master detected at [email protected]:40532
> [19:35:13]W: [Step 11/11] I0411 19:35:13.664755 31206 slave.cpp:1002]
> Authenticating with master [email protected]:40532
> [19:35:13]W: [Step 11/11] I0411 19:35:13.664768 31206 slave.cpp:1007] Using
> default CRAM-MD5 authenticatee
> [19:35:13]W: [Step 11/11] I0411 19:35:13.664881 31206 slave.cpp:975]
> Detecting new master
> [19:35:13]W: [Step 11/11] I0411 19:35:13.664901 31205
> authenticatee.cpp:121] Creating new client SASL connection
> [19:35:13]W: [Step 11/11] I0411 19:35:13.664996 31206 slave.cpp:4970]
> Received oversubscribable resources from the resource estimator
> [19:35:13]W: [Step 11/11] I0411 19:35:13.665134 31206 master.cpp:5695]
> Authenticating slave(454)@172.30.2.184:40532
> [19:35:13]W: [Step 11/11] I0411 19:35:13.665220 31207
> authenticator.cpp:413] Starting authentication session for
> crammd5_authenticatee(927)@172.30.2.184:40532
> [19:35:13]W: [Step 11/11] I0411 19:35:13.665401 31202 authenticator.cpp:98]
> Creating new server SASL connection
> [19:35:13]W: [Step 11/11] I0411 19:35:13.665621 31204
> authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
> [19:35:13]W: [Step 11/11] I0411 19:35:13.665642 31204
> authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
> [19:35:13]W: [Step 11/11] I0411 19:35:13.665737 31204
> authenticator.cpp:203] Received SASL authentication start
> [19:35:13]W: [Step 11/11] I0411 19:35:13.665776 31204
> authenticator.cpp:325] Authentication requires more steps
> [19:35:13]W: [Step 11/11] I0411 19:35:13.665849 31204
> authenticatee.cpp:258] Received SASL authentication step
> [19:35:13]W: [Step 11/11] I0411 19:35:13.665948 31208
> authenticator.cpp:231] Received SASL authentication step
> [19:35:13]W: [Step 11/11] I0411 19:35:13.665972 31208 auxprop.cpp:107]
> Request to lookup properties for user: 'test-principal' realm:
> 'ip-172-30-2-184.mesosphere.io' server FQDN: 'ip-172-30-2-184.mesosphere.io'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> [19:35:13]W: [Step 11/11] I0411 19:35:13.665980 31208 auxprop.cpp:179]
> Looking up auxiliary property '*userPassword'
> [19:35:13]W: [Step 11/11] I0411 19:35:13.666005 31208 auxprop.cpp:179]
> Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> [19:35:13]W: [Step 11/11] I0411 19:35:13.666023 31208 auxprop.cpp:107]
> Request to lookup properties for user: 'test-principal' realm:
> 'ip-172-30-2-184.mesosphere.io' server FQDN: 'ip-172-30-2-184.mesosphere.io'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> [19:35:13]W: [Step 11/11] I0411 19:35:13.666031 31208 auxprop.cpp:129]
> Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> [19:35:13]W: [Step 11/11] I0411 19:35:13.666036 31208 auxprop.cpp:129]
> Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since
> SASL_AUXPROP_AUTHZID == true
> [19:35:13]W: [Step 11/11] I0411 19:35:13.666046 31208
> authenticator.cpp:317] Authentication success
> [19:35:13]W: [Step 11/11] I0411 19:35:13.666116 31201
> authenticatee.cpp:298] Authentication success
> [19:35:13]W: [Step 11/11] I0411 19:35:13.666152 31203 master.cpp:5725]
> Successfully authenticated principal 'test-principal' at
> slave(454)@172.30.2.184:40532
> [19:35:13]W: [Step 11/11] I0411 19:35:13.666180 31207
> authenticator.cpp:431] Authentication session cleanup for
> crammd5_authenticatee(927)@172.30.2.184:40532
> [19:35:13]W: [Step 11/11] I0411 19:35:13.666429 31208 slave.cpp:1072]
> Successfully authenticated with master [email protected]:40532
> [19:35:13]W: [Step 11/11] I0411 19:35:13.666530 31208 slave.cpp:1468] Will
> retry registration in 11.861394ms if necessary
> [19:35:13]W: [Step 11/11] I0411 19:35:13.666678 31205 master.cpp:4406]
> Registering agent at slave(454)@172.30.2.184:40532
> (ip-172-30-2-184.mesosphere.io) with id
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-S0
> [19:35:13]W: [Step 11/11] I0411 19:35:13.667063 31201 registrar.cpp:463]
> Applied 1 operations in 56478ns; attempting to update the 'registry'
> [19:35:13]W: [Step 11/11] I0411 19:35:13.667695 31206 log.cpp:683]
> Attempting to append 396 bytes to the log
> [19:35:13]W: [Step 11/11] I0411 19:35:13.667812 31202 coordinator.cpp:348]
> Coordinator attempting to write APPEND action at position 3
> [19:35:13]W: [Step 11/11] I0411 19:35:13.668459 31205 replica.cpp:537]
> Replica received write request for position 3 from (16991)@172.30.2.184:40532
> [19:35:13]W: [Step 11/11] I0411 19:35:13.669265 31205 leveldb.cpp:341]
> Persisting action (415 bytes) to leveldb took 768956ns
> [19:35:13]W: [Step 11/11] I0411 19:35:13.669284 31205 replica.cpp:712]
> Persisted action at 3
> [19:35:13]W: [Step 11/11] I0411 19:35:13.669803 31202 replica.cpp:691]
> Replica received learned notice for position 3 from @0.0.0.0:0
> [19:35:13]W: [Step 11/11] I0411 19:35:13.670490 31202 leveldb.cpp:341]
> Persisting action (417 bytes) to leveldb took 659373ns
> [19:35:13]W: [Step 11/11] I0411 19:35:13.670508 31202 replica.cpp:712]
> Persisted action at 3
> [19:35:13]W: [Step 11/11] I0411 19:35:13.670523 31202 replica.cpp:697]
> Replica learned APPEND action at position 3
> [19:35:13]W: [Step 11/11] I0411 19:35:13.671650 31205 registrar.cpp:508]
> Successfully updated the 'registry' in 4.530944ms
> [19:35:13]W: [Step 11/11] I0411 19:35:13.671923 31208 log.cpp:702]
> Attempting to truncate the log to 3
> [19:35:13]W: [Step 11/11] I0411 19:35:13.672019 31203 coordinator.cpp:348]
> Coordinator attempting to write TRUNCATE action at position 4
> [19:35:13]W: [Step 11/11] I0411 19:35:13.672302 31203 slave.cpp:3675]
> Received ping from slave-observer(422)@172.30.2.184:40532
> [19:35:13]W: [Step 11/11] I0411 19:35:13.672374 31207 master.cpp:4474]
> Registered agent abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-S0 at
> slave(454)@172.30.2.184:40532 (ip-172-30-2-184.mesosphere.io) with cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> [19:35:13]W: [Step 11/11] I0411 19:35:13.672508 31203 slave.cpp:1116]
> Registered with master [email protected]:40532; given agent ID
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-S0
> [19:35:13]W: [Step 11/11] I0411 19:35:13.672531 31203 fetcher.cpp:81]
> Clearing fetcher cache
> [19:35:13]W: [Step 11/11] I0411 19:35:13.672570 31208 hierarchical.cpp:473]
> Added agent abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-S0
> (ip-172-30-2-184.mesosphere.io) with cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000] (allocated: )
> [19:35:13]W: [Step 11/11] I0411 19:35:13.672677 31202
> status_update_manager.cpp:181] Resuming sending status updates
> [19:35:13]W: [Step 11/11] I0411 19:35:13.672720 31206 replica.cpp:537]
> Replica received write request for position 4 from (16992)@172.30.2.184:40532
> [19:35:13]W: [Step 11/11] I0411 19:35:13.672799 31203 slave.cpp:1139]
> Checkpointing SlaveInfo to
> '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutorWithVolumes_gPh4rA/meta/slaves/abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-S0/slave.info'
> [19:35:13]W: [Step 11/11] I0411 19:35:13.672992 31203 slave.cpp:1176]
> Forwarding total oversubscribed resources
> [19:35:13]W: [Step 11/11] I0411 19:35:13.673120 31203 master.cpp:4818]
> Received update of agent abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-S0 at
> slave(454)@172.30.2.184:40532 (ip-172-30-2-184.mesosphere.io) with total
> oversubscribed resources
> [19:35:13]W: [Step 11/11] I0411 19:35:13.673305 31208
> hierarchical.cpp:1583] No inverse offers to send out!
> [19:35:13]W: [Step 11/11] I0411 19:35:13.673360 31208
> hierarchical.cpp:1162] Performed allocation for agent
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-S0 in 748812ns
> [19:35:13]W: [Step 11/11] I0411 19:35:13.673390 31206 leveldb.cpp:341]
> Persisting action (16 bytes) to leveldb took 637058ns
> [19:35:13]W: [Step 11/11] I0411 19:35:13.673413 31206 replica.cpp:712]
> Persisted action at 4
> [19:35:13]W: [Step 11/11] I0411 19:35:13.673607 31204 master.cpp:5524]
> Sending 1 offers to framework abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000
> (default) at [email protected]:40532
> [19:35:13]W: [Step 11/11] I0411 19:35:13.673840 31208 hierarchical.cpp:531]
> Agent abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-S0 (ip-172-30-2-184.mesosphere.io)
> updated with oversubscribed resources (total: cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024;
> disk(*):1024; ports(*):[31000-32000])
> [19:35:13]W: [Step 11/11] I0411 19:35:13.673949 31202 replica.cpp:691]
> Replica received learned notice for position 4 from @0.0.0.0:0
> [19:35:13]W: [Step 11/11] I0411 19:35:13.673990 31208
> hierarchical.cpp:1488] No resources available to allocate!
> [19:35:13]W: [Step 11/11] I0411 19:35:13.674028 31208
> hierarchical.cpp:1583] No inverse offers to send out!
> [19:35:13]W: [Step 11/11] I0411 19:35:13.674072 31208
> hierarchical.cpp:1162] Performed allocation for agent
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-S0 in 186758ns
> [19:35:13]W: [Step 11/11] I0411 19:35:13.674083 31203 sched.cpp:876]
> Scheduler::resourceOffers took 122346ns
> [19:35:13]W: [Step 11/11] I0411 19:35:13.674620 31202 leveldb.cpp:341]
> Persisting action (18 bytes) to leveldb took 643873ns
> [19:35:13]W: [Step 11/11] I0411 19:35:13.674666 31202 leveldb.cpp:399]
> Deleting ~2 keys from leveldb took 27499ns
> [19:35:13]W: [Step 11/11] I0411 19:35:13.674680 31202 replica.cpp:712]
> Persisted action at 4
> [19:35:13]W: [Step 11/11] I0411 19:35:13.674695 31202 replica.cpp:697]
> Replica learned TRUNCATE action at position 4
> [19:35:13]W: [Step 11/11] I0411 19:35:13.675678 31202 master.cpp:3304]
> Processing ACCEPT call for offers: [ abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-O0
> ] on agent abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-S0 at
> slave(454)@172.30.2.184:40532 (ip-172-30-2-184.mesosphere.io) for framework
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000 (default) at
> [email protected]:40532
> [19:35:13]W: [Step 11/11] I0411 19:35:13.675737 31202 master.cpp:2907]
> Authorizing framework principal 'test-principal' to launch task
> d92427b4-3b52-4b10-b4f0-5deba52b22f9 as user 'root'
> [19:35:13]W: [Step 11/11] I0411 19:35:13.677170 31202 master.hpp:177]
> Adding task d92427b4-3b52-4b10-b4f0-5deba52b22f9 with resources cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] on agent
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-S0 (ip-172-30-2-184.mesosphere.io)
> [19:35:13]W: [Step 11/11] I0411 19:35:13.677336 31202 master.cpp:3789]
> Launching task d92427b4-3b52-4b10-b4f0-5deba52b22f9 of framework
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000 (default) at
> [email protected]:40532 with
> resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on
> agent abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-S0 at
> slave(454)@172.30.2.184:40532 (ip-172-30-2-184.mesosphere.io)
> [19:35:13]W: [Step 11/11] I0411 19:35:13.677650 31207 slave.cpp:1508] Got
> assigned task d92427b4-3b52-4b10-b4f0-5deba52b22f9 for framework
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000
> [19:35:13]W: [Step 11/11] I0411 19:35:13.677850 31207 resources.cpp:572]
> Parsing resources as JSON failed: cpus:0.1;mem:32
> [19:35:13]W: [Step 11/11] Trying semicolon-delimited string format instead
> [19:35:13]W: [Step 11/11] I0411 19:35:13.678338 31207 slave.cpp:1627]
> Launching task d92427b4-3b52-4b10-b4f0-5deba52b22f9 for framework
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000
> [19:35:13]W: [Step 11/11] I0411 19:35:13.678416 31207 resources.cpp:572]
> Parsing resources as JSON failed: cpus:0.1;mem:32
> [19:35:13]W: [Step 11/11] Trying semicolon-delimited string format instead
> [19:35:13]W: [Step 11/11] I0411 19:35:13.679029 31207 paths.cpp:528] Trying
> to chown
> '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutorWithVolumes_gPh4rA/slaves/abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-S0/frameworks/abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000/executors/d92427b4-3b52-4b10-b4f0-5deba52b22f9/runs/a2a172ec-2634-4cdd-b28b-d404bd8e9e1c'
> to user 'root'
> [19:35:13]W: [Step 11/11] I0411 19:35:13.683634 31207 slave.cpp:5586]
> Launching executor d92427b4-3b52-4b10-b4f0-5deba52b22f9 of framework
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000 with resources cpus(*):0.1;
> mem(*):32 in work directory
> '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutorWithVolumes_gPh4rA/slaves/abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-S0/frameworks/abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000/executors/d92427b4-3b52-4b10-b4f0-5deba52b22f9/runs/a2a172ec-2634-4cdd-b28b-d404bd8e9e1c'
> [19:35:13]W: [Step 11/11] I0411 19:35:13.684170 31207 slave.cpp:1845]
> Queuing task 'd92427b4-3b52-4b10-b4f0-5deba52b22f9' for executor
> 'd92427b4-3b52-4b10-b4f0-5deba52b22f9' of framework
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000
> [19:35:13]W: [Step 11/11] I0411 19:35:13.684172 31202
> containerizer.cpp:682] Starting container
> 'a2a172ec-2634-4cdd-b28b-d404bd8e9e1c' for executor
> 'd92427b4-3b52-4b10-b4f0-5deba52b22f9' of framework
> 'abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000'
> [19:35:13]W: [Step 11/11] I0411 19:35:13.684300 31207 slave.cpp:892]
> Successfully attached file
> '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutorWithVolumes_gPh4rA/slaves/abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-S0/frameworks/abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000/executors/d92427b4-3b52-4b10-b4f0-5deba52b22f9/runs/a2a172ec-2634-4cdd-b28b-d404bd8e9e1c'
> [19:35:13]W: [Step 11/11] I0411 19:35:13.684814 31201 provisioner.cpp:285]
> Provisioning image rootfs
> '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutorWithVolumes_gPh4rA/provisioner/containers/a2a172ec-2634-4cdd-b28b-d404bd8e9e1c/backends/copy/rootfses/7339b9af-a2bc-4042-be97-9557e21dc6da'
> for container a2a172ec-2634-4cdd-b28b-d404bd8e9e1c
> [19:35:13]W: [Step 11/11] I0411 19:35:13.685442 31206 copy.cpp:128] Copying
> layer path '/tmp/0PzkwC/test_image' to rootfs
> '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutorWithVolumes_gPh4rA/provisioner/containers/a2a172ec-2634-4cdd-b28b-d404bd8e9e1c/backends/copy/rootfses/7339b9af-a2bc-4042-be97-9557e21dc6da'
> [19:35:13]W: [Step 11/11] I0411 19:35:13.920727 31208
> hierarchical.cpp:1488] No resources available to allocate!
> [19:35:13]W: [Step 11/11] I0411 19:35:13.920788 31208
> hierarchical.cpp:1583] No inverse offers to send out!
> [19:35:13]W: [Step 11/11] I0411 19:35:13.920858 31208
> hierarchical.cpp:1139] Performed allocation for 1 agents in 366102ns
> [19:35:14]W: [Step 11/11] I0411 19:35:14.922166 31203
> hierarchical.cpp:1488] No resources available to allocate!
> [19:35:14]W: [Step 11/11] I0411 19:35:14.922224 31203
> hierarchical.cpp:1583] No inverse offers to send out!
> [19:35:14]W: [Step 11/11] I0411 19:35:14.922289 31203
> hierarchical.cpp:1139] Performed allocation for 1 agents in 340046ns
> [19:35:15]W: [Step 11/11] I0411 19:35:15.923585 31205
> hierarchical.cpp:1488] No resources available to allocate!
> [19:35:15]W: [Step 11/11] I0411 19:35:15.923645 31205
> hierarchical.cpp:1583] No inverse offers to send out!
> [19:35:15]W: [Step 11/11] I0411 19:35:15.923727 31205
> hierarchical.cpp:1139] Performed allocation for 1 agents in 369960ns
> [19:35:16]W: [Step 11/11] I0411 19:35:16.924886 31204
> hierarchical.cpp:1488] No resources available to allocate!
> [19:35:16]W: [Step 11/11] I0411 19:35:16.924947 31204
> hierarchical.cpp:1583] No inverse offers to send out!
> [19:35:16]W: [Step 11/11] I0411 19:35:16.925012 31204
> hierarchical.cpp:1139] Performed allocation for 1 agents in 361456ns
> [19:35:17]W: [Step 11/11] I0411 19:35:17.396033 31203
> linux_launcher.cpp:281] Cloning child process with flags = CLONE_NEWNS
> [19:35:17]W: [Step 11/11] +
> /mnt/teamcity/work/4240ba9ddd0997c3/build/src/mesos-containerizer mount
> --help=false --operation=make-rslave --path=/
> [19:35:17]W: [Step 11/11] + grep -E
> /mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutorWithVolumes_gPh4rA/.+
> /proc/self/mountinfo
> [19:35:17]W: [Step 11/11] + grep -v a2a172ec-2634-4cdd-b28b-d404bd8e9e1c
> [19:35:17]W: [Step 11/11] + cut '-d ' -f5
> [19:35:17]W: [Step 11/11] + xargs --no-run-if-empty umount -l
> [19:35:17]W: [Step 11/11] + mount -n --rbind
> /mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutorWithVolumes_gPh4rA/provisioner/containers/a2a172ec-2634-4cdd-b28b-d404bd8e9e1c/backends/copy/rootfses/7339b9af-a2bc-4042-be97-9557e21dc6da
>
> /mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutorWithVolumes_gPh4rA/slaves/abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-S0/frameworks/abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000/executors/d92427b4-3b52-4b10-b4f0-5deba52b22f9/runs/a2a172ec-2634-4cdd-b28b-d404bd8e9e1c/.rootfs
> [19:35:17]W: [Step 11/11] + mount -n --rbind /tmp/0PzkwC/dir2
> /mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutorWithVolumes_gPh4rA/slaves/abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-S0/frameworks/abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000/executors/d92427b4-3b52-4b10-b4f0-5deba52b22f9/runs/a2a172ec-2634-4cdd-b28b-d404bd8e9e1c/relative_dir
> [19:35:17]W: [Step 11/11] + mount -n --rbind /tmp/0PzkwC/dir1
> /mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutorWithVolumes_gPh4rA/slaves/abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-S0/frameworks/abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000/executors/d92427b4-3b52-4b10-b4f0-5deba52b22f9/runs/a2a172ec-2634-4cdd-b28b-d404bd8e9e1c/.rootfs/tmp
> [19:35:17]W: [Step 11/11] WARNING: Logging before InitGoogleLogging() is
> written to STDERR
> [19:35:17]W: [Step 11/11] I0411 19:35:17.552160 15448 process.cpp:985]
> libprocess is initialized on 172.30.2.184:46795 with 8 worker threads
> [19:35:17]W: [Step 11/11] I0411 19:35:17.552795 15448 logging.cpp:195]
> Logging to STDERR
> [19:35:17]W: [Step 11/11] I0411 19:35:17.554147 15448 exec.cpp:150]
> Version: 0.29.0
> [19:35:17]W: [Step 11/11] I0411 19:35:17.560665 15496 exec.cpp:200]
> Executor started at: executor(1)@172.30.2.184:46795 with pid 15448
> [19:35:17]W: [Step 11/11] I0411 19:35:17.562374 31208 slave.cpp:2836] Got
> registration for executor 'd92427b4-3b52-4b10-b4f0-5deba52b22f9' of framework
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000 from executor(1)@172.30.2.184:46795
> [19:35:17]W: [Step 11/11] I0411 19:35:17.564164 31205 slave.cpp:2010]
> Sending queued task 'd92427b4-3b52-4b10-b4f0-5deba52b22f9' to executor
> 'd92427b4-3b52-4b10-b4f0-5deba52b22f9' of framework
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000 at executor(1)@172.30.2.184:46795
> [19:35:17]W: [Step 11/11] I0411 19:35:17.564231 15501 exec.cpp:225]
> Executor registered on agent abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-S0
> [19:35:17] : [Step 11/11] Registered executor on
> ip-172-30-2-184.mesosphere.io
> [19:35:17]W: [Step 11/11] I0411 19:35:17.565734 15501 exec.cpp:237]
> Executor::registered took 365026ns
> [19:35:17]W: [Step 11/11] I0411 19:35:17.566006 15501 exec.cpp:312]
> Executor asked to run task 'd92427b4-3b52-4b10-b4f0-5deba52b22f9'
> [19:35:17]W: [Step 11/11] I0411 19:35:17.566136 15501 exec.cpp:321]
> Executor::launchTask took 110150ns
> [19:35:17] : [Step 11/11] Starting task d92427b4-3b52-4b10-b4f0-5deba52b22f9
> [19:35:17] : [Step 11/11] Forked command at 15505
> [19:35:17]W: [Step 11/11] I0411 19:35:17.571274 15502 exec.cpp:535]
> Executor sending status update TASK_RUNNING (UUID:
> 8bf6a9fb-5ae6-413f-8126-b17f0f2fbb59) for task
> d92427b4-3b52-4b10-b4f0-5deba52b22f9 of framework
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000
> [19:35:17] : [Step 11/11] sh -c 'test -f /tmp/testfile && test -d
> /mnt/mesos/sandbox/relative_dir'
> [19:35:17]W: [Step 11/11] I0411 19:35:17.572180 31208 slave.cpp:3195]
> Handling status update TASK_RUNNING (UUID:
> 8bf6a9fb-5ae6-413f-8126-b17f0f2fbb59) for task
> d92427b4-3b52-4b10-b4f0-5deba52b22f9 of framework
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000 from executor(1)@172.30.2.184:46795
> [19:35:17]W: [Step 11/11] I0411 19:35:17.573412 31206
> status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID:
> 8bf6a9fb-5ae6-413f-8126-b17f0f2fbb59) for task
> d92427b4-3b52-4b10-b4f0-5deba52b22f9 of framework
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000
> [19:35:17]W: [Step 11/11] I0411 19:35:17.573449 31206
> status_update_manager.cpp:497] Creating StatusUpdate stream for task
> d92427b4-3b52-4b10-b4f0-5deba52b22f9 of framework
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000
> [19:35:17]W: [Step 11/11] I0411 19:35:17.573824 31206
> status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID:
> 8bf6a9fb-5ae6-413f-8126-b17f0f2fbb59) for task
> d92427b4-3b52-4b10-b4f0-5deba52b22f9 of framework
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000 to the agent
> [19:35:17]W: [Step 11/11] I0411 19:35:17.574084 31203 slave.cpp:3593]
> Forwarding the update TASK_RUNNING (UUID:
> 8bf6a9fb-5ae6-413f-8126-b17f0f2fbb59) for task
> d92427b4-3b52-4b10-b4f0-5deba52b22f9 of framework
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000 to [email protected]:40532
> [19:35:17]W: [Step 11/11] I0411 19:35:17.574259 31203 slave.cpp:3487]
> Status update manager successfully handled status update TASK_RUNNING (UUID:
> 8bf6a9fb-5ae6-413f-8126-b17f0f2fbb59) for task
> d92427b4-3b52-4b10-b4f0-5deba52b22f9 of framework
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000
> [19:35:17]W: [Step 11/11] I0411 19:35:17.574292 31203 slave.cpp:3503]
> Sending acknowledgement for status update TASK_RUNNING (UUID:
> 8bf6a9fb-5ae6-413f-8126-b17f0f2fbb59) for task
> d92427b4-3b52-4b10-b4f0-5deba52b22f9 of framework
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000 to executor(1)@172.30.2.184:46795
> [19:35:17]W: [Step 11/11] I0411 19:35:17.574419 31205 master.cpp:4963]
> Status update TASK_RUNNING (UUID: 8bf6a9fb-5ae6-413f-8126-b17f0f2fbb59) for
> task d92427b4-3b52-4b10-b4f0-5deba52b22f9 of framework
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000 from agent
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-S0 at slave(454)@172.30.2.184:40532
> (ip-172-30-2-184.mesosphere.io)
> [19:35:17]W: [Step 11/11] I0411 19:35:17.574458 31205 master.cpp:5011]
> Forwarding status update TASK_RUNNING (UUID:
> 8bf6a9fb-5ae6-413f-8126-b17f0f2fbb59) for task
> d92427b4-3b52-4b10-b4f0-5deba52b22f9 of framework
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000
> [19:35:17]W: [Step 11/11] I0411 19:35:17.574622 31205 master.cpp:6624]
> Updating the state of task d92427b4-3b52-4b10-b4f0-5deba52b22f9 of framework
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000 (latest state: TASK_RUNNING, status
> update state: TASK_RUNNING)
> [19:35:17]W: [Step 11/11] I0411 19:35:17.574895 15501 exec.cpp:358]
> Executor received status update acknowledgement
> 8bf6a9fb-5ae6-413f-8126-b17f0f2fbb59 for task
> d92427b4-3b52-4b10-b4f0-5deba52b22f9 of framework
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000
> [19:35:17]W: [Step 11/11] I0411 19:35:17.574954 31202 sched.cpp:984]
> Scheduler::statusUpdate took 173875ns
> [19:35:17]W: [Step 11/11] I0411 19:35:17.575302 31206 master.cpp:4118]
> Processing ACKNOWLEDGE call 8bf6a9fb-5ae6-413f-8126-b17f0f2fbb59 for task
> d92427b4-3b52-4b10-b4f0-5deba52b22f9 of framework
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000 (default) at
> [email protected]:40532 on agent
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-S0
> [19:35:17]W: [Step 11/11] I0411 19:35:17.575542 31208
> status_update_manager.cpp:392] Received status update acknowledgement (UUID:
> 8bf6a9fb-5ae6-413f-8126-b17f0f2fbb59) for task
> d92427b4-3b52-4b10-b4f0-5deba52b22f9 of framework
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000
> [19:35:17]W: [Step 11/11] I0411 19:35:17.575788 31207 slave.cpp:2605]
> Status update manager successfully handled status update acknowledgement
> (UUID: 8bf6a9fb-5ae6-413f-8126-b17f0f2fbb59) for task
> d92427b4-3b52-4b10-b4f0-5deba52b22f9 of framework
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000
> [19:35:17] : [Step 11/11] Command exited with status 0 (pid: 15505)
> [19:35:17]W: [Step 11/11] I0411 19:35:17.671139 15503 exec.cpp:535]
> Executor sending status update TASK_FINISHED (UUID:
> 710d9da2-7b0a-485b-97f2-76073bc8786d) for task
> d92427b4-3b52-4b10-b4f0-5deba52b22f9 of framework
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000
> [19:35:17]W: [Step 11/11] I0411 19:35:17.672031 31208 slave.cpp:3195]
> Handling status update TASK_FINISHED (UUID:
> 710d9da2-7b0a-485b-97f2-76073bc8786d) for task
> d92427b4-3b52-4b10-b4f0-5deba52b22f9 of framework
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000 from executor(1)@172.30.2.184:46795
> [19:35:17]W: [Step 11/11] I0411 19:35:17.672986 31207 slave.cpp:5896]
> Terminating task d92427b4-3b52-4b10-b4f0-5deba52b22f9
> [19:35:17]W: [Step 11/11] I0411 19:35:17.673919 31206
> status_update_manager.cpp:320] Received status update TASK_FINISHED (UUID:
> 710d9da2-7b0a-485b-97f2-76073bc8786d) for task
> d92427b4-3b52-4b10-b4f0-5deba52b22f9 of framework
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000
> [19:35:17]W: [Step 11/11] I0411 19:35:17.674084 31206
> status_update_manager.cpp:374] Forwarding update TASK_FINISHED (UUID:
> 710d9da2-7b0a-485b-97f2-76073bc8786d) for task
> d92427b4-3b52-4b10-b4f0-5deba52b22f9 of framework
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000 to the agent
> [19:35:17]W: [Step 11/11] I0411 19:35:17.674309 31205 slave.cpp:3593]
> Forwarding the update TASK_FINISHED (UUID:
> 710d9da2-7b0a-485b-97f2-76073bc8786d) for task
> d92427b4-3b52-4b10-b4f0-5deba52b22f9 of framework
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000 to [email protected]:40532
> [19:35:17]W: [Step 11/11] I0411 19:35:17.674489 31205 slave.cpp:3487]
> Status update manager successfully handled status update TASK_FINISHED (UUID:
> 710d9da2-7b0a-485b-97f2-76073bc8786d) for task
> d92427b4-3b52-4b10-b4f0-5deba52b22f9 of framework
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000
> [19:35:17]W: [Step 11/11] I0411 19:35:17.674525 31205 slave.cpp:3503]
> Sending acknowledgement for status update TASK_FINISHED (UUID:
> 710d9da2-7b0a-485b-97f2-76073bc8786d) for task
> d92427b4-3b52-4b10-b4f0-5deba52b22f9 of framework
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000 to executor(1)@172.30.2.184:46795
> [19:35:17]W: [Step 11/11] I0411 19:35:17.674602 31204 master.cpp:4963]
> Status update TASK_FINISHED (UUID: 710d9da2-7b0a-485b-97f2-76073bc8786d) for
> task d92427b4-3b52-4b10-b4f0-5deba52b22f9 of framework
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000 from agent
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-S0 at slave(454)@172.30.2.184:40532
> (ip-172-30-2-184.mesosphere.io)
> [19:35:17]W: [Step 11/11] I0411 19:35:17.674636 31204 master.cpp:5011]
> Forwarding status update TASK_FINISHED (UUID:
> 710d9da2-7b0a-485b-97f2-76073bc8786d) for task
> d92427b4-3b52-4b10-b4f0-5deba52b22f9 of framework
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000
> [19:35:17]W: [Step 11/11] I0411 19:35:17.674803 31204 master.cpp:6624]
> Updating the state of task d92427b4-3b52-4b10-b4f0-5deba52b22f9 of framework
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000 (latest state: TASK_FINISHED,
> status update state: TASK_FINISHED)
> [19:35:17]W: [Step 11/11] I0411 19:35:17.674975 31208 sched.cpp:984]
> Scheduler::statusUpdate took 93388ns
> [19:35:17]W: [Step 11/11] I0411 19:35:17.675070 15497 exec.cpp:358]
> Executor received status update acknowledgement
> 710d9da2-7b0a-485b-97f2-76073bc8786d for task
> d92427b4-3b52-4b10-b4f0-5deba52b22f9 of framework
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000
> [19:35:17]W: [Step 11/11] I0411 19:35:17.675328 31187 sched.cpp:1907] Asked
> to stop the driver
> [19:35:17]W: [Step 11/11] I0411 19:35:17.675408 31205 sched.cpp:1146]
> Stopping framework 'abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000'
> [19:35:17]W: [Step 11/11] I0411 19:35:17.675434 31204 master.cpp:4118]
> Processing ACKNOWLEDGE call 710d9da2-7b0a-485b-97f2-76073bc8786d for task
> d92427b4-3b52-4b10-b4f0-5deba52b22f9 of framework
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000 (default) at
> [email protected]:40532 on agent
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-S0
> [19:35:17]W: [Step 11/11] I0411 19:35:17.675480 31204 master.cpp:6690]
> Removing task d92427b4-3b52-4b10-b4f0-5deba52b22f9 with resources cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000 on agent
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-S0 at slave(454)@172.30.2.184:40532
> (ip-172-30-2-184.mesosphere.io)
> [19:35:17]W: [Step 11/11] I0411 19:35:17.675608 31207 hierarchical.cpp:891]
> Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000],
> allocated: ) on agent abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-S0 from framework
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000
> [19:35:17]W: [Step 11/11] I0411 19:35:17.675874 31204 master.cpp:6097]
> Processing TEARDOWN call for framework
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000 (default) at
> [email protected]:40532
> [19:35:17]W: [Step 11/11] I0411 19:35:17.675899 31204 master.cpp:6109]
> Removing framework abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000 (default) at
> [email protected]:40532
> [19:35:17]W: [Step 11/11] I0411 19:35:17.675974 31201
> status_update_manager.cpp:392] Received status update acknowledgement (UUID:
> 710d9da2-7b0a-485b-97f2-76073bc8786d) for task
> d92427b4-3b52-4b10-b4f0-5deba52b22f9 of framework
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000
> [19:35:17]W: [Step 11/11] I0411 19:35:17.676022 31203 hierarchical.cpp:375]
> Deactivated framework abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000
> [19:35:17]W: [Step 11/11] I0411 19:35:17.676101 31203 slave.cpp:2226] Asked
> to shut down framework abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000 by
> [email protected]:40532
> [19:35:17]W: [Step 11/11] I0411 19:35:17.676134 31203 slave.cpp:2251]
> Shutting down framework abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000
> [19:35:17]W: [Step 11/11] I0411 19:35:17.676159 31201
> status_update_manager.cpp:528] Cleaning up status update stream for task
> d92427b4-3b52-4b10-b4f0-5deba52b22f9 of framework
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000
> [19:35:17]W: [Step 11/11] I0411 19:35:17.676182 31203 slave.cpp:4409]
> Shutting down executor 'd92427b4-3b52-4b10-b4f0-5deba52b22f9' of framework
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000 at executor(1)@172.30.2.184:46795
> [19:35:17]W: [Step 11/11] I0411 19:35:17.676492 31207 slave.cpp:2605]
> Status update manager successfully handled status update acknowledgement
> (UUID: 710d9da2-7b0a-485b-97f2-76073bc8786d) for task
> d92427b4-3b52-4b10-b4f0-5deba52b22f9 of framework
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000
> [19:35:17]W: [Step 11/11] I0411 19:35:17.676540 31207 slave.cpp:5937]
> Completing task d92427b4-3b52-4b10-b4f0-5deba52b22f9
> [19:35:17]W: [Step 11/11] I0411 19:35:17.676684 31202 hierarchical.cpp:326]
> Removed framework abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000
> [19:35:17]W: [Step 11/11] I0411 19:35:17.676813 15498 exec.cpp:399]
> Executor asked to shutdown
> [19:35:17]W: [Step 11/11] I0411 19:35:17.676918 31208
> containerizer.cpp:1439] Destroying container
> 'a2a172ec-2634-4cdd-b28b-d404bd8e9e1c'
> [19:35:17]W: [Step 11/11] I0411 19:35:17.676935 15498 exec.cpp:414]
> Executor::shutdown took 16385ns
> [19:35:17]W: [Step 11/11] I0411 19:35:17.676960 15503 exec.cpp:91]
> Scheduling shutdown of the executor in 5secs
> [19:35:17]W: [Step 11/11] I0411 19:35:17.679304 31208 cgroups.cpp:2676]
> Freezing cgroup
> /sys/fs/cgroup/freezer/mesos/a2a172ec-2634-4cdd-b28b-d404bd8e9e1c
> [19:35:17]W: [Step 11/11] I0411 19:35:17.681535 31201 cgroups.cpp:1409]
> Successfully froze cgroup
> /sys/fs/cgroup/freezer/mesos/a2a172ec-2634-4cdd-b28b-d404bd8e9e1c after
> 2.180608ms
> [19:35:17]W: [Step 11/11] I0411 19:35:17.683848 31205 cgroups.cpp:2694]
> Thawing cgroup
> /sys/fs/cgroup/freezer/mesos/a2a172ec-2634-4cdd-b28b-d404bd8e9e1c
> [19:35:17]W: [Step 11/11] I0411 19:35:17.685909 31205 cgroups.cpp:1438]
> Successfully thawed cgroup
> /sys/fs/cgroup/freezer/mesos/a2a172ec-2634-4cdd-b28b-d404bd8e9e1c after
> 2.018048ms
> [19:35:17]W: [Step 11/11] I0411 19:35:17.700244 31206 slave.cpp:3721]
> executor(1)@172.30.2.184:46795 exited
> [19:35:17]W: [Step 11/11] I0411 19:35:17.796105 31202
> containerizer.cpp:1674] Executor for container
> 'a2a172ec-2634-4cdd-b28b-d404bd8e9e1c' has exited
> [19:35:17]W: [Step 11/11] I0411 19:35:17.798676 31204 linux.cpp:814]
> Ignoring unmounting sandbox/work directory for container
> a2a172ec-2634-4cdd-b28b-d404bd8e9e1c
> [19:35:17]W: [Step 11/11] I0411 19:35:17.799177 31206 provisioner.cpp:338]
> Destroying container rootfs at
> '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutorWithVolumes_gPh4rA/provisioner/containers/a2a172ec-2634-4cdd-b28b-d404bd8e9e1c/backends/copy/rootfses/7339b9af-a2bc-4042-be97-9557e21dc6da'
> for container a2a172ec-2634-4cdd-b28b-d404bd8e9e1c
> [19:35:17]W: [Step 11/11] I0411 19:35:17.926494 31208
> hierarchical.cpp:1488] No resources available to allocate!
> [19:35:17]W: [Step 11/11] I0411 19:35:17.926590 31208
> hierarchical.cpp:1139] Performed allocation for 1 agents in 331329ns
> [19:35:18]W: [Step 11/11] I0411 19:35:18.927258 31208
> hierarchical.cpp:1488] No resources available to allocate!
> [19:35:18]W: [Step 11/11] I0411 19:35:18.927364 31208
> hierarchical.cpp:1139] Performed allocation for 1 agents in 268372ns
> [19:35:19]W: [Step 11/11] I0411 19:35:19.928421 31201
> hierarchical.cpp:1488] No resources available to allocate!
> [19:35:19]W: [Step 11/11] I0411 19:35:19.928509 31201
> hierarchical.cpp:1139] Performed allocation for 1 agents in 282458ns
> [19:35:20]W: [Step 11/11] I0411 19:35:20.929616 31202
> hierarchical.cpp:1488] No resources available to allocate!
> [19:35:20]W: [Step 11/11] I0411 19:35:20.929703 31202
> hierarchical.cpp:1139] Performed allocation for 1 agents in 285866ns
> [19:35:21]W: [Step 11/11] I0411 19:35:21.930207 31203
> hierarchical.cpp:1488] No resources available to allocate!
> [19:35:21]W: [Step 11/11] I0411 19:35:21.930294 31203
> hierarchical.cpp:1139] Performed allocation for 1 agents in 266291ns
> [19:35:22]W: [Step 11/11] I0411 19:35:22.677112 31203 slave.cpp:4482]
> Killing executor 'd92427b4-3b52-4b10-b4f0-5deba52b22f9' of framework
> abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000 at executor(1)@172.30.2.184:46795
> [19:35:22]W: [Step 11/11] I0411 19:35:22.930769 31207
> hierarchical.cpp:1488] No resources available to allocate!
> [19:35:22]W: [Step 11/11] I0411 19:35:22.930861 31207
> hierarchical.cpp:1139] Performed allocation for 1 agents in 288855ns
> [19:35:23]W: [Step 11/11] I0411 19:35:23.931710 31205
> hierarchical.cpp:1488] No resources available to allocate!
> [19:35:23]W: [Step 11/11] I0411 19:35:23.931802 31205
> hierarchical.cpp:1139] Performed allocation for 1 agents in 293797ns
> [19:35:24]W: [Step 11/11] I0411 19:35:24.932621 31204
> hierarchical.cpp:1488] No resources available to allocate!
> [19:35:24]W: [Step 11/11] I0411 19:35:24.932728 31204
> hierarchical.cpp:1139] Performed allocation for 1 agents in 310203ns
> [19:35:25]W: [Step 11/11] I0411 19:35:25.934168 31203
> hierarchical.cpp:1488] No resources available to allocate!
> [19:35:25]W: [Step 11/11] I0411 19:35:25.934255 31203
> hierarchical.cpp:1139] Performed allocation for 1 agents in 269100ns
> [19:35:26]W: [Step 11/11] I0411 19:35:26.935744 31208
> hierarchical.cpp:1488] No resources available to allocate!
> [19:35:26]W: [Step 11/11] I0411 19:35:26.935832 31208
> hierarchical.cpp:1139] Performed allocation for 1 agents in 279747ns
> [19:35:27]W: [Step 11/11] I0411 19:35:27.937157 31203
> hierarchical.cpp:1488] No resources available to allocate!
> [19:35:27]W: [Step 11/11] I0411 19:35:27.937252 31203
> hierarchical.cpp:1139] Performed allocation for 1 agents in 256914ns
> [19:35:28]W: [Step 11/11] I0411 19:35:28.665484 31203 slave.cpp:4956]
> Querying resource estimator for oversubscribable resources
> [19:35:28]W: [Step 11/11] I0411 19:35:28.665737 31202 slave.cpp:4970]
> Received oversubscribable resources from the resource estimator
> [19:35:28]W: [Step 11/11] I0411 19:35:28.672852 31208 slave.cpp:3675]
> Received ping from slave-observer(422)@172.30.2.184:40532
> [19:35:28]W: [Step 11/11] I0411 19:35:28.938107 31208
> hierarchical.cpp:1488] No resources available to allocate!
> [19:35:28]W: [Step 11/11] I0411 19:35:28.938196 31208
> hierarchical.cpp:1139] Performed allocation for 1 agents in 261170ns
> [19:35:29]W: [Step 11/11] I0411 19:35:29.939237 31205
> hierarchical.cpp:1488] No resources available to allocate!
> [19:35:29]W: [Step 11/11] I0411 19:35:29.939327 31205
> hierarchical.cpp:1139] Performed allocation for 1 agents in 257129ns
> [19:35:30]W: [Step 11/11] I0411 19:35:30.940459 31207
> hierarchical.cpp:1488] No resources available to allocate!
> [19:35:30]W: [Step 11/11] I0411 19:35:30.940547 31207
> hierarchical.cpp:1139] Performed allocation for 1 agents in 266310ns
> [19:35:31]W: [Step 11/11] I0411 19:35:31.941676 31202
> hierarchical.cpp:1488] No resources available to allocate!
> [19:35:31]W: [Step 11/11] I0411 19:35:31.941792 31202
> hierarchical.cpp:1139] Performed allocation for 1 agents in 288291ns
> [19:35:32] : [Step 11/11] ../../src/tests/cluster.cpp:468: Failure
> [19:35:32] : [Step 11/11] Failed to wait 15secs for wait
> [19:35:32]W: [Step 11/11] I0411 19:35:32.677981 31205 slave.cpp:811] Agent
> terminating
> [19:35:32]W: [Step 11/11] I0411 19:35:32.678072 31205 slave.cpp:2226] Asked
> to shut down framework abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000 by @0.0.0.0:0
> [19:35:32]W: [Step 11/11] W0411 19:35:32.678099 31205 slave.cpp:2247]
> Ignoring shutdown framework abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-0000 because
> it is terminating
> [19:35:32]W: [Step 11/11] I0411 19:35:32.678300 31206 master.cpp:1236]
> Agent abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-S0 at
> slave(454)@172.30.2.184:40532 (ip-172-30-2-184.mesosphere.io) disconnected
> [19:35:32]W: [Step 11/11] I0411 19:35:32.678325 31206 master.cpp:2717]
> Disconnecting agent abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-S0 at
> slave(454)@172.30.2.184:40532 (ip-172-30-2-184.mesosphere.io)
> [19:35:32]W: [Step 11/11] I0411 19:35:32.678380 31206 master.cpp:2736]
> Deactivating agent abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-S0 at
> slave(454)@172.30.2.184:40532 (ip-172-30-2-184.mesosphere.io)
> [19:35:32]W: [Step 11/11] I0411 19:35:32.678484 31201 hierarchical.cpp:560]
> Agent abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-S0 deactivated
> [19:35:32]W: [Step 11/11] I0411 19:35:32.942952 31203
> hierarchical.cpp:1488] No resources available to allocate!
> [19:35:32]W: [Step 11/11] I0411 19:35:32.943043 31203
> hierarchical.cpp:1139] Performed allocation for 1 agents in 237075ns
> [19:35:33]W: [Step 11/11] I0411 19:35:33.944149 31205
> hierarchical.cpp:1488] No resources available to allocate!
> [19:35:33]W: [Step 11/11] I0411 19:35:33.944252 31205
> hierarchical.cpp:1139] Performed allocation for 1 agents in 249923ns
> [19:35:34]W: [Step 11/11] I0411 19:35:34.855480 31187 master.cpp:1089]
> Master terminating
> [19:35:34]W: [Step 11/11] I0411 19:35:34.855979 31205 hierarchical.cpp:505]
> Removed agent abd3c4ca-5e96-4cbe-8814-a9c5ebd1767b-S0
> [19:35:34] : [Step 11/11] [ FAILED ]
> LinuxFilesystemIsolatorTest.ROOT_ChangeRootFilesystemCommandExecutorWithVolumes
> (22960 ms)
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
