Anand Mazumdar created MESOS-5747:
-------------------------------------
Summary: DiskResource/PersistentVolumeTest.SlaveRecovery/0 is flaky
Key: MESOS-5747
URL: https://issues.apache.org/jira/browse/MESOS-5747
Project: Mesos
Issue Type: Bug
Environment: Ubuntu 16
Reporter: Anand Mazumdar
Showed up on Internal CI:
{code}
[17:07:42] : [Step 10/10] [ RUN ]
DiskResource/PersistentVolumeTest.SlaveRecovery/0
[17:07:42]W: [Step 10/10] I0629 17:07:42.826249 3720 cluster.cpp:155]
Creating default 'local' authorizer
[17:07:42]W: [Step 10/10] I0629 17:07:42.833847 3720 leveldb.cpp:174]
Opened db in 7.482452ms
[17:07:42]W: [Step 10/10] I0629 17:07:42.834661 3720 leveldb.cpp:181]
Compacted db in 794368ns
[17:07:42]W: [Step 10/10] I0629 17:07:42.834678 3720 leveldb.cpp:196]
Created db iterator in 3611ns
[17:07:42]W: [Step 10/10] I0629 17:07:42.834684 3720 leveldb.cpp:202]
Seeked to beginning of db in 556ns
[17:07:42]W: [Step 10/10] I0629 17:07:42.834689 3720 leveldb.cpp:271]
Iterated through 0 keys in the db in 345ns
[17:07:42]W: [Step 10/10] I0629 17:07:42.834702 3720 replica.cpp:779]
Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
[17:07:42]W: [Step 10/10] I0629 17:07:42.834889 3739 recover.cpp:451]
Starting replica recovery
[17:07:42]W: [Step 10/10] I0629 17:07:42.835039 3739 recover.cpp:477]
Replica is in EMPTY status
[17:07:42]W: [Step 10/10] I0629 17:07:42.835422 3738 replica.cpp:673]
Replica in EMPTY status received a broadcasted recover request from
(22871)@172.30.2.145:46175
[17:07:42]W: [Step 10/10] I0629 17:07:42.835624 3735 recover.cpp:197]
Received a recover response from a replica in EMPTY status
[17:07:42]W: [Step 10/10] I0629 17:07:42.835758 3740 recover.cpp:568]
Updating replica status to STARTING
[17:07:42]W: [Step 10/10] I0629 17:07:42.835814 3740 master.cpp:382]
Master 59345281-cdcf-49ad-a546-9e2584432372 (ip-172-30-2-145.mesosphere.io)
started on 172.30.2.145:46175
[17:07:42]W: [Step 10/10] I0629 17:07:42.835829 3740 master.cpp:384] Flags
at startup: --acls="" --agent_ping_timeout="15secs"
--agent_reregister_timeout="10mins" --allocation_interval="1secs"
--allocator="HierarchicalDRF" --authenticate_agents="true"
--authenticate_frameworks="true" --authenticate_http="true"
--authenticate_http_frameworks="true" --authenticators="crammd5"
--authorizers="local" --credentials="/tmp/nsSI5J/credentials"
--framework_sorter="drf" --help="false" --hostname_lookup="true"
--http_authenticators="basic" --http_framework_authenticators="basic"
--initialize_driver_logging="true" --log_auto_initialize="true"
--logbufsecs="0" --logging_level="INFO" --max_agent_ping_timeouts="5"
--max_completed_frameworks="50" --max_completed_tasks_per_framework="1000"
--quiet="false" --recovery_agent_removal_limit="100%"
--registry="replicated_log" --registry_fetch_timeout="1mins"
--registry_store_timeout="100secs" --registry_strict="true"
--root_submissions="true" --user_sorter="drf" --version="false"
--webui_dir="/usr/local/share/mesos/webui" --work_dir="/tmp/nsSI5J/master"
--zk_session_timeout="10secs"
[17:07:42]W: [Step 10/10] I0629 17:07:42.835991 3740 master.cpp:434]
Master only allowing authenticated frameworks to register
[17:07:42]W: [Step 10/10] I0629 17:07:42.835999 3740 master.cpp:448]
Master only allowing authenticated agents to register
[17:07:42]W: [Step 10/10] I0629 17:07:42.836004 3740 master.cpp:461]
Master only allowing authenticated HTTP frameworks to register
[17:07:42]W: [Step 10/10] I0629 17:07:42.836007 3740 credentials.hpp:37]
Loading credentials for authentication from '/tmp/nsSI5J/credentials'
[17:07:42]W: [Step 10/10] I0629 17:07:42.836081 3740 master.cpp:506] Using
default 'crammd5' authenticator
[17:07:42]W: [Step 10/10] I0629 17:07:42.836120 3740 master.cpp:578] Using
default 'basic' HTTP authenticator
[17:07:42]W: [Step 10/10] I0629 17:07:42.836174 3740 master.cpp:658] Using
default 'basic' HTTP framework authenticator
[17:07:42]W: [Step 10/10] I0629 17:07:42.836231 3740 master.cpp:705]
Authorization enabled
[17:07:42]W: [Step 10/10] I0629 17:07:42.836277 3739
whitelist_watcher.cpp:77] No whitelist given
[17:07:42]W: [Step 10/10] I0629 17:07:42.836329 3736 hierarchical.cpp:142]
Initialized hierarchical allocator process
[17:07:42]W: [Step 10/10] I0629 17:07:42.836783 3740 master.cpp:1971] The
newly elected leader is [email protected]:46175 with id
59345281-cdcf-49ad-a546-9e2584432372
[17:07:42]W: [Step 10/10] I0629 17:07:42.836797 3740 master.cpp:1984]
Elected as the leading master!
[17:07:42]W: [Step 10/10] I0629 17:07:42.836803 3740 master.cpp:1671]
Recovering from registrar
[17:07:42]W: [Step 10/10] I0629 17:07:42.836865 3741 registrar.cpp:332]
Recovering registrar
[17:07:42]W: [Step 10/10] I0629 17:07:42.838137 3735 leveldb.cpp:304]
Persisting metadata (8 bytes) to leveldb took 2.281411ms
[17:07:42]W: [Step 10/10] I0629 17:07:42.838160 3735 replica.cpp:320]
Persisted replica status to STARTING
[17:07:42]W: [Step 10/10] I0629 17:07:42.838228 3735 recover.cpp:477]
Replica is in STARTING status
[17:07:42]W: [Step 10/10] I0629 17:07:42.838601 3737 replica.cpp:673]
Replica in STARTING status received a broadcasted recover request from
(22874)@172.30.2.145:46175
[17:07:42]W: [Step 10/10] I0629 17:07:42.838740 3734 recover.cpp:197]
Received a recover response from a replica in STARTING status
[17:07:42]W: [Step 10/10] I0629 17:07:42.838886 3738 recover.cpp:568]
Updating replica status to VOTING
[17:07:42]W: [Step 10/10] I0629 17:07:42.839633 3741 leveldb.cpp:304]
Persisting metadata (8 bytes) to leveldb took 641045ns
[17:07:42]W: [Step 10/10] I0629 17:07:42.839648 3741 replica.cpp:320]
Persisted replica status to VOTING
[17:07:42]W: [Step 10/10] I0629 17:07:42.839681 3741 recover.cpp:582]
Successfully joined the Paxos group
[17:07:42]W: [Step 10/10] I0629 17:07:42.839732 3741 recover.cpp:466]
Recover process terminated
[17:07:42]W: [Step 10/10] I0629 17:07:42.839882 3735 log.cpp:553]
Attempting to start the writer
[17:07:42]W: [Step 10/10] I0629 17:07:42.840248 3738 replica.cpp:493]
Replica received implicit promise request from (22875)@172.30.2.145:46175 with
proposal 1
[17:07:42]W: [Step 10/10] I0629 17:07:42.840874 3738 leveldb.cpp:304]
Persisting metadata (8 bytes) to leveldb took 602484ns
[17:07:42]W: [Step 10/10] I0629 17:07:42.840888 3738 replica.cpp:342]
Persisted promised to 1
[17:07:42]W: [Step 10/10] I0629 17:07:42.841140 3740 coordinator.cpp:238]
Coordinator attempting to fill missing positions
[17:07:42]W: [Step 10/10] I0629 17:07:42.841532 3739 replica.cpp:388]
Replica received explicit promise request from (22876)@172.30.2.145:46175 for
position 0 with proposal 2
[17:07:42]W: [Step 10/10] I0629 17:07:42.842186 3739 leveldb.cpp:341]
Persisting action (8 bytes) to leveldb took 630897ns
[17:07:42]W: [Step 10/10] I0629 17:07:42.842200 3739 replica.cpp:712]
Persisted action at 0
[17:07:42]W: [Step 10/10] I0629 17:07:42.842579 3736 replica.cpp:537]
Replica received write request for position 0 from (22877)@172.30.2.145:46175
[17:07:42]W: [Step 10/10] I0629 17:07:42.842612 3736 leveldb.cpp:436]
Reading position from leveldb took 11031ns
[17:07:42]W: [Step 10/10] I0629 17:07:42.843236 3736 leveldb.cpp:341]
Persisting action (14 bytes) to leveldb took 609786ns
[17:07:42]W: [Step 10/10] I0629 17:07:42.843250 3736 replica.cpp:712]
Persisted action at 0
[17:07:42]W: [Step 10/10] I0629 17:07:42.843518 3739 replica.cpp:691]
Replica received learned notice for position 0 from @0.0.0.0:0
[17:07:42]W: [Step 10/10] I0629 17:07:42.844149 3739 leveldb.cpp:341]
Persisting action (16 bytes) to leveldb took 611169ns
[17:07:42]W: [Step 10/10] I0629 17:07:42.844163 3739 replica.cpp:712]
Persisted action at 0
[17:07:42]W: [Step 10/10] I0629 17:07:42.844168 3739 replica.cpp:697]
Replica learned NOP action at position 0
[17:07:42]W: [Step 10/10] I0629 17:07:42.844409 3738 log.cpp:569] Writer
started with ending position 0
[17:07:42]W: [Step 10/10] I0629 17:07:42.844678 3738 leveldb.cpp:436]
Reading position from leveldb took 9715ns
[17:07:42]W: [Step 10/10] I0629 17:07:42.844892 3734 registrar.cpp:365]
Successfully fetched the registry (0B) in 7.935232ms
[17:07:42]W: [Step 10/10] I0629 17:07:42.844926 3734 registrar.cpp:464]
Applied 1 operations in 2835ns; attempting to update the 'registry'
[17:07:42]W: [Step 10/10] I0629 17:07:42.845098 3735 log.cpp:577]
Attempting to append 209 bytes to the log
[17:07:42]W: [Step 10/10] I0629 17:07:42.845156 3736 coordinator.cpp:348]
Coordinator attempting to write APPEND action at position 1
[17:07:42]W: [Step 10/10] I0629 17:07:42.845475 3737 replica.cpp:537]
Replica received write request for position 1 from (22878)@172.30.2.145:46175
[17:07:42]W: [Step 10/10] I0629 17:07:42.846097 3737 leveldb.cpp:341]
Persisting action (228 bytes) to leveldb took 603334ns
[17:07:42]W: [Step 10/10] I0629 17:07:42.846110 3737 replica.cpp:712]
Persisted action at 1
[17:07:42]W: [Step 10/10] I0629 17:07:42.846344 3738 replica.cpp:691]
Replica received learned notice for position 1 from @0.0.0.0:0
[17:07:42]W: [Step 10/10] I0629 17:07:42.846943 3738 leveldb.cpp:341]
Persisting action (230 bytes) to leveldb took 579548ns
[17:07:42]W: [Step 10/10] I0629 17:07:42.846957 3738 replica.cpp:712]
Persisted action at 1
[17:07:42]W: [Step 10/10] I0629 17:07:42.846962 3738 replica.cpp:697]
Replica learned APPEND action at position 1
[17:07:42]W: [Step 10/10] I0629 17:07:42.847199 3739 registrar.cpp:509]
Successfully updated the 'registry' in 2.255104ms
[17:07:42]W: [Step 10/10] I0629 17:07:42.847254 3739 registrar.cpp:395]
Successfully recovered registrar
[17:07:42]W: [Step 10/10] I0629 17:07:42.847273 3741 log.cpp:596]
Attempting to truncate the log to 1
[17:07:42]W: [Step 10/10] I0629 17:07:42.847367 3741 coordinator.cpp:348]
Coordinator attempting to write TRUNCATE action at position 2
[17:07:42]W: [Step 10/10] I0629 17:07:42.847374 3739 master.cpp:1779]
Recovered 0 agents from the Registry (170B) ; allowing 10mins for agents to
re-register
[17:07:42]W: [Step 10/10] I0629 17:07:42.847409 3736 hierarchical.cpp:169]
Skipping recovery of hierarchical allocator: nothing to recover
[17:07:42]W: [Step 10/10] I0629 17:07:42.847659 3738 replica.cpp:537]
Replica received write request for position 2 from (22879)@172.30.2.145:46175
[17:07:42]W: [Step 10/10] I0629 17:07:42.848454 3738 leveldb.cpp:341]
Persisting action (16 bytes) to leveldb took 774431ns
[17:07:42]W: [Step 10/10] I0629 17:07:42.848467 3738 replica.cpp:712]
Persisted action at 2
[17:07:42]W: [Step 10/10] I0629 17:07:42.848704 3741 replica.cpp:691]
Replica received learned notice for position 2 from @0.0.0.0:0
[17:07:42]W: [Step 10/10] I0629 17:07:42.849524 3741 leveldb.cpp:341]
Persisting action (18 bytes) to leveldb took 798146ns
[17:07:42]W: [Step 10/10] I0629 17:07:42.849542 3741 leveldb.cpp:399]
Deleting ~1 keys from leveldb took 8350ns
[17:07:42]W: [Step 10/10] I0629 17:07:42.849550 3741 replica.cpp:712]
Persisted action at 2
[17:07:42]W: [Step 10/10] I0629 17:07:42.849555 3741 replica.cpp:697]
Replica learned TRUNCATE action at position 2
[17:07:42]W: [Step 10/10] I0629 17:07:42.858269 3720 resources.cpp:572]
Parsing resources as JSON failed: cpus:2;mem:2048
[17:07:42]W: [Step 10/10] Trying semicolon-delimited string format instead
[17:07:42]W: [Step 10/10] I0629 17:07:42.858958 3720
containerizer.cpp:201] Using isolation:
posix/cpu,posix/mem,filesystem/posix,network/cni
[17:07:42]W: [Step 10/10] I0629 17:07:42.862290 3720
linux_launcher.cpp:101] Using /sys/fs/cgroup/freezer as the freezer hierarchy
for the Linux launcher
[17:07:42]W: [Step 10/10] I0629 17:07:42.863170 3720 cluster.cpp:432]
Creating default 'local' authorizer
[17:07:42]W: [Step 10/10] I0629 17:07:42.863579 3735 slave.cpp:203] Agent
started on 569)@172.30.2.145:46175
[17:07:42]W: [Step 10/10] I0629 17:07:42.863595 3735 slave.cpp:204] 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/DiskResource_PersistentVolumeTest_SlaveRecovery_0_HcUaGu/credential"
--default_role="*" --disk_watch_interval="1mins" --docker="docker"
--docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io";
--docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock"
--docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker"
--docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume"
--enforce_container_disk_quota="false" --executor_registration_timeout="1mins"
--executor_shutdown_grace_period="5secs"
--fetcher_cache_dir="/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_HcUaGu/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/DiskResource_PersistentVolumeTest_SlaveRecovery_0_HcUaGu/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="[{"name":"cpus","role":"*","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","role":"*","scalar":{"value":2048.0},"type":"SCALAR"},{"name":"disk","role":"role1","scalar":{"value":4096.0},"type":"SCALAR"}]"
--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/DiskResource_PersistentVolumeTest_SlaveRecovery_0_HcUaGu"
[17:07:42]W: [Step 10/10] I0629 17:07:42.863870 3735 credentials.hpp:86]
Loading credential for authentication from
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_HcUaGu/credential'
[17:07:42]W: [Step 10/10] I0629 17:07:42.863937 3735 slave.cpp:341] Agent
using credential for: test-principal
[17:07:42]W: [Step 10/10] I0629 17:07:42.863950 3735 credentials.hpp:37]
Loading credentials for authentication from
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_HcUaGu/http_credentials'
[17:07:42]W: [Step 10/10] I0629 17:07:42.864006 3735 slave.cpp:393] Using
default 'basic' HTTP authenticator
[17:07:42]W: [Step 10/10] I0629 17:07:42.864079 3720 sched.cpp:224]
Version: 1.0.0
[17:07:42]W: [Step 10/10] I0629 17:07:42.864254 3739 sched.cpp:328] New
master detected at [email protected]:46175
[17:07:42]W: [Step 10/10] I0629 17:07:42.864277 3739 sched.cpp:394]
Authenticating with master [email protected]:46175
[17:07:42]W: [Step 10/10] I0629 17:07:42.864285 3739 sched.cpp:401] Using
default CRAM-MD5 authenticatee
[17:07:42]W: [Step 10/10] I0629 17:07:42.864373 3738
authenticatee.cpp:121] Creating new client SASL connection
[17:07:42]W: [Step 10/10] I0629 17:07:42.864543 3739 master.cpp:5966]
Authenticating [email protected]:46175
[17:07:42]W: [Step 10/10] I0629 17:07:42.864600 3738
authenticator.cpp:414] Starting authentication session for
crammd5_authenticatee(1121)@172.30.2.145:46175
[17:07:42]W: [Step 10/10] I0629 17:07:42.864686 3736 authenticator.cpp:98]
Creating new server SASL connection
[17:07:42]W: [Step 10/10] I0629 17:07:42.864812 3736
authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
[17:07:42]W: [Step 10/10] I0629 17:07:42.864833 3736
authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
[17:07:42]W: [Step 10/10] I0629 17:07:42.864888 3737
authenticator.cpp:204] Received SASL authentication start
[17:07:42]W: [Step 10/10] I0629 17:07:42.864925 3737
authenticator.cpp:326] Authentication requires more steps
[17:07:42]W: [Step 10/10] I0629 17:07:42.864956 3737
authenticatee.cpp:259] Received SASL authentication step
[17:07:42]W: [Step 10/10] I0629 17:07:42.865005 3737
authenticator.cpp:232] Received SASL authentication step
[17:07:42]W: [Step 10/10] I0629 17:07:42.865022 3737 auxprop.cpp:107]
Request to lookup properties for user: 'test-principal' realm:
'ip-172-30-2-145.mesosphere.io' server FQDN: 'ip-172-30-2-145.mesosphere.io'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
[17:07:42]W: [Step 10/10] I0629 17:07:42.865033 3737 auxprop.cpp:179]
Looking up auxiliary property '*userPassword'
[17:07:42]W: [Step 10/10] I0629 17:07:42.865044 3737 auxprop.cpp:179]
Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
[17:07:42]W: [Step 10/10] I0629 17:07:42.865051 3737 auxprop.cpp:107]
Request to lookup properties for user: 'test-principal' realm:
'ip-172-30-2-145.mesosphere.io' server FQDN: 'ip-172-30-2-145.mesosphere.io'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
[17:07:42]W: [Step 10/10] I0629 17:07:42.865056 3737 auxprop.cpp:129]
Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
[17:07:42]W: [Step 10/10] I0629 17:07:42.865061 3737 auxprop.cpp:129]
Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID
== true
[17:07:42]W: [Step 10/10] I0629 17:07:42.865069 3737
authenticator.cpp:318] Authentication success
[17:07:42]W: [Step 10/10] I0629 17:07:42.865114 3736
authenticatee.cpp:299] Authentication success
[17:07:42]W: [Step 10/10] I0629 17:07:42.865139 3738
authenticator.cpp:432] Authentication session cleanup for
crammd5_authenticatee(1121)@172.30.2.145:46175
[17:07:42]W: [Step 10/10] I0629 17:07:42.865146 3737 master.cpp:5996]
Successfully authenticated principal 'test-principal' at
[email protected]:46175
[17:07:42]W: [Step 10/10] I0629 17:07:42.865262 3736 sched.cpp:484]
Successfully authenticated with master [email protected]:46175
[17:07:42]W: [Step 10/10] I0629 17:07:42.865274 3736 sched.cpp:800]
Sending SUBSCRIBE call to [email protected]:46175
[17:07:42]W: [Step 10/10] I0629 17:07:42.865314 3736 sched.cpp:833] Will
retry registration in 1.94488096secs if necessary
[17:07:42]W: [Step 10/10] I0629 17:07:42.865380 3734 master.cpp:2548]
Received SUBSCRIBE call for framework 'default' at
[email protected]:46175
[17:07:42]W: [Step 10/10] I0629 17:07:42.865402 3734 master.cpp:2010]
Authorizing framework principal 'test-principal' to receive offers for role
'role1'
[17:07:42]W: [Step 10/10] I0629 17:07:42.865516 3737 master.cpp:2624]
Subscribing framework default with checkpointing enabled and capabilities [ ]
[17:07:42]W: [Step 10/10] I0629 17:07:42.865661 3734 hierarchical.cpp:268]
Added framework 59345281-cdcf-49ad-a546-9e2584432372-0000
[17:07:42]W: [Step 10/10] I0629 17:07:42.865676 3740 sched.cpp:723]
Framework registered with 59345281-cdcf-49ad-a546-9e2584432372-0000
[17:07:42]W: [Step 10/10] I0629 17:07:42.865680 3734
hierarchical.cpp:1512] No allocations performed
[17:07:42]W: [Step 10/10] I0629 17:07:42.865711 3734
hierarchical.cpp:1607] No inverse offers to send out!
[17:07:42]W: [Step 10/10] I0629 17:07:42.865725 3734
hierarchical.cpp:1147] Performed allocation for 0 agents in 50765ns
[17:07:42]W: [Step 10/10] I0629 17:07:42.865732 3740 sched.cpp:737]
Scheduler::registered took 31034ns
[17:07:42]W: [Step 10/10] I0629 17:07:42.867944 3735 slave.cpp:592] Agent
resources: cpus(*):2; mem(*):2048; disk(role1):4096; ports(*):[31000-32000]
[17:07:42]W: [Step 10/10] I0629 17:07:42.867969 3735 slave.cpp:600] Agent
attributes: [ ]
[17:07:42]W: [Step 10/10] I0629 17:07:42.867974 3735 slave.cpp:605] Agent
hostname: ip-172-30-2-145.mesosphere.io
[17:07:42]W: [Step 10/10] I0629 17:07:42.868314 3735 state.cpp:57]
Recovering state from
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_HcUaGu/meta'
[17:07:42]W: [Step 10/10] I0629 17:07:42.868460 3739
status_update_manager.cpp:200] Recovering status update manager
[17:07:42]W: [Step 10/10] I0629 17:07:42.868553 3738
containerizer.cpp:514] Recovering containerizer
[17:07:42]W: [Step 10/10] I0629 17:07:42.869357 3734 provisioner.cpp:253]
Provisioner recovery complete
[17:07:42]W: [Step 10/10] I0629 17:07:42.869508 3734 slave.cpp:4840]
Finished recovery
[17:07:42]W: [Step 10/10] I0629 17:07:42.869669 3734 slave.cpp:5012]
Querying resource estimator for oversubscribable resources
[17:07:42]W: [Step 10/10] I0629 17:07:42.869770 3734 slave.cpp:967] New
master detected at [email protected]:46175
[17:07:42]W: [Step 10/10] I0629 17:07:42.869786 3734 slave.cpp:1029]
Authenticating with master [email protected]:46175
[17:07:42]W: [Step 10/10] I0629 17:07:42.869791 3741
status_update_manager.cpp:174] Pausing sending status updates
[17:07:42]W: [Step 10/10] I0629 17:07:42.869796 3734 slave.cpp:1040] Using
default CRAM-MD5 authenticatee
[17:07:42]W: [Step 10/10] I0629 17:07:42.869845 3734 slave.cpp:1002]
Detecting new master
[17:07:42]W: [Step 10/10] I0629 17:07:42.869863 3739
authenticatee.cpp:121] Creating new client SASL connection
[17:07:42]W: [Step 10/10] I0629 17:07:42.869896 3734 slave.cpp:5026]
Received oversubscribable resources from the resource estimator
[17:07:42]W: [Step 10/10] I0629 17:07:42.869992 3739 master.cpp:5966]
Authenticating slave(569)@172.30.2.145:46175
[17:07:42]W: [Step 10/10] I0629 17:07:42.870043 3735
authenticator.cpp:414] Starting authentication session for
crammd5_authenticatee(1122)@172.30.2.145:46175
[17:07:42]W: [Step 10/10] I0629 17:07:42.870126 3741 authenticator.cpp:98]
Creating new server SASL connection
[17:07:42]W: [Step 10/10] I0629 17:07:42.870244 3741
authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
[17:07:42]W: [Step 10/10] I0629 17:07:42.870263 3741
authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
[17:07:42]W: [Step 10/10] I0629 17:07:42.870309 3740
authenticator.cpp:204] Received SASL authentication start
[17:07:42]W: [Step 10/10] I0629 17:07:42.870340 3740
authenticator.cpp:326] Authentication requires more steps
[17:07:42]W: [Step 10/10] I0629 17:07:42.870373 3740
authenticatee.cpp:259] Received SASL authentication step
[17:07:42]W: [Step 10/10] I0629 17:07:42.870411 3740
authenticator.cpp:232] Received SASL authentication step
[17:07:42]W: [Step 10/10] I0629 17:07:42.870429 3740 auxprop.cpp:107]
Request to lookup properties for user: 'test-principal' realm:
'ip-172-30-2-145.mesosphere.io' server FQDN: 'ip-172-30-2-145.mesosphere.io'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
[17:07:42]W: [Step 10/10] I0629 17:07:42.870440 3740 auxprop.cpp:179]
Looking up auxiliary property '*userPassword'
[17:07:42]W: [Step 10/10] I0629 17:07:42.870447 3740 auxprop.cpp:179]
Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
[17:07:42]W: [Step 10/10] I0629 17:07:42.870455 3740 auxprop.cpp:107]
Request to lookup properties for user: 'test-principal' realm:
'ip-172-30-2-145.mesosphere.io' server FQDN: 'ip-172-30-2-145.mesosphere.io'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
[17:07:42]W: [Step 10/10] I0629 17:07:42.870458 3740 auxprop.cpp:129]
Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
[17:07:42]W: [Step 10/10] I0629 17:07:42.870462 3740 auxprop.cpp:129]
Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID
== true
[17:07:42]W: [Step 10/10] I0629 17:07:42.870471 3740
authenticator.cpp:318] Authentication success
[17:07:42]W: [Step 10/10] I0629 17:07:42.870504 3740
authenticatee.cpp:299] Authentication success
[17:07:42]W: [Step 10/10] I0629 17:07:42.870532 3738 master.cpp:5996]
Successfully authenticated principal 'test-principal' at
slave(569)@172.30.2.145:46175
[17:07:42]W: [Step 10/10] I0629 17:07:42.870543 3734
authenticator.cpp:432] Authentication session cleanup for
crammd5_authenticatee(1122)@172.30.2.145:46175
[17:07:42]W: [Step 10/10] I0629 17:07:42.870656 3736 slave.cpp:1108]
Successfully authenticated with master [email protected]:46175
[17:07:42]W: [Step 10/10] I0629 17:07:42.870733 3736 slave.cpp:1511] Will
retry registration in 15.127298ms if necessary
[17:07:42]W: [Step 10/10] I0629 17:07:42.870793 3741 master.cpp:4674]
Registering agent at slave(569)@172.30.2.145:46175
(ip-172-30-2-145.mesosphere.io) with id 59345281-cdcf-49ad-a546-9e2584432372-S0
[17:07:42]W: [Step 10/10] I0629 17:07:42.870908 3735 registrar.cpp:464]
Applied 1 operations in 14086ns; attempting to update the 'registry'
[17:07:42]W: [Step 10/10] I0629 17:07:42.871121 3739 log.cpp:577]
Attempting to append 399 bytes to the log
[17:07:42]W: [Step 10/10] I0629 17:07:42.871176 3734 coordinator.cpp:348]
Coordinator attempting to write APPEND action at position 3
[17:07:42]W: [Step 10/10] I0629 17:07:42.871490 3734 replica.cpp:537]
Replica received write request for position 3 from (22897)@172.30.2.145:46175
[17:07:42]W: [Step 10/10] I0629 17:07:42.872146 3734 leveldb.cpp:341]
Persisting action (418 bytes) to leveldb took 637267ns
[17:07:42]W: [Step 10/10] I0629 17:07:42.872159 3734 replica.cpp:712]
Persisted action at 3
[17:07:42]W: [Step 10/10] I0629 17:07:42.872431 3738 replica.cpp:691]
Replica received learned notice for position 3 from @0.0.0.0:0
[17:07:42]W: [Step 10/10] I0629 17:07:42.873061 3738 leveldb.cpp:341]
Persisting action (420 bytes) to leveldb took 613136ns
[17:07:42]W: [Step 10/10] I0629 17:07:42.873080 3738 replica.cpp:712]
Persisted action at 3
[17:07:42]W: [Step 10/10] I0629 17:07:42.873088 3738 replica.cpp:697]
Replica learned APPEND action at position 3
[17:07:42]W: [Step 10/10] I0629 17:07:42.873448 3741 registrar.cpp:509]
Successfully updated the 'registry' in 2.516992ms
[17:07:42]W: [Step 10/10] I0629 17:07:42.873500 3735 log.cpp:596]
Attempting to truncate the log to 3
[17:07:42]W: [Step 10/10] I0629 17:07:42.873563 3737 coordinator.cpp:348]
Coordinator attempting to write TRUNCATE action at position 4
[17:07:42]W: [Step 10/10] I0629 17:07:42.873656 3735 slave.cpp:3742]
Received ping from slave-observer(517)@172.30.2.145:46175
[17:07:42]W: [Step 10/10] I0629 17:07:42.873746 3739 master.cpp:4743]
Registered agent 59345281-cdcf-49ad-a546-9e2584432372-S0 at
slave(569)@172.30.2.145:46175 (ip-172-30-2-145.mesosphere.io) with cpus(*):2;
mem(*):2048; disk(role1):4096; ports(*):[31000-32000]
[17:07:42]W: [Step 10/10] I0629 17:07:42.873775 3738 slave.cpp:1152]
Registered with master [email protected]:46175; given agent ID
59345281-cdcf-49ad-a546-9e2584432372-S0
[17:07:42]W: [Step 10/10] I0629 17:07:42.873788 3738 fetcher.cpp:86]
Clearing fetcher cache
[17:07:42]W: [Step 10/10] I0629 17:07:42.873781 3741 hierarchical.cpp:481]
Added agent 59345281-cdcf-49ad-a546-9e2584432372-S0
(ip-172-30-2-145.mesosphere.io) with cpus(*):2; mem(*):2048; disk(role1):4096;
ports(*):[31000-32000] (allocated: )
[17:07:42]W: [Step 10/10] I0629 17:07:42.873890 3737
status_update_manager.cpp:181] Resuming sending status updates
[17:07:42]W: [Step 10/10] I0629 17:07:42.873916 3735 replica.cpp:537]
Replica received write request for position 4 from (22898)@172.30.2.145:46175
[17:07:42]W: [Step 10/10] I0629 17:07:42.873950 3741
hierarchical.cpp:1607] No inverse offers to send out!
[17:07:42]W: [Step 10/10] I0629 17:07:42.873975 3741
hierarchical.cpp:1170] Performed allocation for agent
59345281-cdcf-49ad-a546-9e2584432372-S0 in 167767ns
[17:07:42]W: [Step 10/10] I0629 17:07:42.874013 3738 slave.cpp:1175]
Checkpointing SlaveInfo to
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_HcUaGu/meta/slaves/59345281-cdcf-49ad-a546-9e2584432372-S0/slave.info'
[17:07:42]W: [Step 10/10] I0629 17:07:42.874034 3739 master.cpp:5795]
Sending 1 offers to framework 59345281-cdcf-49ad-a546-9e2584432372-0000
(default) at [email protected]:46175
[17:07:42]W: [Step 10/10] I0629 17:07:42.874111 3738 slave.cpp:1212]
Forwarding total oversubscribed resources
[17:07:42]W: [Step 10/10] I0629 17:07:42.874157 3738 master.cpp:5089]
Received update of agent 59345281-cdcf-49ad-a546-9e2584432372-S0 at
slave(569)@172.30.2.145:46175 (ip-172-30-2-145.mesosphere.io) with total
oversubscribed resources
[17:07:42]W: [Step 10/10] I0629 17:07:42.874172 3739 sched.cpp:897]
Scheduler::resourceOffers took 40147ns
[17:07:42]W: [Step 10/10] I0629 17:07:42.874301 3736 hierarchical.cpp:539]
Agent 59345281-cdcf-49ad-a546-9e2584432372-S0 (ip-172-30-2-145.mesosphere.io)
updated with oversubscribed resources (total: cpus(*):2; mem(*):2048;
disk(role1):4096; ports(*):[31000-32000], allocated: disk(role1):4096;
cpus(*):2; mem(*):2048; ports(*):[31000-32000])
[17:07:42]W: [Step 10/10] I0629 17:07:42.874339 3736
hierarchical.cpp:1512] No allocations performed
[17:07:42]W: [Step 10/10] I0629 17:07:42.874349 3736
hierarchical.cpp:1607] No inverse offers to send out!
[17:07:42]W: [Step 10/10] I0629 17:07:42.874354 3720 resources.cpp:572]
Parsing resources as JSON failed: cpus:1;mem:128
[17:07:42]W: [Step 10/10] Trying semicolon-delimited string format instead
[17:07:42]W: [Step 10/10] I0629 17:07:42.874359 3736
hierarchical.cpp:1170] Performed allocation for agent
59345281-cdcf-49ad-a546-9e2584432372-S0 in 36598ns
[17:07:42]W: [Step 10/10] I0629 17:07:42.874577 3735 leveldb.cpp:341]
Persisting action (16 bytes) to leveldb took 636027ns
[17:07:42]W: [Step 10/10] I0629 17:07:42.874595 3735 replica.cpp:712]
Persisted action at 4
[17:07:42]W: [Step 10/10] I0629 17:07:42.874698 3737 master.cpp:3466]
Processing ACCEPT call for offers: [ 59345281-cdcf-49ad-a546-9e2584432372-O0 ]
on agent 59345281-cdcf-49ad-a546-9e2584432372-S0 at
slave(569)@172.30.2.145:46175 (ip-172-30-2-145.mesosphere.io) for framework
59345281-cdcf-49ad-a546-9e2584432372-0000 (default) at
[email protected]:46175
[17:07:42]W: [Step 10/10] I0629 17:07:42.874740 3737 master.cpp:3251]
Authorizing principal 'test-principal' to create volumes
[17:07:42]W: [Step 10/10] I0629 17:07:42.874801 3737 master.cpp:3104]
Authorizing framework principal 'test-principal' to launch task
7ce5efb6-ec84-4a89-822b-bff47f3a9609
[17:07:42]W: [Step 10/10] I0629 17:07:42.874912 3740 replica.cpp:691]
Replica received learned notice for position 4 from @0.0.0.0:0
[17:07:42]W: [Step 10/10] I0629 17:07:42.875171 3734 master.cpp:3799]
Applying CREATE operation for volumes disk(role1)[id1:path1]:2048 from
framework 59345281-cdcf-49ad-a546-9e2584432372-0000 (default) at
[email protected]:46175 to agent
59345281-cdcf-49ad-a546-9e2584432372-S0 at slave(569)@172.30.2.145:46175
(ip-172-30-2-145.mesosphere.io)
[17:07:42]W: [Step 10/10] I0629 17:07:42.875254 3734 master.cpp:7048]
Sending checkpointed resources disk(role1)[id1:path1]:2048 to agent
59345281-cdcf-49ad-a546-9e2584432372-S0 at slave(569)@172.30.2.145:46175
(ip-172-30-2-145.mesosphere.io)
[17:07:42]W: [Step 10/10] I0629 17:07:42.875454 3734 master.cpp:7515]
Adding task 7ce5efb6-ec84-4a89-822b-bff47f3a9609 with resources cpus(*):1;
mem(*):128; disk(role1)[id1:path1]:2048 on agent
59345281-cdcf-49ad-a546-9e2584432372-S0 (ip-172-30-2-145.mesosphere.io)
[17:07:42]W: [Step 10/10] I0629 17:07:42.875490 3734 master.cpp:3955]
Launching task 7ce5efb6-ec84-4a89-822b-bff47f3a9609 of framework
59345281-cdcf-49ad-a546-9e2584432372-0000 (default) at
[email protected]:46175 with
resources cpus(*):1; mem(*):128; disk(role1)[id1:path1]:2048 on agent
59345281-cdcf-49ad-a546-9e2584432372-S0 at slave(569)@172.30.2.145:46175
(ip-172-30-2-145.mesosphere.io)
[17:07:42]W: [Step 10/10] I0629 17:07:42.875515 3740 leveldb.cpp:341]
Persisting action (18 bytes) to leveldb took 581749ns
[17:07:42]W: [Step 10/10] I0629 17:07:42.875509 3739 hierarchical.cpp:662]
Updated allocation of framework 59345281-cdcf-49ad-a546-9e2584432372-0000 on
agent 59345281-cdcf-49ad-a546-9e2584432372-S0 from disk(role1):4096; cpus(*):2;
mem(*):2048; ports(*):[31000-32000] to disk(role1):2048; cpus(*):2;
mem(*):2048; ports(*):[31000-32000]; disk(role1)[id1:path1]:2048
[17:07:42]W: [Step 10/10] I0629 17:07:42.875540 3740 leveldb.cpp:399]
Deleting ~2 keys from leveldb took 11489ns
[17:07:42]W: [Step 10/10] I0629 17:07:42.875547 3740 replica.cpp:712]
Persisted action at 4
[17:07:42]W: [Step 10/10] I0629 17:07:42.875552 3740 replica.cpp:697]
Replica learned TRUNCATE action at position 4
[17:07:42]W: [Step 10/10] I0629 17:07:42.875615 3736 slave.cpp:2582]
Updated checkpointed resources from to disk(role1)[id1:path1]:2048
[17:07:42]W: [Step 10/10] I0629 17:07:42.875638 3739 hierarchical.cpp:899]
Recovered disk(role1):2048; cpus(*):1; mem(*):1920; ports(*):[31000-32000]
(total: cpus(*):2; mem(*):2048; disk(role1):2048; ports(*):[31000-32000];
disk(role1)[id1:path1]:2048, allocated: disk(role1)[id1:path1]:2048; cpus(*):1;
mem(*):128) on agent 59345281-cdcf-49ad-a546-9e2584432372-S0 from framework
59345281-cdcf-49ad-a546-9e2584432372-0000
[17:07:42]W: [Step 10/10] I0629 17:07:42.875672 3739 hierarchical.cpp:936]
Framework 59345281-cdcf-49ad-a546-9e2584432372-0000 filtered agent
59345281-cdcf-49ad-a546-9e2584432372-S0 for 5secs
[17:07:42]W: [Step 10/10] I0629 17:07:42.875697 3736 slave.cpp:1551] Got
assigned task 7ce5efb6-ec84-4a89-822b-bff47f3a9609 for framework
59345281-cdcf-49ad-a546-9e2584432372-0000
[17:07:42]W: [Step 10/10] I0629 17:07:42.875759 3736 slave.cpp:5646]
Checkpointing FrameworkInfo to
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_HcUaGu/meta/slaves/59345281-cdcf-49ad-a546-9e2584432372-S0/frameworks/59345281-cdcf-49ad-a546-9e2584432372-0000/framework.info'
[17:07:42]W: [Step 10/10] I0629 17:07:42.875872 3736 slave.cpp:5657]
Checkpointing framework pid
'[email protected]:46175' to
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_HcUaGu/meta/slaves/59345281-cdcf-49ad-a546-9e2584432372-S0/frameworks/59345281-cdcf-49ad-a546-9e2584432372-0000/framework.pid'
[17:07:42]W: [Step 10/10] I0629 17:07:42.875972 3736 resources.cpp:572]
Parsing resources as JSON failed: cpus:0.1;mem:32
[17:07:42]W: [Step 10/10] Trying semicolon-delimited string format instead
[17:07:42]W: [Step 10/10] I0629 17:07:42.876106 3736 slave.cpp:1670]
Launching task 7ce5efb6-ec84-4a89-822b-bff47f3a9609 for framework
59345281-cdcf-49ad-a546-9e2584432372-0000
[17:07:42]W: [Step 10/10] I0629 17:07:42.876137 3736 resources.cpp:572]
Parsing resources as JSON failed: cpus:0.1;mem:32
[17:07:42]W: [Step 10/10] Trying semicolon-delimited string format instead
[17:07:42]W: [Step 10/10] I0629 17:07:42.876384 3736 paths.cpp:528] Trying
to chown
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_HcUaGu/slaves/59345281-cdcf-49ad-a546-9e2584432372-S0/frameworks/59345281-cdcf-49ad-a546-9e2584432372-0000/executors/7ce5efb6-ec84-4a89-822b-bff47f3a9609/runs/a001d565-ff42-4eba-8775-31bc1f107315'
to user 'root'
[17:07:42]W: [Step 10/10] I0629 17:07:42.882984 3736 slave.cpp:6128]
Checkpointing ExecutorInfo to
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_HcUaGu/meta/slaves/59345281-cdcf-49ad-a546-9e2584432372-S0/frameworks/59345281-cdcf-49ad-a546-9e2584432372-0000/executors/7ce5efb6-ec84-4a89-822b-bff47f3a9609/executor.info'
[17:07:42]W: [Step 10/10] I0629 17:07:42.883285 3736 slave.cpp:5726]
Launching executor 7ce5efb6-ec84-4a89-822b-bff47f3a9609 of framework
59345281-cdcf-49ad-a546-9e2584432372-0000 with resources cpus(*):0.1; mem(*):32
in work directory
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_HcUaGu/slaves/59345281-cdcf-49ad-a546-9e2584432372-S0/frameworks/59345281-cdcf-49ad-a546-9e2584432372-0000/executors/7ce5efb6-ec84-4a89-822b-bff47f3a9609/runs/a001d565-ff42-4eba-8775-31bc1f107315'
[17:07:42]W: [Step 10/10] I0629 17:07:42.883527 3736 slave.cpp:6151]
Checkpointing TaskInfo to
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_HcUaGu/meta/slaves/59345281-cdcf-49ad-a546-9e2584432372-S0/frameworks/59345281-cdcf-49ad-a546-9e2584432372-0000/executors/7ce5efb6-ec84-4a89-822b-bff47f3a9609/runs/a001d565-ff42-4eba-8775-31bc1f107315/tasks/7ce5efb6-ec84-4a89-822b-bff47f3a9609/task.info'
[17:07:42]W: [Step 10/10] I0629 17:07:42.883548 3737
containerizer.cpp:773] Starting container
'a001d565-ff42-4eba-8775-31bc1f107315' for executor
'7ce5efb6-ec84-4a89-822b-bff47f3a9609' of framework
'59345281-cdcf-49ad-a546-9e2584432372-0000'
[17:07:42]W: [Step 10/10] I0629 17:07:42.883662 3736 slave.cpp:1896]
Queuing task '7ce5efb6-ec84-4a89-822b-bff47f3a9609' for executor
'7ce5efb6-ec84-4a89-822b-bff47f3a9609' of framework
59345281-cdcf-49ad-a546-9e2584432372-0000
[17:07:42]W: [Step 10/10] I0629 17:07:42.883710 3736 slave.cpp:920]
Successfully attached file
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_HcUaGu/slaves/59345281-cdcf-49ad-a546-9e2584432372-S0/frameworks/59345281-cdcf-49ad-a546-9e2584432372-0000/executors/7ce5efb6-ec84-4a89-822b-bff47f3a9609/runs/a001d565-ff42-4eba-8775-31bc1f107315'
[17:07:42]W: [Step 10/10] I0629 17:07:42.883868 3741 posix.cpp:194]
Changing the ownership of the persistent volume at
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_HcUaGu/volumes/roles/role1/id1'
with uid 0 and gid 0
[17:07:42]W: [Step 10/10] I0629 17:07:42.883898 3741 posix.cpp:238] Adding
symlink from
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_HcUaGu/volumes/roles/role1/id1'
to
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_HcUaGu/slaves/59345281-cdcf-49ad-a546-9e2584432372-S0/frameworks/59345281-cdcf-49ad-a546-9e2584432372-0000/executors/7ce5efb6-ec84-4a89-822b-bff47f3a9609/runs/a001d565-ff42-4eba-8775-31bc1f107315/path1'
for persistent volume disk(role1)[id1:path1]:2048 of container
a001d565-ff42-4eba-8775-31bc1f107315
[17:07:42]W: [Step 10/10] I0629 17:07:42.884742 3740
containerizer.cpp:1264] Launching 'mesos-containerizer' with flags
'--command="{"shell":true,"value":"\/mnt\/teamcity\/work\/4240ba9ddd0997c3\/build\/src\/mesos-executor"}"
--commands="{"commands":[]}" --help="false" --pipe_read="107"
--pipe_write="140"
--sandbox="/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_HcUaGu/slaves/59345281-cdcf-49ad-a546-9e2584432372-S0/frameworks/59345281-cdcf-49ad-a546-9e2584432372-0000/executors/7ce5efb6-ec84-4a89-822b-bff47f3a9609/runs/a001d565-ff42-4eba-8775-31bc1f107315"
--user="root"'
[17:07:42]W: [Step 10/10] I0629 17:07:42.884809 3740
linux_launcher.cpp:281] Cloning child process with flags =
[17:07:42]W: [Step 10/10] I0629 17:07:42.900671 3740
containerizer.cpp:1299] Checkpointing executor's forked pid 22957 to
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_HcUaGu/meta/slaves/59345281-cdcf-49ad-a546-9e2584432372-S0/frameworks/59345281-cdcf-49ad-a546-9e2584432372-0000/executors/7ce5efb6-ec84-4a89-822b-bff47f3a9609/runs/a001d565-ff42-4eba-8775-31bc1f107315/pids/forked.pid'
[17:07:42]W: [Step 10/10] I0629 17:07:42.968351 22989 exec.cpp:161]
Version: 1.0.0
[17:07:42]W: [Step 10/10] I0629 17:07:42.968901 3734 slave.cpp:2884] Got
registration for executor '7ce5efb6-ec84-4a89-822b-bff47f3a9609' of framework
59345281-cdcf-49ad-a546-9e2584432372-0000 from executor(1)@172.30.2.145:38212
[17:07:42]W: [Step 10/10] I0629 17:07:42.969054 3734 slave.cpp:2970]
Checkpointing executor pid 'executor(1)@172.30.2.145:38212' to
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_HcUaGu/meta/slaves/59345281-cdcf-49ad-a546-9e2584432372-S0/frameworks/59345281-cdcf-49ad-a546-9e2584432372-0000/executors/7ce5efb6-ec84-4a89-822b-bff47f3a9609/runs/a001d565-ff42-4eba-8775-31bc1f107315/pids/libprocess.pid'
[17:07:42]W: [Step 10/10] I0629 17:07:42.969468 22985 exec.cpp:236]
Executor registered on agent 59345281-cdcf-49ad-a546-9e2584432372-S0
[17:07:42]W: [Step 10/10] I0629 17:07:42.969805 3737 slave.cpp:2061]
Sending queued task '7ce5efb6-ec84-4a89-822b-bff47f3a9609' to executor
'7ce5efb6-ec84-4a89-822b-bff47f3a9609' of framework
59345281-cdcf-49ad-a546-9e2584432372-0000 at executor(1)@172.30.2.145:38212
[17:07:42] : [Step 10/10] Received SUBSCRIBED event
[17:07:42] : [Step 10/10] Subscribed executor on
ip-172-30-2-145.mesosphere.io
[17:07:42] : [Step 10/10] Received LAUNCH event
[17:07:42] : [Step 10/10] Starting task 7ce5efb6-ec84-4a89-822b-bff47f3a9609
[17:07:42] : [Step 10/10] Forked command at 22994
[17:07:42] : [Step 10/10] sh -c 'while true; do test -d path1; done'
[17:07:42]W: [Step 10/10] I0629 17:07:42.973260 3735 slave.cpp:3267]
Handling status update TASK_RUNNING (UUID:
9caaea55-4c6b-4a34-9869-2b00d0c35bfb) for task
7ce5efb6-ec84-4a89-822b-bff47f3a9609 of framework
59345281-cdcf-49ad-a546-9e2584432372-0000 from executor(1)@172.30.2.145:38212
[17:07:42]W: [Step 10/10] I0629 17:07:42.973800 3741
status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID:
9caaea55-4c6b-4a34-9869-2b00d0c35bfb) for task
7ce5efb6-ec84-4a89-822b-bff47f3a9609 of framework
59345281-cdcf-49ad-a546-9e2584432372-0000
[17:07:42]W: [Step 10/10] I0629 17:07:42.973834 3741
status_update_manager.cpp:497] Creating StatusUpdate stream for task
7ce5efb6-ec84-4a89-822b-bff47f3a9609 of framework
59345281-cdcf-49ad-a546-9e2584432372-0000
[17:07:42]W: [Step 10/10] I0629 17:07:42.974079 3741
status_update_manager.cpp:825] Checkpointing UPDATE for status update
TASK_RUNNING (UUID: 9caaea55-4c6b-4a34-9869-2b00d0c35bfb) for task
7ce5efb6-ec84-4a89-822b-bff47f3a9609 of framework
59345281-cdcf-49ad-a546-9e2584432372-0000
[17:07:43]W: [Step 10/10] I0629 17:07:43.836679 3735
hierarchical.cpp:1698] Filtered offer with disk(role1):2048; cpus(*):1;
mem(*):1920; ports(*):[31000-32000] on agent
59345281-cdcf-49ad-a546-9e2584432372-S0 for framework
59345281-cdcf-49ad-a546-9e2584432372-0000
[17:07:43]W: [Step 10/10] I0629 17:07:43.836745 3735
hierarchical.cpp:1512] No allocations performed
[17:07:43]W: [Step 10/10] I0629 17:07:43.836751 3735
hierarchical.cpp:1607] No inverse offers to send out!
[17:07:43]W: [Step 10/10] I0629 17:07:43.836768 3735
hierarchical.cpp:1147] Performed allocation for 1 agents in 220658ns
[17:07:44]W: [Step 10/10] I0629 17:07:44.837916 3737
hierarchical.cpp:1698] Filtered offer with disk(role1):2048; cpus(*):1;
mem(*):1920; ports(*):[31000-32000] on agent
59345281-cdcf-49ad-a546-9e2584432372-S0 for framework
59345281-cdcf-49ad-a546-9e2584432372-0000
[17:07:44]W: [Step 10/10] I0629 17:07:44.837980 3737
hierarchical.cpp:1512] No allocations performed
[17:07:44]W: [Step 10/10] I0629 17:07:44.837987 3737
hierarchical.cpp:1607] No inverse offers to send out!
[17:07:44]W: [Step 10/10] I0629 17:07:44.838002 3737
hierarchical.cpp:1147] Performed allocation for 1 agents in 224968ns
[17:07:45]W: [Step 10/10] I0629 17:07:45.838881 3735
hierarchical.cpp:1698] Filtered offer with disk(role1):2048; cpus(*):1;
mem(*):1920; ports(*):[31000-32000] on agent
59345281-cdcf-49ad-a546-9e2584432372-S0 for framework
59345281-cdcf-49ad-a546-9e2584432372-0000
[17:07:45]W: [Step 10/10] I0629 17:07:45.838945 3735
hierarchical.cpp:1512] No allocations performed
[17:07:45]W: [Step 10/10] I0629 17:07:45.838953 3735
hierarchical.cpp:1607] No inverse offers to send out!
[17:07:45]W: [Step 10/10] I0629 17:07:45.838965 3735
hierarchical.cpp:1147] Performed allocation for 1 agents in 206930ns
[17:07:46]W: [Step 10/10] I0629 17:07:46.840325 3734
hierarchical.cpp:1698] Filtered offer with disk(role1):2048; cpus(*):1;
mem(*):1920; ports(*):[31000-32000] on agent
59345281-cdcf-49ad-a546-9e2584432372-S0 for framework
59345281-cdcf-49ad-a546-9e2584432372-0000
[17:07:46]W: [Step 10/10] I0629 17:07:46.840390 3734
hierarchical.cpp:1512] No allocations performed
[17:07:46]W: [Step 10/10] I0629 17:07:46.840397 3734
hierarchical.cpp:1607] No inverse offers to send out!
[17:07:46]W: [Step 10/10] I0629 17:07:46.840412 3734
hierarchical.cpp:1147] Performed allocation for 1 agents in 288650ns
[17:07:47]W: [Step 10/10] I0629 17:07:47.841547 3734
hierarchical.cpp:1698] Filtered offer with disk(role1):2048; cpus(*):1;
mem(*):1920; ports(*):[31000-32000] on agent
59345281-cdcf-49ad-a546-9e2584432372-S0 for framework
59345281-cdcf-49ad-a546-9e2584432372-0000
[17:07:47]W: [Step 10/10] I0629 17:07:47.841614 3734
hierarchical.cpp:1512] No allocations performed
[17:07:47]W: [Step 10/10] I0629 17:07:47.841620 3734
hierarchical.cpp:1607] No inverse offers to send out!
[17:07:47]W: [Step 10/10] I0629 17:07:47.841634 3734
hierarchical.cpp:1147] Performed allocation for 1 agents in 206835ns
[17:07:48]W: [Step 10/10] I0629 17:07:48.842597 3739
hierarchical.cpp:1607] No inverse offers to send out!
[17:07:48]W: [Step 10/10] I0629 17:07:48.842654 3739
hierarchical.cpp:1147] Performed allocation for 1 agents in 249576ns
[17:07:48]W: [Step 10/10] I0629 17:07:48.842711 3735 master.cpp:5795]
Sending 1 offers to framework 59345281-cdcf-49ad-a546-9e2584432372-0000
(default) at [email protected]:46175
[17:07:48]W: [Step 10/10] I0629 17:07:48.842846 3735 sched.cpp:897]
Scheduler::resourceOffers took 14892ns
[17:07:49]W: [Step 10/10] I0629 17:07:49.843474 3738
hierarchical.cpp:1512] No allocations performed
[17:07:49]W: [Step 10/10] I0629 17:07:49.843515 3738
hierarchical.cpp:1607] No inverse offers to send out!
[17:07:49]W: [Step 10/10] I0629 17:07:49.843533 3738
hierarchical.cpp:1147] Performed allocation for 1 agents in 146298ns
[17:07:50]W: [Step 10/10] I0629 17:07:50.844720 3735
hierarchical.cpp:1512] No allocations performed
[17:07:50]W: [Step 10/10] I0629 17:07:50.844760 3735
hierarchical.cpp:1607] No inverse offers to send out!
[17:07:50]W: [Step 10/10] I0629 17:07:50.844776 3735
hierarchical.cpp:1147] Performed allocation for 1 agents in 114714ns
[17:07:51]W: [Step 10/10] I0629 17:07:51.845829 3737
hierarchical.cpp:1512] No allocations performed
[17:07:51]W: [Step 10/10] I0629 17:07:51.845870 3737
hierarchical.cpp:1607] No inverse offers to send out!
[17:07:51]W: [Step 10/10] I0629 17:07:51.845887 3737
hierarchical.cpp:1147] Performed allocation for 1 agents in 118453ns
[17:07:52]W: [Step 10/10] I0629 17:07:52.846472 3735
hierarchical.cpp:1512] No allocations performed
[17:07:52]W: [Step 10/10] I0629 17:07:52.846511 3735
hierarchical.cpp:1607] No inverse offers to send out!
[17:07:52]W: [Step 10/10] I0629 17:07:52.846527 3735
hierarchical.cpp:1147] Performed allocation for 1 agents in 110050ns
[17:07:53]W: [Step 10/10] I0629 17:07:53.847558 3734
hierarchical.cpp:1512] No allocations performed
[17:07:53]W: [Step 10/10] I0629 17:07:53.847597 3734
hierarchical.cpp:1607] No inverse offers to send out!
[17:07:53]W: [Step 10/10] I0629 17:07:53.847615 3734
hierarchical.cpp:1147] Performed allocation for 1 agents in 110011ns
[17:07:54]W: [Step 10/10] I0629 17:07:54.848455 3737
hierarchical.cpp:1512] No allocations performed
[17:07:54]W: [Step 10/10] I0629 17:07:54.848497 3737
hierarchical.cpp:1607] No inverse offers to send out!
[17:07:54]W: [Step 10/10] I0629 17:07:54.848515 3737
hierarchical.cpp:1147] Performed allocation for 1 agents in 125449ns
[17:07:55]W: [Step 10/10] I0629 17:07:55.849454 3739
hierarchical.cpp:1512] No allocations performed
[17:07:55]W: [Step 10/10] I0629 17:07:55.849500 3739
hierarchical.cpp:1607] No inverse offers to send out!
[17:07:55]W: [Step 10/10] I0629 17:07:55.849519 3739
hierarchical.cpp:1147] Performed allocation for 1 agents in 126594ns
[17:07:56]W: [Step 10/10] I0629 17:07:56.850775 3740
hierarchical.cpp:1512] No allocations performed
[17:07:56]W: [Step 10/10] I0629 17:07:56.850818 3740
hierarchical.cpp:1607] No inverse offers to send out!
[17:07:56]W: [Step 10/10] I0629 17:07:56.850836 3740
hierarchical.cpp:1147] Performed allocation for 1 agents in 152945ns
[17:07:57]W: [Step 10/10] I0629 17:07:57.851872 3737
hierarchical.cpp:1512] No allocations performed
[17:07:57]W: [Step 10/10] I0629 17:07:57.851914 3737
hierarchical.cpp:1607] No inverse offers to send out!
[17:07:57]W: [Step 10/10] I0629 17:07:57.851934 3737
hierarchical.cpp:1147] Performed allocation for 1 agents in 118869ns
[17:07:57]W: [Step 10/10] I0629 17:07:57.870530 3739 slave.cpp:5012]
Querying resource estimator for oversubscribable resources
[17:07:57]W: [Step 10/10] I0629 17:07:57.870662 3738 slave.cpp:5026]
Received oversubscribable resources from the resource estimator
[17:07:57]W: [Step 10/10] I0629 17:07:57.874852 3734 slave.cpp:3742]
Received ping from slave-observer(517)@172.30.2.145:46175
[17:07:57] : [Step 10/10] ../../src/tests/persistent_volume_tests.cpp:966:
Failure
[17:07:57] : [Step 10/10] Failed to wait 15secs for status1
[17:07:57] : [Step 10/10] ../../src/tests/persistent_volume_tests.cpp:955:
Failure
[17:07:57] : [Step 10/10] Actual function call count doesn't match
EXPECT_CALL(sched, statusUpdate(&driver, _))...
[17:07:57] : [Step 10/10] Expected: to be called twice
[17:07:57] : [Step 10/10] Actual: never called - unsatisfied and
active
[17:07:57]W: [Step 10/10] I0629 17:07:57.875155 3737 master.cpp:1408]
Framework 59345281-cdcf-49ad-a546-9e2584432372-0000 (default) at
[email protected]:46175 disconnected
[17:07:57]W: [Step 10/10] I0629 17:07:57.875175 3737 master.cpp:2849]
Disconnecting framework 59345281-cdcf-49ad-a546-9e2584432372-0000 (default) at
[email protected]:46175
[17:07:57]W: [Step 10/10] I0629 17:07:57.875185 3737 master.cpp:2873]
Deactivating framework 59345281-cdcf-49ad-a546-9e2584432372-0000 (default) at
[email protected]:46175
[17:07:57]W: [Step 10/10] I0629 17:07:57.875283 3740 hierarchical.cpp:379]
Deactivated framework 59345281-cdcf-49ad-a546-9e2584432372-0000
[17:07:57]W: [Step 10/10] W0629 17:07:57.875299 3737 master.hpp:2059]
Master attempted to send message to disconnected framework
59345281-cdcf-49ad-a546-9e2584432372-0000 (default) at
[email protected]:46175
[17:07:57]W: [Step 10/10] I0629 17:07:57.875356 3737 master.cpp:1421]
Giving framework 59345281-cdcf-49ad-a546-9e2584432372-0000 (default) at
[email protected]:46175 0ns to
failover
[17:07:57]W: [Step 10/10] I0629 17:07:57.875411 3740 hierarchical.cpp:899]
Recovered disk(role1):2048; cpus(*):1; mem(*):1920; ports(*):[31000-32000]
(total: cpus(*):2; mem(*):2048; disk(role1):2048; ports(*):[31000-32000];
disk(role1)[id1:path1]:2048, allocated: disk(role1)[id1:path1]:2048; cpus(*):1;
mem(*):128) on agent 59345281-cdcf-49ad-a546-9e2584432372-S0 from framework
59345281-cdcf-49ad-a546-9e2584432372-0000
[17:07:57]W: [Step 10/10] I0629 17:07:57.875592 3739
containerizer.cpp:1573] Destroying container
'a001d565-ff42-4eba-8775-31bc1f107315'
[17:07:57]W: [Step 10/10] I0629 17:07:57.876600 3737 master.cpp:5647]
Framework failover timeout, removing framework
59345281-cdcf-49ad-a546-9e2584432372-0000 (default) at
[email protected]:46175
[17:07:57]W: [Step 10/10] I0629 17:07:57.876616 3737 master.cpp:6377]
Removing framework 59345281-cdcf-49ad-a546-9e2584432372-0000 (default) at
[email protected]:46175
[17:07:57]W: [Step 10/10] I0629 17:07:57.876665 3737 master.cpp:6909]
Updating the state of task 7ce5efb6-ec84-4a89-822b-bff47f3a9609 of framework
59345281-cdcf-49ad-a546-9e2584432372-0000 (latest state: TASK_KILLED, status
update state: TASK_KILLED)
[17:07:57]W: [Step 10/10] I0629 17:07:57.876673 3734 slave.cpp:2274] Asked
to shut down framework 59345281-cdcf-49ad-a546-9e2584432372-0000 by
[email protected]:46175
[17:07:57]W: [Step 10/10] I0629 17:07:57.876698 3734 slave.cpp:2299]
Shutting down framework 59345281-cdcf-49ad-a546-9e2584432372-0000
[17:07:57]W: [Step 10/10] I0629 17:07:57.876713 3734 slave.cpp:4465]
Shutting down executor '7ce5efb6-ec84-4a89-822b-bff47f3a9609' of framework
59345281-cdcf-49ad-a546-9e2584432372-0000 at executor(1)@172.30.2.145:38212
[17:07:57]W: [Step 10/10] I0629 17:07:57.876792 3737 master.cpp:6975]
Removing task 7ce5efb6-ec84-4a89-822b-bff47f3a9609 with resources cpus(*):1;
mem(*):128; disk(role1)[id1:path1]:2048 of framework
59345281-cdcf-49ad-a546-9e2584432372-0000 on agent
59345281-cdcf-49ad-a546-9e2584432372-S0 at slave(569)@172.30.2.145:46175
(ip-172-30-2-145.mesosphere.io)
[17:07:57]W: [Step 10/10] I0629 17:07:57.876823 3738 hierarchical.cpp:899]
Recovered cpus(*):1; mem(*):128; disk(role1)[id1:path1]:2048 (total: cpus(*):2;
mem(*):2048; disk(role1):2048; ports(*):[31000-32000];
disk(role1)[id1:path1]:2048, allocated: ) on agent
59345281-cdcf-49ad-a546-9e2584432372-S0 from framework
59345281-cdcf-49ad-a546-9e2584432372-0000
[17:07:57]W: [Step 10/10] I0629 17:07:57.876991 3735 hierarchical.cpp:330]
Removed framework 59345281-cdcf-49ad-a546-9e2584432372-0000
[17:07:57]W: [Step 10/10] I0629 17:07:57.877025 3738 cgroups.cpp:2676]
Freezing cgroup
/sys/fs/cgroup/freezer/mesos/a001d565-ff42-4eba-8775-31bc1f107315
[17:07:57]W: [Step 10/10] I0629 17:07:57.877079 22988 exec.cpp:413]
Executor asked to shutdown
[17:07:57] : [Step 10/10] Received SHUTDOWN event
[17:07:57] : [Step 10/10] Shutting down
[17:07:57] : [Step 10/10] Sending SIGTERM to process tree at pid 22994
[17:07:57]W: [Step 10/10] I0629 17:07:57.878743 3739 cgroups.cpp:1409]
Successfully froze cgroup
/sys/fs/cgroup/freezer/mesos/a001d565-ff42-4eba-8775-31bc1f107315 after
1.690112ms
[17:07:57]W: [Step 10/10] I0629 17:07:57.879796 3737 cgroups.cpp:2694]
Thawing cgroup /sys/fs/cgroup/freezer/mesos/a001d565-ff42-4eba-8775-31bc1f107315
[17:07:57]W: [Step 10/10] I0629 17:07:57.880858 3739 cgroups.cpp:1438]
Successfully thawed cgroup
/sys/fs/cgroup/freezer/mesos/a001d565-ff42-4eba-8775-31bc1f107315 after
1.040128ms
[17:07:57]W: [Step 10/10] I0629 17:07:57.882511 3736 slave.cpp:3788]
executor(1)@172.30.2.145:38212 exited
[17:07:57]W: [Step 10/10] I0629 17:07:57.890024 3739
containerizer.cpp:1809] Executor for container
'a001d565-ff42-4eba-8775-31bc1f107315' has exited
[17:07:57]W: [Step 10/10] I0629 17:07:57.891419 3736 provisioner.cpp:411]
Ignoring destroy request for unknown container
a001d565-ff42-4eba-8775-31bc1f107315
[17:07:57]W: [Step 10/10] I0629 17:07:57.891540 3735 slave.cpp:4147]
Executor '7ce5efb6-ec84-4a89-822b-bff47f3a9609' of framework
59345281-cdcf-49ad-a546-9e2584432372-0000 terminated with signal Killed
[17:07:57]W: [Step 10/10] I0629 17:07:57.891563 3735 slave.cpp:4251]
Cleaning up executor '7ce5efb6-ec84-4a89-822b-bff47f3a9609' of framework
59345281-cdcf-49ad-a546-9e2584432372-0000 at executor(1)@172.30.2.145:38212
[17:07:58]W: [Step 10/10] I0629 17:07:58.852751 3738
hierarchical.cpp:1512] No allocations performed
[17:07:58]W: [Step 10/10] I0629 17:07:58.852803 3738
hierarchical.cpp:1147] Performed allocation for 1 agents in 110817ns
[17:07:59]W: [Step 10/10] I0629 17:07:59.853654 3739
hierarchical.cpp:1512] No allocations performed
[17:07:59]W: [Step 10/10] I0629 17:07:59.853704 3739
hierarchical.cpp:1147] Performed allocation for 1 agents in 113791ns
[17:08:00]W: [Step 10/10] I0629 17:08:00.854429 3737
hierarchical.cpp:1512] No allocations performed
[17:08:00]W: [Step 10/10] I0629 17:08:00.854481 3737
hierarchical.cpp:1147] Performed allocation for 1 agents in 106162ns
[17:08:01]W: [Step 10/10] I0629 17:08:01.855291 3736
hierarchical.cpp:1512] No allocations performed
[17:08:01]W: [Step 10/10] I0629 17:08:01.855345 3736
hierarchical.cpp:1147] Performed allocation for 1 agents in 109864ns
[17:08:02]W: [Step 10/10] I0629 17:08:02.856176 3738
hierarchical.cpp:1512] No allocations performed
[17:08:02]W: [Step 10/10] I0629 17:08:02.856251 3738
hierarchical.cpp:1147] Performed allocation for 1 agents in 125120ns
[17:08:03]W: [Step 10/10] I0629 17:08:03.857237 3736
hierarchical.cpp:1512] No allocations performed
[17:08:03]W: [Step 10/10] I0629 17:08:03.857288 3736
hierarchical.cpp:1147] Performed allocation for 1 agents in 98233ns
[17:08:04]W: [Step 10/10] I0629 17:08:04.858162 3739
hierarchical.cpp:1512] No allocations performed
[17:08:04]W: [Step 10/10] I0629 17:08:04.858218 3739
hierarchical.cpp:1147] Performed allocation for 1 agents in 118808ns
[17:08:05]W: [Step 10/10] I0629 17:08:05.858827 3737
hierarchical.cpp:1512] No allocations performed
[17:08:05]W: [Step 10/10] I0629 17:08:05.858882 3737
hierarchical.cpp:1147] Performed allocation for 1 agents in 104916ns
[17:08:06]W: [Step 10/10] I0629 17:08:06.859602 3740
hierarchical.cpp:1512] No allocations performed
[17:08:06]W: [Step 10/10] I0629 17:08:06.859652 3740
hierarchical.cpp:1147] Performed allocation for 1 agents in 102983ns
[17:08:07]W: [Step 10/10] I0629 17:08:07.860299 3736
hierarchical.cpp:1512] No allocations performed
[17:08:07]W: [Step 10/10] I0629 17:08:07.860349 3736
hierarchical.cpp:1147] Performed allocation for 1 agents in 96003ns
[17:08:08]W: [Step 10/10] I0629 17:08:08.861210 3736
hierarchical.cpp:1512] No allocations performed
[17:08:08]W: [Step 10/10] I0629 17:08:08.861261 3736
hierarchical.cpp:1147] Performed allocation for 1 agents in 109484ns
[17:08:09]W: [Step 10/10] I0629 17:08:09.862000 3738
hierarchical.cpp:1512] No allocations performed
[17:08:09]W: [Step 10/10] I0629 17:08:09.862049 3738
hierarchical.cpp:1147] Performed allocation for 1 agents in 96178ns
[17:08:10]W: [Step 10/10] I0629 17:08:10.862892 3740
hierarchical.cpp:1512] No allocations performed
[17:08:10]W: [Step 10/10] I0629 17:08:10.862941 3740
hierarchical.cpp:1147] Performed allocation for 1 agents in 95525ns
[17:08:11]W: [Step 10/10] I0629 17:08:11.554158 3736 gc.cpp:55] Scheduling
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_HcUaGu/slaves/59345281-cdcf-49ad-a546-9e2584432372-S0/frameworks/59345281-cdcf-49ad-a546-9e2584432372-0000/executors/7ce5efb6-ec84-4a89-822b-bff47f3a9609/runs/a001d565-ff42-4eba-8775-31bc1f107315'
for gc 6.9999935871763days in the future
[17:08:11]W: [Step 10/10] I0629 17:08:11.554222 3735 slave.cpp:4339]
Cleaning up framework 59345281-cdcf-49ad-a546-9e2584432372-0000
[17:08:11]W: [Step 10/10] I0629 17:08:11.554265 3736 gc.cpp:55] Scheduling
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_HcUaGu/slaves/59345281-cdcf-49ad-a546-9e2584432372-S0/frameworks/59345281-cdcf-49ad-a546-9e2584432372-0000/executors/7ce5efb6-ec84-4a89-822b-bff47f3a9609'
for gc 6.9999935864237days in the future
[17:08:11]W: [Step 10/10] I0629 17:08:11.554311 3736 gc.cpp:55] Scheduling
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_HcUaGu/meta/slaves/59345281-cdcf-49ad-a546-9e2584432372-S0/frameworks/59345281-cdcf-49ad-a546-9e2584432372-0000/executors/7ce5efb6-ec84-4a89-822b-bff47f3a9609/runs/a001d565-ff42-4eba-8775-31bc1f107315'
for gc 6.99999358599704days in the future
[17:08:11]W: [Step 10/10] I0629 17:08:11.554334 3736 gc.cpp:55] Scheduling
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_HcUaGu/meta/slaves/59345281-cdcf-49ad-a546-9e2584432372-S0/frameworks/59345281-cdcf-49ad-a546-9e2584432372-0000/executors/7ce5efb6-ec84-4a89-822b-bff47f3a9609'
for gc 6.99999358557926days in the future
[17:08:11]W: [Step 10/10] I0629 17:08:11.554342 3735 slave.cpp:839] Agent
terminating
[17:08:11]W: [Step 10/10] I0629 17:08:11.554358 3736 gc.cpp:55] Scheduling
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_HcUaGu/slaves/59345281-cdcf-49ad-a546-9e2584432372-S0/frameworks/59345281-cdcf-49ad-a546-9e2584432372-0000'
for gc 6.99999358443259days in the future
[17:08:11]W: [Step 10/10] I0629 17:08:11.554381 3736 gc.cpp:55] Scheduling
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_HcUaGu/meta/slaves/59345281-cdcf-49ad-a546-9e2584432372-S0/frameworks/59345281-cdcf-49ad-a546-9e2584432372-0000'
for gc 6.99999358420148days in the future
[17:08:11]W: [Step 10/10] I0629 17:08:11.554450 3739 master.cpp:1369]
Agent 59345281-cdcf-49ad-a546-9e2584432372-S0 at slave(569)@172.30.2.145:46175
(ip-172-30-2-145.mesosphere.io) disconnected
[17:08:11]W: [Step 10/10] I0629 17:08:11.554472 3739 master.cpp:2908]
Disconnecting agent 59345281-cdcf-49ad-a546-9e2584432372-S0 at
slave(569)@172.30.2.145:46175 (ip-172-30-2-145.mesosphere.io)
[17:08:11]W: [Step 10/10] I0629 17:08:11.554504 3739 master.cpp:2927]
Deactivating agent 59345281-cdcf-49ad-a546-9e2584432372-S0 at
slave(569)@172.30.2.145:46175 (ip-172-30-2-145.mesosphere.io)
[17:08:11]W: [Step 10/10] I0629 17:08:11.554590 3739 hierarchical.cpp:568]
Agent 59345281-cdcf-49ad-a546-9e2584432372-S0 deactivated
[17:08:11]W: [Step 10/10] I0629 17:08:11.769428 3741
status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID:
9caaea55-4c6b-4a34-9869-2b00d0c35bfb) for task
7ce5efb6-ec84-4a89-822b-bff47f3a9609 of framework
59345281-cdcf-49ad-a546-9e2584432372-0000 to the agent
[17:08:11]W: [Step 10/10] I0629 17:08:11.771039 3720 master.cpp:1216]
Master terminating
[17:08:11]W: [Step 10/10] I0629 17:08:11.771204 3735 hierarchical.cpp:513]
Removed agent 59345281-cdcf-49ad-a546-9e2584432372-S0
[17:08:11] : [Step 10/10]
../../3rdparty/libprocess/include/process/gmock.hpp:487: Failure
[17:08:11] : [Step 10/10] Actual function call count doesn't match
EXPECT_CALL(filter->mock, filter(testing::A()))...
[17:08:11] : [Step 10/10] Expected args: dispatch matcher (1-byte
object <20>, 16-byte object <20-CB 4D-00 00-00 00-00 00-00 00-00 00-00 00-00>)
[17:08:11]W: [Step 10/10] I0629 17:08:11.788439 3720 cluster.cpp:155]
Creating default 'local' authorizer
[17:08:11] : [Step 10/10] Expected: to be called once
[17:08:11] : [Step 10/10] Actual: never called - unsatisfied and
active
[17:08:11] : [Step 10/10] [ FAILED ]
DiskResource/PersistentVolumeTest.SlaveRecovery/0, where GetParam() = 0 (28947
ms)
{code}
Example correct output:
{code}
[16:43:55] : [Step 10/10] [ RUN ]
DiskResource/PersistentVolumeTest.SlaveRecovery/0
[16:43:55]W: [Step 10/10] I0629 16:43:55.438680 3624 cluster.cpp:155]
Creating default 'local' authorizer
[16:43:55]W: [Step 10/10] I0629 16:43:55.445861 3624 leveldb.cpp:174]
Opened db in 7.040549ms
[16:43:55]W: [Step 10/10] I0629 16:43:55.446467 3624 leveldb.cpp:181]
Compacted db in 583688ns
[16:43:55]W: [Step 10/10] I0629 16:43:55.446485 3624 leveldb.cpp:196]
Created db iterator in 5270ns
[16:43:55]W: [Step 10/10] I0629 16:43:55.446492 3624 leveldb.cpp:202]
Seeked to beginning of db in 380ns
[16:43:55]W: [Step 10/10] I0629 16:43:55.446497 3624 leveldb.cpp:271]
Iterated through 0 keys in the db in 516ns
[16:43:55]W: [Step 10/10] I0629 16:43:55.446511 3624 replica.cpp:779]
Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
[16:43:55]W: [Step 10/10] I0629 16:43:55.446760 3639 recover.cpp:451]
Starting replica recovery
[16:43:55]W: [Step 10/10] I0629 16:43:55.446924 3638 recover.cpp:477]
Replica is in EMPTY status
[16:43:55]W: [Step 10/10] I0629 16:43:55.447260 3638 replica.cpp:673]
Replica in EMPTY status received a broadcasted recover request from
(22868)@172.30.2.177:42583
[16:43:55]W: [Step 10/10] I0629 16:43:55.447357 3639 recover.cpp:197]
Received a recover response from a replica in EMPTY status
[16:43:55]W: [Step 10/10] I0629 16:43:55.447492 3638 recover.cpp:568]
Updating replica status to STARTING
[16:43:55]W: [Step 10/10] I0629 16:43:55.447844 3641 master.cpp:382]
Master f6bafbec-70f1-4462-a64b-3fddc24c0600 (ip-172-30-2-177.mesosphere.io)
started on 172.30.2.177:42583
[16:43:55]W: [Step 10/10] I0629 16:43:55.447856 3641 master.cpp:384] Flags
at startup: --acls="" --agent_ping_timeout="15secs"
--agent_reregister_timeout="10mins" --allocation_interval="1secs"
--allocator="HierarchicalDRF" --authenticate_agents="true"
--authenticate_frameworks="true" --authenticate_http="true"
--authenticate_http_frameworks="true" --authenticators="crammd5"
--authorizers="local" --credentials="/tmp/Gi8ZgS/credentials"
--framework_sorter="drf" --help="false" --hostname_lookup="true"
--http_authenticators="basic" --http_framework_authenticators="basic"
--initialize_driver_logging="true" --log_auto_initialize="true"
--logbufsecs="0" --logging_level="INFO" --max_agent_ping_timeouts="5"
--max_completed_frameworks="50" --max_completed_tasks_per_framework="1000"
--quiet="false" --recovery_agent_removal_limit="100%"
--registry="replicated_log" --registry_fetch_timeout="1mins"
--registry_store_timeout="100secs" --registry_strict="true"
--root_submissions="true" --user_sorter="drf" --version="false"
--webui_dir="/usr/local/share/mesos/webui" --work_dir="/tmp/Gi8ZgS/master"
--zk_session_timeout="10secs"
[16:43:55]W: [Step 10/10] I0629 16:43:55.447975 3641 master.cpp:434]
Master only allowing authenticated frameworks to register
[16:43:55]W: [Step 10/10] I0629 16:43:55.447981 3641 master.cpp:448]
Master only allowing authenticated agents to register
[16:43:55]W: [Step 10/10] I0629 16:43:55.447985 3641 master.cpp:461]
Master only allowing authenticated HTTP frameworks to register
[16:43:55]W: [Step 10/10] I0629 16:43:55.447989 3641 credentials.hpp:37]
Loading credentials for authentication from '/tmp/Gi8ZgS/credentials'
[16:43:55]W: [Step 10/10] I0629 16:43:55.448065 3641 master.cpp:506] Using
default 'crammd5' authenticator
[16:43:55]W: [Step 10/10] I0629 16:43:55.448102 3641 master.cpp:578] Using
default 'basic' HTTP authenticator
[16:43:55]W: [Step 10/10] I0629 16:43:55.448149 3641 master.cpp:658] Using
default 'basic' HTTP framework authenticator
[16:43:55]W: [Step 10/10] I0629 16:43:55.448174 3641 master.cpp:705]
Authorization enabled
[16:43:55]W: [Step 10/10] I0629 16:43:55.448238 3638 hierarchical.cpp:142]
Initialized hierarchical allocator process
[16:43:55]W: [Step 10/10] I0629 16:43:55.448299 3645
whitelist_watcher.cpp:77] No whitelist given
[16:43:55]W: [Step 10/10] I0629 16:43:55.448849 3641 master.cpp:1971] The
newly elected leader is [email protected]:42583 with id
f6bafbec-70f1-4462-a64b-3fddc24c0600
[16:43:55]W: [Step 10/10] I0629 16:43:55.448864 3641 master.cpp:1984]
Elected as the leading master!
[16:43:55]W: [Step 10/10] I0629 16:43:55.448869 3641 master.cpp:1671]
Recovering from registrar
[16:43:55]W: [Step 10/10] I0629 16:43:55.448922 3638 registrar.cpp:332]
Recovering registrar
[16:43:55]W: [Step 10/10] I0629 16:43:55.450688 3644 leveldb.cpp:304]
Persisting metadata (8 bytes) to leveldb took 3.066397ms
[16:43:55]W: [Step 10/10] I0629 16:43:55.450707 3644 replica.cpp:320]
Persisted replica status to STARTING
[16:43:55]W: [Step 10/10] I0629 16:43:55.450759 3644 recover.cpp:477]
Replica is in STARTING status
[16:43:55]W: [Step 10/10] I0629 16:43:55.451028 3644 replica.cpp:673]
Replica in STARTING status received a broadcasted recover request from
(22871)@172.30.2.177:42583
[16:43:55]W: [Step 10/10] I0629 16:43:55.451129 3644 recover.cpp:197]
Received a recover response from a replica in STARTING status
[16:43:55]W: [Step 10/10] I0629 16:43:55.451304 3640 recover.cpp:568]
Updating replica status to VOTING
[16:43:55]W: [Step 10/10] I0629 16:43:55.451817 3640 leveldb.cpp:304]
Persisting metadata (8 bytes) to leveldb took 468448ns
[16:43:55]W: [Step 10/10] I0629 16:43:55.451833 3640 replica.cpp:320]
Persisted replica status to VOTING
[16:43:55]W: [Step 10/10] I0629 16:43:55.451867 3640 recover.cpp:582]
Successfully joined the Paxos group
[16:43:55]W: [Step 10/10] I0629 16:43:55.451911 3640 recover.cpp:466]
Recover process terminated
[16:43:55]W: [Step 10/10] I0629 16:43:55.452055 3640 log.cpp:553]
Attempting to start the writer
[16:43:55]W: [Step 10/10] I0629 16:43:55.452388 3644 replica.cpp:493]
Replica received implicit promise request from (22872)@172.30.2.177:42583 with
proposal 1
[16:43:55]W: [Step 10/10] I0629 16:43:55.452898 3644 leveldb.cpp:304]
Persisting metadata (8 bytes) to leveldb took 488090ns
[16:43:55]W: [Step 10/10] I0629 16:43:55.452914 3644 replica.cpp:342]
Persisted promised to 1
[16:43:55]W: [Step 10/10] I0629 16:43:55.453145 3640 coordinator.cpp:238]
Coordinator attempting to fill missing positions
[16:43:55]W: [Step 10/10] I0629 16:43:55.453668 3639 replica.cpp:388]
Replica received explicit promise request from (22873)@172.30.2.177:42583 for
position 0 with proposal 2
[16:43:55]W: [Step 10/10] I0629 16:43:55.454131 3639 leveldb.cpp:341]
Persisting action (8 bytes) to leveldb took 440734ns
[16:43:55]W: [Step 10/10] I0629 16:43:55.454145 3639 replica.cpp:712]
Persisted action at 0
[16:43:55]W: [Step 10/10] I0629 16:43:55.454591 3639 replica.cpp:537]
Replica received write request for position 0 from (22874)@172.30.2.177:42583
[16:43:55]W: [Step 10/10] I0629 16:43:55.454613 3639 leveldb.cpp:436]
Reading position from leveldb took 8298ns
[16:43:55]W: [Step 10/10] I0629 16:43:55.455452 3639 leveldb.cpp:341]
Persisting action (14 bytes) to leveldb took 825144ns
[16:43:55]W: [Step 10/10] I0629 16:43:55.455466 3639 replica.cpp:712]
Persisted action at 0
[16:43:55]W: [Step 10/10] I0629 16:43:55.455708 3643 replica.cpp:691]
Replica received learned notice for position 0 from @0.0.0.0:0
[16:43:55]W: [Step 10/10] I0629 16:43:55.456187 3643 leveldb.cpp:341]
Persisting action (16 bytes) to leveldb took 460076ns
[16:43:55]W: [Step 10/10] I0629 16:43:55.456200 3643 replica.cpp:712]
Persisted action at 0
[16:43:55]W: [Step 10/10] I0629 16:43:55.456205 3643 replica.cpp:697]
Replica learned NOP action at position 0
[16:43:55]W: [Step 10/10] I0629 16:43:55.456346 3644 log.cpp:569] Writer
started with ending position 0
[16:43:55]W: [Step 10/10] I0629 16:43:55.456661 3642 leveldb.cpp:436]
Reading position from leveldb took 9712ns
[16:43:55]W: [Step 10/10] I0629 16:43:55.456921 3642 registrar.cpp:365]
Successfully fetched the registry (0B) in 7.9808ms
[16:43:55]W: [Step 10/10] I0629 16:43:55.456949 3642 registrar.cpp:464]
Applied 1 operations in 2644ns; attempting to update the 'registry'
[16:43:55]W: [Step 10/10] I0629 16:43:55.457131 3639 log.cpp:577]
Attempting to append 209 bytes to the log
[16:43:55]W: [Step 10/10] I0629 16:43:55.457190 3640 coordinator.cpp:348]
Coordinator attempting to write APPEND action at position 1
[16:43:55]W: [Step 10/10] I0629 16:43:55.457497 3641 replica.cpp:537]
Replica received write request for position 1 from (22875)@172.30.2.177:42583
[16:43:55]W: [Step 10/10] I0629 16:43:55.457970 3641 leveldb.cpp:341]
Persisting action (228 bytes) to leveldb took 454712ns
[16:43:55]W: [Step 10/10] I0629 16:43:55.457983 3641 replica.cpp:712]
Persisted action at 1
[16:43:55]W: [Step 10/10] I0629 16:43:55.458189 3645 replica.cpp:691]
Replica received learned notice for position 1 from @0.0.0.0:0
[16:43:55]W: [Step 10/10] I0629 16:43:55.458724 3645 leveldb.cpp:341]
Persisting action (230 bytes) to leveldb took 513223ns
[16:43:55]W: [Step 10/10] I0629 16:43:55.458739 3645 replica.cpp:712]
Persisted action at 1
[16:43:55]W: [Step 10/10] I0629 16:43:55.458745 3645 replica.cpp:697]
Replica learned APPEND action at position 1
[16:43:55]W: [Step 10/10] I0629 16:43:55.458955 3642 registrar.cpp:509]
Successfully updated the 'registry' in 1.98784ms
[16:43:55]W: [Step 10/10] I0629 16:43:55.459015 3638 log.cpp:596]
Attempting to truncate the log to 1
[16:43:55]W: [Step 10/10] I0629 16:43:55.459034 3642 registrar.cpp:395]
Successfully recovered registrar
[16:43:55]W: [Step 10/10] I0629 16:43:55.459062 3638 coordinator.cpp:348]
Coordinator attempting to write TRUNCATE action at position 2
[16:43:55]W: [Step 10/10] I0629 16:43:55.459154 3639 master.cpp:1779]
Recovered 0 agents from the Registry (170B) ; allowing 10mins for agents to
re-register
[16:43:55]W: [Step 10/10] I0629 16:43:55.459214 3641 hierarchical.cpp:169]
Skipping recovery of hierarchical allocator: nothing to recover
[16:43:55]W: [Step 10/10] I0629 16:43:55.459489 3639 replica.cpp:537]
Replica received write request for position 2 from (22876)@172.30.2.177:42583
[16:43:55]W: [Step 10/10] I0629 16:43:55.459962 3639 leveldb.cpp:341]
Persisting action (16 bytes) to leveldb took 455920ns
[16:43:55]W: [Step 10/10] I0629 16:43:55.459974 3639 replica.cpp:712]
Persisted action at 2
[16:43:55]W: [Step 10/10] I0629 16:43:55.460204 3640 replica.cpp:691]
Replica received learned notice for position 2 from @0.0.0.0:0
[16:43:55]W: [Step 10/10] I0629 16:43:55.460660 3640 leveldb.cpp:341]
Persisting action (18 bytes) to leveldb took 435975ns
[16:43:55]W: [Step 10/10] I0629 16:43:55.460680 3640 leveldb.cpp:399]
Deleting ~1 keys from leveldb took 8718ns
[16:43:55]W: [Step 10/10] I0629 16:43:55.460687 3640 replica.cpp:712]
Persisted action at 2
[16:43:55]W: [Step 10/10] I0629 16:43:55.460692 3640 replica.cpp:697]
Replica learned TRUNCATE action at position 2
[16:43:55]W: [Step 10/10] I0629 16:43:55.470141 3624 resources.cpp:572]
Parsing resources as JSON failed: cpus:2;mem:2048
[16:43:55]W: [Step 10/10] Trying semicolon-delimited string format instead
[16:43:55]W: [Step 10/10] I0629 16:43:55.470999 3624
containerizer.cpp:201] Using isolation:
posix/cpu,posix/mem,filesystem/posix,network/cni
[16:43:55]W: [Step 10/10] I0629 16:43:55.474357 3624
linux_launcher.cpp:101] Using /sys/fs/cgroup/freezer as the freezer hierarchy
for the Linux launcher
[16:43:55]W: [Step 10/10] I0629 16:43:55.475308 3624 cluster.cpp:432]
Creating default 'local' authorizer
[16:43:55]W: [Step 10/10] I0629 16:43:55.475801 3644 slave.cpp:203] Agent
started on 569)@172.30.2.177:42583
[16:43:55]W: [Step 10/10] I0629 16:43:55.475812 3644 slave.cpp:204] 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/DiskResource_PersistentVolumeTest_SlaveRecovery_0_Obawjb/credential"
--default_role="*" --disk_watch_interval="1mins" --docker="docker"
--docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io";
--docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock"
--docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker"
--docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume"
--enforce_container_disk_quota="false" --executor_registration_timeout="1mins"
--executor_shutdown_grace_period="5secs"
--fetcher_cache_dir="/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_Obawjb/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/DiskResource_PersistentVolumeTest_SlaveRecovery_0_Obawjb/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="[{"name":"cpus","role":"*","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","role":"*","scalar":{"value":2048.0},"type":"SCALAR"},{"name":"disk","role":"role1","scalar":{"value":4096.0},"type":"SCALAR"}]"
--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/DiskResource_PersistentVolumeTest_SlaveRecovery_0_Obawjb"
[16:43:55]W: [Step 10/10] I0629 16:43:55.476007 3644 credentials.hpp:86]
Loading credential for authentication from
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_Obawjb/credential'
[16:43:55]W: [Step 10/10] I0629 16:43:55.476059 3644 slave.cpp:341] Agent
using credential for: test-principal
[16:43:55]W: [Step 10/10] I0629 16:43:55.476069 3644 credentials.hpp:37]
Loading credentials for authentication from
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_Obawjb/http_credentials'
[16:43:55]W: [Step 10/10] I0629 16:43:55.476135 3644 slave.cpp:393] Using
default 'basic' HTTP authenticator
[16:43:55]W: [Step 10/10] I0629 16:43:55.476310 3624 sched.cpp:224]
Version: 1.0.0
[16:43:55]W: [Step 10/10] I0629 16:43:55.476441 3644 slave.cpp:592] Agent
resources: cpus(*):2; mem(*):2048; disk(role1):4096; ports(*):[31000-32000]
[16:43:55]W: [Step 10/10] I0629 16:43:55.476475 3644 slave.cpp:600] Agent
attributes: [ ]
[16:43:55]W: [Step 10/10] I0629 16:43:55.476485 3644 slave.cpp:605] Agent
hostname: ip-172-30-2-177.mesosphere.io
[16:43:55]W: [Step 10/10] I0629 16:43:55.476511 3641 sched.cpp:328] New
master detected at [email protected]:42583
[16:43:55]W: [Step 10/10] I0629 16:43:55.476533 3641 sched.cpp:394]
Authenticating with master [email protected]:42583
[16:43:55]W: [Step 10/10] I0629 16:43:55.476539 3641 sched.cpp:401] Using
default CRAM-MD5 authenticatee
[16:43:55]W: [Step 10/10] I0629 16:43:55.476698 3638
authenticatee.cpp:121] Creating new client SASL connection
[16:43:55]W: [Step 10/10] I0629 16:43:55.476800 3645 state.cpp:57]
Recovering state from
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_Obawjb/meta'
[16:43:55]W: [Step 10/10] I0629 16:43:55.476876 3641 master.cpp:5966]
Authenticating [email protected]:42583
[16:43:55]W: [Step 10/10] I0629 16:43:55.476923 3638
status_update_manager.cpp:200] Recovering status update manager
[16:43:55]W: [Step 10/10] I0629 16:43:55.476954 3643
authenticator.cpp:414] Starting authentication session for
crammd5_authenticatee(1120)@172.30.2.177:42583
[16:43:55]W: [Step 10/10] I0629 16:43:55.477030 3644 authenticator.cpp:98]
Creating new server SASL connection
[16:43:55]W: [Step 10/10] I0629 16:43:55.477048 3642
containerizer.cpp:514] Recovering containerizer
[16:43:55]W: [Step 10/10] I0629 16:43:55.477154 3644
authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
[16:43:55]W: [Step 10/10] I0629 16:43:55.477167 3644
authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
[16:43:55]W: [Step 10/10] I0629 16:43:55.477206 3644
authenticator.cpp:204] Received SASL authentication start
[16:43:55]W: [Step 10/10] I0629 16:43:55.477241 3644
authenticator.cpp:326] Authentication requires more steps
[16:43:55]W: [Step 10/10] I0629 16:43:55.477272 3644
authenticatee.cpp:259] Received SASL authentication step
[16:43:55]W: [Step 10/10] I0629 16:43:55.477319 3644
authenticator.cpp:232] Received SASL authentication step
[16:43:55]W: [Step 10/10] I0629 16:43:55.477339 3644 auxprop.cpp:107]
Request to lookup properties for user: 'test-principal' realm:
'ip-172-30-2-177.mesosphere.io' server FQDN: 'ip-172-30-2-177.mesosphere.io'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
[16:43:55]W: [Step 10/10] I0629 16:43:55.477345 3644 auxprop.cpp:179]
Looking up auxiliary property '*userPassword'
[16:43:55]W: [Step 10/10] I0629 16:43:55.477352 3644 auxprop.cpp:179]
Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
[16:43:55]W: [Step 10/10] I0629 16:43:55.477360 3644 auxprop.cpp:107]
Request to lookup properties for user: 'test-principal' realm:
'ip-172-30-2-177.mesosphere.io' server FQDN: 'ip-172-30-2-177.mesosphere.io'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
[16:43:55]W: [Step 10/10] I0629 16:43:55.477365 3644 auxprop.cpp:129]
Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
[16:43:55]W: [Step 10/10] I0629 16:43:55.477367 3644 auxprop.cpp:129]
Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID
== true
[16:43:55]W: [Step 10/10] I0629 16:43:55.477376 3644
authenticator.cpp:318] Authentication success
[16:43:55]W: [Step 10/10] I0629 16:43:55.477421 3644
authenticatee.cpp:299] Authentication success
[16:43:55]W: [Step 10/10] I0629 16:43:55.477437 3645
authenticator.cpp:432] Authentication session cleanup for
crammd5_authenticatee(1120)@172.30.2.177:42583
[16:43:55]W: [Step 10/10] I0629 16:43:55.477463 3641 master.cpp:5996]
Successfully authenticated principal 'test-principal' at
[email protected]:42583
[16:43:55]W: [Step 10/10] I0629 16:43:55.477596 3639 sched.cpp:484]
Successfully authenticated with master [email protected]:42583
[16:43:55]W: [Step 10/10] I0629 16:43:55.477607 3639 sched.cpp:800]
Sending SUBSCRIBE call to [email protected]:42583
[16:43:55]W: [Step 10/10] I0629 16:43:55.477675 3639 sched.cpp:833] Will
retry registration in 1.579777559secs if necessary
[16:43:55]W: [Step 10/10] I0629 16:43:55.477715 3645 master.cpp:2548]
Received SUBSCRIBE call for framework 'default' at
[email protected]:42583
[16:43:55]W: [Step 10/10] I0629 16:43:55.477740 3645 master.cpp:2010]
Authorizing framework principal 'test-principal' to receive offers for role
'role1'
[16:43:55]W: [Step 10/10] I0629 16:43:55.477912 3644 master.cpp:2624]
Subscribing framework default with checkpointing enabled and capabilities [ ]
[16:43:55]W: [Step 10/10] I0629 16:43:55.477990 3643 provisioner.cpp:253]
Provisioner recovery complete
[16:43:55]W: [Step 10/10] I0629 16:43:55.478054 3642 hierarchical.cpp:268]
Added framework f6bafbec-70f1-4462-a64b-3fddc24c0600-0000
[16:43:55]W: [Step 10/10] I0629 16:43:55.478077 3642
hierarchical.cpp:1512] No allocations performed
[16:43:55]W: [Step 10/10] I0629 16:43:55.478088 3642
hierarchical.cpp:1607] No inverse offers to send out!
[16:43:55]W: [Step 10/10] I0629 16:43:55.478102 3642
hierarchical.cpp:1147] Performed allocation for 0 agents in 32864ns
[16:43:55]W: [Step 10/10] I0629 16:43:55.478126 3638 sched.cpp:723]
Framework registered with f6bafbec-70f1-4462-a64b-3fddc24c0600-0000
[16:43:55]W: [Step 10/10] I0629 16:43:55.478173 3638 sched.cpp:737]
Scheduler::registered took 30913ns
[16:43:55]W: [Step 10/10] I0629 16:43:55.478183 3643 slave.cpp:4840]
Finished recovery
[16:43:55]W: [Step 10/10] I0629 16:43:55.478376 3643 slave.cpp:5012]
Querying resource estimator for oversubscribable resources
[16:43:55]W: [Step 10/10] I0629 16:43:55.478449 3643 slave.cpp:967] New
master detected at [email protected]:42583
[16:43:55]W: [Step 10/10] I0629 16:43:55.478458 3641
status_update_manager.cpp:174] Pausing sending status updates
[16:43:55]W: [Step 10/10] I0629 16:43:55.478461 3643 slave.cpp:1029]
Authenticating with master [email protected]:42583
[16:43:55]W: [Step 10/10] I0629 16:43:55.478497 3643 slave.cpp:1040] Using
default CRAM-MD5 authenticatee
[16:43:55]W: [Step 10/10] I0629 16:43:55.478533 3643 slave.cpp:1002]
Detecting new master
[16:43:55]W: [Step 10/10] I0629 16:43:55.478554 3638
authenticatee.cpp:121] Creating new client SASL connection
[16:43:55]W: [Step 10/10] I0629 16:43:55.478579 3643 slave.cpp:5026]
Received oversubscribable resources from the resource estimator
[16:43:55]W: [Step 10/10] I0629 16:43:55.478690 3638 master.cpp:5966]
Authenticating slave(569)@172.30.2.177:42583
[16:43:55]W: [Step 10/10] I0629 16:43:55.478749 3645
authenticator.cpp:414] Starting authentication session for
crammd5_authenticatee(1121)@172.30.2.177:42583
[16:43:55]W: [Step 10/10] I0629 16:43:55.478827 3644 authenticator.cpp:98]
Creating new server SASL connection
[16:43:55]W: [Step 10/10] I0629 16:43:55.478937 3644
authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
[16:43:55]W: [Step 10/10] I0629 16:43:55.478957 3644
authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
[16:43:55]W: [Step 10/10] I0629 16:43:55.479007 3642
authenticator.cpp:204] Received SASL authentication start
[16:43:55]W: [Step 10/10] I0629 16:43:55.479037 3642
authenticator.cpp:326] Authentication requires more steps
[16:43:55]W: [Step 10/10] I0629 16:43:55.479077 3642
authenticatee.cpp:259] Received SASL authentication step
[16:43:55]W: [Step 10/10] I0629 16:43:55.479130 3642
authenticator.cpp:232] Received SASL authentication step
[16:43:55]W: [Step 10/10] I0629 16:43:55.479145 3642 auxprop.cpp:107]
Request to lookup properties for user: 'test-principal' realm:
'ip-172-30-2-177.mesosphere.io' server FQDN: 'ip-172-30-2-177.mesosphere.io'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
[16:43:55]W: [Step 10/10] I0629 16:43:55.479151 3642 auxprop.cpp:179]
Looking up auxiliary property '*userPassword'
[16:43:55]W: [Step 10/10] I0629 16:43:55.479156 3642 auxprop.cpp:179]
Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
[16:43:55]W: [Step 10/10] I0629 16:43:55.479162 3642 auxprop.cpp:107]
Request to lookup properties for user: 'test-principal' realm:
'ip-172-30-2-177.mesosphere.io' server FQDN: 'ip-172-30-2-177.mesosphere.io'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
[16:43:55]W: [Step 10/10] I0629 16:43:55.479166 3642 auxprop.cpp:129]
Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
[16:43:55]W: [Step 10/10] I0629 16:43:55.479171 3642 auxprop.cpp:129]
Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID
== true
[16:43:55]W: [Step 10/10] I0629 16:43:55.479181 3642
authenticator.cpp:318] Authentication success
[16:43:55]W: [Step 10/10] I0629 16:43:55.479235 3641
authenticatee.cpp:299] Authentication success
[16:43:55]W: [Step 10/10] I0629 16:43:55.479259 3642 master.cpp:5996]
Successfully authenticated principal 'test-principal' at
slave(569)@172.30.2.177:42583
[16:43:55]W: [Step 10/10] I0629 16:43:55.479281 3643
authenticator.cpp:432] Authentication session cleanup for
crammd5_authenticatee(1121)@172.30.2.177:42583
[16:43:55]W: [Step 10/10] I0629 16:43:55.479390 3641 slave.cpp:1108]
Successfully authenticated with master [email protected]:42583
[16:43:55]W: [Step 10/10] I0629 16:43:55.479449 3641 slave.cpp:1511] Will
retry registration in 15.109725ms if necessary
[16:43:55]W: [Step 10/10] I0629 16:43:55.479496 3642 master.cpp:4674]
Registering agent at slave(569)@172.30.2.177:42583
(ip-172-30-2-177.mesosphere.io) with id f6bafbec-70f1-4462-a64b-3fddc24c0600-S0
[16:43:55]W: [Step 10/10] I0629 16:43:55.479609 3638 registrar.cpp:464]
Applied 1 operations in 16953ns; attempting to update the 'registry'
[16:43:55]W: [Step 10/10] I0629 16:43:55.479835 3641 log.cpp:577]
Attempting to append 399 bytes to the log
[16:43:55]W: [Step 10/10] I0629 16:43:55.479897 3640 coordinator.cpp:348]
Coordinator attempting to write APPEND action at position 3
[16:43:55]W: [Step 10/10] I0629 16:43:55.480178 3642 replica.cpp:537]
Replica received write request for position 3 from (22894)@172.30.2.177:42583
[16:43:55]W: [Step 10/10] I0629 16:43:55.480756 3642 leveldb.cpp:341]
Persisting action (418 bytes) to leveldb took 559037ns
[16:43:55]W: [Step 10/10] I0629 16:43:55.480768 3642 replica.cpp:712]
Persisted action at 3
[16:43:55]W: [Step 10/10] I0629 16:43:55.480970 3639 replica.cpp:691]
Replica received learned notice for position 3 from @0.0.0.0:0
[16:43:55]W: [Step 10/10] I0629 16:43:55.481449 3639 leveldb.cpp:341]
Persisting action (420 bytes) to leveldb took 459322ns
[16:43:55]W: [Step 10/10] I0629 16:43:55.481462 3639 replica.cpp:712]
Persisted action at 3
[16:43:55]W: [Step 10/10] I0629 16:43:55.481467 3639 replica.cpp:697]
Replica learned APPEND action at position 3
[16:43:55]W: [Step 10/10] I0629 16:43:55.481745 3642 registrar.cpp:509]
Successfully updated the 'registry' in 2.113024ms
[16:43:55]W: [Step 10/10] I0629 16:43:55.481818 3645 log.cpp:596]
Attempting to truncate the log to 3
[16:43:55]W: [Step 10/10] I0629 16:43:55.481879 3644 coordinator.cpp:348]
Coordinator attempting to write TRUNCATE action at position 4
[16:43:55]W: [Step 10/10] I0629 16:43:55.481940 3641 slave.cpp:3742]
Received ping from slave-observer(517)@172.30.2.177:42583
[16:43:55]W: [Step 10/10] I0629 16:43:55.482019 3643 master.cpp:4743]
Registered agent f6bafbec-70f1-4462-a64b-3fddc24c0600-S0 at
slave(569)@172.30.2.177:42583 (ip-172-30-2-177.mesosphere.io) with cpus(*):2;
mem(*):2048; disk(role1):4096; ports(*):[31000-32000]
[16:43:55]W: [Step 10/10] I0629 16:43:55.482040 3644 slave.cpp:1152]
Registered with master [email protected]:42583; given agent ID
f6bafbec-70f1-4462-a64b-3fddc24c0600-S0
[16:43:55]W: [Step 10/10] I0629 16:43:55.482053 3639 hierarchical.cpp:481]
Added agent f6bafbec-70f1-4462-a64b-3fddc24c0600-S0
(ip-172-30-2-177.mesosphere.io) with cpus(*):2; mem(*):2048; disk(role1):4096;
ports(*):[31000-32000] (allocated: )
[16:43:55]W: [Step 10/10] I0629 16:43:55.482069 3644 fetcher.cpp:86]
Clearing fetcher cache
[16:43:55]W: [Step 10/10] I0629 16:43:55.482147 3643
status_update_manager.cpp:181] Resuming sending status updates
[16:43:55]W: [Step 10/10] I0629 16:43:55.482214 3641 replica.cpp:537]
Replica received write request for position 4 from (22895)@172.30.2.177:42583
[16:43:55]W: [Step 10/10] I0629 16:43:55.482218 3639
hierarchical.cpp:1607] No inverse offers to send out!
[16:43:55]W: [Step 10/10] I0629 16:43:55.482262 3639
hierarchical.cpp:1170] Performed allocation for agent
f6bafbec-70f1-4462-a64b-3fddc24c0600-S0 in 173730ns
[16:43:55]W: [Step 10/10] I0629 16:43:55.482269 3644 slave.cpp:1175]
Checkpointing SlaveInfo to
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_Obawjb/meta/slaves/f6bafbec-70f1-4462-a64b-3fddc24c0600-S0/slave.info'
[16:43:55]W: [Step 10/10] I0629 16:43:55.482326 3640 master.cpp:5795]
Sending 1 offers to framework f6bafbec-70f1-4462-a64b-3fddc24c0600-0000
(default) at [email protected]:42583
[16:43:55]W: [Step 10/10] I0629 16:43:55.482383 3644 slave.cpp:1212]
Forwarding total oversubscribed resources
[16:43:55]W: [Step 10/10] I0629 16:43:55.482451 3644 master.cpp:5089]
Received update of agent f6bafbec-70f1-4462-a64b-3fddc24c0600-S0 at
slave(569)@172.30.2.177:42583 (ip-172-30-2-177.mesosphere.io) with total
oversubscribed resources
[16:43:55]W: [Step 10/10] I0629 16:43:55.482461 3640 sched.cpp:897]
Scheduler::resourceOffers took 49233ns
[16:43:55]W: [Step 10/10] I0629 16:43:55.482590 3624 resources.cpp:572]
Parsing resources as JSON failed: cpus:1;mem:128
[16:43:55]W: [Step 10/10] Trying semicolon-delimited string format instead
[16:43:55]W: [Step 10/10] I0629 16:43:55.482614 3644 hierarchical.cpp:539]
Agent f6bafbec-70f1-4462-a64b-3fddc24c0600-S0 (ip-172-30-2-177.mesosphere.io)
updated with oversubscribed resources (total: cpus(*):2; mem(*):2048;
disk(role1):4096; ports(*):[31000-32000], allocated: disk(role1):4096;
cpus(*):2; mem(*):2048; ports(*):[31000-32000])
[16:43:55]W: [Step 10/10] I0629 16:43:55.482702 3641 leveldb.cpp:341]
Persisting action (16 bytes) to leveldb took 454994ns
[16:43:55]W: [Step 10/10] I0629 16:43:55.482710 3644
hierarchical.cpp:1512] No allocations performed
[16:43:55]W: [Step 10/10] I0629 16:43:55.482720 3641 replica.cpp:712]
Persisted action at 4
[16:43:55]W: [Step 10/10] I0629 16:43:55.482758 3644
hierarchical.cpp:1607] No inverse offers to send out!
[16:43:55]W: [Step 10/10] I0629 16:43:55.482777 3644
hierarchical.cpp:1170] Performed allocation for agent
f6bafbec-70f1-4462-a64b-3fddc24c0600-S0 in 140401ns
[16:43:55]W: [Step 10/10] I0629 16:43:55.483016 3641 master.cpp:3466]
Processing ACCEPT call for offers: [ f6bafbec-70f1-4462-a64b-3fddc24c0600-O0 ]
on agent f6bafbec-70f1-4462-a64b-3fddc24c0600-S0 at
slave(569)@172.30.2.177:42583 (ip-172-30-2-177.mesosphere.io) for framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000 (default) at
[email protected]:42583
[16:43:55]W: [Step 10/10] I0629 16:43:55.483047 3641 master.cpp:3251]
Authorizing principal 'test-principal' to create volumes
[16:43:55]W: [Step 10/10] I0629 16:43:55.483093 3641 master.cpp:3104]
Authorizing framework principal 'test-principal' to launch task
6ab9e748-a3cf-4417-9e1e-5899a5090af0
[16:43:55]W: [Step 10/10] I0629 16:43:55.483129 3640 replica.cpp:691]
Replica received learned notice for position 4 from @0.0.0.0:0
[16:43:55]W: [Step 10/10] I0629 16:43:55.483485 3641 master.cpp:3799]
Applying CREATE operation for volumes disk(role1)[id1:path1]:2048 from
framework f6bafbec-70f1-4462-a64b-3fddc24c0600-0000 (default) at
[email protected]:42583 to agent
f6bafbec-70f1-4462-a64b-3fddc24c0600-S0 at slave(569)@172.30.2.177:42583
(ip-172-30-2-177.mesosphere.io)
[16:43:55]W: [Step 10/10] I0629 16:43:55.483582 3641 master.cpp:7048]
Sending checkpointed resources disk(role1)[id1:path1]:2048 to agent
f6bafbec-70f1-4462-a64b-3fddc24c0600-S0 at slave(569)@172.30.2.177:42583
(ip-172-30-2-177.mesosphere.io)
[16:43:55]W: [Step 10/10] I0629 16:43:55.483604 3640 leveldb.cpp:341]
Persisting action (18 bytes) to leveldb took 453606ns
[16:43:55]W: [Step 10/10] I0629 16:43:55.483638 3640 leveldb.cpp:399]
Deleting ~2 keys from leveldb took 15905ns
[16:43:55]W: [Step 10/10] I0629 16:43:55.483651 3640 replica.cpp:712]
Persisted action at 4
[16:43:55]W: [Step 10/10] I0629 16:43:55.483660 3640 replica.cpp:697]
Replica learned TRUNCATE action at position 4
[16:43:55]W: [Step 10/10] I0629 16:43:55.483810 3641 master.cpp:7515]
Adding task 6ab9e748-a3cf-4417-9e1e-5899a5090af0 with resources cpus(*):1;
mem(*):128; disk(role1)[id1:path1]:2048 on agent
f6bafbec-70f1-4462-a64b-3fddc24c0600-S0 (ip-172-30-2-177.mesosphere.io)
[16:43:55]W: [Step 10/10] I0629 16:43:55.483835 3639 hierarchical.cpp:662]
Updated allocation of framework f6bafbec-70f1-4462-a64b-3fddc24c0600-0000 on
agent f6bafbec-70f1-4462-a64b-3fddc24c0600-S0 from disk(role1):4096; cpus(*):2;
mem(*):2048; ports(*):[31000-32000] to disk(role1):2048; cpus(*):2;
mem(*):2048; ports(*):[31000-32000]; disk(role1)[id1:path1]:2048
[16:43:55]W: [Step 10/10] I0629 16:43:55.483849 3641 master.cpp:3955]
Launching task 6ab9e748-a3cf-4417-9e1e-5899a5090af0 of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000 (default) at
[email protected]:42583 with
resources cpus(*):1; mem(*):128; disk(role1)[id1:path1]:2048 on agent
f6bafbec-70f1-4462-a64b-3fddc24c0600-S0 at slave(569)@172.30.2.177:42583
(ip-172-30-2-177.mesosphere.io)
[16:43:55]W: [Step 10/10] I0629 16:43:55.483863 3638 slave.cpp:2582]
Updated checkpointed resources from to disk(role1)[id1:path1]:2048
[16:43:55]W: [Step 10/10] I0629 16:43:55.483957 3642 slave.cpp:1551] Got
assigned task 6ab9e748-a3cf-4417-9e1e-5899a5090af0 for framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000
[16:43:55]W: [Step 10/10] I0629 16:43:55.483983 3643 hierarchical.cpp:899]
Recovered disk(role1):2048; cpus(*):1; mem(*):1920; ports(*):[31000-32000]
(total: cpus(*):2; mem(*):2048; disk(role1):2048; ports(*):[31000-32000];
disk(role1)[id1:path1]:2048, allocated: disk(role1)[id1:path1]:2048; cpus(*):1;
mem(*):128) on agent f6bafbec-70f1-4462-a64b-3fddc24c0600-S0 from framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000
[16:43:55]W: [Step 10/10] I0629 16:43:55.484007 3643 hierarchical.cpp:936]
Framework f6bafbec-70f1-4462-a64b-3fddc24c0600-0000 filtered agent
f6bafbec-70f1-4462-a64b-3fddc24c0600-S0 for 5secs
[16:43:55]W: [Step 10/10] I0629 16:43:55.484021 3642 slave.cpp:5646]
Checkpointing FrameworkInfo to
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_Obawjb/meta/slaves/f6bafbec-70f1-4462-a64b-3fddc24c0600-S0/frameworks/f6bafbec-70f1-4462-a64b-3fddc24c0600-0000/framework.info'
[16:43:55]W: [Step 10/10] I0629 16:43:55.484134 3642 slave.cpp:5657]
Checkpointing framework pid
'[email protected]:42583' to
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_Obawjb/meta/slaves/f6bafbec-70f1-4462-a64b-3fddc24c0600-S0/frameworks/f6bafbec-70f1-4462-a64b-3fddc24c0600-0000/framework.pid'
[16:43:55]W: [Step 10/10] I0629 16:43:55.484230 3642 resources.cpp:572]
Parsing resources as JSON failed: cpus:0.1;mem:32
[16:43:55]W: [Step 10/10] Trying semicolon-delimited string format instead
[16:43:55]W: [Step 10/10] I0629 16:43:55.484354 3642 slave.cpp:1670]
Launching task 6ab9e748-a3cf-4417-9e1e-5899a5090af0 for framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000
[16:43:55]W: [Step 10/10] I0629 16:43:55.484385 3642 resources.cpp:572]
Parsing resources as JSON failed: cpus:0.1;mem:32
[16:43:55]W: [Step 10/10] Trying semicolon-delimited string format instead
[16:43:55]W: [Step 10/10] I0629 16:43:55.484575 3642 paths.cpp:528] Trying
to chown
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_Obawjb/slaves/f6bafbec-70f1-4462-a64b-3fddc24c0600-S0/frameworks/f6bafbec-70f1-4462-a64b-3fddc24c0600-0000/executors/6ab9e748-a3cf-4417-9e1e-5899a5090af0/runs/86bbfc31-eab8-4e39-aea1-c052ce8d16ee'
to user 'root'
[16:43:55]W: [Step 10/10] I0629 16:43:55.490312 3642 slave.cpp:6128]
Checkpointing ExecutorInfo to
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_Obawjb/meta/slaves/f6bafbec-70f1-4462-a64b-3fddc24c0600-S0/frameworks/f6bafbec-70f1-4462-a64b-3fddc24c0600-0000/executors/6ab9e748-a3cf-4417-9e1e-5899a5090af0/executor.info'
[16:43:55]W: [Step 10/10] I0629 16:43:55.490613 3642 slave.cpp:5726]
Launching executor 6ab9e748-a3cf-4417-9e1e-5899a5090af0 of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000 with resources cpus(*):0.1; mem(*):32
in work directory
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_Obawjb/slaves/f6bafbec-70f1-4462-a64b-3fddc24c0600-S0/frameworks/f6bafbec-70f1-4462-a64b-3fddc24c0600-0000/executors/6ab9e748-a3cf-4417-9e1e-5899a5090af0/runs/86bbfc31-eab8-4e39-aea1-c052ce8d16ee'
[16:43:55]W: [Step 10/10] I0629 16:43:55.490852 3639
containerizer.cpp:773] Starting container
'86bbfc31-eab8-4e39-aea1-c052ce8d16ee' for executor
'6ab9e748-a3cf-4417-9e1e-5899a5090af0' of framework
'f6bafbec-70f1-4462-a64b-3fddc24c0600-0000'
[16:43:55]W: [Step 10/10] I0629 16:43:55.490887 3642 slave.cpp:6151]
Checkpointing TaskInfo to
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_Obawjb/meta/slaves/f6bafbec-70f1-4462-a64b-3fddc24c0600-S0/frameworks/f6bafbec-70f1-4462-a64b-3fddc24c0600-0000/executors/6ab9e748-a3cf-4417-9e1e-5899a5090af0/runs/86bbfc31-eab8-4e39-aea1-c052ce8d16ee/tasks/6ab9e748-a3cf-4417-9e1e-5899a5090af0/task.info'
[16:43:55]W: [Step 10/10] I0629 16:43:55.491031 3642 slave.cpp:1896]
Queuing task '6ab9e748-a3cf-4417-9e1e-5899a5090af0' for executor
'6ab9e748-a3cf-4417-9e1e-5899a5090af0' of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000
[16:43:55]W: [Step 10/10] I0629 16:43:55.491080 3642 slave.cpp:920]
Successfully attached file
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_Obawjb/slaves/f6bafbec-70f1-4462-a64b-3fddc24c0600-S0/frameworks/f6bafbec-70f1-4462-a64b-3fddc24c0600-0000/executors/6ab9e748-a3cf-4417-9e1e-5899a5090af0/runs/86bbfc31-eab8-4e39-aea1-c052ce8d16ee'
[16:43:55]W: [Step 10/10] I0629 16:43:55.491116 3641 posix.cpp:194]
Changing the ownership of the persistent volume at
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_Obawjb/volumes/roles/role1/id1'
with uid 0 and gid 0
[16:43:55]W: [Step 10/10] I0629 16:43:55.491144 3641 posix.cpp:238] Adding
symlink from
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_Obawjb/volumes/roles/role1/id1'
to
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_Obawjb/slaves/f6bafbec-70f1-4462-a64b-3fddc24c0600-S0/frameworks/f6bafbec-70f1-4462-a64b-3fddc24c0600-0000/executors/6ab9e748-a3cf-4417-9e1e-5899a5090af0/runs/86bbfc31-eab8-4e39-aea1-c052ce8d16ee/path1'
for persistent volume disk(role1)[id1:path1]:2048 of container
86bbfc31-eab8-4e39-aea1-c052ce8d16ee
[16:43:55]W: [Step 10/10] I0629 16:43:55.492033 3641
containerizer.cpp:1264] Launching 'mesos-containerizer' with flags
'--command="{"shell":true,"value":"\/mnt\/teamcity\/work\/4240ba9ddd0997c3\/build\/src\/mesos-executor"}"
--commands="{"commands":[]}" --help="false" --pipe_read="49"
--pipe_write="109"
--sandbox="/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_Obawjb/slaves/f6bafbec-70f1-4462-a64b-3fddc24c0600-S0/frameworks/f6bafbec-70f1-4462-a64b-3fddc24c0600-0000/executors/6ab9e748-a3cf-4417-9e1e-5899a5090af0/runs/86bbfc31-eab8-4e39-aea1-c052ce8d16ee"
--user="root"'
[16:43:55]W: [Step 10/10] I0629 16:43:55.492090 3641
linux_launcher.cpp:281] Cloning child process with flags =
[16:43:55]W: [Step 10/10] I0629 16:43:55.511029 3641
containerizer.cpp:1299] Checkpointing executor's forked pid 22743 to
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_Obawjb/meta/slaves/f6bafbec-70f1-4462-a64b-3fddc24c0600-S0/frameworks/f6bafbec-70f1-4462-a64b-3fddc24c0600-0000/executors/6ab9e748-a3cf-4417-9e1e-5899a5090af0/runs/86bbfc31-eab8-4e39-aea1-c052ce8d16ee/pids/forked.pid'
[16:43:55]W: [Step 10/10] I0629 16:43:55.574214 22757 exec.cpp:161]
Version: 1.0.0
[16:43:55]W: [Step 10/10] I0629 16:43:55.574726 3640 slave.cpp:2884] Got
registration for executor '6ab9e748-a3cf-4417-9e1e-5899a5090af0' of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000 from executor(1)@172.30.2.177:35992
[16:43:55]W: [Step 10/10] I0629 16:43:55.574908 3640 slave.cpp:2970]
Checkpointing executor pid 'executor(1)@172.30.2.177:35992' to
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_Obawjb/meta/slaves/f6bafbec-70f1-4462-a64b-3fddc24c0600-S0/frameworks/f6bafbec-70f1-4462-a64b-3fddc24c0600-0000/executors/6ab9e748-a3cf-4417-9e1e-5899a5090af0/runs/86bbfc31-eab8-4e39-aea1-c052ce8d16ee/pids/libprocess.pid'
[16:43:55]W: [Step 10/10] I0629 16:43:55.575414 22777 exec.cpp:236]
Executor registered on agent f6bafbec-70f1-4462-a64b-3fddc24c0600-S0
[16:43:55]W: [Step 10/10] I0629 16:43:55.575594 3640 slave.cpp:2061]
Sending queued task '6ab9e748-a3cf-4417-9e1e-5899a5090af0' to executor
'6ab9e748-a3cf-4417-9e1e-5899a5090af0' of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000 at executor(1)@172.30.2.177:35992
[16:43:55] : [Step 10/10] Received SUBSCRIBED event
[16:43:55] : [Step 10/10] Subscribed executor on
ip-172-30-2-177.mesosphere.io
[16:43:55] : [Step 10/10] Received LAUNCH event
[16:43:55] : [Step 10/10] Starting task 6ab9e748-a3cf-4417-9e1e-5899a5090af0
[16:43:55] : [Step 10/10] Forked command at 22780
[16:43:55] : [Step 10/10] sh -c 'while true; do test -d path1; done'
[16:43:55]W: [Step 10/10] I0629 16:43:55.579604 3639 slave.cpp:3267]
Handling status update TASK_RUNNING (UUID:
090453c5-fcf3-413c-b898-d230e599a489) for task
6ab9e748-a3cf-4417-9e1e-5899a5090af0 of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000 from executor(1)@172.30.2.177:35992
[16:43:55]W: [Step 10/10] I0629 16:43:55.580054 3644
status_update_manager.cpp:320] Received status update TASK_RUNNING (UUID:
090453c5-fcf3-413c-b898-d230e599a489) for task
6ab9e748-a3cf-4417-9e1e-5899a5090af0 of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000
[16:43:55]W: [Step 10/10] I0629 16:43:55.580073 3644
status_update_manager.cpp:497] Creating StatusUpdate stream for task
6ab9e748-a3cf-4417-9e1e-5899a5090af0 of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000
[16:43:55]W: [Step 10/10] I0629 16:43:55.580241 3644
status_update_manager.cpp:825] Checkpointing UPDATE for status update
TASK_RUNNING (UUID: 090453c5-fcf3-413c-b898-d230e599a489) for task
6ab9e748-a3cf-4417-9e1e-5899a5090af0 of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000
[16:43:55]W: [Step 10/10] I0629 16:43:55.590425 3644
status_update_manager.cpp:374] Forwarding update TASK_RUNNING (UUID:
090453c5-fcf3-413c-b898-d230e599a489) for task
6ab9e748-a3cf-4417-9e1e-5899a5090af0 of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000 to the agent
[16:43:55]W: [Step 10/10] I0629 16:43:55.590541 3643 slave.cpp:3660]
Forwarding the update TASK_RUNNING (UUID: 090453c5-fcf3-413c-b898-d230e599a489)
for task 6ab9e748-a3cf-4417-9e1e-5899a5090af0 of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000 to [email protected]:42583
[16:43:55]W: [Step 10/10] I0629 16:43:55.590611 3643 slave.cpp:3554]
Status update manager successfully handled status update TASK_RUNNING (UUID:
090453c5-fcf3-413c-b898-d230e599a489) for task
6ab9e748-a3cf-4417-9e1e-5899a5090af0 of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000
[16:43:55]W: [Step 10/10] I0629 16:43:55.590626 3643 slave.cpp:3570]
Sending acknowledgement for status update TASK_RUNNING (UUID:
090453c5-fcf3-413c-b898-d230e599a489) for task
6ab9e748-a3cf-4417-9e1e-5899a5090af0 of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000 to executor(1)@172.30.2.177:35992
[16:43:55]W: [Step 10/10] I0629 16:43:55.590698 3639 master.cpp:5234]
Status update TASK_RUNNING (UUID: 090453c5-fcf3-413c-b898-d230e599a489) for
task 6ab9e748-a3cf-4417-9e1e-5899a5090af0 of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000 from agent
f6bafbec-70f1-4462-a64b-3fddc24c0600-S0 at slave(569)@172.30.2.177:42583
(ip-172-30-2-177.mesosphere.io)
[16:43:55]W: [Step 10/10] I0629 16:43:55.590728 3639 master.cpp:5282]
Forwarding status update TASK_RUNNING (UUID:
090453c5-fcf3-413c-b898-d230e599a489) for task
6ab9e748-a3cf-4417-9e1e-5899a5090af0 of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000
[16:43:55]W: [Step 10/10] I0629 16:43:55.590793 3639 master.cpp:6909]
Updating the state of task 6ab9e748-a3cf-4417-9e1e-5899a5090af0 of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000 (latest state: TASK_RUNNING, status
update state: TASK_RUNNING)
[16:43:55]W: [Step 10/10] I0629 16:43:55.590939 3642 sched.cpp:1005]
Scheduler::statusUpdate took 60736ns
[16:43:55]W: [Step 10/10] I0629 16:43:55.591073 3639 master.cpp:4386]
Processing ACKNOWLEDGE call 090453c5-fcf3-413c-b898-d230e599a489 for task
6ab9e748-a3cf-4417-9e1e-5899a5090af0 of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000 (default) at
[email protected]:42583 on agent
f6bafbec-70f1-4462-a64b-3fddc24c0600-S0
[16:43:55]W: [Step 10/10] I0629 16:43:55.591177 3640
status_update_manager.cpp:392] Received status update acknowledgement (UUID:
090453c5-fcf3-413c-b898-d230e599a489) for task
6ab9e748-a3cf-4417-9e1e-5899a5090af0 of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000
[16:43:55]W: [Step 10/10] I0629 16:43:55.591228 3640
status_update_manager.cpp:825] Checkpointing ACK for status update TASK_RUNNING
(UUID: 090453c5-fcf3-413c-b898-d230e599a489) for task
6ab9e748-a3cf-4417-9e1e-5899a5090af0 of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000
[16:43:55]W: [Step 10/10] I0629 16:43:55.593852 3640 slave.cpp:2653]
Status update manager successfully handled status update acknowledgement (UUID:
090453c5-fcf3-413c-b898-d230e599a489) for task
6ab9e748-a3cf-4417-9e1e-5899a5090af0 of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000
[16:43:55]W: [Step 10/10] I0629 16:43:55.593976 3639 slave.cpp:839] Agent
terminating
[16:43:55]W: [Step 10/10] I0629 16:43:55.594096 3639 master.cpp:1369]
Agent f6bafbec-70f1-4462-a64b-3fddc24c0600-S0 at slave(569)@172.30.2.177:42583
(ip-172-30-2-177.mesosphere.io) disconnected
[16:43:55]W: [Step 10/10] I0629 16:43:55.594115 3639 master.cpp:2908]
Disconnecting agent f6bafbec-70f1-4462-a64b-3fddc24c0600-S0 at
slave(569)@172.30.2.177:42583 (ip-172-30-2-177.mesosphere.io)
[16:43:55]W: [Step 10/10] I0629 16:43:55.594144 3639 master.cpp:2927]
Deactivating agent f6bafbec-70f1-4462-a64b-3fddc24c0600-S0 at
slave(569)@172.30.2.177:42583 (ip-172-30-2-177.mesosphere.io)
[16:43:55]W: [Step 10/10] I0629 16:43:55.594205 3640 hierarchical.cpp:568]
Agent f6bafbec-70f1-4462-a64b-3fddc24c0600-S0 deactivated
[16:43:55]W: [Step 10/10] I0629 16:43:55.594951 3624
containerizer.cpp:201] Using isolation:
posix/cpu,posix/mem,filesystem/posix,network/cni
[16:43:55]W: [Step 10/10] I0629 16:43:55.598244 3624
linux_launcher.cpp:101] Using /sys/fs/cgroup/freezer as the freezer hierarchy
for the Linux launcher
[16:43:55]W: [Step 10/10] I0629 16:43:55.599012 3624 cluster.cpp:432]
Creating default 'local' authorizer
[16:43:55]W: [Step 10/10] I0629 16:43:55.599529 3642 slave.cpp:203] Agent
started on 570)@172.30.2.177:42583
[16:43:55]W: [Step 10/10] I0629 16:43:55.599556 3642 slave.cpp:204] 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/DiskResource_PersistentVolumeTest_SlaveRecovery_0_Obawjb/credential"
--default_role="*" --disk_watch_interval="1mins" --docker="docker"
--docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io";
--docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock"
--docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker"
--docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume"
--enforce_container_disk_quota="false" --executor_registration_timeout="1mins"
--executor_shutdown_grace_period="5secs"
--fetcher_cache_dir="/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_Obawjb/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/DiskResource_PersistentVolumeTest_SlaveRecovery_0_Obawjb/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="[{"name":"cpus","role":"*","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","role":"*","scalar":{"value":2048.0},"type":"SCALAR"},{"name":"disk","role":"role1","scalar":{"value":4096.0},"type":"SCALAR"}]"
--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/DiskResource_PersistentVolumeTest_SlaveRecovery_0_Obawjb"
[16:43:55]W: [Step 10/10] I0629 16:43:55.599745 3642 credentials.hpp:86]
Loading credential for authentication from
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_Obawjb/credential'
[16:43:55]W: [Step 10/10] I0629 16:43:55.599802 3642 slave.cpp:341] Agent
using credential for: test-principal
[16:43:55]W: [Step 10/10] I0629 16:43:55.599814 3642 credentials.hpp:37]
Loading credentials for authentication from
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_Obawjb/http_credentials'
[16:43:55]W: [Step 10/10] I0629 16:43:55.599875 3642 slave.cpp:393] Using
default 'basic' HTTP authenticator
[16:43:55]W: [Step 10/10] I0629 16:43:55.600249 3642 slave.cpp:592] Agent
resources: cpus(*):2; mem(*):2048; disk(role1):4096; ports(*):[31000-32000]
[16:43:55]W: [Step 10/10] I0629 16:43:55.600271 3642 slave.cpp:600] Agent
attributes: [ ]
[16:43:55]W: [Step 10/10] I0629 16:43:55.600276 3642 slave.cpp:605] Agent
hostname: ip-172-30-2-177.mesosphere.io
[16:43:55]W: [Step 10/10] I0629 16:43:55.600656 3638 state.cpp:57]
Recovering state from
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_Obawjb/meta'
[16:43:55]W: [Step 10/10] I0629 16:43:55.602387 3640 fetcher.cpp:86]
Clearing fetcher cache
[16:43:55]W: [Step 10/10] I0629 16:43:55.602418 3640 slave.cpp:4928]
Recovering framework f6bafbec-70f1-4462-a64b-3fddc24c0600-0000
[16:43:55]W: [Step 10/10] I0629 16:43:55.602432 3640 slave.cpp:5850]
Recovering executor '6ab9e748-a3cf-4417-9e1e-5899a5090af0' of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000
[16:43:55]W: [Step 10/10] I0629 16:43:55.602684 3638
status_update_manager.cpp:200] Recovering status update manager
[16:43:55]W: [Step 10/10] I0629 16:43:55.602700 3638
status_update_manager.cpp:208] Recovering executor
'6ab9e748-a3cf-4417-9e1e-5899a5090af0' of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000
[16:43:55]W: [Step 10/10] I0629 16:43:55.602726 3638
status_update_manager.cpp:497] Creating StatusUpdate stream for task
6ab9e748-a3cf-4417-9e1e-5899a5090af0 of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000
[16:43:55]W: [Step 10/10] I0629 16:43:55.602908 3638
status_update_manager.cpp:801] Replaying status update stream for task
6ab9e748-a3cf-4417-9e1e-5899a5090af0
[16:43:55]W: [Step 10/10] I0629 16:43:55.603199 3643
containerizer.cpp:514] Recovering containerizer
[16:43:55]W: [Step 10/10] I0629 16:43:55.603234 3643
containerizer.cpp:569] Recovering container
'86bbfc31-eab8-4e39-aea1-c052ce8d16ee' for executor
'6ab9e748-a3cf-4417-9e1e-5899a5090af0' of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000
[16:43:55]W: [Step 10/10] I0629 16:43:55.604558 3643 provisioner.cpp:253]
Provisioner recovery complete
[16:43:55]W: [Step 10/10] I0629 16:43:55.604885 3640 slave.cpp:4780]
Sending reconnect request to executor '6ab9e748-a3cf-4417-9e1e-5899a5090af0' of
framework f6bafbec-70f1-4462-a64b-3fddc24c0600-0000 at
executor(1)@172.30.2.177:35992
[16:43:55]W: [Step 10/10] I0629 16:43:55.605111 22778 exec.cpp:282]
Received reconnect request from agent f6bafbec-70f1-4462-a64b-3fddc24c0600-S0
[16:43:55]W: [Step 10/10] I0629 16:43:55.605345 3638 slave.cpp:3054]
Re-registering executor '6ab9e748-a3cf-4417-9e1e-5899a5090af0' of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000
[16:43:55]W: [Step 10/10] I0629 16:43:55.605547 3638 posix.cpp:194]
Changing the ownership of the persistent volume at
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_Obawjb/volumes/roles/role1/id1'
with uid 0 and gid 0
[16:43:55]W: [Step 10/10] I0629 16:43:55.605554 22771 exec.cpp:259]
Executor re-registered on agent f6bafbec-70f1-4462-a64b-3fddc24c0600-S0
[16:43:55] : [Step 10/10] Received SUBSCRIBED event
[16:43:55] : [Step 10/10] Subscribed executor on
ip-172-30-2-177.mesosphere.io
[16:43:55]W: [Step 10/10] I0629 16:43:55.623047 3644
hierarchical.cpp:1512] No allocations performed
[16:43:55]W: [Step 10/10] I0629 16:43:55.623078 3644
hierarchical.cpp:1607] No inverse offers to send out!
[16:43:55]W: [Step 10/10] I0629 16:43:55.623126 3644
hierarchical.cpp:1147] Performed allocation for 1 agents in 143291ns
[16:43:55]W: [Step 10/10] I0629 16:43:55.623164 3645 slave.cpp:3207]
Cleaning up un-reregistered executors
[16:43:55]W: [Step 10/10] I0629 16:43:55.623239 3645 slave.cpp:4840]
Finished recovery
[16:43:55]W: [Step 10/10] I0629 16:43:55.623453 3645 slave.cpp:5012]
Querying resource estimator for oversubscribable resources
[16:43:55]W: [Step 10/10] I0629 16:43:55.623541 3642 slave.cpp:5026]
Received oversubscribable resources from the resource estimator
[16:43:55]W: [Step 10/10] I0629 16:43:55.623594 3642 slave.cpp:967] New
master detected at [email protected]:42583
[16:43:55]W: [Step 10/10] I0629 16:43:55.623601 3645
status_update_manager.cpp:174] Pausing sending status updates
[16:43:55]W: [Step 10/10] I0629 16:43:55.623620 3642 slave.cpp:1029]
Authenticating with master [email protected]:42583
[16:43:55]W: [Step 10/10] I0629 16:43:55.623638 3642 slave.cpp:1040] Using
default CRAM-MD5 authenticatee
[16:43:55]W: [Step 10/10] I0629 16:43:55.623682 3642 slave.cpp:1002]
Detecting new master
[16:43:55]W: [Step 10/10] I0629 16:43:55.623741 3641
authenticatee.cpp:121] Creating new client SASL connection
[16:43:55]W: [Step 10/10] I0629 16:43:55.623967 3641 master.cpp:5966]
Authenticating slave(570)@172.30.2.177:42583
[16:43:55]W: [Step 10/10] I0629 16:43:55.624033 3638
authenticator.cpp:414] Starting authentication session for
crammd5_authenticatee(1122)@172.30.2.177:42583
[16:43:55]W: [Step 10/10] I0629 16:43:55.624116 3643 authenticator.cpp:98]
Creating new server SASL connection
[16:43:55]W: [Step 10/10] I0629 16:43:55.624248 3643
authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
[16:43:55]W: [Step 10/10] I0629 16:43:55.624263 3643
authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
[16:43:55]W: [Step 10/10] I0629 16:43:55.624300 3643
authenticator.cpp:204] Received SASL authentication start
[16:43:55]W: [Step 10/10] I0629 16:43:55.624330 3643
authenticator.cpp:326] Authentication requires more steps
[16:43:55]W: [Step 10/10] I0629 16:43:55.624363 3643
authenticatee.cpp:259] Received SASL authentication step
[16:43:55]W: [Step 10/10] I0629 16:43:55.624413 3643
authenticator.cpp:232] Received SASL authentication step
[16:43:55]W: [Step 10/10] I0629 16:43:55.624429 3643 auxprop.cpp:107]
Request to lookup properties for user: 'test-principal' realm:
'ip-172-30-2-177.mesosphere.io' server FQDN: 'ip-172-30-2-177.mesosphere.io'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
[16:43:55]W: [Step 10/10] I0629 16:43:55.624440 3643 auxprop.cpp:179]
Looking up auxiliary property '*userPassword'
[16:43:55]W: [Step 10/10] I0629 16:43:55.624452 3643 auxprop.cpp:179]
Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
[16:43:55]W: [Step 10/10] I0629 16:43:55.624460 3643 auxprop.cpp:107]
Request to lookup properties for user: 'test-principal' realm:
'ip-172-30-2-177.mesosphere.io' server FQDN: 'ip-172-30-2-177.mesosphere.io'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
[16:43:55]W: [Step 10/10] I0629 16:43:55.624465 3643 auxprop.cpp:129]
Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
[16:43:55]W: [Step 10/10] I0629 16:43:55.624469 3643 auxprop.cpp:129]
Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID
== true
[16:43:55]W: [Step 10/10] I0629 16:43:55.624477 3643
authenticator.cpp:318] Authentication success
[16:43:55]W: [Step 10/10] I0629 16:43:55.624528 3638
authenticatee.cpp:299] Authentication success
[16:43:55]W: [Step 10/10] I0629 16:43:55.624548 3640
authenticator.cpp:432] Authentication session cleanup for
crammd5_authenticatee(1122)@172.30.2.177:42583
[16:43:55]W: [Step 10/10] I0629 16:43:55.624558 3643 master.cpp:5996]
Successfully authenticated principal 'test-principal' at
slave(570)@172.30.2.177:42583
[16:43:55]W: [Step 10/10] I0629 16:43:55.624680 3638 slave.cpp:1108]
Successfully authenticated with master [email protected]:42583
[16:43:55]W: [Step 10/10] I0629 16:43:55.624773 3638 slave.cpp:1511] Will
retry registration in 14.032325ms if necessary
[16:43:55]W: [Step 10/10] I0629 16:43:55.624852 3639 master.cpp:4835]
Re-registering agent f6bafbec-70f1-4462-a64b-3fddc24c0600-S0 at
slave(569)@172.30.2.177:42583 (ip-172-30-2-177.mesosphere.io)
[16:43:55]W: [Step 10/10] I0629 16:43:55.624924 3639 master.cpp:5027]
Sending updated checkpointed resources disk(role1)[id1:path1]:2048 to agent
f6bafbec-70f1-4462-a64b-3fddc24c0600-S0 at slave(570)@172.30.2.177:42583
(ip-172-30-2-177.mesosphere.io)
[16:43:55]W: [Step 10/10] I0629 16:43:55.624984 3641 slave.cpp:1254]
Re-registered with master [email protected]:42583
[16:43:55]W: [Step 10/10] I0629 16:43:55.625032 3641 slave.cpp:1290]
Forwarding total oversubscribed resources
[16:43:55]W: [Step 10/10] I0629 16:43:55.625033 3645 hierarchical.cpp:556]
Agent f6bafbec-70f1-4462-a64b-3fddc24c0600-S0 reactivated
[16:43:55]W: [Step 10/10] I0629 16:43:55.625107 3641 slave.cpp:2443]
Updating framework f6bafbec-70f1-4462-a64b-3fddc24c0600-0000 pid to
[email protected]:42583
[16:43:55]W: [Step 10/10] I0629 16:43:55.625143 3641 slave.cpp:2459]
Checkpointing framework pid
'[email protected]:42583' to
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_Obawjb/meta/slaves/f6bafbec-70f1-4462-a64b-3fddc24c0600-S0/frameworks/f6bafbec-70f1-4462-a64b-3fddc24c0600-0000/framework.pid'
[16:43:55] : [Step 10/10] Received KILL event
[16:43:55]W: [Step 10/10] I0629 16:43:55.625161 3638
status_update_manager.cpp:181] Resuming sending status updates
[16:43:55] : [Step 10/10] Received kill for task
6ab9e748-a3cf-4417-9e1e-5899a5090af0 with grace period of 3secs
[16:43:55]W: [Step 10/10] I0629 16:43:55.625144 3645 master.cpp:5089]
Received update of agent f6bafbec-70f1-4462-a64b-3fddc24c0600-S0 at
slave(570)@172.30.2.177:42583 (ip-172-30-2-177.mesosphere.io) with total
oversubscribed resources
[16:43:55] : [Step 10/10] Sending SIGTERM to process tree at pid 22780
[16:43:55]W: [Step 10/10] I0629 16:43:55.625283 3645 master.cpp:4278]
Telling agent f6bafbec-70f1-4462-a64b-3fddc24c0600-S0 at
slave(570)@172.30.2.177:42583 (ip-172-30-2-177.mesosphere.io) to kill task
6ab9e748-a3cf-4417-9e1e-5899a5090af0 of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000 (default) at
[email protected]:42583
[16:43:55]W: [Step 10/10] I0629 16:43:55.625334 3645
status_update_manager.cpp:181] Resuming sending status updates
[16:43:55]W: [Step 10/10] I0629 16:43:55.625349 3638 hierarchical.cpp:539]
Agent f6bafbec-70f1-4462-a64b-3fddc24c0600-S0 (ip-172-30-2-177.mesosphere.io)
updated with oversubscribed resources (total: cpus(*):2; mem(*):2048;
disk(role1):2048; ports(*):[31000-32000]; disk(role1)[id1:path1]:2048,
allocated: disk(role1)[id1:path1]:2048; cpus(*):1; mem(*):128)
[16:43:55]W: [Step 10/10] I0629 16:43:55.625434 3638
hierarchical.cpp:1698] Filtered offer with disk(role1):2048; cpus(*):1;
mem(*):1920; ports(*):[31000-32000] on agent
f6bafbec-70f1-4462-a64b-3fddc24c0600-S0 for framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000
[16:43:55]W: [Step 10/10] I0629 16:43:55.625452 3638
hierarchical.cpp:1512] No allocations performed
[16:43:55]W: [Step 10/10] I0629 16:43:55.625458 3638
hierarchical.cpp:1607] No inverse offers to send out!
[16:43:55]W: [Step 10/10] I0629 16:43:55.625465 3638
hierarchical.cpp:1170] Performed allocation for agent
f6bafbec-70f1-4462-a64b-3fddc24c0600-S0 in 90007ns
[16:43:55]W: [Step 10/10] I0629 16:43:55.625520 3641 slave.cpp:2582]
Updated checkpointed resources from disk(role1)[id1:path1]:2048 to
disk(role1)[id1:path1]:2048
[16:43:55]W: [Step 10/10] I0629 16:43:55.625571 3641 slave.cpp:2091] Asked
to kill task 6ab9e748-a3cf-4417-9e1e-5899a5090af0 of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000
[16:43:55] : [Step 10/10] Sent SIGTERM to the following process trees:
[16:43:55] : [Step 10/10] [
[16:43:55] : [Step 10/10] --- 22780 sh -c while true; do test -d path1;
done
[16:43:55] : [Step 10/10] ]
[16:43:55] : [Step 10/10] Scheduling escalation to SIGKILL in 3secs from now
[16:43:55] : [Step 10/10] Command terminated with signal Terminated (pid:
22780)
[16:43:55]W: [Step 10/10] I0629 16:43:55.680194 3640 slave.cpp:3267]
Handling status update TASK_KILLED (UUID: d73af84d-9943-4a6a-94ac-3b314a46d0a4)
for task 6ab9e748-a3cf-4417-9e1e-5899a5090af0 of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000 from executor(1)@172.30.2.177:35992
[16:43:55]W: [Step 10/10] I0629 16:43:55.680619 3640 slave.cpp:6066]
Terminating task 6ab9e748-a3cf-4417-9e1e-5899a5090af0
[16:43:55]W: [Step 10/10] I0629 16:43:55.680806 3640 posix.cpp:139]
Removing symlink
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_Obawjb/slaves/f6bafbec-70f1-4462-a64b-3fddc24c0600-S0/frameworks/f6bafbec-70f1-4462-a64b-3fddc24c0600-0000/executors/6ab9e748-a3cf-4417-9e1e-5899a5090af0/runs/86bbfc31-eab8-4e39-aea1-c052ce8d16ee/path1'
for persistent volume disk(role1)[id1:path1]:2048 of container
86bbfc31-eab8-4e39-aea1-c052ce8d16ee
[16:43:55]W: [Step 10/10] I0629 16:43:55.681077 3640
status_update_manager.cpp:320] Received status update TASK_KILLED (UUID:
d73af84d-9943-4a6a-94ac-3b314a46d0a4) for task
6ab9e748-a3cf-4417-9e1e-5899a5090af0 of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000
[16:43:55]W: [Step 10/10] I0629 16:43:55.681103 3640
status_update_manager.cpp:825] Checkpointing UPDATE for status update
TASK_KILLED (UUID: d73af84d-9943-4a6a-94ac-3b314a46d0a4) for task
6ab9e748-a3cf-4417-9e1e-5899a5090af0 of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000
[16:43:55]W: [Step 10/10] I0629 16:43:55.687985 3640
status_update_manager.cpp:374] Forwarding update TASK_KILLED (UUID:
d73af84d-9943-4a6a-94ac-3b314a46d0a4) for task
6ab9e748-a3cf-4417-9e1e-5899a5090af0 of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000 to the agent
[16:43:55]W: [Step 10/10] I0629 16:43:55.688079 3639 slave.cpp:3660]
Forwarding the update TASK_KILLED (UUID: d73af84d-9943-4a6a-94ac-3b314a46d0a4)
for task 6ab9e748-a3cf-4417-9e1e-5899a5090af0 of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000 to [email protected]:42583
[16:43:55]W: [Step 10/10] I0629 16:43:55.688159 3639 slave.cpp:3554]
Status update manager successfully handled status update TASK_KILLED (UUID:
d73af84d-9943-4a6a-94ac-3b314a46d0a4) for task
6ab9e748-a3cf-4417-9e1e-5899a5090af0 of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000
[16:43:55]W: [Step 10/10] I0629 16:43:55.688181 3639 slave.cpp:3570]
Sending acknowledgement for status update TASK_KILLED (UUID:
d73af84d-9943-4a6a-94ac-3b314a46d0a4) for task
6ab9e748-a3cf-4417-9e1e-5899a5090af0 of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000 to executor(1)@172.30.2.177:35992
[16:43:55]W: [Step 10/10] I0629 16:43:55.688213 3640 master.cpp:5234]
Status update TASK_KILLED (UUID: d73af84d-9943-4a6a-94ac-3b314a46d0a4) for task
6ab9e748-a3cf-4417-9e1e-5899a5090af0 of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000 from agent
f6bafbec-70f1-4462-a64b-3fddc24c0600-S0 at slave(570)@172.30.2.177:42583
(ip-172-30-2-177.mesosphere.io)
[16:43:55]W: [Step 10/10] I0629 16:43:55.688231 3640 master.cpp:5282]
Forwarding status update TASK_KILLED (UUID:
d73af84d-9943-4a6a-94ac-3b314a46d0a4) for task
6ab9e748-a3cf-4417-9e1e-5899a5090af0 of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000
[16:43:55]W: [Step 10/10] I0629 16:43:55.688278 3640 master.cpp:6909]
Updating the state of task 6ab9e748-a3cf-4417-9e1e-5899a5090af0 of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000 (latest state: TASK_KILLED, status
update state: TASK_KILLED)
[16:43:55]W: [Step 10/10] I0629 16:43:55.688364 3645 sched.cpp:1005]
Scheduler::statusUpdate took 38883ns
[16:43:55]W: [Step 10/10] I0629 16:43:55.688457 3640 master.cpp:4386]
Processing ACKNOWLEDGE call d73af84d-9943-4a6a-94ac-3b314a46d0a4 for task
6ab9e748-a3cf-4417-9e1e-5899a5090af0 of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000 (default) at
[email protected]:42583 on agent
f6bafbec-70f1-4462-a64b-3fddc24c0600-S0
[16:43:55]W: [Step 10/10] I0629 16:43:55.688448 3644 hierarchical.cpp:899]
Recovered cpus(*):1; mem(*):128; disk(role1)[id1:path1]:2048 (total: cpus(*):2;
mem(*):2048; disk(role1):2048; ports(*):[31000-32000];
disk(role1)[id1:path1]:2048, allocated: ) on agent
f6bafbec-70f1-4462-a64b-3fddc24c0600-S0 from framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000
[16:43:55]W: [Step 10/10] I0629 16:43:55.688483 3640 master.cpp:6975]
Removing task 6ab9e748-a3cf-4417-9e1e-5899a5090af0 with resources cpus(*):1;
mem(*):128; disk(role1)[id1:path1]:2048 of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000 on agent
f6bafbec-70f1-4462-a64b-3fddc24c0600-S0 at slave(570)@172.30.2.177:42583
(ip-172-30-2-177.mesosphere.io)
[16:43:55]W: [Step 10/10] I0629 16:43:55.688616 3639
status_update_manager.cpp:392] Received status update acknowledgement (UUID:
d73af84d-9943-4a6a-94ac-3b314a46d0a4) for task
6ab9e748-a3cf-4417-9e1e-5899a5090af0 of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000
[16:43:55]W: [Step 10/10] I0629 16:43:55.688657 3624 sched.cpp:1964] Asked
to stop the driver
[16:43:55]W: [Step 10/10] I0629 16:43:55.688658 3639
status_update_manager.cpp:825] Checkpointing ACK for status update TASK_KILLED
(UUID: d73af84d-9943-4a6a-94ac-3b314a46d0a4) for task
6ab9e748-a3cf-4417-9e1e-5899a5090af0 of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000
[16:43:55]W: [Step 10/10] I0629 16:43:55.688714 3640 sched.cpp:1167]
Stopping framework 'f6bafbec-70f1-4462-a64b-3fddc24c0600-0000'
[16:43:55]W: [Step 10/10] I0629 16:43:55.688797 3645 master.cpp:6365]
Processing TEARDOWN call for framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000 (default) at
[email protected]:42583
[16:43:55]W: [Step 10/10] I0629 16:43:55.688819 3645 master.cpp:6377]
Removing framework f6bafbec-70f1-4462-a64b-3fddc24c0600-0000 (default) at
[email protected]:42583
[16:43:55]W: [Step 10/10] I0629 16:43:55.688916 3644 hierarchical.cpp:379]
Deactivated framework f6bafbec-70f1-4462-a64b-3fddc24c0600-0000
[16:43:55]W: [Step 10/10] I0629 16:43:55.688946 3641 slave.cpp:2274] Asked
to shut down framework f6bafbec-70f1-4462-a64b-3fddc24c0600-0000 by
[email protected]:42583
[16:43:55]W: [Step 10/10] I0629 16:43:55.688961 3641 slave.cpp:2299]
Shutting down framework f6bafbec-70f1-4462-a64b-3fddc24c0600-0000
[16:43:55]W: [Step 10/10] I0629 16:43:55.688971 3641 slave.cpp:4465]
Shutting down executor '6ab9e748-a3cf-4417-9e1e-5899a5090af0' of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000 at executor(1)@172.30.2.177:35992
[16:43:55]W: [Step 10/10] I0629 16:43:55.689049 3643 hierarchical.cpp:330]
Removed framework f6bafbec-70f1-4462-a64b-3fddc24c0600-0000
[16:43:55]W: [Step 10/10] I0629 16:43:55.689152 22775 exec.cpp:413]
Executor asked to shutdown
[16:43:55]W: [Step 10/10] I0629 16:43:55.689508 3642
containerizer.cpp:1573] Destroying container
'86bbfc31-eab8-4e39-aea1-c052ce8d16ee'
[16:43:55]W: [Step 10/10] I0629 16:43:55.690671 3642 cgroups.cpp:2676]
Freezing cgroup
/sys/fs/cgroup/freezer/mesos/86bbfc31-eab8-4e39-aea1-c052ce8d16ee
[16:43:55]W: [Step 10/10] I0629 16:43:55.691648 3640 cgroups.cpp:1409]
Successfully froze cgroup
/sys/fs/cgroup/freezer/mesos/86bbfc31-eab8-4e39-aea1-c052ce8d16ee after 955904ns
[16:43:55]W: [Step 10/10] I0629 16:43:55.692684 3645 cgroups.cpp:2694]
Thawing cgroup /sys/fs/cgroup/freezer/mesos/86bbfc31-eab8-4e39-aea1-c052ce8d16ee
[16:43:55]W: [Step 10/10] I0629 16:43:55.693651 3641 cgroups.cpp:1438]
Successfully thawed cgroup
/sys/fs/cgroup/freezer/mesos/86bbfc31-eab8-4e39-aea1-c052ce8d16ee after 947968ns
[16:43:55]W: [Step 10/10] I0629 16:43:55.694733 3645 slave.cpp:3788]
executor(1)@172.30.2.177:35992 exited
[16:43:55]W: [Step 10/10] I0629 16:43:55.698081 3639
status_update_manager.cpp:528] Cleaning up status update stream for task
6ab9e748-a3cf-4417-9e1e-5899a5090af0 of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000
[16:43:55]W: [Step 10/10] I0629 16:43:55.698180 3639 slave.cpp:2653]
Status update manager successfully handled status update acknowledgement (UUID:
d73af84d-9943-4a6a-94ac-3b314a46d0a4) for task
6ab9e748-a3cf-4417-9e1e-5899a5090af0 of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000
[16:43:55]W: [Step 10/10] I0629 16:43:55.698200 3639 slave.cpp:6107]
Completing task 6ab9e748-a3cf-4417-9e1e-5899a5090af0
[16:43:55]W: [Step 10/10] I0629 16:43:55.724177 3639
containerizer.cpp:1809] Executor for container
'86bbfc31-eab8-4e39-aea1-c052ce8d16ee' has exited
[16:43:55]W: [Step 10/10] I0629 16:43:55.725417 3639 provisioner.cpp:411]
Ignoring destroy request for unknown container
86bbfc31-eab8-4e39-aea1-c052ce8d16ee
[16:43:55]W: [Step 10/10] I0629 16:43:55.725541 3642 slave.cpp:4147]
Executor '6ab9e748-a3cf-4417-9e1e-5899a5090af0' of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000 terminated with signal Killed
[16:43:55]W: [Step 10/10] I0629 16:43:55.725566 3642 slave.cpp:4251]
Cleaning up executor '6ab9e748-a3cf-4417-9e1e-5899a5090af0' of framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000 at executor(1)@172.30.2.177:35992
[16:43:55]W: [Step 10/10] I0629 16:43:55.725735 3643 gc.cpp:55] Scheduling
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_Obawjb/slaves/f6bafbec-70f1-4462-a64b-3fddc24c0600-S0/frameworks/f6bafbec-70f1-4462-a64b-3fddc24c0600-0000/executors/6ab9e748-a3cf-4417-9e1e-5899a5090af0/runs/86bbfc31-eab8-4e39-aea1-c052ce8d16ee'
for gc 6.99999160070518days in the future
[16:43:55]W: [Step 10/10] I0629 16:43:55.725813 3643 gc.cpp:55] Scheduling
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_Obawjb/slaves/f6bafbec-70f1-4462-a64b-3fddc24c0600-S0/frameworks/f6bafbec-70f1-4462-a64b-3fddc24c0600-0000/executors/6ab9e748-a3cf-4417-9e1e-5899a5090af0'
for gc 6.99999160014815days in the future
[16:43:55]W: [Step 10/10] I0629 16:43:55.725831 3642 slave.cpp:4339]
Cleaning up framework f6bafbec-70f1-4462-a64b-3fddc24c0600-0000
[16:43:55]W: [Step 10/10] I0629 16:43:55.725838 3643 gc.cpp:55] Scheduling
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_Obawjb/meta/slaves/f6bafbec-70f1-4462-a64b-3fddc24c0600-S0/frameworks/f6bafbec-70f1-4462-a64b-3fddc24c0600-0000/executors/6ab9e748-a3cf-4417-9e1e-5899a5090af0/runs/86bbfc31-eab8-4e39-aea1-c052ce8d16ee'
for gc 6.99999159970963days in the future
[16:43:55]W: [Step 10/10] I0629 16:43:55.725862 3643 gc.cpp:55] Scheduling
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_Obawjb/meta/slaves/f6bafbec-70f1-4462-a64b-3fddc24c0600-S0/frameworks/f6bafbec-70f1-4462-a64b-3fddc24c0600-0000/executors/6ab9e748-a3cf-4417-9e1e-5899a5090af0'
for gc 6.9999915993037days in the future
[16:43:55]W: [Step 10/10] I0629 16:43:55.725891 3644
status_update_manager.cpp:282] Closing status update streams for framework
f6bafbec-70f1-4462-a64b-3fddc24c0600-0000
[16:43:55]W: [Step 10/10] I0629 16:43:55.725919 3645 gc.cpp:55] Scheduling
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_Obawjb/slaves/f6bafbec-70f1-4462-a64b-3fddc24c0600-S0/frameworks/f6bafbec-70f1-4462-a64b-3fddc24c0600-0000'
for gc 6.99999159855407days in the future
[16:43:55]W: [Step 10/10] I0629 16:43:55.725929 3642 slave.cpp:839] Agent
terminating
[16:43:55]W: [Step 10/10] I0629 16:43:55.725955 3645 gc.cpp:55] Scheduling
'/mnt/teamcity/temp/buildTmp/DiskResource_PersistentVolumeTest_SlaveRecovery_0_Obawjb/meta/slaves/f6bafbec-70f1-4462-a64b-3fddc24c0600-S0/frameworks/f6bafbec-70f1-4462-a64b-3fddc24c0600-0000'
for gc 6.99999159822815days in the future
[16:43:55]W: [Step 10/10] I0629 16:43:55.728305 3624 master.cpp:1216]
Master terminating
[16:43:55]W: [Step 10/10] I0629 16:43:55.728474 3638 hierarchical.cpp:513]
Removed agent f6bafbec-70f1-4462-a64b-3fddc24c0600-S0
[16:43:55] : [Step 10/10] [ OK ]
DiskResource/PersistentVolumeTest.SlaveRecovery/0 (293 ms)
{code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
