[
https://issues.apache.org/jira/browse/MESOS-5284?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
haosdent reassigned MESOS-5284:
-------------------------------
Assignee: haosdent
> LinuxFilesystemIsolatorTest.ROOT_ChangeRootFilesystemCommandExecutor is flaky.
> ------------------------------------------------------------------------------
>
> Key: MESOS-5284
> URL: https://issues.apache.org/jira/browse/MESOS-5284
> Project: Mesos
> Issue Type: Bug
> Components: tests
> Environment: CentOS 7 with SSL
> Reporter: Gilbert Song
> Assignee: haosdent
> Labels: mesosphere
>
> Observed on the internal Mesosphere CI:
> {code}
> [18:03:58] : [Step 10/10] [ RUN ]
> LinuxFilesystemIsolatorTest.ROOT_ChangeRootFilesystemCommandExecutor
> [18:03:58]W: [Step 10/10] I0425 18:03:58.584962 642 cluster.cpp:149]
> Creating default 'local' authorizer
> [18:03:58]W: [Step 10/10] I0425 18:03:58.597232 642 leveldb.cpp:174]
> Opened db in 12.195009ms
> [18:03:58]W: [Step 10/10] I0425 18:03:58.598534 642 leveldb.cpp:181]
> Compacted db in 1.266907ms
> [18:03:58]W: [Step 10/10] I0425 18:03:58.598558 642 leveldb.cpp:196]
> Created db iterator in 5704ns
> [18:03:58]W: [Step 10/10] I0425 18:03:58.598565 642 leveldb.cpp:202]
> Seeked to beginning of db in 703ns
> [18:03:58]W: [Step 10/10] I0425 18:03:58.598570 642 leveldb.cpp:271]
> Iterated through 0 keys in the db in 272ns
> [18:03:58]W: [Step 10/10] I0425 18:03:58.598585 642 replica.cpp:779]
> Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
> [18:03:58]W: [Step 10/10] I0425 18:03:58.598815 663 recover.cpp:447]
> Starting replica recovery
> [18:03:58]W: [Step 10/10] I0425 18:03:58.598927 663 recover.cpp:473]
> Replica is in EMPTY status
> [18:03:58]W: [Step 10/10] I0425 18:03:58.599241 663 replica.cpp:673]
> Replica in EMPTY status received a broadcasted recover request from
> (17941)@172.30.2.229:48705
> [18:03:58]W: [Step 10/10] I0425 18:03:58.599323 663 recover.cpp:193]
> Received a recover response from a replica in EMPTY status
> [18:03:58]W: [Step 10/10] I0425 18:03:58.599472 657 recover.cpp:564]
> Updating replica status to STARTING
> [18:03:58]W: [Step 10/10] I0425 18:03:58.600092 661 master.cpp:382]
> Master 7e239aa6-d964-4f11-95a8-ba808ad23f4e (ip-172-30-2-229.mesosphere.io)
> started on 172.30.2.229:48705
> [18:03:58]W: [Step 10/10] I0425 18:03:58.600105 661 master.cpp:384] Flags
> at startup: --acls="" --allocation_interval="1secs"
> --allocator="HierarchicalDRF" --authenticate="true"
> --authenticate_http="true" --authenticate_http_frameworks="true"
> --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local"
> --credentials="/tmp/XRr1Iz/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_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/XRr1Iz/master"
> --zk_session_timeout="10secs"
> [18:03:58]W: [Step 10/10] I0425 18:03:58.600225 661 master.cpp:433]
> Master only allowing authenticated frameworks to register
> [18:03:58]W: [Step 10/10] I0425 18:03:58.600231 661 master.cpp:439]
> Master only allowing authenticated agents to register
> [18:03:58]W: [Step 10/10] I0425 18:03:58.600234 661 master.cpp:445]
> Master only allowing authenticated HTTP frameworks to register
> [18:03:58]W: [Step 10/10] I0425 18:03:58.600239 661 credentials.hpp:37]
> Loading credentials for authentication from '/tmp/XRr1Iz/credentials'
> [18:03:58]W: [Step 10/10] I0425 18:03:58.600371 661 master.cpp:489] Using
> default 'crammd5' authenticator
> [18:03:58]W: [Step 10/10] I0425 18:03:58.600410 661 master.cpp:560] Using
> default 'basic' HTTP authenticator
> [18:03:58]W: [Step 10/10] I0425 18:03:58.600461 661 master.cpp:640] Using
> default 'basic' HTTP framework authenticator
> [18:03:58]W: [Step 10/10] I0425 18:03:58.600525 661 master.cpp:687]
> Authorization enabled
> [18:03:58]W: [Step 10/10] I0425 18:03:58.600590 656
> whitelist_watcher.cpp:77] No whitelist given
> [18:03:58]W: [Step 10/10] I0425 18:03:58.600610 660 hierarchical.cpp:142]
> Initialized hierarchical allocator process
> [18:03:58]W: [Step 10/10] I0425 18:03:58.600883 659 leveldb.cpp:304]
> Persisting metadata (8 bytes) to leveldb took 1.350635ms
> [18:03:58]W: [Step 10/10] I0425 18:03:58.600904 659 replica.cpp:320]
> Persisted replica status to STARTING
> [18:03:58]W: [Step 10/10] I0425 18:03:58.601029 659 recover.cpp:473]
> Replica is in STARTING status
> [18:03:58]W: [Step 10/10] I0425 18:03:58.601161 657 master.cpp:1932] The
> newly elected leader is master@172.30.2.229:48705 with id
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e
> [18:03:58]W: [Step 10/10] I0425 18:03:58.601176 657 master.cpp:1945]
> Elected as the leading master!
> [18:03:58]W: [Step 10/10] I0425 18:03:58.601181 657 master.cpp:1632]
> Recovering from registrar
> [18:03:58]W: [Step 10/10] I0425 18:03:58.601227 661 registrar.cpp:331]
> Recovering registrar
> [18:03:58]W: [Step 10/10] I0425 18:03:58.601291 660 replica.cpp:673]
> Replica in STARTING status received a broadcasted recover request from
> (17944)@172.30.2.229:48705
> [18:03:58]W: [Step 10/10] I0425 18:03:58.601460 656 recover.cpp:193]
> Received a recover response from a replica in STARTING status
> [18:03:58]W: [Step 10/10] I0425 18:03:58.601572 663 recover.cpp:564]
> Updating replica status to VOTING
> [18:03:58]W: [Step 10/10] I0425 18:03:58.602798 663 leveldb.cpp:304]
> Persisting metadata (8 bytes) to leveldb took 1.178644ms
> [18:03:58]W: [Step 10/10] I0425 18:03:58.602814 663 replica.cpp:320]
> Persisted replica status to VOTING
> [18:03:58]W: [Step 10/10] I0425 18:03:58.602845 663 recover.cpp:578]
> Successfully joined the Paxos group
> [18:03:58]W: [Step 10/10] I0425 18:03:58.602881 663 recover.cpp:462]
> Recover process terminated
> [18:03:58]W: [Step 10/10] I0425 18:03:58.603023 656 log.cpp:524]
> Attempting to start the writer
> [18:03:58]W: [Step 10/10] I0425 18:03:58.603399 663 replica.cpp:493]
> Replica received implicit promise request from (17945)@172.30.2.229:48705
> with proposal 1
> [18:03:58]W: [Step 10/10] I0425 18:03:58.604593 663 leveldb.cpp:304]
> Persisting metadata (8 bytes) to leveldb took 1.178393ms
> [18:03:58]W: [Step 10/10] I0425 18:03:58.604607 663 replica.cpp:342]
> Persisted promised to 1
> [18:03:58]W: [Step 10/10] I0425 18:03:58.604833 662 coordinator.cpp:238]
> Coordinator attempting to fill missing positions
> [18:03:58]W: [Step 10/10] I0425 18:03:58.605226 660 replica.cpp:388]
> Replica received explicit promise request from (17946)@172.30.2.229:48705 for
> position 0 with proposal 2
> [18:03:58]W: [Step 10/10] I0425 18:03:58.606335 660 leveldb.cpp:341]
> Persisting action (8 bytes) to leveldb took 1.088746ms
> [18:03:58]W: [Step 10/10] I0425 18:03:58.606351 660 replica.cpp:712]
> Persisted action at 0
> [18:03:58]W: [Step 10/10] I0425 18:03:58.606735 661 replica.cpp:537]
> Replica received write request for position 0 from (17947)@172.30.2.229:48705
> [18:03:58]W: [Step 10/10] I0425 18:03:58.606767 661 leveldb.cpp:436]
> Reading position from leveldb took 13169ns
> [18:03:58]W: [Step 10/10] I0425 18:03:58.608047 661 leveldb.cpp:341]
> Persisting action (14 bytes) to leveldb took 1.264327ms
> [18:03:58]W: [Step 10/10] I0425 18:03:58.608062 661 replica.cpp:712]
> Persisted action at 0
> [18:03:58]W: [Step 10/10] I0425 18:03:58.608309 657 replica.cpp:691]
> Replica received learned notice for position 0 from @0.0.0.0:0
> [18:03:58]W: [Step 10/10] I0425 18:03:58.609447 657 leveldb.cpp:341]
> Persisting action (16 bytes) to leveldb took 1.122608ms
> [18:03:58]W: [Step 10/10] I0425 18:03:58.609462 657 replica.cpp:712]
> Persisted action at 0
> [18:03:58]W: [Step 10/10] I0425 18:03:58.609467 657 replica.cpp:697]
> Replica learned NOP action at position 0
> [18:03:58]W: [Step 10/10] I0425 18:03:58.609609 657 log.cpp:540] Writer
> started with ending position 0
> [18:03:58]W: [Step 10/10] I0425 18:03:58.609887 661 leveldb.cpp:436]
> Reading position from leveldb took 8414ns
> [18:03:58]W: [Step 10/10] I0425 18:03:58.610115 661 registrar.cpp:364]
> Successfully fetched the registry (0B) in 8.865024ms
> [18:03:58]W: [Step 10/10] I0425 18:03:58.610144 661 registrar.cpp:463]
> Applied 1 operations in 4077ns; attempting to update the 'registry'
> [18:03:58]W: [Step 10/10] I0425 18:03:58.610333 659 log.cpp:548]
> Attempting to append 210 bytes to the log
> [18:03:58]W: [Step 10/10] I0425 18:03:58.610385 656 coordinator.cpp:348]
> Coordinator attempting to write APPEND action at position 1
> [18:03:58]W: [Step 10/10] I0425 18:03:58.610631 663 replica.cpp:537]
> Replica received write request for position 1 from (17948)@172.30.2.229:48705
> [18:03:58]W: [Step 10/10] I0425 18:03:58.611784 663 leveldb.cpp:341]
> Persisting action (229 bytes) to leveldb took 1.132676ms
> [18:03:58]W: [Step 10/10] I0425 18:03:58.611799 663 replica.cpp:712]
> Persisted action at 1
> [18:03:58]W: [Step 10/10] I0425 18:03:58.612002 662 replica.cpp:691]
> Replica received learned notice for position 1 from @0.0.0.0:0
> [18:03:58]W: [Step 10/10] I0425 18:03:58.613100 662 leveldb.cpp:341]
> Persisting action (231 bytes) to leveldb took 1.077829ms
> [18:03:58]W: [Step 10/10] I0425 18:03:58.613114 662 replica.cpp:712]
> Persisted action at 1
> [18:03:58]W: [Step 10/10] I0425 18:03:58.613121 662 replica.cpp:697]
> Replica learned APPEND action at position 1
> [18:03:58]W: [Step 10/10] I0425 18:03:58.613335 659 registrar.cpp:508]
> Successfully updated the 'registry' in 3.173888ms
> [18:03:58]W: [Step 10/10] I0425 18:03:58.613402 657 log.cpp:567]
> Attempting to truncate the log to 1
> [18:03:58]W: [Step 10/10] I0425 18:03:58.613420 659 registrar.cpp:394]
> Successfully recovered registrar
> [18:03:58]W: [Step 10/10] I0425 18:03:58.613545 663 coordinator.cpp:348]
> Coordinator attempting to write TRUNCATE action at position 2
> [18:03:58]W: [Step 10/10] I0425 18:03:58.613566 656 master.cpp:1740]
> Recovered 0 agents from the Registry (171B) ; allowing 10mins for agents to
> re-register
> [18:03:58]W: [Step 10/10] I0425 18:03:58.613679 659 hierarchical.cpp:169]
> Skipping recovery of hierarchical allocator: nothing to recover
> [18:03:58]W: [Step 10/10] I0425 18:03:58.613807 660 replica.cpp:537]
> Replica received write request for position 2 from (17949)@172.30.2.229:48705
> [18:03:58]W: [Step 10/10] I0425 18:03:58.615124 660 leveldb.cpp:341]
> Persisting action (16 bytes) to leveldb took 1.299877ms
> [18:03:58]W: [Step 10/10] I0425 18:03:58.615140 660 replica.cpp:712]
> Persisted action at 2
> [18:03:58]W: [Step 10/10] I0425 18:03:58.615324 657 replica.cpp:691]
> Replica received learned notice for position 2 from @0.0.0.0:0
> [18:03:58]W: [Step 10/10] I0425 18:03:58.616408 657 leveldb.cpp:341]
> Persisting action (18 bytes) to leveldb took 1.067973ms
> [18:03:58]W: [Step 10/10] I0425 18:03:58.616437 657 leveldb.cpp:399]
> Deleting ~1 keys from leveldb took 14275ns
> [18:03:58]W: [Step 10/10] I0425 18:03:58.616446 657 replica.cpp:712]
> Persisted action at 2
> [18:03:58]W: [Step 10/10] I0425 18:03:58.616451 657 replica.cpp:697]
> Replica learned TRUNCATE action at position 2
> [18:03:59]W: [Step 10/10] I0425 18:03:59.601456 662
> hierarchical.cpp:1488] No resources available to allocate!
> [18:03:59]W: [Step 10/10] I0425 18:03:59.601508 662
> hierarchical.cpp:1139] Performed allocation for 0 agents in 90519ns
> [18:04:00]W: [Step 10/10] I0425 18:04:00.326802 642 linux.cpp:81] Making
> '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutor_nZJkSj'
> a shared mount
> [18:04:00]W: [Step 10/10] I0425 18:04:00.339643 642
> linux_launcher.cpp:101] Using /sys/fs/cgroup/freezer as the freezer hierarchy
> for the Linux launcher
> [18:04:00]W: [Step 10/10] I0425 18:04:00.340358 642 cluster.cpp:398]
> Creating default 'local' authorizer
> [18:04:00]W: [Step 10/10] I0425 18:04:00.340817 658 slave.cpp:204] Agent
> started on 458)@172.30.2.229:48705
> [18:04:00]W: [Step 10/10] I0425 18:04:00.340831 658 slave.cpp:205] Flags
> at startup: --acls="" --appc_simple_discovery_uri_prefix="http://";
> --appc_store_dir="/tmp/mesos/store/appc" --authenticate_http="true"
> --authenticatee="crammd5" --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="/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutor_nZJkSj/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_ChangeRootFilesystemCommandExecutor_nZJkSj/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="/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutor_nZJkSj/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_ChangeRootFilesystemCommandExecutor_nZJkSj"
> [18:04:00]W: [Step 10/10] I0425 18:04:00.341024 658 credentials.hpp:86]
> Loading credential for authentication from
> '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutor_nZJkSj/credential'
> [18:04:00]W: [Step 10/10] I0425 18:04:00.341190 658 slave.cpp:342] Agent
> using credential for: test-principal
> [18:04:00]W: [Step 10/10] I0425 18:04:00.341203 658 credentials.hpp:37]
> Loading credentials for authentication from
> '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutor_nZJkSj/http_credentials'
> [18:04:00]W: [Step 10/10] I0425 18:04:00.341292 658 slave.cpp:394] Using
> default 'basic' HTTP authenticator
> [18:04:00]W: [Step 10/10] I0425 18:04:00.341378 658 resources.cpp:572]
> Parsing resources as JSON failed:
> cpus:2;mem:1024;disk:1024;ports:[31000-32000]
> [18:04:00]W: [Step 10/10] Trying semicolon-delimited string format instead
> [18:04:00]W: [Step 10/10] I0425 18:04:00.341543 642 sched.cpp:224]
> Version: 0.29.0
> [18:04:00]W: [Step 10/10] I0425 18:04:00.341552 658 slave.cpp:593] Agent
> resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> [18:04:00]W: [Step 10/10] I0425 18:04:00.341583 658 slave.cpp:601] Agent
> attributes: [ ]
> [18:04:00]W: [Step 10/10] I0425 18:04:00.341591 658 slave.cpp:606] Agent
> hostname: ip-172-30-2-229.mesosphere.io
> [18:04:00]W: [Step 10/10] I0425 18:04:00.341683 660 sched.cpp:328] New
> master detected at master@172.30.2.229:48705
> [18:04:00]W: [Step 10/10] I0425 18:04:00.341712 660 sched.cpp:384]
> Authenticating with master master@172.30.2.229:48705
> [18:04:00]W: [Step 10/10] I0425 18:04:00.341722 660 sched.cpp:391] Using
> default CRAM-MD5 authenticatee
> [18:04:00]W: [Step 10/10] I0425 18:04:00.341886 661
> authenticatee.cpp:121] Creating new client SASL connection
> [18:04:00]W: [Step 10/10] I0425 18:04:00.341940 658 state.cpp:57]
> Recovering state from
> '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutor_nZJkSj/meta'
> [18:04:00]W: [Step 10/10] I0425 18:04:00.342118 658
> status_update_manager.cpp:200] Recovering status update manager
> [18:04:00]W: [Step 10/10] I0425 18:04:00.342120 662 master.cpp:5803]
> Authenticating
> scheduler-46c11828-a1c6-4ea0-8ec2-2ffb638437ba@172.30.2.229:48705
> [18:04:00]W: [Step 10/10] I0425 18:04:00.342188 661
> authenticator.cpp:413] Starting authentication session for
> crammd5_authenticatee(932)@172.30.2.229:48705
> [18:04:00]W: [Step 10/10] I0425 18:04:00.342308 660
> containerizer.cpp:444] Recovering containerizer
> [18:04:00]W: [Step 10/10] I0425 18:04:00.342308 657 authenticator.cpp:98]
> Creating new server SASL connection
> [18:04:00]W: [Step 10/10] I0425 18:04:00.342531 657
> authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
> [18:04:00]W: [Step 10/10] I0425 18:04:00.342551 657
> authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
> [18:04:00]W: [Step 10/10] I0425 18:04:00.342634 659
> authenticator.cpp:203] Received SASL authentication start
> [18:04:00]W: [Step 10/10] I0425 18:04:00.342669 659
> authenticator.cpp:325] Authentication requires more steps
> [18:04:00]W: [Step 10/10] I0425 18:04:00.342701 659
> authenticatee.cpp:258] Received SASL authentication step
> [18:04:00]W: [Step 10/10] I0425 18:04:00.342789 656
> authenticator.cpp:231] Received SASL authentication step
> [18:04:00]W: [Step 10/10] I0425 18:04:00.342808 656 auxprop.cpp:107]
> Request to lookup properties for user: 'test-principal' realm:
> 'ip-172-30-2-229.mesosphere.io' server FQDN: 'ip-172-30-2-229.mesosphere.io'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> [18:04:00]W: [Step 10/10] I0425 18:04:00.342814 656 auxprop.cpp:179]
> Looking up auxiliary property '*userPassword'
> [18:04:00]W: [Step 10/10] I0425 18:04:00.342825 656 auxprop.cpp:179]
> Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> [18:04:00]W: [Step 10/10] I0425 18:04:00.342833 656 auxprop.cpp:107]
> Request to lookup properties for user: 'test-principal' realm:
> 'ip-172-30-2-229.mesosphere.io' server FQDN: 'ip-172-30-2-229.mesosphere.io'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> [18:04:00]W: [Step 10/10] I0425 18:04:00.342836 656 auxprop.cpp:129]
> Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> [18:04:00]W: [Step 10/10] I0425 18:04:00.342840 656 auxprop.cpp:129]
> Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since
> SASL_AUXPROP_AUTHZID == true
> [18:04:00]W: [Step 10/10] I0425 18:04:00.342849 656
> authenticator.cpp:317] Authentication success
> [18:04:00]W: [Step 10/10] I0425 18:04:00.342896 659
> authenticator.cpp:431] Authentication session cleanup for
> crammd5_authenticatee(932)@172.30.2.229:48705
> [18:04:00]W: [Step 10/10] I0425 18:04:00.342897 662
> authenticatee.cpp:298] Authentication success
> [18:04:00]W: [Step 10/10] I0425 18:04:00.342916 656 master.cpp:5833]
> Successfully authenticated principal 'test-principal' at
> scheduler-46c11828-a1c6-4ea0-8ec2-2ffb638437ba@172.30.2.229:48705
> [18:04:00]W: [Step 10/10] I0425 18:04:00.343030 663 sched.cpp:474]
> Successfully authenticated with master master@172.30.2.229:48705
> [18:04:00]W: [Step 10/10] I0425 18:04:00.343044 663 sched.cpp:783]
> Sending SUBSCRIBE call to master@172.30.2.229:48705
> [18:04:00]W: [Step 10/10] I0425 18:04:00.343091 663 sched.cpp:816] Will
> retry registration in 485.223658ms if necessary
> [18:04:00]W: [Step 10/10] I0425 18:04:00.343134 656 master.cpp:2465]
> Received SUBSCRIBE call for framework 'default' at
> scheduler-46c11828-a1c6-4ea0-8ec2-2ffb638437ba@172.30.2.229:48705
> [18:04:00]W: [Step 10/10] I0425 18:04:00.343152 656 master.cpp:1971]
> Authorizing framework principal 'test-principal' to receive offers for role
> '*'
> [18:04:00]W: [Step 10/10] I0425 18:04:00.343235 656 master.cpp:2541]
> Subscribing framework default with checkpointing disabled and capabilities [
> ]
> [18:04:00]W: [Step 10/10] I0425 18:04:00.343372 657 hierarchical.cpp:264]
> Added framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
> [18:04:00]W: [Step 10/10] I0425 18:04:00.343391 657
> hierarchical.cpp:1488] No resources available to allocate!
> [18:04:00]W: [Step 10/10] I0425 18:04:00.343400 657
> hierarchical.cpp:1583] No inverse offers to send out!
> [18:04:00]W: [Step 10/10] I0425 18:04:00.343417 657
> hierarchical.cpp:1139] Performed allocation for 0 agents in 32147ns
> [18:04:00]W: [Step 10/10] I0425 18:04:00.343487 656 sched.cpp:710]
> Framework registered with 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
> [18:04:00]W: [Step 10/10] I0425 18:04:00.343518 656 sched.cpp:724]
> Scheduler::registered took 20476ns
> [18:04:00]W: [Step 10/10] I0425 18:04:00.344192 659 provisioner.cpp:245]
> Provisioner recovery complete
> [18:04:00]W: [Step 10/10] I0425 18:04:00.344338 663 slave.cpp:4826]
> Finished recovery
> [18:04:00]W: [Step 10/10] I0425 18:04:00.344614 663 slave.cpp:4998]
> Querying resource estimator for oversubscribable resources
> [18:04:00]W: [Step 10/10] I0425 18:04:00.344729 659 slave.cpp:953] New
> master detected at master@172.30.2.229:48705
> [18:04:00]W: [Step 10/10] I0425 18:04:00.344738 662
> status_update_manager.cpp:174] Pausing sending status updates
> [18:04:00]W: [Step 10/10] I0425 18:04:00.344745 659 slave.cpp:1016]
> Authenticating with master master@172.30.2.229:48705
> [18:04:00]W: [Step 10/10] I0425 18:04:00.344753 659 slave.cpp:1021] Using
> default CRAM-MD5 authenticatee
> [18:04:00]W: [Step 10/10] I0425 18:04:00.344786 659 slave.cpp:989]
> Detecting new master
> [18:04:00]W: [Step 10/10] I0425 18:04:00.344811 656
> authenticatee.cpp:121] Creating new client SASL connection
> [18:04:00]W: [Step 10/10] I0425 18:04:00.344854 659 slave.cpp:5012]
> Received oversubscribable resources from the resource estimator
> [18:04:00]W: [Step 10/10] I0425 18:04:00.344982 656 master.cpp:5803]
> Authenticating slave(458)@172.30.2.229:48705
> [18:04:00]W: [Step 10/10] I0425 18:04:00.345024 656
> authenticator.cpp:413] Starting authentication session for
> crammd5_authenticatee(933)@172.30.2.229:48705
> [18:04:00]W: [Step 10/10] I0425 18:04:00.345121 660 authenticator.cpp:98]
> Creating new server SASL connection
> [18:04:00]W: [Step 10/10] I0425 18:04:00.345310 660
> authenticatee.cpp:212] Received SASL authentication mechanisms: CRAM-MD5
> [18:04:00]W: [Step 10/10] I0425 18:04:00.345327 660
> authenticatee.cpp:238] Attempting to authenticate with mechanism 'CRAM-MD5'
> [18:04:00]W: [Step 10/10] I0425 18:04:00.345374 660
> authenticator.cpp:203] Received SASL authentication start
> [18:04:00]W: [Step 10/10] I0425 18:04:00.345408 660
> authenticator.cpp:325] Authentication requires more steps
> [18:04:00]W: [Step 10/10] I0425 18:04:00.345450 660
> authenticatee.cpp:258] Received SASL authentication step
> [18:04:00]W: [Step 10/10] I0425 18:04:00.345540 658
> authenticator.cpp:231] Received SASL authentication step
> [18:04:00]W: [Step 10/10] I0425 18:04:00.345553 658 auxprop.cpp:107]
> Request to lookup properties for user: 'test-principal' realm:
> 'ip-172-30-2-229.mesosphere.io' server FQDN: 'ip-172-30-2-229.mesosphere.io'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> [18:04:00]W: [Step 10/10] I0425 18:04:00.345558 658 auxprop.cpp:179]
> Looking up auxiliary property '*userPassword'
> [18:04:00]W: [Step 10/10] I0425 18:04:00.345566 658 auxprop.cpp:179]
> Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
> [18:04:00]W: [Step 10/10] I0425 18:04:00.345571 658 auxprop.cpp:107]
> Request to lookup properties for user: 'test-principal' realm:
> 'ip-172-30-2-229.mesosphere.io' server FQDN: 'ip-172-30-2-229.mesosphere.io'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> [18:04:00]W: [Step 10/10] I0425 18:04:00.345576 658 auxprop.cpp:129]
> Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
> [18:04:00]W: [Step 10/10] I0425 18:04:00.345578 658 auxprop.cpp:129]
> Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since
> SASL_AUXPROP_AUTHZID == true
> [18:04:00]W: [Step 10/10] I0425 18:04:00.345585 658
> authenticator.cpp:317] Authentication success
> [18:04:00]W: [Step 10/10] I0425 18:04:00.345640 659 master.cpp:5833]
> Successfully authenticated principal 'test-principal' at
> slave(458)@172.30.2.229:48705
> [18:04:00]W: [Step 10/10] I0425 18:04:00.345652 657
> authenticator.cpp:431] Authentication session cleanup for
> crammd5_authenticatee(933)@172.30.2.229:48705
> [18:04:00]W: [Step 10/10] I0425 18:04:00.345666 661
> authenticatee.cpp:298] Authentication success
> [18:04:00]W: [Step 10/10] I0425 18:04:00.345746 661 slave.cpp:1086]
> Successfully authenticated with master master@172.30.2.229:48705
> [18:04:00]W: [Step 10/10] I0425 18:04:00.345789 661 slave.cpp:1482] Will
> retry registration in 19.872252ms if necessary
> [18:04:00]W: [Step 10/10] I0425 18:04:00.345850 659 master.cpp:4514]
> Registering agent at slave(458)@172.30.2.229:48705
> (ip-172-30-2-229.mesosphere.io) with id
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0
> [18:04:00]W: [Step 10/10] I0425 18:04:00.345944 657 registrar.cpp:463]
> Applied 1 operations in 15436ns; attempting to update the 'registry'
> [18:04:00]W: [Step 10/10] I0425 18:04:00.346144 659 log.cpp:548]
> Attempting to append 396 bytes to the log
> [18:04:00]W: [Step 10/10] I0425 18:04:00.346197 658 coordinator.cpp:348]
> Coordinator attempting to write APPEND action at position 3
> [18:04:00]W: [Step 10/10] I0425 18:04:00.346508 658 replica.cpp:537]
> Replica received write request for position 3 from (17965)@172.30.2.229:48705
> [18:04:00]W: [Step 10/10] I0425 18:04:00.347267 658 leveldb.cpp:341]
> Persisting action (415 bytes) to leveldb took 736349ns
> [18:04:00]W: [Step 10/10] I0425 18:04:00.347286 658 replica.cpp:712]
> Persisted action at 3
> [18:04:00]W: [Step 10/10] I0425 18:04:00.347520 659 replica.cpp:691]
> Replica received learned notice for position 3 from @0.0.0.0:0
> [18:04:00]W: [Step 10/10] I0425 18:04:00.348105 659 leveldb.cpp:341]
> Persisting action (417 bytes) to leveldb took 565502ns
> [18:04:00]W: [Step 10/10] I0425 18:04:00.348116 659 replica.cpp:712]
> Persisted action at 3
> [18:04:00]W: [Step 10/10] I0425 18:04:00.348121 659 replica.cpp:697]
> Replica learned APPEND action at position 3
> [18:04:00]W: [Step 10/10] I0425 18:04:00.348390 658 registrar.cpp:508]
> Successfully updated the 'registry' in 2.422784ms
> [18:04:00]W: [Step 10/10] I0425 18:04:00.348438 663 log.cpp:567]
> Attempting to truncate the log to 3
> [18:04:00]W: [Step 10/10] I0425 18:04:00.348547 656 coordinator.cpp:348]
> Coordinator attempting to write TRUNCATE action at position 4
> [18:04:00]W: [Step 10/10] I0425 18:04:00.348604 659 master.cpp:4582]
> Registered agent 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0 at
> slave(458)@172.30.2.229:48705 (ip-172-30-2-229.mesosphere.io) with cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000]
> [18:04:00]W: [Step 10/10] I0425 18:04:00.348654 656 slave.cpp:3701]
> Received ping from slave-observer(423)@172.30.2.229:48705
> [18:04:00]W: [Step 10/10] I0425 18:04:00.348670 660 hierarchical.cpp:473]
> Added agent 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0
> (ip-172-30-2-229.mesosphere.io) with cpus(*):2; mem(*):1024; disk(*):1024;
> ports(*):[31000-32000] (allocated: )
> [18:04:00]W: [Step 10/10] I0425 18:04:00.348711 656 slave.cpp:1130]
> Registered with master master@172.30.2.229:48705; given agent ID
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0
> [18:04:00]W: [Step 10/10] I0425 18:04:00.348726 656 fetcher.cpp:81]
> Clearing fetcher cache
> [18:04:00]W: [Step 10/10] I0425 18:04:00.348769 659 replica.cpp:537]
> Replica received write request for position 4 from (17966)@172.30.2.229:48705
> [18:04:00]W: [Step 10/10] I0425 18:04:00.348834 660
> hierarchical.cpp:1583] No inverse offers to send out!
> [18:04:00]W: [Step 10/10] I0425 18:04:00.348858 660
> hierarchical.cpp:1162] Performed allocation for agent
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0 in 160800ns
> [18:04:00]W: [Step 10/10] I0425 18:04:00.348888 660
> status_update_manager.cpp:181] Resuming sending status updates
> [18:04:00]W: [Step 10/10] I0425 18:04:00.348994 660 master.cpp:5632]
> Sending 1 offers to framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
> (default) at scheduler-46c11828-a1c6-4ea0-8ec2-2ffb638437ba@172.30.2.229:48705
> [18:04:00]W: [Step 10/10] I0425 18:04:00.348999 656 slave.cpp:1153]
> Checkpointing SlaveInfo to
> '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutor_nZJkSj/meta/slaves/7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0/slave.info'
> [18:04:00]W: [Step 10/10] I0425 18:04:00.349146 660 sched.cpp:880]
> Scheduler::resourceOffers took 40293ns
> [18:04:00]W: [Step 10/10] I0425 18:04:00.349184 656 slave.cpp:1190]
> Forwarding total oversubscribed resources
> [18:04:00]W: [Step 10/10] I0425 18:04:00.349258 656 master.cpp:4926]
> Received update of agent 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0 at
> slave(458)@172.30.2.229:48705 (ip-172-30-2-229.mesosphere.io) with total
> oversubscribed resources
> [18:04:00]W: [Step 10/10] I0425 18:04:00.349381 656 hierarchical.cpp:531]
> Agent 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0 (ip-172-30-2-229.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])
> [18:04:00]W: [Step 10/10] I0425 18:04:00.349417 659 leveldb.cpp:341]
> Persisting action (16 bytes) to leveldb took 632584ns
> [18:04:00]W: [Step 10/10] I0425 18:04:00.349428 659 replica.cpp:712]
> Persisted action at 4
> [18:04:00]W: [Step 10/10] I0425 18:04:00.349427 656
> hierarchical.cpp:1488] No resources available to allocate!
> [18:04:00]W: [Step 10/10] I0425 18:04:00.349441 656
> hierarchical.cpp:1583] No inverse offers to send out!
> [18:04:00]W: [Step 10/10] I0425 18:04:00.349454 656
> hierarchical.cpp:1162] Performed allocation for agent
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0 in 44061ns
> [18:04:00]W: [Step 10/10] I0425 18:04:00.349580 660 master.cpp:3412]
> Processing ACCEPT call for offers: [ 7e239aa6-d964-4f11-95a8-ba808ad23f4e-O0
> ] on agent 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0 at
> slave(458)@172.30.2.229:48705 (ip-172-30-2-229.mesosphere.io) for framework
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 (default) at
> scheduler-46c11828-a1c6-4ea0-8ec2-2ffb638437ba@172.30.2.229:48705
> [18:04:00]W: [Step 10/10] I0425 18:04:00.349602 660 master.cpp:3015]
> Authorizing framework principal 'test-principal' to launch task
> 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 as user 'root'
> [18:04:00]W: [Step 10/10] I0425 18:04:00.349720 661 replica.cpp:691]
> Replica received learned notice for position 4 from @0.0.0.0:0
> [18:04:00]W: [Step 10/10] I0425 18:04:00.350009 659 master.hpp:177]
> Adding task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 with resources cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] on agent
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0 (ip-172-30-2-229.mesosphere.io)
> [18:04:00]W: [Step 10/10] I0425 18:04:00.350044 659 master.cpp:3897]
> Launching task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 (default) at
> scheduler-46c11828-a1c6-4ea0-8ec2-2ffb638437ba@172.30.2.229:48705 with
> resources cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on
> agent 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0 at
> slave(458)@172.30.2.229:48705 (ip-172-30-2-229.mesosphere.io)
> [18:04:00]W: [Step 10/10] I0425 18:04:00.350181 658 slave.cpp:1522] Got
> assigned task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 for framework
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
> [18:04:00]W: [Step 10/10] I0425 18:04:00.350261 658 resources.cpp:572]
> Parsing resources as JSON failed: cpus:0.1;mem:32
> [18:04:00]W: [Step 10/10] Trying semicolon-delimited string format instead
> [18:04:00]W: [Step 10/10] I0425 18:04:00.350317 661 leveldb.cpp:341]
> Persisting action (18 bytes) to leveldb took 575979ns
> [18:04:00]W: [Step 10/10] I0425 18:04:00.350348 661 leveldb.cpp:399]
> Deleting ~2 keys from leveldb took 16773ns
> [18:04:00]W: [Step 10/10] I0425 18:04:00.350361 661 replica.cpp:712]
> Persisted action at 4
> [18:04:00]W: [Step 10/10] I0425 18:04:00.350369 661 replica.cpp:697]
> Replica learned TRUNCATE action at position 4
> [18:04:00]W: [Step 10/10] I0425 18:04:00.350391 658 slave.cpp:1641]
> Launching task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 for framework
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
> [18:04:00]W: [Step 10/10] I0425 18:04:00.350428 658 resources.cpp:572]
> Parsing resources as JSON failed: cpus:0.1;mem:32
> [18:04:00]W: [Step 10/10] Trying semicolon-delimited string format instead
> [18:04:00]W: [Step 10/10] I0425 18:04:00.350800 658 paths.cpp:528] Trying
> to chown
> '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutor_nZJkSj/slaves/7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0/frameworks/7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000/executors/52bf3e3e-f9e2-417c-a66d-24c5f8ec2898/runs/57198894-8507-4f3e-8c9b-428c1cdeb9bb'
> to user 'root'
> [18:04:00]W: [Step 10/10] I0425 18:04:00.355469 658 slave.cpp:5646]
> Launching executor 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 with resources cpus(*):0.1;
> mem(*):32 in work directory
> '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutor_nZJkSj/slaves/7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0/frameworks/7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000/executors/52bf3e3e-f9e2-417c-a66d-24c5f8ec2898/runs/57198894-8507-4f3e-8c9b-428c1cdeb9bb'
> [18:04:00]W: [Step 10/10] I0425 18:04:00.355728 658 slave.cpp:1867]
> Queuing task '52bf3e3e-f9e2-417c-a66d-24c5f8ec2898' for executor
> '52bf3e3e-f9e2-417c-a66d-24c5f8ec2898' of framework
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
> [18:04:00]W: [Step 10/10] I0425 18:04:00.355738 662
> containerizer.cpp:703] Starting container
> '57198894-8507-4f3e-8c9b-428c1cdeb9bb' for executor
> '52bf3e3e-f9e2-417c-a66d-24c5f8ec2898' of framework
> '7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000'
> [18:04:00]W: [Step 10/10] I0425 18:04:00.355782 658 slave.cpp:906]
> Successfully attached file
> '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutor_nZJkSj/slaves/7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0/frameworks/7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000/executors/52bf3e3e-f9e2-417c-a66d-24c5f8ec2898/runs/57198894-8507-4f3e-8c9b-428c1cdeb9bb'
> [18:04:00]W: [Step 10/10] I0425 18:04:00.356014 661 provisioner.cpp:285]
> Provisioning image rootfs
> '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutor_nZJkSj/provisioner/containers/57198894-8507-4f3e-8c9b-428c1cdeb9bb/backends/copy/rootfses/264fec60-6476-4aab-94af-d459a15c2448'
> for container 57198894-8507-4f3e-8c9b-428c1cdeb9bb
> [18:04:00]W: [Step 10/10] I0425 18:04:00.356412 657 copy.cpp:128] Copying
> layer path '/tmp/XRr1Iz/test_image' to rootfs
> '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutor_nZJkSj/provisioner/containers/57198894-8507-4f3e-8c9b-428c1cdeb9bb/backends/copy/rootfses/264fec60-6476-4aab-94af-d459a15c2448'
> [18:04:00]W: [Step 10/10] I0425 18:04:00.602272 656
> hierarchical.cpp:1488] No resources available to allocate!
> [18:04:00]W: [Step 10/10] I0425 18:04:00.602299 656
> hierarchical.cpp:1583] No inverse offers to send out!
> [18:04:00]W: [Step 10/10] I0425 18:04:00.602319 656
> hierarchical.cpp:1139] Performed allocation for 1 agents in 123386ns
> [18:04:01]W: [Step 10/10] I0425 18:04:01.603039 659
> hierarchical.cpp:1488] No resources available to allocate!
> [18:04:01]W: [Step 10/10] I0425 18:04:01.603067 659
> hierarchical.cpp:1583] No inverse offers to send out!
> [18:04:01]W: [Step 10/10] I0425 18:04:01.603086 659
> hierarchical.cpp:1139] Performed allocation for 1 agents in 138139ns
> [18:04:02]W: [Step 10/10] I0425 18:04:02.603773 657
> hierarchical.cpp:1488] No resources available to allocate!
> [18:04:02]W: [Step 10/10] I0425 18:04:02.603811 657
> hierarchical.cpp:1583] No inverse offers to send out!
> [18:04:02]W: [Step 10/10] I0425 18:04:02.603828 657
> hierarchical.cpp:1139] Performed allocation for 1 agents in 113145ns
> [18:04:03]W: [Step 10/10] I0425 18:04:03.604910 660
> hierarchical.cpp:1488] No resources available to allocate!
> [18:04:03]W: [Step 10/10] I0425 18:04:03.604938 660
> hierarchical.cpp:1583] No inverse offers to send out!
> [18:04:03]W: [Step 10/10] I0425 18:04:03.604954 660
> hierarchical.cpp:1139] Performed allocation for 1 agents in 126355ns
> [18:04:04]W: [Step 10/10] I0425 18:04:04.346846 661
> linux_launcher.cpp:281] Cloning child process with flags = CLONE_NEWNS
> [18:04:04]W: [Step 10/10] +
> /mnt/teamcity/work/4240ba9ddd0997c3/build/src/mesos-containerizer mount
> --help=false --operation=make-rslave --path=/
> [18:04:04]W: [Step 10/10] + grep -E
> /mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutor_nZJkSj/.+
> /proc/self/mountinfo
> [18:04:04]W: [Step 10/10] + grep -v 57198894-8507-4f3e-8c9b-428c1cdeb9bb
> [18:04:04]W: [Step 10/10] + cut '-d ' -f5
> [18:04:04]W: [Step 10/10] + xargs --no-run-if-empty umount -l
> [18:04:04]W: [Step 10/10] + mount -n --rbind
> /mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutor_nZJkSj/provisioner/containers/57198894-8507-4f3e-8c9b-428c1cdeb9bb/backends/copy/rootfses/264fec60-6476-4aab-94af-d459a15c2448
>
> /mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutor_nZJkSj/slaves/7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0/frameworks/7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000/executors/52bf3e3e-f9e2-417c-a66d-24c5f8ec2898/runs/57198894-8507-4f3e-8c9b-428c1cdeb9bb/.rootfs
> [18:04:04]W: [Step 10/10] WARNING: Logging before InitGoogleLogging() is
> written to STDERR
> [18:04:04]W: [Step 10/10] I0425 18:04:04.457139 15601 process.cpp:991]
> libprocess is initialized on 172.30.2.229:48674 with 8 worker threads
> [18:04:04]W: [Step 10/10] I0425 18:04:04.457484 15601 logging.cpp:195]
> Logging to STDERR
> [18:04:04]W: [Step 10/10] I0425 18:04:04.458220 15601 exec.cpp:150]
> Version: 0.29.0
> [18:04:04]W: [Step 10/10] I0425 18:04:04.459712 15648 exec.cpp:200]
> Executor started at: executor(1)@172.30.2.229:48674 with pid 15601
> [18:04:04]W: [Step 10/10] I0425 18:04:04.460300 656 slave.cpp:2862] Got
> registration for executor '52bf3e3e-f9e2-417c-a66d-24c5f8ec2898' of framework
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 from executor(1)@172.30.2.229:48674
> [18:04:04]W: [Step 10/10] I0425 18:04:04.460985 660 slave.cpp:2032]
> Sending queued task '52bf3e3e-f9e2-417c-a66d-24c5f8ec2898' to executor
> '52bf3e3e-f9e2-417c-a66d-24c5f8ec2898' of framework
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 at executor(1)@172.30.2.229:48674
> [18:04:04]W: [Step 10/10] I0425 18:04:04.461005 15647 exec.cpp:225]
> Executor registered on agent 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0
> [18:04:04]W: [Step 10/10] I0425 18:04:04.461822 15647 exec.cpp:237]
> Executor::registered took 101939ns
> [18:04:04]W: [Step 10/10] I0425 18:04:04.462000 15647 exec.cpp:312]
> Executor asked to run task '52bf3e3e-f9e2-417c-a66d-24c5f8ec2898'
> [18:04:04]W: [Step 10/10] I0425 18:04:04.462044 15647 exec.cpp:321]
> Executor::launchTask took 30183ns
> [18:04:04] : [Step 10/10] Registered executor on
> ip-172-30-2-229.mesosphere.io
> [18:04:04] : [Step 10/10] Starting task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898
> [18:04:04]W: [Step 10/10] I0425 18:04:04.463605 15647 exec.cpp:535]
> Executor sending status update TASK_RUNNING (UUID:
> b38791ab-d91d-4906-9a86-af476b83924e) for task
> 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
> [18:04:04] : [Step 10/10] Forked command at 15656
> [18:04:04]W: [Step 10/10] I0425 18:04:04.464066 656 slave.cpp:3221]
> Handling status update TASK_RUNNING (UUID:
> b38791ab-d91d-4906-9a86-af476b83924e) for task
> 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 from executor(1)@172.30.2.229:48674
> [18:04:04]W: [Step 10/10] I0425 18:04:04.464565 658
> status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID:
> b38791ab-d91d-4906-9a86-af476b83924e) for task
> 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
> [18:04:04] : [Step 10/10] sh -c 'test -d /mnt/mesos/sandbox'
> [18:04:04]W: [Step 10/10] I0425 18:04:04.464589 658
> status_update_manager.cpp:497] Creating StatusUpdate stream for task
> 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
> [18:04:04]W: [Step 10/10] I0425 18:04:04.464783 658
> status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID:
> b38791ab-d91d-4906-9a86-af476b83924e) for task
> 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 to the agent
> [18:04:04]W: [Step 10/10] I0425 18:04:04.464893 661 slave.cpp:3619]
> Forwarding the update TASK_RUNNING (UUID:
> b38791ab-d91d-4906-9a86-af476b83924e) for task
> 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 to master@172.30.2.229:48705
> [18:04:04]W: [Step 10/10] I0425 18:04:04.464998 661 slave.cpp:3513]
> Status update manager successfully handled status update TASK_RUNNING (UUID:
> b38791ab-d91d-4906-9a86-af476b83924e) for task
> 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
> [18:04:04]W: [Step 10/10] I0425 18:04:04.465014 661 slave.cpp:3529]
> Sending acknowledgement for status update TASK_RUNNING (UUID:
> b38791ab-d91d-4906-9a86-af476b83924e) for task
> 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 to executor(1)@172.30.2.229:48674
> [18:04:04]W: [Step 10/10] I0425 18:04:04.465016 658 master.cpp:5071]
> Status update TASK_RUNNING (UUID: b38791ab-d91d-4906-9a86-af476b83924e) for
> task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 from agent
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0 at slave(458)@172.30.2.229:48705
> (ip-172-30-2-229.mesosphere.io)
> [18:04:04]W: [Step 10/10] I0425 18:04:04.465035 658 master.cpp:5119]
> Forwarding status update TASK_RUNNING (UUID:
> b38791ab-d91d-4906-9a86-af476b83924e) for task
> 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
> [18:04:04]W: [Step 10/10] I0425 18:04:04.465086 658 master.cpp:6727]
> Updating the state of task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 (latest state: TASK_RUNNING, status
> update state: TASK_RUNNING)
> [18:04:04]W: [Step 10/10] I0425 18:04:04.465193 661 sched.cpp:988]
> Scheduler::statusUpdate took 56656ns
> [18:04:04]W: [Step 10/10] I0425 18:04:04.465309 657 master.cpp:4226]
> Processing ACKNOWLEDGE call b38791ab-d91d-4906-9a86-af476b83924e for task
> 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 (default) at
> scheduler-46c11828-a1c6-4ea0-8ec2-2ffb638437ba@172.30.2.229:48705 on agent
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0
> [18:04:04]W: [Step 10/10] I0425 18:04:04.465338 15652 exec.cpp:358]
> Executor received status update acknowledgement
> b38791ab-d91d-4906-9a86-af476b83924e for task
> 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
> [18:04:04]W: [Step 10/10] I0425 18:04:04.465440 657
> status_update_manager.cpp:392] Received status update acknowledgement (UUID:
> b38791ab-d91d-4906-9a86-af476b83924e) for task
> 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
> [18:04:04]W: [Step 10/10] I0425 18:04:04.465507 658 slave.cpp:2631]
> Status update manager successfully handled status update acknowledgement
> (UUID: b38791ab-d91d-4906-9a86-af476b83924e) for task
> 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
> [18:04:04] : [Step 10/10] Command exited with status 0 (pid: 15656)
> [18:04:04]W: [Step 10/10] I0425 18:04:04.565306 15648 exec.cpp:535]
> Executor sending status update TASK_FINISHED (UUID:
> 244979d6-35e7-4a28-875e-31c5289240d3) for task
> 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
> [18:04:04]W: [Step 10/10] I0425 18:04:04.565690 657 slave.cpp:3221]
> Handling status update TASK_FINISHED (UUID:
> 244979d6-35e7-4a28-875e-31c5289240d3) for task
> 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 from executor(1)@172.30.2.229:48674
> [18:04:04]W: [Step 10/10] I0425 18:04:04.566062 662 slave.cpp:5966]
> Terminating task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898
> [18:04:04]W: [Step 10/10] I0425 18:04:04.566371 662
> status_update_manager.cpp:320] Received status update TASK_FINISHED (UUID:
> 244979d6-35e7-4a28-875e-31c5289240d3) for task
> 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
> [18:04:04]W: [Step 10/10] I0425 18:04:04.566422 662
> status_update_manager.cpp:374] Forwarding update TASK_FINISHED (UUID:
> 244979d6-35e7-4a28-875e-31c5289240d3) for task
> 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 to the agent
> [18:04:04]W: [Step 10/10] I0425 18:04:04.566495 660 slave.cpp:3619]
> Forwarding the update TASK_FINISHED (UUID:
> 244979d6-35e7-4a28-875e-31c5289240d3) for task
> 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 to master@172.30.2.229:48705
> [18:04:04]W: [Step 10/10] I0425 18:04:04.566575 660 slave.cpp:3513]
> Status update manager successfully handled status update TASK_FINISHED (UUID:
> 244979d6-35e7-4a28-875e-31c5289240d3) for task
> 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
> [18:04:04]W: [Step 10/10] I0425 18:04:04.566589 660 slave.cpp:3529]
> Sending acknowledgement for status update TASK_FINISHED (UUID:
> 244979d6-35e7-4a28-875e-31c5289240d3) for task
> 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 to executor(1)@172.30.2.229:48674
> [18:04:04]W: [Step 10/10] I0425 18:04:04.566658 659 master.cpp:5071]
> Status update TASK_FINISHED (UUID: 244979d6-35e7-4a28-875e-31c5289240d3) for
> task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 from agent
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0 at slave(458)@172.30.2.229:48705
> (ip-172-30-2-229.mesosphere.io)
> [18:04:04]W: [Step 10/10] I0425 18:04:04.566684 659 master.cpp:5119]
> Forwarding status update TASK_FINISHED (UUID:
> 244979d6-35e7-4a28-875e-31c5289240d3) for task
> 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
> [18:04:04]W: [Step 10/10] I0425 18:04:04.566733 659 master.cpp:6727]
> Updating the state of task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 (latest state: TASK_FINISHED,
> status update state: TASK_FINISHED)
> [18:04:04]W: [Step 10/10] I0425 18:04:04.566829 15650 exec.cpp:358]
> Executor received status update acknowledgement
> 244979d6-35e7-4a28-875e-31c5289240d3 for task
> 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
> [18:04:04]W: [Step 10/10] I0425 18:04:04.566850 661 sched.cpp:988]
> Scheduler::statusUpdate took 41212ns
> [18:04:04]W: [Step 10/10] I0425 18:04:04.566905 662 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 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0 from framework
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
> [18:04:04]W: [Step 10/10] I0425 18:04:04.566972 661 master.cpp:4226]
> Processing ACKNOWLEDGE call 244979d6-35e7-4a28-875e-31c5289240d3 for task
> 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 (default) at
> scheduler-46c11828-a1c6-4ea0-8ec2-2ffb638437ba@172.30.2.229:48705 on agent
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0
> [18:04:04]W: [Step 10/10] I0425 18:04:04.566990 661 master.cpp:6793]
> Removing task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 with resources cpus(*):2;
> mem(*):1024; disk(*):1024; ports(*):[31000-32000] of framework
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 on agent
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0 at slave(458)@172.30.2.229:48705
> (ip-172-30-2-229.mesosphere.io)
> [18:04:04]W: [Step 10/10] I0425 18:04:04.567018 642 sched.cpp:1911] Asked
> to stop the driver
> [18:04:04]W: [Step 10/10] I0425 18:04:04.567078 659 sched.cpp:1150]
> Stopping framework '7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000'
> [18:04:04]W: [Step 10/10] I0425 18:04:04.567165 661 master.cpp:6200]
> Processing TEARDOWN call for framework
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 (default) at
> scheduler-46c11828-a1c6-4ea0-8ec2-2ffb638437ba@172.30.2.229:48705
> [18:04:04]W: [Step 10/10] I0425 18:04:04.567178 661 master.cpp:6212]
> Removing framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 (default) at
> scheduler-46c11828-a1c6-4ea0-8ec2-2ffb638437ba@172.30.2.229:48705
> [18:04:04]W: [Step 10/10] I0425 18:04:04.567196 663
> status_update_manager.cpp:392] Received status update acknowledgement (UUID:
> 244979d6-35e7-4a28-875e-31c5289240d3) for task
> 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
> [18:04:04]W: [Step 10/10] I0425 18:04:04.567248 663
> status_update_manager.cpp:528] Cleaning up status update stream for task
> 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
> [18:04:04]W: [Step 10/10] I0425 18:04:04.567271 656 slave.cpp:2252] Asked
> to shut down framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 by
> master@172.30.2.229:48705
> [18:04:04]W: [Step 10/10] I0425 18:04:04.567288 656 slave.cpp:2277]
> Shutting down framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
> [18:04:04]W: [Step 10/10] I0425 18:04:04.567302 656 slave.cpp:4451]
> Shutting down executor '52bf3e3e-f9e2-417c-a66d-24c5f8ec2898' of framework
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 at executor(1)@172.30.2.229:48674
> [18:04:04]W: [Step 10/10] I0425 18:04:04.567414 656 slave.cpp:2631]
> Status update manager successfully handled status update acknowledgement
> (UUID: 244979d6-35e7-4a28-875e-31c5289240d3) for task
> 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898 of framework
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
> [18:04:04]W: [Step 10/10] I0425 18:04:04.567435 656 slave.cpp:6007]
> Completing task 52bf3e3e-f9e2-417c-a66d-24c5f8ec2898
> [18:04:04]W: [Step 10/10] I0425 18:04:04.567548 657 hierarchical.cpp:375]
> Deactivated framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
> [18:04:04]W: [Step 10/10] I0425 18:04:04.567594 15647 exec.cpp:399]
> Executor asked to shutdown
> [18:04:04]W: [Step 10/10] I0425 18:04:04.567625 657 hierarchical.cpp:326]
> Removed framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000
> [18:04:04]W: [Step 10/10] I0425 18:04:04.567633 15647 exec.cpp:414]
> Executor::shutdown took 4162ns
> [18:04:04]W: [Step 10/10] I0425 18:04:04.567662 15647 exec.cpp:91]
> Scheduling shutdown of the executor in 5secs
> [18:04:04]W: [Step 10/10] I0425 18:04:04.567800 661
> containerizer.cpp:1481] Destroying container
> '57198894-8507-4f3e-8c9b-428c1cdeb9bb'
> [18:04:04]W: [Step 10/10] I0425 18:04:04.569454 657 cgroups.cpp:2676]
> Freezing cgroup
> /sys/fs/cgroup/freezer/mesos/57198894-8507-4f3e-8c9b-428c1cdeb9bb
> [18:04:04]W: [Step 10/10] I0425 18:04:04.570904 661 cgroups.cpp:1409]
> Successfully froze cgroup
> /sys/fs/cgroup/freezer/mesos/57198894-8507-4f3e-8c9b-428c1cdeb9bb after
> 1.430016ms
> [18:04:04]W: [Step 10/10] I0425 18:04:04.572533 663 cgroups.cpp:2694]
> Thawing cgroup
> /sys/fs/cgroup/freezer/mesos/57198894-8507-4f3e-8c9b-428c1cdeb9bb
> [18:04:04]W: [Step 10/10] I0425 18:04:04.574110 657 cgroups.cpp:1438]
> Successfully thawed cgroup
> /sys/fs/cgroup/freezer/mesos/57198894-8507-4f3e-8c9b-428c1cdeb9bb after
> 1.55776ms
> [18:04:04]W: [Step 10/10] I0425 18:04:04.575166 661 slave.cpp:3747]
> executor(1)@172.30.2.229:48674 exited
> [18:04:04]W: [Step 10/10] I0425 18:04:04.605558 661
> hierarchical.cpp:1488] No resources available to allocate!
> [18:04:04]W: [Step 10/10] I0425 18:04:04.605597 661
> hierarchical.cpp:1139] Performed allocation for 1 agents in 82646ns
> [18:04:04]W: [Step 10/10] I0425 18:04:04.646847 661
> containerizer.cpp:1717] Executor for container
> '57198894-8507-4f3e-8c9b-428c1cdeb9bb' has exited
> [18:04:04]W: [Step 10/10] I0425 18:04:04.648252 663 linux.cpp:822]
> Ignoring unmounting sandbox/work directory for container
> 57198894-8507-4f3e-8c9b-428c1cdeb9bb
> [18:04:04]W: [Step 10/10] I0425 18:04:04.648402 657 provisioner.cpp:338]
> Destroying container rootfs at
> '/mnt/teamcity/temp/buildTmp/LinuxFilesystemIsolatorTest_ROOT_ChangeRootFilesystemCommandExecutor_nZJkSj/provisioner/containers/57198894-8507-4f3e-8c9b-428c1cdeb9bb/backends/copy/rootfses/264fec60-6476-4aab-94af-d459a15c2448'
> for container 57198894-8507-4f3e-8c9b-428c1cdeb9bb
> [18:04:05]W: [Step 10/10] I0425 18:04:05.606057 660
> hierarchical.cpp:1488] No resources available to allocate!
> [18:04:05]W: [Step 10/10] I0425 18:04:05.606106 660
> hierarchical.cpp:1139] Performed allocation for 1 agents in 125175ns
> [18:04:06]W: [Step 10/10] I0425 18:04:06.606617 662
> hierarchical.cpp:1488] No resources available to allocate!
> [18:04:06]W: [Step 10/10] I0425 18:04:06.606653 662
> hierarchical.cpp:1139] Performed allocation for 1 agents in 94758ns
> [18:04:07]W: [Step 10/10] I0425 18:04:07.607285 658
> hierarchical.cpp:1488] No resources available to allocate!
> [18:04:07]W: [Step 10/10] I0425 18:04:07.607324 658
> hierarchical.cpp:1139] Performed allocation for 1 agents in 104606ns
> [18:04:08]W: [Step 10/10] I0425 18:04:08.607969 656
> hierarchical.cpp:1488] No resources available to allocate!
> [18:04:08]W: [Step 10/10] I0425 18:04:08.608006 656
> hierarchical.cpp:1139] Performed allocation for 1 agents in 87577ns
> [18:04:09]W: [Step 10/10] I0425 18:04:09.568349 657 slave.cpp:4524]
> Killing executor '52bf3e3e-f9e2-417c-a66d-24c5f8ec2898' of framework
> 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 at executor(1)@172.30.2.229:48674
> [18:04:09]W: [Step 10/10] I0425 18:04:09.608618 661
> hierarchical.cpp:1488] No resources available to allocate!
> [18:04:09]W: [Step 10/10] I0425 18:04:09.608666 661
> hierarchical.cpp:1139] Performed allocation for 1 agents in 107807ns
> [18:04:10]W: [Step 10/10] I0425 18:04:10.609025 656
> hierarchical.cpp:1488] No resources available to allocate!
> [18:04:10]W: [Step 10/10] I0425 18:04:10.609067 656
> hierarchical.cpp:1139] Performed allocation for 1 agents in 76953ns
> [18:04:11]W: [Step 10/10] I0425 18:04:11.609622 662
> hierarchical.cpp:1488] No resources available to allocate!
> [18:04:11]W: [Step 10/10] I0425 18:04:11.609657 662
> hierarchical.cpp:1139] Performed allocation for 1 agents in 85763ns
> [18:04:12]W: [Step 10/10] I0425 18:04:12.610268 659
> hierarchical.cpp:1488] No resources available to allocate!
> [18:04:12]W: [Step 10/10] I0425 18:04:12.610303 659
> hierarchical.cpp:1139] Performed allocation for 1 agents in 98315ns
> [18:04:13]W: [Step 10/10] I0425 18:04:13.610864 663
> hierarchical.cpp:1488] No resources available to allocate!
> [18:04:13]W: [Step 10/10] I0425 18:04:13.610908 663
> hierarchical.cpp:1139] Performed allocation for 1 agents in 136620ns
> [18:04:14]W: [Step 10/10] I0425 18:04:14.611521 662
> hierarchical.cpp:1488] No resources available to allocate!
> [18:04:14]W: [Step 10/10] I0425 18:04:14.611557 662
> hierarchical.cpp:1139] Performed allocation for 1 agents in 82004ns
> [18:04:15]W: [Step 10/10] I0425 18:04:15.345278 658 slave.cpp:4998]
> Querying resource estimator for oversubscribable resources
> [18:04:15]W: [Step 10/10] I0425 18:04:15.345414 657 slave.cpp:5012]
> Received oversubscribable resources from the resource estimator
> [18:04:15]W: [Step 10/10] I0425 18:04:15.349479 659 slave.cpp:3701]
> Received ping from slave-observer(423)@172.30.2.229:48705
> [18:04:15]W: [Step 10/10] I0425 18:04:15.612602 662
> hierarchical.cpp:1488] No resources available to allocate!
> [18:04:15]W: [Step 10/10] I0425 18:04:15.612638 662
> hierarchical.cpp:1139] Performed allocation for 1 agents in 81616ns
> [18:04:16]W: [Step 10/10] I0425 18:04:16.613032 656
> hierarchical.cpp:1488] No resources available to allocate!
> [18:04:16]W: [Step 10/10] I0425 18:04:16.613067 656
> hierarchical.cpp:1139] Performed allocation for 1 agents in 80321ns
> [18:04:17]W: [Step 10/10] I0425 18:04:17.613535 660
> hierarchical.cpp:1488] No resources available to allocate!
> [18:04:17]W: [Step 10/10] I0425 18:04:17.613569 660
> hierarchical.cpp:1139] Performed allocation for 1 agents in 74160ns
> [18:04:18]W: [Step 10/10] I0425 18:04:18.614146 657
> hierarchical.cpp:1488] No resources available to allocate!
> [18:04:18]W: [Step 10/10] I0425 18:04:18.614181 657
> hierarchical.cpp:1139] Performed allocation for 1 agents in 84861ns
> [18:04:19]W: [Step 10/10] I0425 18:04:19.568646 642 slave.cpp:825] Agent
> terminating
> [18:04:19] : [Step 10/10] ../../src/tests/cluster.cpp:500: Failure
> [18:04:19] : [Step 10/10] Failed to wait 15secs for wait
> [18:04:19]W: [Step 10/10] I0425 18:04:19.568676 642 slave.cpp:2252] Asked
> to shut down framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 by @0.0.0.0:0
> [18:04:19]W: [Step 10/10] W0425 18:04:19.568694 642 slave.cpp:2273]
> Ignoring shutdown framework 7e239aa6-d964-4f11-95a8-ba808ad23f4e-0000 because
> it is terminating
> [18:04:19]W: [Step 10/10] I0425 18:04:19.568778 658 master.cpp:1336]
> Agent 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0 at
> slave(458)@172.30.2.229:48705 (ip-172-30-2-229.mesosphere.io) disconnected
> [18:04:19]W: [Step 10/10] I0425 18:04:19.568796 658 master.cpp:2825]
> Disconnecting agent 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0 at
> slave(458)@172.30.2.229:48705 (ip-172-30-2-229.mesosphere.io)
> [18:04:19]W: [Step 10/10] I0425 18:04:19.568825 658 master.cpp:2844]
> Deactivating agent 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0 at
> slave(458)@172.30.2.229:48705 (ip-172-30-2-229.mesosphere.io)
> [18:04:19]W: [Step 10/10] I0425 18:04:19.568877 659 hierarchical.cpp:560]
> Agent 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0 deactivated
> [18:04:19]W: [Step 10/10] I0425 18:04:19.614851 656
> hierarchical.cpp:1488] No resources available to allocate!
> [18:04:19]W: [Step 10/10] I0425 18:04:19.614899 656
> hierarchical.cpp:1139] Performed allocation for 1 agents in 81590ns
> [18:04:20]W: [Step 10/10] I0425 18:04:20.203956 642 master.cpp:1189]
> Master terminating
> [18:04:20]W: [Step 10/10] I0425 18:04:20.204100 661 hierarchical.cpp:505]
> Removed agent 7e239aa6-d964-4f11-95a8-ba808ad23f4e-S0
> [18:04:20] : [Step 10/10] [ FAILED ]
> LinuxFilesystemIsolatorTest.ROOT_ChangeRootFilesystemCommandExecutor (21627
> ms)
> {code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
