Gilbert Song created MESOS-5284:
-----------------------------------
Summary:
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
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 [email protected]: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 [email protected]:48705
[18:04:00]W: [Step 10/10] I0425 18:04:00.341712 660 sched.cpp:384]
Authenticating with master [email protected]: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 [email protected]: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
[email protected]:48705
[18:04:00]W: [Step 10/10] I0425 18:04:00.343030 663 sched.cpp:474]
Successfully authenticated with master [email protected]:48705
[18:04:00]W: [Step 10/10] I0425 18:04:00.343044 663 sched.cpp:783]
Sending SUBSCRIBE call to [email protected]: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
[email protected]: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 [email protected]: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 [email protected]: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 [email protected]: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 [email protected]: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 [email protected]: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
[email protected]: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
[email protected]: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 [email protected]: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
[email protected]: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 [email protected]: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
[email protected]: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
[email protected]: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
[email protected]: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
[email protected]: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)
