Greg Mann created MESOS-5128:
--------------------------------
Summary: PersistentVolumeTest.AccessPersistentVolume is flaky
Key: MESOS-5128
URL: https://issues.apache.org/jira/browse/MESOS-5128
Project: Mesos
Issue Type: Bug
Components: tests
Affects Versions: 0.28.0
Environment: Ubuntu 14.04 using gcc, with libevent and SSL enabled
Reporter: Greg Mann
Observed on ASF CI:
{code}
[ RUN ] DiskResource/PersistentVolumeTest.AccessPersistentVolume/0
I0405 17:29:19.134435 31837 cluster.cpp:139] Creating default 'local' authorizer
I0405 17:29:19.251143 31837 leveldb.cpp:174] Opened db in 116.386403ms
I0405 17:29:19.310050 31837 leveldb.cpp:181] Compacted db in 58.80688ms
I0405 17:29:19.310180 31837 leveldb.cpp:196] Created db iterator in 37145ns
I0405 17:29:19.310199 31837 leveldb.cpp:202] Seeked to beginning of db in 4212ns
I0405 17:29:19.310210 31837 leveldb.cpp:271] Iterated through 0 keys in the db
in 410ns
I0405 17:29:19.310279 31837 replica.cpp:779] Replica recovered with log
positions 0 -> 0 with 1 holes and 0 unlearned
I0405 17:29:19.311069 31861 recover.cpp:447] Starting replica recovery
I0405 17:29:19.311362 31861 recover.cpp:473] Replica is in EMPTY status
I0405 17:29:19.312641 31861 replica.cpp:673] Replica in EMPTY status received a
broadcasted recover request from (14359)@172.17.0.4:43972
I0405 17:29:19.313045 31860 recover.cpp:193] Received a recover response from a
replica in EMPTY status
I0405 17:29:19.313608 31860 recover.cpp:564] Updating replica status to STARTING
I0405 17:29:19.316416 31867 master.cpp:376] Master
9565ff6f-f1b6-4259-8430-690e635c391f (4090d10eba90) started on 172.17.0.4:43972
I0405 17:29:19.316470 31867 master.cpp:378] Flags at startup: --acls=""
--allocation_interval="1secs" --allocator="HierarchicalDRF"
--authenticate="true" --authenticate_http="true" --authenticate_slaves="true"
--authenticators="crammd5" --authorizers="local"
--credentials="/tmp/0A9ELu/credentials" --framework_sorter="drf" --help="false"
--hostname_lookup="true" --http_authenticators="basic"
--initialize_driver_logging="true" --log_auto_initialize="true"
--logbufsecs="0" --logging_level="INFO" --max_completed_frameworks="50"
--max_completed_tasks_per_framework="1000" --max_slave_ping_timeouts="5"
--quiet="false" --recovery_slave_removal_limit="100%"
--registry="replicated_log" --registry_fetch_timeout="1mins"
--registry_store_timeout="100secs" --registry_strict="true"
--root_submissions="true" --slave_ping_timeout="15secs"
--slave_reregister_timeout="10mins" --user_sorter="drf" --version="false"
--webui_dir="/mesos/mesos-0.29.0/_inst/share/mesos/webui"
--work_dir="/tmp/0A9ELu/master" --zk_session_timeout="10secs"
I0405 17:29:19.316938 31867 master.cpp:427] Master only allowing authenticated
frameworks to register
I0405 17:29:19.316951 31867 master.cpp:432] Master only allowing authenticated
agents to register
I0405 17:29:19.316961 31867 credentials.hpp:37] Loading credentials for
authentication from '/tmp/0A9ELu/credentials'
I0405 17:29:19.317402 31867 master.cpp:474] Using default 'crammd5'
authenticator
I0405 17:29:19.317643 31867 master.cpp:545] Using default 'basic' HTTP
authenticator
I0405 17:29:19.317854 31867 master.cpp:583] Authorization enabled
I0405 17:29:19.318081 31864 whitelist_watcher.cpp:77] No whitelist given
I0405 17:29:19.318079 31861 hierarchical.cpp:144] Initialized hierarchical
allocator process
I0405 17:29:19.320838 31864 master.cpp:1826] The newly elected leader is
master@172.17.0.4:43972 with id 9565ff6f-f1b6-4259-8430-690e635c391f
I0405 17:29:19.320888 31864 master.cpp:1839] Elected as the leading master!
I0405 17:29:19.320909 31864 master.cpp:1526] Recovering from registrar
I0405 17:29:19.321218 31871 registrar.cpp:331] Recovering registrar
I0405 17:29:19.347045 31860 leveldb.cpp:304] Persisting metadata (8 bytes) to
leveldb took 33.164133ms
I0405 17:29:19.347126 31860 replica.cpp:320] Persisted replica status to
STARTING
I0405 17:29:19.347611 31869 recover.cpp:473] Replica is in STARTING status
I0405 17:29:19.349215 31871 replica.cpp:673] Replica in STARTING status
received a broadcasted recover request from (14361)@172.17.0.4:43972
I0405 17:29:19.349653 31870 recover.cpp:193] Received a recover response from a
replica in STARTING status
I0405 17:29:19.350236 31866 recover.cpp:564] Updating replica status to VOTING
I0405 17:29:19.388882 31864 leveldb.cpp:304] Persisting metadata (8 bytes) to
leveldb took 38.38299ms
I0405 17:29:19.388993 31864 replica.cpp:320] Persisted replica status to VOTING
I0405 17:29:19.389369 31856 recover.cpp:578] Successfully joined the Paxos group
I0405 17:29:19.389735 31856 recover.cpp:462] Recover process terminated
I0405 17:29:19.390476 31868 log.cpp:659] Attempting to start the writer
I0405 17:29:19.392125 31862 replica.cpp:493] Replica received implicit promise
request from (14362)@172.17.0.4:43972 with proposal 1
I0405 17:29:19.430706 31862 leveldb.cpp:304] Persisting metadata (8 bytes) to
leveldb took 38.505062ms
I0405 17:29:19.430816 31862 replica.cpp:342] Persisted promised to 1
I0405 17:29:19.431918 31856 coordinator.cpp:238] Coordinator attempting to fill
missing positions
I0405 17:29:19.433725 31861 replica.cpp:388] Replica received explicit promise
request from (14363)@172.17.0.4:43972 for position 0 with proposal 2
I0405 17:29:19.472491 31861 leveldb.cpp:341] Persisting action (8 bytes) to
leveldb took 38.659492ms
I0405 17:29:19.472595 31861 replica.cpp:712] Persisted action at 0
I0405 17:29:19.474556 31864 replica.cpp:537] Replica received write request for
position 0 from (14364)@172.17.0.4:43972
I0405 17:29:19.474652 31864 leveldb.cpp:436] Reading position from leveldb took
49423ns
I0405 17:29:19.528175 31864 leveldb.cpp:341] Persisting action (14 bytes) to
leveldb took 53.443616ms
I0405 17:29:19.528300 31864 replica.cpp:712] Persisted action at 0
I0405 17:29:19.529389 31865 replica.cpp:691] Replica received learned notice
for position 0 from @0.0.0.0:0
I0405 17:29:19.571137 31865 leveldb.cpp:341] Persisting action (16 bytes) to
leveldb took 41.676495ms
I0405 17:29:19.571254 31865 replica.cpp:712] Persisted action at 0
I0405 17:29:19.571302 31865 replica.cpp:697] Replica learned NOP action at
position 0
I0405 17:29:19.572322 31856 log.cpp:675] Writer started with ending position 0
I0405 17:29:19.574060 31861 leveldb.cpp:436] Reading position from leveldb took
83200ns
I0405 17:29:19.575417 31864 registrar.cpp:364] Successfully fetched the
registry (0B) in 0ns
I0405 17:29:19.575565 31864 registrar.cpp:463] Applied 1 operations in 46419ns;
attempting to update the 'registry'
I0405 17:29:19.576517 31857 log.cpp:683] Attempting to append 170 bytes to the
log
I0405 17:29:19.576849 31857 coordinator.cpp:348] Coordinator attempting to
write APPEND action at position 1
I0405 17:29:19.578390 31857 replica.cpp:537] Replica received write request for
position 1 from (14365)@172.17.0.4:43972
I0405 17:29:19.780277 31857 leveldb.cpp:341] Persisting action (189 bytes) to
leveldb took 201.808617ms
I0405 17:29:19.780366 31857 replica.cpp:712] Persisted action at 1
I0405 17:29:19.782024 31857 replica.cpp:691] Replica received learned notice
for position 1 from @0.0.0.0:0
I0405 17:29:19.823770 31857 leveldb.cpp:341] Persisting action (191 bytes) to
leveldb took 41.667662ms
I0405 17:29:19.823851 31857 replica.cpp:712] Persisted action at 1
I0405 17:29:19.823889 31857 replica.cpp:697] Replica learned APPEND action at
position 1
I0405 17:29:19.825701 31867 registrar.cpp:508] Successfully updated the
'registry' in 0ns
I0405 17:29:19.825929 31867 registrar.cpp:394] Successfully recovered registrar
I0405 17:29:19.826015 31857 log.cpp:702] Attempting to truncate the log to 1
I0405 17:29:19.826262 31867 coordinator.cpp:348] Coordinator attempting to
write TRUNCATE action at position 2
I0405 17:29:19.827647 31867 replica.cpp:537] Replica received write request for
position 2 from (14366)@172.17.0.4:43972
I0405 17:29:19.828018 31857 master.cpp:1634] Recovered 0 agents from the
Registry (131B) ; allowing 10mins for agents to re-register
I0405 17:29:19.828065 31861 hierarchical.cpp:171] Skipping recovery of
hierarchical allocator: nothing to recover
I0405 17:29:19.865555 31867 leveldb.cpp:341] Persisting action (16 bytes) to
leveldb took 37.822178ms
I0405 17:29:19.865661 31867 replica.cpp:712] Persisted action at 2
I0405 17:29:19.866921 31867 replica.cpp:691] Replica received learned notice
for position 2 from @0.0.0.0:0
I0405 17:29:19.907341 31867 leveldb.cpp:341] Persisting action (18 bytes) to
leveldb took 40.356649ms
I0405 17:29:19.907531 31867 leveldb.cpp:399] Deleting ~1 keys from leveldb took
91109ns
I0405 17:29:19.907560 31867 replica.cpp:712] Persisted action at 2
I0405 17:29:19.907599 31867 replica.cpp:697] Replica learned TRUNCATE action at
position 2
I0405 17:29:19.923305 31837 resources.cpp:572] Parsing resources as JSON
failed: cpus:2;mem:2048
Trying semicolon-delimited string format instead
I0405 17:29:19.926491 31837 containerizer.cpp:155] Using isolation:
posix/cpu,posix/mem,filesystem/posix
W0405 17:29:19.927836 31837 backend.cpp:66] Failed to create 'bind' backend:
BindBackend requires root privileges
I0405 17:29:19.932029 31862 slave.cpp:200] Agent started on
441)@172.17.0.4:43972
I0405 17:29:19.932086 31862 slave.cpp:201] Flags at startup:
--appc_simple_discovery_uri_prefix="http://";
--appc_store_dir="/tmp/mesos/store/appc" --authenticate_http="true"
--authenticatee="crammd5" --cgroups_cpu_enable_pids_and_tids_count="false"
--cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup"
--cgroups_limit_swap="false" --cgroups_root="mesos"
--container_disk_watch_interval="15secs" --containerizers="mesos"
--credential="/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_0_fJS7AC/credential"
--default_role="*" --disk_watch_interval="1mins" --docker="docker"
--docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io";
--docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock"
--docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker"
--enforce_container_disk_quota="false" --executor_registration_timeout="1mins"
--executor_shutdown_grace_period="5secs"
--fetcher_cache_dir="/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_0_fJS7AC/fetch"
--fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks"
--gc_disk_headroom="0.1" --hadoop_home="" --help="false"
--hostname_lookup="true" --http_authenticators="basic"
--http_credentials="/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_0_fJS7AC/http_credentials"
--image_provisioner_backend="copy" --initialize_driver_logging="true"
--isolation="posix/cpu,posix/mem"
--launcher_dir="/mesos/mesos-0.29.0/_build/src" --logbufsecs="0"
--logging_level="INFO" --oversubscribed_resources_interval="15secs"
--perf_duration="10secs" --perf_interval="1mins"
--qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect"
--recovery_timeout="15mins" --registration_backoff_factor="10ms"
--resources="[{"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="/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_0_fJS7AC"
I0405 17:29:19.932665 31862 credentials.hpp:86] Loading credential for
authentication from
'/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_0_fJS7AC/credential'
I0405 17:29:19.932934 31862 slave.cpp:338] Agent using credential for:
test-principal
I0405 17:29:19.932968 31862 credentials.hpp:37] Loading credentials for
authentication from
'/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_0_fJS7AC/http_credentials'
I0405 17:29:19.933284 31862 slave.cpp:390] Using default 'basic' HTTP
authenticator
I0405 17:29:19.934916 31837 sched.cpp:222] Version: 0.29.0
I0405 17:29:19.935566 31862 slave.cpp:589] Agent resources: cpus(*):2;
mem(*):2048; disk(role1):4096; ports(*):[31000-32000]
I0405 17:29:19.935664 31862 slave.cpp:597] Agent attributes: [ ]
I0405 17:29:19.935679 31862 slave.cpp:602] Agent hostname: 4090d10eba90
I0405 17:29:19.938390 31864 state.cpp:57] Recovering state from
'/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_0_fJS7AC/meta'
I0405 17:29:19.940608 31869 sched.cpp:326] New master detected at
master@172.17.0.4:43972
I0405 17:29:19.940749 31869 sched.cpp:382] Authenticating with master
master@172.17.0.4:43972
I0405 17:29:19.940773 31869 sched.cpp:389] Using default CRAM-MD5 authenticatee
I0405 17:29:19.942371 31869 authenticatee.cpp:121] Creating new client SASL
connection
I0405 17:29:19.942873 31859 master.cpp:5679] Authenticating
scheduler-bdf68f7f-d938-47ed-a132-bb3f218628bf@172.17.0.4:43972
I0405 17:29:19.943156 31859 authenticator.cpp:413] Starting authentication
session for crammd5_authenticatee(896)@172.17.0.4:43972
I0405 17:29:19.943507 31863 authenticator.cpp:98] Creating new server SASL
connection
I0405 17:29:19.943740 31859 authenticatee.cpp:212] Received SASL authentication
mechanisms: CRAM-MD5
I0405 17:29:19.943783 31859 authenticatee.cpp:238] Attempting to authenticate
with mechanism 'CRAM-MD5'
I0405 17:29:19.943892 31859 authenticator.cpp:203] Received SASL authentication
start
I0405 17:29:19.943977 31859 authenticator.cpp:325] Authentication requires more
steps
I0405 17:29:19.944066 31859 authenticatee.cpp:258] Received SASL authentication
step
I0405 17:29:19.944164 31859 authenticator.cpp:231] Received SASL authentication
step
I0405 17:29:19.944193 31859 auxprop.cpp:107] Request to lookup properties for
user: 'test-principal' realm: '4090d10eba90' server FQDN: '4090d10eba90'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
I0405 17:29:19.944206 31859 auxprop.cpp:179] Looking up auxiliary property
'*userPassword'
I0405 17:29:19.944268 31859 auxprop.cpp:179] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0405 17:29:19.944300 31859 auxprop.cpp:107] Request to lookup properties for
user: 'test-principal' realm: '4090d10eba90' server FQDN: '4090d10eba90'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
I0405 17:29:19.944313 31859 auxprop.cpp:129] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0405 17:29:19.944321 31859 auxprop.cpp:129] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0405 17:29:19.944339 31859 authenticator.cpp:317] Authentication success
I0405 17:29:19.944541 31859 authenticatee.cpp:298] Authentication success
I0405 17:29:19.944655 31859 master.cpp:5709] Successfully authenticated
principal 'test-principal' at
scheduler-bdf68f7f-d938-47ed-a132-bb3f218628bf@172.17.0.4:43972
I0405 17:29:19.944737 31859 authenticator.cpp:431] Authentication session
cleanup for crammd5_authenticatee(896)@172.17.0.4:43972
I0405 17:29:19.945111 31859 sched.cpp:472] Successfully authenticated with
master master@172.17.0.4:43972
I0405 17:29:19.945132 31859 sched.cpp:777] Sending SUBSCRIBE call to
master@172.17.0.4:43972
I0405 17:29:19.945591 31859 sched.cpp:810] Will retry registration in
372.80738ms if necessary
I0405 17:29:19.945744 31865 master.cpp:2346] Received SUBSCRIBE call for
framework 'default' at
scheduler-bdf68f7f-d938-47ed-a132-bb3f218628bf@172.17.0.4:43972
I0405 17:29:19.945838 31865 master.cpp:1865] Authorizing framework principal
'test-principal' to receive offers for role 'role1'
I0405 17:29:19.946194 31865 master.cpp:2417] Subscribing framework default with
checkpointing disabled and capabilities [ ]
I0405 17:29:19.946866 31866 hierarchical.cpp:266] Added framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000
I0405 17:29:19.946974 31866 hierarchical.cpp:1490] No resources available to
allocate!
I0405 17:29:19.947010 31866 hierarchical.cpp:1585] No inverse offers to send
out!
I0405 17:29:19.947054 31865 sched.cpp:704] Framework registered with
9565ff6f-f1b6-4259-8430-690e635c391f-0000
I0405 17:29:19.947074 31866 hierarchical.cpp:1141] Performed allocation for 0
agents in 178242ns
I0405 17:29:19.947124 31865 sched.cpp:718] Scheduler::registered took 38907ns
I0405 17:29:19.948712 31866 status_update_manager.cpp:200] Recovering status
update manager
I0405 17:29:19.948901 31866 containerizer.cpp:416] Recovering containerizer
I0405 17:29:19.951021 31866 provisioner.cpp:245] Provisioner recovery complete
I0405 17:29:19.951802 31866 slave.cpp:4773] Finished recovery
I0405 17:29:19.952518 31866 slave.cpp:4945] Querying resource estimator for
oversubscribable resources
I0405 17:29:19.953248 31866 slave.cpp:928] New master detected at
master@172.17.0.4:43972
I0405 17:29:19.953305 31865 status_update_manager.cpp:174] Pausing sending
status updates
I0405 17:29:19.953626 31866 slave.cpp:991] Authenticating with master
master@172.17.0.4:43972
I0405 17:29:19.953716 31866 slave.cpp:996] Using default CRAM-MD5 authenticatee
I0405 17:29:19.954074 31866 slave.cpp:964] Detecting new master
I0405 17:29:19.954167 31861 authenticatee.cpp:121] Creating new client SASL
connection
I0405 17:29:19.954372 31866 slave.cpp:4959] Received oversubscribable resources
from the resource estimator
I0405 17:29:19.954756 31866 master.cpp:5679] Authenticating
slave(441)@172.17.0.4:43972
I0405 17:29:19.954944 31861 authenticator.cpp:413] Starting authentication
session for crammd5_authenticatee(897)@172.17.0.4:43972
I0405 17:29:19.955368 31863 authenticator.cpp:98] Creating new server SASL
connection
I0405 17:29:19.955687 31861 authenticatee.cpp:212] Received SASL authentication
mechanisms: CRAM-MD5
I0405 17:29:19.955801 31861 authenticatee.cpp:238] Attempting to authenticate
with mechanism 'CRAM-MD5'
I0405 17:29:19.956075 31861 authenticator.cpp:203] Received SASL authentication
start
I0405 17:29:19.956279 31861 authenticator.cpp:325] Authentication requires more
steps
I0405 17:29:19.956455 31861 authenticatee.cpp:258] Received SASL authentication
step
I0405 17:29:19.956676 31861 authenticator.cpp:231] Received SASL authentication
step
I0405 17:29:19.956815 31861 auxprop.cpp:107] Request to lookup properties for
user: 'test-principal' realm: '4090d10eba90' server FQDN: '4090d10eba90'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: false
I0405 17:29:19.956907 31861 auxprop.cpp:179] Looking up auxiliary property
'*userPassword'
I0405 17:29:19.957044 31861 auxprop.cpp:179] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0405 17:29:19.957166 31861 auxprop.cpp:107] Request to lookup properties for
user: 'test-principal' realm: '4090d10eba90' server FQDN: '4090d10eba90'
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
SASL_AUXPROP_AUTHZID: true
I0405 17:29:19.957264 31861 auxprop.cpp:129] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0405 17:29:19.957353 31861 auxprop.cpp:129] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0405 17:29:19.957449 31861 authenticator.cpp:317] Authentication success
I0405 17:29:19.957664 31857 authenticatee.cpp:298] Authentication success
I0405 17:29:19.957813 31857 master.cpp:5709] Successfully authenticated
principal 'test-principal' at slave(441)@172.17.0.4:43972
I0405 17:29:19.958008 31861 authenticator.cpp:431] Authentication session
cleanup for crammd5_authenticatee(897)@172.17.0.4:43972
I0405 17:29:19.958732 31857 slave.cpp:1061] Successfully authenticated with
master master@172.17.0.4:43972
I0405 17:29:19.958930 31857 slave.cpp:1457] Will retry registration in
18.568334ms if necessary
I0405 17:29:19.959262 31857 master.cpp:4390] Registering agent at
slave(441)@172.17.0.4:43972 (4090d10eba90) with id
9565ff6f-f1b6-4259-8430-690e635c391f-S0
I0405 17:29:19.959934 31857 registrar.cpp:463] Applied 1 operations in 99197ns;
attempting to update the 'registry'
I0405 17:29:19.961587 31857 log.cpp:683] Attempting to append 343 bytes to the
log
I0405 17:29:19.961879 31857 coordinator.cpp:348] Coordinator attempting to
write APPEND action at position 3
I0405 17:29:19.963135 31857 replica.cpp:537] Replica received write request for
position 3 from (14381)@172.17.0.4:43972
I0405 17:29:19.999408 31857 leveldb.cpp:341] Persisting action (362 bytes) to
leveldb took 36.200109ms
I0405 17:29:19.999512 31857 replica.cpp:712] Persisted action at 3
I0405 17:29:20.001049 31869 replica.cpp:691] Replica received learned notice
for position 3 from @0.0.0.0:0
I0405 17:29:20.038849 31869 leveldb.cpp:341] Persisting action (364 bytes) to
leveldb took 37.709507ms
I0405 17:29:20.038930 31869 replica.cpp:712] Persisted action at 3
I0405 17:29:20.038965 31869 replica.cpp:697] Replica learned APPEND action at
position 3
I0405 17:29:20.041484 31869 registrar.cpp:508] Successfully updated the
'registry' in 0ns
I0405 17:29:20.041785 31869 log.cpp:702] Attempting to truncate the log to 3
I0405 17:29:20.042364 31859 coordinator.cpp:348] Coordinator attempting to
write TRUNCATE action at position 4
I0405 17:29:20.043767 31859 replica.cpp:537] Replica received write request for
position 4 from (14382)@172.17.0.4:43972
I0405 17:29:20.044585 31869 master.cpp:4458] Registered agent
9565ff6f-f1b6-4259-8430-690e635c391f-S0 at slave(441)@172.17.0.4:43972
(4090d10eba90) with cpus(*):2; mem(*):2048; disk(role1):4096;
ports(*):[31000-32000]
I0405 17:29:20.044910 31864 slave.cpp:1105] Registered with master
master@172.17.0.4:43972; given agent ID 9565ff6f-f1b6-4259-8430-690e635c391f-S0
I0405 17:29:20.045075 31864 fetcher.cpp:81] Clearing fetcher cache
I0405 17:29:20.045140 31870 hierarchical.cpp:476] Added agent
9565ff6f-f1b6-4259-8430-690e635c391f-S0 (4090d10eba90) with cpus(*):2;
mem(*):2048; disk(role1):4096; ports(*):[31000-32000] (allocated: )
I0405 17:29:20.045581 31864 slave.cpp:1128] Checkpointing SlaveInfo to
'/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_0_fJS7AC/meta/slaves/9565ff6f-f1b6-4259-8430-690e635c391f-S0/slave.info'
I0405 17:29:20.045974 31864 slave.cpp:1165] Forwarding total oversubscribed
resources
I0405 17:29:20.046077 31864 slave.cpp:3664] Received ping from
slave-observer(399)@172.17.0.4:43972
I0405 17:29:20.046193 31864 status_update_manager.cpp:181] Resuming sending
status updates
I0405 17:29:20.046289 31870 hierarchical.cpp:1585] No inverse offers to send
out!
I0405 17:29:20.046370 31870 hierarchical.cpp:1164] Performed allocation for
agent 9565ff6f-f1b6-4259-8430-690e635c391f-S0 in 1.153377ms
I0405 17:29:20.046499 31864 master.cpp:4802] Received update of agent
9565ff6f-f1b6-4259-8430-690e635c391f-S0 at slave(441)@172.17.0.4:43972
(4090d10eba90) with total oversubscribed resources
I0405 17:29:20.047142 31868 hierarchical.cpp:534] Agent
9565ff6f-f1b6-4259-8430-690e635c391f-S0 (4090d10eba90) 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])
I0405 17:29:20.047960 31868 hierarchical.cpp:1490] No resources available to
allocate!
I0405 17:29:20.048009 31868 hierarchical.cpp:1585] No inverse offers to send
out!
I0405 17:29:20.048065 31868 hierarchical.cpp:1164] Performed allocation for
agent 9565ff6f-f1b6-4259-8430-690e635c391f-S0 in 866803ns
I0405 17:29:20.048591 31864 master.cpp:5508] Sending 1 offers to framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000 (default) at
scheduler-bdf68f7f-d938-47ed-a132-bb3f218628bf@172.17.0.4:43972
I0405 17:29:20.049188 31860 sched.cpp:874] Scheduler::resourceOffers took
114867ns
I0405 17:29:20.080921 31859 leveldb.cpp:341] Persisting action (16 bytes) to
leveldb took 37.025538ms
I0405 17:29:20.081001 31859 replica.cpp:712] Persisted action at 4
I0405 17:29:20.082425 31859 replica.cpp:691] Replica received learned notice
for position 4 from @0.0.0.0:0
I0405 17:29:20.106056 31859 leveldb.cpp:341] Persisting action (18 bytes) to
leveldb took 23.583037ms
I0405 17:29:20.106205 31859 leveldb.cpp:399] Deleting ~2 keys from leveldb took
76995ns
I0405 17:29:20.106240 31859 replica.cpp:712] Persisted action at 4
I0405 17:29:20.106278 31859 replica.cpp:697] Replica learned TRUNCATE action at
position 4
I0405 17:29:20.119488 31837 resources.cpp:572] Parsing resources as JSON
failed: cpus:1;mem:128
Trying semicolon-delimited string format instead
I0405 17:29:20.121356 31859 master.cpp:3288] Processing ACCEPT call for offers:
[ 9565ff6f-f1b6-4259-8430-690e635c391f-O0 ] on agent
9565ff6f-f1b6-4259-8430-690e635c391f-S0 at slave(441)@172.17.0.4:43972
(4090d10eba90) for framework 9565ff6f-f1b6-4259-8430-690e635c391f-0000
(default) at scheduler-bdf68f7f-d938-47ed-a132-bb3f218628bf@172.17.0.4:43972
I0405 17:29:20.121485 31859 master.cpp:3046] Authorizing principal
'test-principal' to create volumes
I0405 17:29:20.121692 31859 master.cpp:2891] Authorizing framework principal
'test-principal' to launch task 91050005-0b1d-4a37-9ea1-f8ae1ff3b542 as user
'mesos'
I0405 17:29:20.123877 31871 master.cpp:3617] Applying CREATE operation for
volumes disk(role1)[id1:path1]:2048 from framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000 (default) at
scheduler-bdf68f7f-d938-47ed-a132-bb3f218628bf@172.17.0.4:43972 to agent
9565ff6f-f1b6-4259-8430-690e635c391f-S0 at slave(441)@172.17.0.4:43972
(4090d10eba90)
I0405 17:29:20.125424 31871 master.cpp:6747] Sending checkpointed resources
disk(role1)[id1:path1]:2048 to agent 9565ff6f-f1b6-4259-8430-690e635c391f-S0 at
slave(441)@172.17.0.4:43972 (4090d10eba90)
I0405 17:29:20.126397 31856 hierarchical.cpp:656] Updated allocation of
framework 9565ff6f-f1b6-4259-8430-690e635c391f-0000 on agent
9565ff6f-f1b6-4259-8430-690e635c391f-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
I0405 17:29:20.126667 31871 master.hpp:177] Adding task
91050005-0b1d-4a37-9ea1-f8ae1ff3b542 with resources cpus(*):1; mem(*):128;
disk(role1)[id1:path1]:2048 on agent 9565ff6f-f1b6-4259-8430-690e635c391f-S0
(4090d10eba90)
I0405 17:29:20.126875 31871 master.cpp:3773] Launching task
91050005-0b1d-4a37-9ea1-f8ae1ff3b542 of framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000 (default) at
scheduler-bdf68f7f-d938-47ed-a132-bb3f218628bf@172.17.0.4:43972 with resources
cpus(*):1; mem(*):128; disk(role1)[id1:path1]:2048 on agent
9565ff6f-f1b6-4259-8430-690e635c391f-S0 at slave(441)@172.17.0.4:43972
(4090d10eba90)
I0405 17:29:20.127390 31856 slave.cpp:2523] Updated checkpointed resources from
to disk(role1)[id1:path1]:2048
I0405 17:29:20.127615 31856 slave.cpp:1497] Got assigned task
91050005-0b1d-4a37-9ea1-f8ae1ff3b542 for framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000
I0405 17:29:20.127876 31856 resources.cpp:572] Parsing resources as JSON
failed: cpus:0.1;mem:32
Trying semicolon-delimited string format instead
I0405 17:29:20.127841 31871 hierarchical.cpp:893] 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
9565ff6f-f1b6-4259-8430-690e635c391f-S0 from framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000
I0405 17:29:20.127913 31871 hierarchical.cpp:930] Framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000 filtered agent
9565ff6f-f1b6-4259-8430-690e635c391f-S0 for 5secs
I0405 17:29:20.128667 31856 slave.cpp:1616] Launching task
91050005-0b1d-4a37-9ea1-f8ae1ff3b542 for framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000
I0405 17:29:20.128937 31856 resources.cpp:572] Parsing resources as JSON
failed: cpus:0.1;mem:32
Trying semicolon-delimited string format instead
I0405 17:29:20.129776 31856 paths.cpp:528] Trying to chown
'/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_0_fJS7AC/slaves/9565ff6f-f1b6-4259-8430-690e635c391f-S0/frameworks/9565ff6f-f1b6-4259-8430-690e635c391f-0000/executors/91050005-0b1d-4a37-9ea1-f8ae1ff3b542/runs/bc8b48e5-dd32-4283-a1a6-e1988c82ae09'
to user 'mesos'
I0405 17:29:20.145324 31856 slave.cpp:5575] Launching executor
91050005-0b1d-4a37-9ea1-f8ae1ff3b542 of framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000 with resources cpus(*):0.1; mem(*):32
in work directory
'/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_0_fJS7AC/slaves/9565ff6f-f1b6-4259-8430-690e635c391f-S0/frameworks/9565ff6f-f1b6-4259-8430-690e635c391f-0000/executors/91050005-0b1d-4a37-9ea1-f8ae1ff3b542/runs/bc8b48e5-dd32-4283-a1a6-e1988c82ae09'
I0405 17:29:20.146057 31858 containerizer.cpp:675] Starting container
'bc8b48e5-dd32-4283-a1a6-e1988c82ae09' for executor
'91050005-0b1d-4a37-9ea1-f8ae1ff3b542' of framework
'9565ff6f-f1b6-4259-8430-690e635c391f-0000'
I0405 17:29:20.146078 31856 slave.cpp:1834] Queuing task
'91050005-0b1d-4a37-9ea1-f8ae1ff3b542' for executor
'91050005-0b1d-4a37-9ea1-f8ae1ff3b542' of framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000
I0405 17:29:20.146203 31856 slave.cpp:881] Successfully attached file
'/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_0_fJS7AC/slaves/9565ff6f-f1b6-4259-8430-690e635c391f-S0/frameworks/9565ff6f-f1b6-4259-8430-690e635c391f-0000/executors/91050005-0b1d-4a37-9ea1-f8ae1ff3b542/runs/bc8b48e5-dd32-4283-a1a6-e1988c82ae09'
I0405 17:29:20.147619 31859 posix.cpp:206] Changing the ownership of the
persistent volume at
'/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_0_fJS7AC/volumes/roles/role1/id1'
with uid 1000 and gid 1000
I0405 17:29:20.162421 31859 posix.cpp:250] Adding symlink from
'/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_0_fJS7AC/volumes/roles/role1/id1'
to
'/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_0_fJS7AC/slaves/9565ff6f-f1b6-4259-8430-690e635c391f-S0/frameworks/9565ff6f-f1b6-4259-8430-690e635c391f-0000/executors/91050005-0b1d-4a37-9ea1-f8ae1ff3b542/runs/bc8b48e5-dd32-4283-a1a6-e1988c82ae09/path1'
for persistent volume disk(role1)[id1:path1]:2048 of container
bc8b48e5-dd32-4283-a1a6-e1988c82ae09
I0405 17:29:20.172133 31861 launcher.cpp:123] Forked child with pid '7927' for
container 'bc8b48e5-dd32-4283-a1a6-e1988c82ae09'
WARNING: Logging before InitGoogleLogging() is written to STDERR
I0405 17:29:20.376197 7941 process.cpp:986] libprocess is initialized on
172.17.0.4:50952 with 16 worker threads
I0405 17:29:20.378132 7941 logging.cpp:195] Logging to STDERR
I0405 17:29:20.380861 7941 exec.cpp:150] Version: 0.29.0
I0405 17:29:20.396257 7966 exec.cpp:200] Executor started at:
executor(1)@172.17.0.4:50952 with pid 7941
I0405 17:29:20.399426 31860 slave.cpp:2825] Got registration for executor
'91050005-0b1d-4a37-9ea1-f8ae1ff3b542' of framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000 from executor(1)@172.17.0.4:50952
I0405 17:29:20.402995 7966 exec.cpp:225] Executor registered on agent
9565ff6f-f1b6-4259-8430-690e635c391f-S0
I0405 17:29:20.403014 31860 slave.cpp:1999] Sending queued task
'91050005-0b1d-4a37-9ea1-f8ae1ff3b542' to executor
'91050005-0b1d-4a37-9ea1-f8ae1ff3b542' of framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000 at executor(1)@172.17.0.4:50952
I0405 17:29:20.405624 7966 exec.cpp:237] Executor::registered took 393272ns
I0405 17:29:20.406108 7966 exec.cpp:312] Executor asked to run task
'91050005-0b1d-4a37-9ea1-f8ae1ff3b542'
Registered executor on 4090d10eba90
I0405 17:29:20.406708 7966 exec.cpp:321] Executor::launchTask took 568039ns
Starting task 91050005-0b1d-4a37-9ea1-f8ae1ff3b542
Forked command at 7972
sh -c 'echo abc > path1/file'
I0405 17:29:20.411375 7966 exec.cpp:535] Executor sending status update
TASK_RUNNING (UUID: cf4f8fe9-44f2-43ce-8868-b3a09b7298cf) for task
91050005-0b1d-4a37-9ea1-f8ae1ff3b542 of framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000
I0405 17:29:20.413156 31857 slave.cpp:3184] Handling status update TASK_RUNNING
(UUID: cf4f8fe9-44f2-43ce-8868-b3a09b7298cf) for task
91050005-0b1d-4a37-9ea1-f8ae1ff3b542 of framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000 from executor(1)@172.17.0.4:50952
I0405 17:29:20.415714 31857 status_update_manager.cpp:320] Received status
update TASK_RUNNING (UUID: cf4f8fe9-44f2-43ce-8868-b3a09b7298cf) for task
91050005-0b1d-4a37-9ea1-f8ae1ff3b542 of framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000
I0405 17:29:20.415788 31857 status_update_manager.cpp:497] Creating
StatusUpdate stream for task 91050005-0b1d-4a37-9ea1-f8ae1ff3b542 of framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000
I0405 17:29:20.416345 31857 status_update_manager.cpp:374] Forwarding update
TASK_RUNNING (UUID: cf4f8fe9-44f2-43ce-8868-b3a09b7298cf) for task
91050005-0b1d-4a37-9ea1-f8ae1ff3b542 of framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000 to the agent
I0405 17:29:20.416720 31870 slave.cpp:3582] Forwarding the update TASK_RUNNING
(UUID: cf4f8fe9-44f2-43ce-8868-b3a09b7298cf) for task
91050005-0b1d-4a37-9ea1-f8ae1ff3b542 of framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000 to master@172.17.0.4:43972
I0405 17:29:20.416954 31870 slave.cpp:3476] Status update manager successfully
handled status update TASK_RUNNING (UUID: cf4f8fe9-44f2-43ce-8868-b3a09b7298cf)
for task 91050005-0b1d-4a37-9ea1-f8ae1ff3b542 of framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000
I0405 17:29:20.416997 31870 slave.cpp:3492] Sending acknowledgement for status
update TASK_RUNNING (UUID: cf4f8fe9-44f2-43ce-8868-b3a09b7298cf) for task
91050005-0b1d-4a37-9ea1-f8ae1ff3b542 of framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000 to executor(1)@172.17.0.4:50952
I0405 17:29:20.417505 31870 master.cpp:4947] Status update TASK_RUNNING (UUID:
cf4f8fe9-44f2-43ce-8868-b3a09b7298cf) for task
91050005-0b1d-4a37-9ea1-f8ae1ff3b542 of framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000 from agent
9565ff6f-f1b6-4259-8430-690e635c391f-S0 at slave(441)@172.17.0.4:43972
(4090d10eba90)
I0405 17:29:20.417549 31870 master.cpp:4995] Forwarding status update
TASK_RUNNING (UUID: cf4f8fe9-44f2-43ce-8868-b3a09b7298cf) for task
91050005-0b1d-4a37-9ea1-f8ae1ff3b542 of framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000
I0405 17:29:20.417724 31870 master.cpp:6608] Updating the state of task
91050005-0b1d-4a37-9ea1-f8ae1ff3b542 of framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000 (latest state: TASK_RUNNING, status
update state: TASK_RUNNING)
I0405 17:29:20.417943 7960 exec.cpp:358] Executor received status update
acknowledgement cf4f8fe9-44f2-43ce-8868-b3a09b7298cf for task
91050005-0b1d-4a37-9ea1-f8ae1ff3b542 of framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000
I0405 17:29:20.418002 31870 sched.cpp:982] Scheduler::statusUpdate took 105225ns
I0405 17:29:20.418623 31870 master.cpp:4102] Processing ACKNOWLEDGE call
cf4f8fe9-44f2-43ce-8868-b3a09b7298cf for task
91050005-0b1d-4a37-9ea1-f8ae1ff3b542 of framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000 (default) at
scheduler-bdf68f7f-d938-47ed-a132-bb3f218628bf@172.17.0.4:43972 on agent
9565ff6f-f1b6-4259-8430-690e635c391f-S0
I0405 17:29:20.419181 31860 status_update_manager.cpp:392] Received status
update acknowledgement (UUID: cf4f8fe9-44f2-43ce-8868-b3a09b7298cf) for task
91050005-0b1d-4a37-9ea1-f8ae1ff3b542 of framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000
I0405 17:29:20.419816 31860 slave.cpp:2594] Status update manager successfully
handled status update acknowledgement (UUID:
cf4f8fe9-44f2-43ce-8868-b3a09b7298cf) for task
91050005-0b1d-4a37-9ea1-f8ae1ff3b542 of framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000
I0405 17:29:20.513465 7969 exec.cpp:535] Executor sending status update
TASK_FINISHED (UUID: 128eb7af-a662-4cbb-9401-125dca38f719) for task
91050005-0b1d-4a37-9ea1-f8ae1ff3b542 of framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000
Command exited with status 0 (pid: 7972)
I0405 17:29:20.515449 31870 slave.cpp:3184] Handling status update
TASK_FINISHED (UUID: 128eb7af-a662-4cbb-9401-125dca38f719) for task
91050005-0b1d-4a37-9ea1-f8ae1ff3b542 of framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000 from executor(1)@172.17.0.4:50952
I0405 17:29:20.516875 31860 slave.cpp:5885] Terminating task
91050005-0b1d-4a37-9ea1-f8ae1ff3b542
I0405 17:29:20.517496 31867 posix.cpp:156] Removing symlink
'/tmp/DiskResource_PersistentVolumeTest_AccessPersistentVolume_0_fJS7AC/slaves/9565ff6f-f1b6-4259-8430-690e635c391f-S0/frameworks/9565ff6f-f1b6-4259-8430-690e635c391f-0000/executors/91050005-0b1d-4a37-9ea1-f8ae1ff3b542/runs/bc8b48e5-dd32-4283-a1a6-e1988c82ae09/path1'
for persistent volume disk(role1)[id1:path1]:2048 of container
bc8b48e5-dd32-4283-a1a6-e1988c82ae09
I0405 17:29:20.519361 31864 status_update_manager.cpp:320] Received status
update TASK_FINISHED (UUID: 128eb7af-a662-4cbb-9401-125dca38f719) for task
91050005-0b1d-4a37-9ea1-f8ae1ff3b542 of framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000
I0405 17:29:20.519850 31864 status_update_manager.cpp:374] Forwarding update
TASK_FINISHED (UUID: 128eb7af-a662-4cbb-9401-125dca38f719) for task
91050005-0b1d-4a37-9ea1-f8ae1ff3b542 of framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000 to the agent
I0405 17:29:20.520678 31870 slave.cpp:3582] Forwarding the update TASK_FINISHED
(UUID: 128eb7af-a662-4cbb-9401-125dca38f719) for task
91050005-0b1d-4a37-9ea1-f8ae1ff3b542 of framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000 to master@172.17.0.4:43972
I0405 17:29:20.520901 31870 slave.cpp:3476] Status update manager successfully
handled status update TASK_FINISHED (UUID:
128eb7af-a662-4cbb-9401-125dca38f719) for task
91050005-0b1d-4a37-9ea1-f8ae1ff3b542 of framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000
I0405 17:29:20.520949 31870 slave.cpp:3492] Sending acknowledgement for status
update TASK_FINISHED (UUID: 128eb7af-a662-4cbb-9401-125dca38f719) for task
91050005-0b1d-4a37-9ea1-f8ae1ff3b542 of framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000 to executor(1)@172.17.0.4:50952
I0405 17:29:20.521550 31864 master.cpp:4947] Status update TASK_FINISHED (UUID:
128eb7af-a662-4cbb-9401-125dca38f719) for task
91050005-0b1d-4a37-9ea1-f8ae1ff3b542 of framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000 from agent
9565ff6f-f1b6-4259-8430-690e635c391f-S0 at slave(441)@172.17.0.4:43972
(4090d10eba90)
I0405 17:29:20.521610 31864 master.cpp:4995] Forwarding status update
TASK_FINISHED (UUID: 128eb7af-a662-4cbb-9401-125dca38f719) for task
91050005-0b1d-4a37-9ea1-f8ae1ff3b542 of framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000
I0405 17:29:20.522099 31871 sched.cpp:982] Scheduler::statusUpdate took 102502ns
I0405 17:29:20.522367 31864 master.cpp:6608] Updating the state of task
91050005-0b1d-4a37-9ea1-f8ae1ff3b542 of framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000 (latest state: TASK_FINISHED, status
update state: TASK_FINISHED)
I0405 17:29:20.524288 31871 hierarchical.cpp:1676] Filtered offer with
disk(role1):2048; cpus(*):1; mem(*):1920; ports(*):[31000-32000] on agent
9565ff6f-f1b6-4259-8430-690e635c391f-S0 for framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000
I0405 17:29:20.524379 31871 hierarchical.cpp:1490] No resources available to
allocate!
I0405 17:29:20.524451 31871 hierarchical.cpp:1585] No inverse offers to send
out!
I0405 17:29:20.524551 31871 hierarchical.cpp:1141] Performed allocation for 1
agents in 961746ns
I0405 17:29:20.525182 31858 hierarchical.cpp:893] 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 9565ff6f-f1b6-4259-8430-690e635c391f-S0 from framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000
I0405 17:29:20.525197 31864 master.cpp:4102] Processing ACKNOWLEDGE call
128eb7af-a662-4cbb-9401-125dca38f719 for task
91050005-0b1d-4a37-9ea1-f8ae1ff3b542 of framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000 (default) at
scheduler-bdf68f7f-d938-47ed-a132-bb3f218628bf@172.17.0.4:43972 on agent
9565ff6f-f1b6-4259-8430-690e635c391f-S0
I0405 17:29:20.525380 31864 master.cpp:6674] Removing task
91050005-0b1d-4a37-9ea1-f8ae1ff3b542 with resources cpus(*):1; mem(*):128;
disk(role1)[id1:path1]:2048 of framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000 on agent
9565ff6f-f1b6-4259-8430-690e635c391f-S0 at slave(441)@172.17.0.4:43972
(4090d10eba90)
I0405 17:29:20.526067 31864 status_update_manager.cpp:392] Received status
update acknowledgement (UUID: 128eb7af-a662-4cbb-9401-125dca38f719) for task
91050005-0b1d-4a37-9ea1-f8ae1ff3b542 of framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000
I0405 17:29:20.526425 31864 status_update_manager.cpp:528] Cleaning up status
update stream for task 91050005-0b1d-4a37-9ea1-f8ae1ff3b542 of framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000
I0405 17:29:20.526917 31864 slave.cpp:2594] Status update manager successfully
handled status update acknowledgement (UUID:
128eb7af-a662-4cbb-9401-125dca38f719) for task
91050005-0b1d-4a37-9ea1-f8ae1ff3b542 of framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000
I0405 17:29:20.527048 31864 slave.cpp:5926] Completing task
91050005-0b1d-4a37-9ea1-f8ae1ff3b542
I0405 17:29:20.527732 7964 exec.cpp:358] Executor received status update
acknowledgement 128eb7af-a662-4cbb-9401-125dca38f719 for task
91050005-0b1d-4a37-9ea1-f8ae1ff3b542 of framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000
I0405 17:29:21.527920 31859 slave.cpp:3710] executor(1)@172.17.0.4:50952 exited
../../src/tests/persistent_volume_tests.cpp:825: Failure
Failed to wait 15secs for offers
I0405 17:29:35.542609 31856 master.cpp:1269] Framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000 (default) at
scheduler-bdf68f7f-d938-47ed-a132-bb3f218628bf@172.17.0.4:43972 disconnected
I0405 17:29:35.542811 31856 master.cpp:2642] Disconnecting framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000 (default) at
scheduler-bdf68f7f-d938-47ed-a132-bb3f218628bf@172.17.0.4:43972
I0405 17:29:35.542994 31856 master.cpp:2666] Deactivating framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000 (default) at
scheduler-bdf68f7f-d938-47ed-a132-bb3f218628bf@172.17.0.4:43972
I0405 17:29:35.543349 31860 hierarchical.cpp:378] Deactivated framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000
I0405 17:29:35.543501 31856 master.cpp:1293] Giving framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000 (default) at
scheduler-bdf68f7f-d938-47ed-a132-bb3f218628bf@172.17.0.4:43972 0ns to failover
I0405 17:29:35.543903 31868 master.cpp:5360] Framework failover timeout,
removing framework 9565ff6f-f1b6-4259-8430-690e635c391f-0000 (default) at
scheduler-bdf68f7f-d938-47ed-a132-bb3f218628bf@172.17.0.4:43972
I0405 17:29:35.543936 31868 master.cpp:6093] Removing framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000 (default) at
scheduler-bdf68f7f-d938-47ed-a132-bb3f218628bf@172.17.0.4:43972
I0405 17:29:35.544337 31861 slave.cpp:2215] Asked to shut down framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000 by master@172.17.0.4:43972
I0405 17:29:35.544381 31861 slave.cpp:2240] Shutting down framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000
I0405 17:29:35.544456 31861 slave.cpp:4398] Shutting down executor
'91050005-0b1d-4a37-9ea1-f8ae1ff3b542' of framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000 at executor(1)@172.17.0.4:50952
I0405 17:29:35.544960 31872 poll_socket.cpp:110] Socket error while connecting
I0405 17:29:35.545013 31872 process.cpp:1650] Failed to send
'mesos.internal.ShutdownExecutorMessage' to '172.17.0.4:50952', connect: Socket
error while connecting
E0405 17:29:35.545106 31872 process.cpp:1958] Failed to shutdown socket with fd
27: Transport endpoint is not connected
I0405 17:29:35.545474 31864 hierarchical.cpp:329] Removed framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000
../../src/tests/persistent_volume_tests.cpp:819: Failure
Actual function call count doesn't match EXPECT_CALL(sched,
resourceOffers(&driver, _))...
Expected: to be called at least once
Actual: never called - unsatisfied and active
I0405 17:29:35.558538 31858 containerizer.cpp:1432] Destroying container
'bc8b48e5-dd32-4283-a1a6-e1988c82ae09'
../../src/tests/cluster.cpp:453: Failure
Failed to wait 15secs for wait
I0405 17:29:50.565403 31870 slave.cpp:800] Agent terminating
I0405 17:29:50.565512 31870 slave.cpp:2215] Asked to shut down framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000 by @0.0.0.0:0
W0405 17:29:50.565544 31870 slave.cpp:2236] Ignoring shutdown framework
9565ff6f-f1b6-4259-8430-690e635c391f-0000 because it is terminating
I0405 17:29:50.574620 31866 master.cpp:1230] Agent
9565ff6f-f1b6-4259-8430-690e635c391f-S0 at slave(441)@172.17.0.4:43972
(4090d10eba90) disconnected
I0405 17:29:50.574766 31866 master.cpp:2701] Disconnecting agent
9565ff6f-f1b6-4259-8430-690e635c391f-S0 at slave(441)@172.17.0.4:43972
(4090d10eba90)
I0405 17:29:50.575003 31866 master.cpp:2720] Deactivating agent
9565ff6f-f1b6-4259-8430-690e635c391f-S0 at slave(441)@172.17.0.4:43972
(4090d10eba90)
I0405 17:29:50.575294 31865 hierarchical.cpp:563] Agent
9565ff6f-f1b6-4259-8430-690e635c391f-S0 deactivated
I0405 17:29:50.605787 31837 master.cpp:1083] Master terminating
I0405 17:29:50.606533 31866 hierarchical.cpp:508] Removed agent
9565ff6f-f1b6-4259-8430-690e635c391f-S0
[ FAILED ] DiskResource/PersistentVolumeTest.AccessPersistentVolume/0, where
GetParam() = 0 (31491 ms)
{code}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
