You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@mesos.apache.org by "Neil Conway (JIRA)" <ji...@apache.org> on 2016/04/06 15:59:25 UTC
[jira] [Assigned] (MESOS-5128)
PersistentVolumeTest.AccessPersistentVolume is flaky
[ https://issues.apache.org/jira/browse/MESOS-5128?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Neil Conway reassigned MESOS-5128:
----------------------------------
Assignee: Neil Conway
> 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
> Assignee: Neil Conway
> Labels: mesosphere
>
> 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)