-----------------------------------------------------------
This is an automatically generated e-mail. To reply, visit:
https://reviews.apache.org/r/71455/#review217663
-----------------------------------------------------------



Bad patch!

Reviews applied: [71454, 71455]

Failed command: ['bash', '-c', "set -o pipefail; export OS='ubuntu:14.04' 
BUILDTOOL='autotools' COMPILER='gcc' CONFIGURATION='--verbose 
--disable-libtool-wrappers --disable-parallel-test-execution' 
ENVIRONMENT='GLOG_v=1 MESOS_VERBOSE=1'; ./support/docker-build.sh 2>&1 | tee 
build_71455"]

Error:
...<truncated>...
pp:891] Removed agent 7a25d834-f5dd-4508-937d-291d4f68748e-S0
[       OK ] 
CSIVersion/StorageLocalResourceProviderTest.CreateDestroyDiskWithRecovery/v0 
(3938 ms)
[ RUN      ] 
CSIVersion/StorageLocalResourceProviderTest.CreateDestroyDiskWithRecovery/v1
I0909 19:07:05.873780 18915 cluster.cpp:177] Creating default 'local' authorizer
I0909 19:07:05.878141 18934 master.cpp:440] Master 
a0055024-74a2-47f4-8a64-e7876b603597 (2e411cc79614) started on 172.17.0.2:33926
I0909 19:07:05.878180 18934 master.cpp:443] Flags at startup: --acls="" 
--agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" 
--allocation_interval="50ms" --allocator="hierarchical" 
--authenticate_agents="true" --authenticate_frameworks="true" 
--authenticate_http_frameworks="true" --authenticate_http_readonly="true" 
--authenticate_http_readwrite="true" --authentication_v0_timeout="15secs" 
--authenticators="crammd5" --authorizers="local" 
--credentials="/tmp/5qNuFe/credentials" --filter_gpu_resources="true" 
--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" 
--max_operator_event_stream_subscribers="1000" 
--max_unreachable_tasks_per_framework="1000" --memory_profiling="false" 
--min_alloca
 table_resources="cpus:0.01|mem:32" --port="5050" 
--publish_per_framework_metrics="true" --quiet="false" 
--recovery_agent_removal_limit="100%" --registry="in_memory" 
--registry_fetch_timeout="1mins" --registry_gc_interval="15mins" 
--registry_max_agent_age="2weeks" --registry_max_agent_count="102400" 
--registry_store_timeout="100secs" --registry_strict="false" 
--require_agent_domain="false" --role_sorter="drf" --root_submissions="true" 
--version="false" --webui_dir="/mesos/mesos-1.10.0/_inst/share/mesos/webui" 
--work_dir="/tmp/5qNuFe/master" --zk_session_timeout="10secs"
I0909 19:07:05.878645 18934 master.cpp:492] Master only allowing authenticated 
frameworks to register
I0909 19:07:05.878664 18934 master.cpp:498] Master only allowing authenticated 
agents to register
I0909 19:07:05.878674 18934 master.cpp:504] Master only allowing authenticated 
HTTP frameworks to register
I0909 19:07:05.878685 18934 credentials.hpp:37] Loading credentials for 
authentication from '/tmp/5qNuFe/credentials'
I0909 19:07:05.879004 18934 master.cpp:548] Using default 'crammd5' 
authenticator
I0909 19:07:05.879210 18934 http.cpp:975] Creating default 'basic' HTTP 
authenticator for realm 'mesos-master-readonly'
I0909 19:07:05.879443 18934 http.cpp:975] Creating default 'basic' HTTP 
authenticator for realm 'mesos-master-readwrite'
I0909 19:07:05.879627 18934 http.cpp:975] Creating default 'basic' HTTP 
authenticator for realm 'mesos-master-scheduler'
I0909 19:07:05.879798 18934 master.cpp:629] Authorization enabled
I0909 19:07:05.880210 18925 hierarchical.cpp:474] Initialized hierarchical 
allocator process
I0909 19:07:05.880225 18929 whitelist_watcher.cpp:77] No whitelist given
I0909 19:07:05.883572 18930 master.cpp:2169] Elected as the leading master!
I0909 19:07:05.883613 18930 master.cpp:1665] Recovering from registrar
I0909 19:07:05.883797 18935 registrar.cpp:339] Recovering registrar
I0909 19:07:05.884609 18935 registrar.cpp:383] Successfully fetched the 
registry (0B) in 756224ns
I0909 19:07:05.884752 18935 registrar.cpp:487] Applied 1 operations in 41971ns; 
attempting to update the registry
I0909 19:07:05.885488 18935 registrar.cpp:544] Successfully updated the 
registry in 660992ns
I0909 19:07:05.885628 18935 registrar.cpp:416] Successfully recovered registrar
I0909 19:07:05.886270 18928 master.cpp:1818] Recovered 0 agents from the 
registry (144B); allowing 10mins for agents to reregister
I0909 19:07:05.886293 18916 hierarchical.cpp:513] Skipping recovery of 
hierarchical allocator: nothing to recover
W0909 19:07:05.892613 18915 process.cpp:2877] Attempted to spawn already 
running process files@172.17.0.2:33926
I0909 19:07:05.894309 18915 containerizer.cpp:318] Using isolation { 
environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni }
W0909 19:07:05.895031 18915 backend.cpp:76] Failed to create 'overlay' backend: 
OverlayBackend requires root privileges
W0909 19:07:05.895066 18915 backend.cpp:76] Failed to create 'aufs' backend: 
AufsBackend requires root privileges
W0909 19:07:05.895200 18915 backend.cpp:76] Failed to create 'bind' backend: 
BindBackend requires root privileges
I0909 19:07:05.895244 18915 provisioner.cpp:300] Using default backend 'copy'
I0909 19:07:05.897827 18915 cluster.cpp:524] Creating default 'local' authorizer
I0909 19:07:05.900156 18925 slave.cpp:267] Mesos agent started on 
(1189)@172.17.0.2:33926
I0909 19:07:05.900185 18925 slave.cpp:268] Flags at startup: --acls="" 
--appc_simple_discovery_uri_prefix="http://"; 
--appc_store_dir="/tmp/5qNuFe/bov1nx/store/appc" 
--authenticate_http_readonly="true" --authenticate_http_readwrite="false" 
--authenticatee="crammd5" --authentication_backoff_factor="1secs" 
--authentication_timeout_max="1mins" --authentication_timeout_min="5secs" 
--authorizer="local" --cgroups_cpu_enable_pids_and_tids_count="false" 
--cgroups_destroy_timeout="1mins" --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/5qNuFe/bov1nx/credential" 
--default_role="*" --disallow_sharing_agent_ipc_namespace="false" 
--disallow_sharing_agent_pid_namespace="false" 
--disk_profile_adaptor="org_apache_mesos_UriDiskProfileAdaptor" 
--disk_watch_interval="1mins" --docker="docker" --docker_ignore_runtime="false" 
--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/5qNuFe/bov1nx/store/docker" 
--docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" 
--docker_volume_chown="false" --enforce_container_disk_quota="false" 
--executor_registration_timeout="1mins" 
--executor_reregistration_timeout="2secs" 
--executor_shutdown_grace_period="5secs" 
--fetcher_cache_dir="/tmp/5qNuFe/bov1nx/fetch" --fetcher_cache_size="2GB" 
--fetcher_stall_timeout="1mins" 
--frameworks_home="/tmp/5qNuFe/bov1nx/frameworks" --gc_delay="1weeks" 
--gc_disk_headroom="0.1" --gc_non_executor_container_sandboxes="false" 
--help="false" --hostname_lookup="true" --http_command_executor="false" 
--http_credentials="/tmp/5qNuFe/bov1nx/http_credentials" 
--http_heartbeat_interval="30secs" --initialize_driver_logging="true" 
--isolation="posix/cpu,posix/mem" --launcher="posix" 
--launcher_dir="/mesos/mesos-1.10.0/
 _build/src" --logbufsecs="0" --logging_level="INFO" 
--max_completed_executors_per_framework="150" --memory_profiling="false" 
--network_cni_metrics="true" --network_cni_root_dir_persist="false" 
--oversubscribed_resources_interval="15secs" --perf_duration="10secs" 
--perf_interval="1mins" --port="5051" --qos_correction_interval_min="0ns" 
--quiet="false" --reconfiguration_policy="equal" --recover="reconnect" 
--recovery_timeout="15mins" --registration_backoff_factor="10ms" 
--resource_provider_config_dir="/tmp/5qNuFe/resource_provider_configs" 
--resources="cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]" 
--revocable_cpu_low_priority="true" 
--runtime_dir="/tmp/CSIVersion_StorageLocalResourceProviderTest_CreateDestroyDiskWithRecovery_v1_Dq4bHs"
 --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/CSIVersion_StorageLocalResourceProviderTest_Create
 DestroyDiskWithRecovery_v1_XQun0n" --zk_session_timeout="10secs"
I0909 19:07:05.900718 18925 credentials.hpp:86] Loading credential for 
authentication from '/tmp/5qNuFe/bov1nx/credential'
I0909 19:07:05.900899 18925 slave.cpp:300] Agent using credential for: 
test-principal
I0909 19:07:05.900925 18925 credentials.hpp:37] Loading credentials for 
authentication from '/tmp/5qNuFe/bov1nx/http_credentials'
I0909 19:07:05.901144 18925 http.cpp:975] Creating default 'basic' HTTP 
authenticator for realm 'mesos-agent-readonly'
I0909 19:07:05.901515 18925 disk_profile_adaptor.cpp:82] Creating disk profile 
adaptor module 'org_apache_mesos_UriDiskProfileAdaptor'
I0909 19:07:05.903128 18936 uri_disk_profile_adaptor.cpp:305] Updated disk 
profile mapping to 1 active profiles
I0909 19:07:05.903141 18925 slave.cpp:615] Agent resources: 
[{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
I0909 19:07:05.903357 18925 slave.cpp:623] Agent attributes: [  ]
I0909 19:07:05.903373 18925 slave.cpp:632] Agent hostname: 2e411cc79614
I0909 19:07:05.903556 18938 status_update_manager_process.hpp:379] Pausing 
operation status update manager
I0909 19:07:05.903591 18926 task_status_update_manager.cpp:181] Pausing sending 
task status updates
I0909 19:07:05.905311 18931 state.cpp:67] Recovering state from 
'/tmp/CSIVersion_StorageLocalResourceProviderTest_CreateDestroyDiskWithRecovery_v1_XQun0n/meta'
I0909 19:07:05.905580 18918 slave.cpp:7491] Finished recovering checkpointed 
state from 
'/tmp/CSIVersion_StorageLocalResourceProviderTest_CreateDestroyDiskWithRecovery_v1_XQun0n/meta',
 beginning agent recovery
I0909 19:07:05.906206 18933 task_status_update_manager.cpp:207] Recovering task 
status update manager
I0909 19:07:05.906769 18924 containerizer.cpp:821] Recovering Mesos containers
I0909 19:07:05.907213 18924 containerizer.cpp:1161] Recovering isolators
I0909 19:07:05.907963 18939 containerizer.cpp:1200] Recovering provisioner
I0909 19:07:05.908823 18926 provisioner.cpp:500] Provisioner recovery complete
I0909 19:07:05.909544 18933 composing.cpp:339] Finished recovering all 
containerizers
I0909 19:07:05.909834 18922 slave.cpp:7972] Recovering executors
I0909 19:07:05.909948 18922 slave.cpp:8125] Finished recovery
I0909 19:07:05.910794 18934 task_status_update_manager.cpp:181] Pausing sending 
task status updates
I0909 19:07:05.910817 18920 status_update_manager_process.hpp:379] Pausing 
operation status update manager
I0909 19:07:05.910861 18928 slave.cpp:1351] New master detected at 
master@172.17.0.2:33926
I0909 19:07:05.911025 18928 slave.cpp:1416] Detecting new master
I0909 19:07:05.914403 18921 slave.cpp:1443] Authenticating with master 
master@172.17.0.2:33926
I0909 19:07:05.914496 18921 slave.cpp:1452] Using default CRAM-MD5 authenticatee
I0909 19:07:05.914825 18924 authenticatee.cpp:121] Creating new client SASL 
connection
I0909 19:07:05.915235 18919 master.cpp:10574] Authenticating 
slave(1189)@172.17.0.2:33926
I0909 19:07:05.915419 18936 authenticator.cpp:414] Starting authentication 
session for crammd5-authenticatee(2014)@172.17.0.2:33926
I0909 19:07:05.915735 18938 authenticator.cpp:98] Creating new server SASL 
connection
I0909 19:07:05.916033 18932 authenticatee.cpp:213] Received SASL authentication 
mechanisms: CRAM-MD5
I0909 19:07:05.916067 18932 authenticatee.cpp:239] Attempting to authenticate 
with mechanism 'CRAM-MD5'
I0909 19:07:05.916183 18932 authenticator.cpp:204] Received SASL authentication 
start
I0909 19:07:05.916256 18932 authenticator.cpp:326] Authentication requires more 
steps
I0909 19:07:05.916385 18925 authenticatee.cpp:259] Received SASL authentication 
step
I0909 19:07:05.916534 18937 authenticator.cpp:232] Received SASL authentication 
step
I0909 19:07:05.916574 18937 auxprop.cpp:109] Request to lookup properties for 
user: 'test-principal' realm: '2e411cc79614' server FQDN: '2e411cc79614' 
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false 
SASL_AUXPROP_AUTHZID: false 
I0909 19:07:05.916589 18937 auxprop.cpp:181] Looking up auxiliary property 
'*userPassword'
I0909 19:07:05.916635 18937 auxprop.cpp:181] Looking up auxiliary property 
'*cmusaslsecretCRAM-MD5'
I0909 19:07:05.916661 18937 auxprop.cpp:109] Request to lookup properties for 
user: 'test-principal' realm: '2e411cc79614' server FQDN: '2e411cc79614' 
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false 
SASL_AUXPROP_AUTHZID: true 
I0909 19:07:05.916676 18937 auxprop.cpp:131] Skipping auxiliary property 
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0909 19:07:05.916693 18937 auxprop.cpp:131] Skipping auxiliary property 
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0909 19:07:05.916712 18937 authenticator.cpp:318] Authentication success
I0909 19:07:05.916805 18917 authenticatee.cpp:299] Authentication success
I0909 19:07:05.916937 18918 master.cpp:10606] Successfully authenticated 
principal 'test-principal' at slave(1189)@172.17.0.2:33926
I0909 19:07:05.917003 18933 authenticator.cpp:432] Authentication session 
cleanup for crammd5-authenticatee(2014)@172.17.0.2:33926
I0909 19:07:05.917220 18931 slave.cpp:1543] Successfully authenticated with 
master master@172.17.0.2:33926
I0909 19:07:05.917593 18931 slave.cpp:1993] Will retry registration in 
10.873206ms if necessary
I0909 19:07:05.917788 18923 master.cpp:7069] Received register agent message 
from slave(1189)@172.17.0.2:33926 (2e411cc79614)
I0909 19:07:05.918081 18923 master.cpp:4189] Authorizing agent providing 
resources 'cpus:2; mem:1024; disk:1024; ports:[31000-32000]' with principal 
'test-principal'
I0909 19:07:05.918808 18920 master.cpp:7136] Authorized registration of agent 
at slave(1189)@172.17.0.2:33926 (2e411cc79614)
I0909 19:07:05.918925 18920 master.cpp:7248] Registering agent at 
slave(1189)@172.17.0.2:33926 (2e411cc79614) with id 
a0055024-74a2-47f4-8a64-e7876b603597-S0
I0909 19:07:05.919674 18930 registrar.cpp:487] Applied 1 operations in 
264534ns; attempting to update the registry
I0909 19:07:05.920500 18930 registrar.cpp:544] Successfully updated the 
registry in 730112ns
I0909 19:07:05.920696 18936 master.cpp:7296] Admitted agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 at slave(1189)@172.17.0.2:33926 
(2e411cc79614)
I0909 19:07:05.921512 18936 master.cpp:7341] Registered agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 at slave(1189)@172.17.0.2:33926 
(2e411cc79614) with cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0909 19:07:05.921681 18932 hierarchical.cpp:854] Added agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 (2e411cc79614) with cpus:2; mem:1024; 
disk:1024; ports:[31000-32000] (offered or allocated: {})
I0909 19:07:05.921742 18926 slave.cpp:1576] Registered with master 
master@172.17.0.2:33926; given agent ID a0055024-74a2-47f4-8a64-e7876b603597-S0
I0909 19:07:05.921860 18935 task_status_update_manager.cpp:188] Resuming 
sending task status updates
I0909 19:07:05.922181 18926 slave.cpp:1611] Checkpointing SlaveInfo to 
'/tmp/CSIVersion_StorageLocalResourceProviderTest_CreateDestroyDiskWithRecovery_v1_XQun0n/meta/slaves/a0055024-74a2-47f4-8a64-e7876b603597-S0/slave.info'
I0909 19:07:05.922235 18932 hierarchical.cpp:1726] Performed allocation for 1 
agents in 155171ns
I0909 19:07:05.922247 18929 status_update_manager_process.hpp:385] Resuming 
operation status update manager
W0909 19:07:05.922678 18915 process.cpp:2877] Attempted to spawn already 
running process version@172.17.0.2:33926
I0909 19:07:05.923346 18926 slave.cpp:1663] Forwarding agent update 
{"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"txeCZF6hRt+nS06GZAsFag=="},"slave_id":{"value":"a0055024-74a2-47f4-8a64-e7876b603597-S0"},"update_oversubscribed_resources":false}
I0909 19:07:05.923979 18915 sched.cpp:239] Version: 1.10.0
I0909 19:07:05.924063 18920 master.cpp:8460] Ignoring update on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 at slave(1189)@172.17.0.2:33926 
(2e411cc79614) as it reports no changes
I0909 19:07:05.924746 18927 sched.cpp:343] New master detected at 
master@172.17.0.2:33926
I0909 19:07:05.924860 18927 sched.cpp:408] Authenticating with master 
master@172.17.0.2:33926
I0909 19:07:05.924885 18927 sched.cpp:415] Using default CRAM-MD5 authenticatee
I0909 19:07:05.925227 18917 authenticatee.cpp:121] Creating new client SASL 
connection
I0909 19:07:05.925608 18917 master.cpp:10574] Authenticating 
scheduler-345c4018-e916-4fc0-9e4f-f427b22ba1a0@172.17.0.2:33926
I0909 19:07:05.925762 18922 authenticator.cpp:414] Starting authentication 
session for crammd5-authenticatee(2015)@172.17.0.2:33926
I0909 19:07:05.926007 18916 authenticator.cpp:98] Creating new server SASL 
connection
I0909 19:07:05.926218 18926 authenticatee.cpp:213] Received SASL authentication 
mechanisms: CRAM-MD5
I0909 19:07:05.926249 18926 authenticatee.cpp:239] Attempting to authenticate 
with mechanism 'CRAM-MD5'
I0909 19:07:05.926388 18931 authenticator.cpp:204] Received SASL authentication 
start
I0909 19:07:05.926463 18931 authenticator.cpp:326] Authentication requires more 
steps
I0909 19:07:05.926579 18931 authenticatee.cpp:259] Received SASL authentication 
step
I0909 19:07:05.926721 18939 authenticator.cpp:232] Received SASL authentication 
step
I0909 19:07:05.926775 18939 auxprop.cpp:109] Request to lookup properties for 
user: 'test-principal' realm: '2e411cc79614' server FQDN: '2e411cc79614' 
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false 
SASL_AUXPROP_AUTHZID: false 
I0909 19:07:05.926807 18939 auxprop.cpp:181] Looking up auxiliary property 
'*userPassword'
I0909 19:07:05.926867 18939 auxprop.cpp:181] Looking up auxiliary property 
'*cmusaslsecretCRAM-MD5'
I0909 19:07:05.926916 18939 auxprop.cpp:109] Request to lookup properties for 
user: 'test-principal' realm: '2e411cc79614' server FQDN: '2e411cc79614' 
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false 
SASL_AUXPROP_AUTHZID: true 
I0909 19:07:05.926945 18939 auxprop.cpp:131] Skipping auxiliary property 
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0909 19:07:05.926965 18939 auxprop.cpp:131] Skipping auxiliary property 
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0909 19:07:05.926995 18939 authenticator.cpp:318] Authentication success
I0909 19:07:05.927095 18920 authenticatee.cpp:299] Authentication success
I0909 19:07:05.927233 18919 master.cpp:10606] Successfully authenticated 
principal 'test-principal' at 
scheduler-345c4018-e916-4fc0-9e4f-f427b22ba1a0@172.17.0.2:33926
I0909 19:07:05.927296 18930 authenticator.cpp:432] Authentication session 
cleanup for crammd5-authenticatee(2015)@172.17.0.2:33926
I0909 19:07:05.927529 18938 sched.cpp:520] Successfully authenticated with 
master master@172.17.0.2:33926
I0909 19:07:05.927561 18938 sched.cpp:835] Sending SUBSCRIBE call to 
master@172.17.0.2:33926
I0909 19:07:05.927727 18938 sched.cpp:870] Will retry registration in 
73.980971ms if necessary
I0909 19:07:05.927939 18927 master.cpp:2909] Received SUBSCRIBE call for 
framework 'default' at 
scheduler-345c4018-e916-4fc0-9e4f-f427b22ba1a0@172.17.0.2:33926
I0909 19:07:05.927983 18927 master.cpp:2241] Authorizing framework principal 
'test-principal' to receive offers for roles '{ storage/role }'
I0909 19:07:05.928568 18935 master.cpp:2996] Subscribing framework default with 
checkpointing disabled and capabilities [ MULTI_ROLE, RESERVATION_REFINEMENT ]
I0909 19:07:05.929306 18922 process.cpp:3671] Handling HTTP event for process 
'slave(1189)' with path: '/slave(1189)/api/v1'
I0909 19:07:05.930300 18935 master.cpp:10804] Adding framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000 (default) at 
scheduler-345c4018-e916-4fc0-9e4f-f427b22ba1a0@172.17.0.2:33926 with roles {  } 
suppressed
I0909 19:07:05.930497 18931 http.cpp:1115] HTTP POST for /slave(1189)/api/v1 
from 172.17.0.2:58812
I0909 19:07:05.930898 18919 sched.cpp:751] Framework registered with 
a0055024-74a2-47f4-8a64-e7876b603597-0000
I0909 19:07:05.930963 18919 sched.cpp:770] Scheduler::registered took 33515ns
I0909 19:07:05.931057 18931 http.cpp:2146] Processing GET_CONTAINERS call
I0909 19:07:05.931425 18934 hierarchical.cpp:605] Added framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000
I0909 19:07:05.932732 18934 hierarchical.cpp:1726] Performed allocation for 1 
agents in 1.028828ms
I0909 19:07:05.933519 18937 master.cpp:10389] Sending offers [ 
a0055024-74a2-47f4-8a64-e7876b603597-O0 ] to framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000 (default) at 
scheduler-345c4018-e916-4fc0-9e4f-f427b22ba1a0@172.17.0.2:33926
I0909 19:07:05.934496 18932 sched.cpp:934] Scheduler::resourceOffers took 
241310ns
I0909 19:07:05.934926 18916 master.cpp:6213] Processing DECLINE call for 
offers: [ a0055024-74a2-47f4-8a64-e7876b603597-O0 ] for framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000 (default) at 
scheduler-345c4018-e916-4fc0-9e4f-f427b22ba1a0@172.17.0.2:33926 with 3.1536e+07 
seconds filter
I0909 19:07:05.935536 18916 master.cpp:12684] Removing offer 
a0055024-74a2-47f4-8a64-e7876b603597-O0
I0909 19:07:05.936424 18921 hierarchical.cpp:1451] Recovered ports(allocated: 
storage/role):[31000-32000]; cpus(allocated: storage/role):2; mem(allocated: 
storage/role):1024; disk(allocated: storage/role):1024 (total: cpus:2; 
mem:1024; disk:1024; ports:[31000-32000], offered or allocated: {}) on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 from framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000
I0909 19:07:05.936501 18921 hierarchical.cpp:1498] Framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000 filtered agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 for 365days
I0909 19:07:05.938206 18920 container_daemon.cpp:121] Launching container 
'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0909 19:07:05.941009 18918 process.cpp:3671] Handling HTTP event for process 
'slave(1189)' with path: '/slave(1189)/api/v1'
I0909 19:07:05.941998 18934 http.cpp:1115] HTTP POST for /slave(1189)/api/v1 
from 172.17.0.2:58814
I0909 19:07:05.942785 18934 http.cpp:2606] Processing LAUNCH_CONTAINER call for 
container 
'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0909 19:07:05.943997 18917 http.cpp:2710] Creating sandbox 
'/tmp/CSIVersion_StorageLocalResourceProviderTest_CreateDestroyDiskWithRecovery_v1_XQun0n/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0909 19:07:05.944758 18932 containerizer.cpp:1396] Starting container 
org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0909 19:07:05.945670 18932 containerizer.cpp:3323] Transitioning the state of 
container 
org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
 from STARTING to PROVISIONING after 333056ns
I0909 19:07:05.946362 18932 containerizer.cpp:1574] Checkpointed 
ContainerConfig at 
'/tmp/CSIVersion_StorageLocalResourceProviderTest_CreateDestroyDiskWithRecovery_v1_Dq4bHs/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE/config'
I0909 19:07:05.946427 18932 containerizer.cpp:3323] Transitioning the state of 
container 
org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
 from PROVISIONING to PREPARING after 759040ns
I0909 19:07:05.949815 18924 containerizer.cpp:2100] Launching 
'mesos-containerizer' with flags '--help="false" 
--launch_info="{"command":{"arguments":["/mesos/mesos-1.10.0/_build/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_CreateDestroyDiskWithRecovery_v1_dj5zjj","--available_capacity=4GB","--volumes=","","--create_parameters=","--volume_metadata="],"shell":false,"value":"/mesos/mesos-1.10.0/_build/src/test-csi-plugin"},"environment":{"variables":[{"name":"MESOS_SANDBOX","type":"VALUE","value":"/tmp/CSIVersion_StorageLocalResourceProviderTest_CreateDestroyDiskWithRecovery_v1_XQun0n/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE"},{"name":"CSI_ENDPOINT","type":"VALUE","value":"unix:///tmp/mesos-csi-zSYBuQ/endpoint.sock"}]},"task_environment":{},"working_directory":"/tmp/CSIVersion_StorageLocalResourceProviderTest_CreateDestroyDiskWithRecovery_v1_XQun0n/containe
 
rs/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE"}"
 --pipe_read="70" --pipe_write="71" 
--runtime_directory="/tmp/CSIVersion_StorageLocalResourceProviderTest_CreateDestroyDiskWithRecovery_v1_Dq4bHs/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE"
 --unshare_namespace_mnt="false"'
I0909 19:07:05.958425 18924 launcher.cpp:145] Forked child with pid '32535' for 
container 
'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0909 19:07:05.959498 18924 containerizer.cpp:3323] Transitioning the state of 
container 
org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
 from PREPARING to ISOLATING after 13.058048ms
I0909 19:07:05.961236 18924 containerizer.cpp:3323] Transitioning the state of 
container 
org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
 from ISOLATING to FETCHING after 1.730816ms
I0909 19:07:05.961634 18937 fetcher.cpp:369] Starting to fetch URIs for 
container: 
org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE,
 directory: 
/tmp/CSIVersion_StorageLocalResourceProviderTest_CreateDestroyDiskWithRecovery_v1_XQun0n/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0909 19:07:05.963075 18923 containerizer.cpp:3323] Transitioning the state of 
container 
org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
 from FETCHING to RUNNING after 1.723136ms
I0909 19:07:05.966171 18929 container_daemon.cpp:140] Invoking post-start hook 
for container 
'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0909 19:07:05.966377 18929 service_manager.cpp:703] Connecting to endpoint 
'unix:///tmp/mesos-csi-zSYBuQ/endpoint.sock' of CSI plugin container 
org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0909 19:07:05.984421 18918 hierarchical.cpp:2581] Filtered offer with 
ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 for role storage/role of framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000
I0909 19:07:05.984577 18918 hierarchical.cpp:1726] Performed allocation for 1 
agents in 717319ns
I0909 19:07:06.036156 18936 hierarchical.cpp:2581] Filtered offer with 
ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 for role storage/role of framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000
I0909 19:07:06.036361 18936 hierarchical.cpp:1726] Performed allocation for 1 
agents in 850284ns
I0909 19:07:06.087462 18919 hierarchical.cpp:2581] Filtered offer with 
ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 for role storage/role of framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000
I0909 19:07:06.087579 18919 hierarchical.cpp:1726] Performed allocation for 1 
agents in 414849ns
I0909 19:07:06.138866 18925 hierarchical.cpp:2581] Filtered offer with 
ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 for role storage/role of framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000
I0909 19:07:06.138989 18925 hierarchical.cpp:1726] Performed allocation for 1 
agents in 453352ns
I0909 19:07:06.190510 18930 hierarchical.cpp:2581] Filtered offer with 
ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 for role storage/role of framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000
I0909 19:07:06.190762 18930 hierarchical.cpp:1726] Performed allocation for 1 
agents in 867024ns
I0909 19:07:06.242045 18935 hierarchical.cpp:2581] Filtered offer with 
ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 for role storage/role of framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000
I0909 19:07:06.242230 18935 hierarchical.cpp:1726] Performed allocation for 1 
agents in 699275ns
I0909 19:07:06.293604 18926 hierarchical.cpp:2581] Filtered offer with 
ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 for role storage/role of framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000
I0909 19:07:06.293771 18926 hierarchical.cpp:1726] Performed allocation for 1 
agents in 662176ns
I0909 19:07:06.345839 18918 hierarchical.cpp:2581] Filtered offer with 
ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 for role storage/role of framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000
I0909 19:07:06.346071 18918 hierarchical.cpp:1726] Performed allocation for 1 
agents in 765127ns
I0909 19:07:06.398123 18936 hierarchical.cpp:2581] Filtered offer with 
ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 for role storage/role of framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000
I0909 19:07:06.398272 18936 hierarchical.cpp:1726] Performed allocation for 1 
agents in 572579ns
I0909 19:07:06.420945 18923 service_manager.cpp:545] Probing endpoint 
'unix:///tmp/mesos-csi-zSYBuQ/endpoint.sock' with CSI v1
I0909 19:07:06.437110 32539 test_csi_plugin.cpp:909] ProbeRequest '{}'
I0909 19:07:06.439581 18933 container_daemon.cpp:171] Waiting for container 
'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0909 19:07:06.442983 32540 test_csi_plugin.cpp:895] 
GetPluginCapabilitiesRequest '{}'
I0909 19:07:06.443653 18939 process.cpp:3671] Handling HTTP event for process 
'slave(1189)' with path: '/slave(1189)/api/v1'
I0909 19:07:06.445255 18924 http.cpp:1115] HTTP POST for /slave(1189)/api/v1 
from 172.17.0.2:58816
I0909 19:07:06.445854 18924 http.cpp:2824] Processing WAIT_CONTAINER call for 
container 
'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0909 19:07:06.448236 32539 test_csi_plugin.cpp:877] GetPluginInfoRequest '{}'
I0909 19:07:06.448650 32540 test_csi_plugin.cpp:877] GetPluginInfoRequest '{}'
I0909 19:07:06.450371 18929 v1_volume_manager.cpp:649] NODE_SERVICE loaded: 
{"name":".","vendorVersion":"1.10.0"}
I0909 19:07:06.450498 18925 hierarchical.cpp:2581] Filtered offer with 
ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 for role storage/role of framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000
I0909 19:07:06.450697 18925 hierarchical.cpp:1726] Performed allocation for 1 
agents in 755023ns
I0909 19:07:06.450968 18929 v1_volume_manager.cpp:649] CONTROLLER_SERVICE 
loaded: {"name":".","vendorVersion":"1.10.0"}
I0909 19:07:06.453346 32541 test_csi_plugin.cpp:1105] 
ControllerGetCapabilitiesRequest '{}'
I0909 19:07:06.456851 32539 test_csi_plugin.cpp:1241] 
NodeGetCapabilitiesRequest '{}'
I0909 19:07:06.460170 32539 test_csi_plugin.cpp:1255] NodeGetInfoRequest '{}'
I0909 19:07:06.462043 18932 provider.cpp:676] Recovered resources '{}' and 0 
operations for resource provider with type 'org.apache.mesos.rp.local.storage' 
and name 'test'
I0909 19:07:06.462218 18938 status_update_manager_process.hpp:379] Pausing 
operation status update manager
I0909 19:07:06.462736 18921 http_connection.hpp:227] New endpoint detected at 
http://172.17.0.2:33926/slave(1189)/api/v1/resource_provider
I0909 19:07:06.465873 18931 http_connection.hpp:283] Connected with the remote 
endpoint at http://172.17.0.2:33926/slave(1189)/api/v1/resource_provider
I0909 19:07:06.466647 18937 provider.cpp:476] Connected to resource provider 
manager
I0909 19:07:06.467572 18922 http_connection.hpp:131] Sending SUBSCRIBE call to 
http://172.17.0.2:33926/slave(1189)/api/v1/resource_provider
I0909 19:07:06.469251 18916 process.cpp:3671] Handling HTTP event for process 
'slave(1189)' with path: '/slave(1189)/api/v1/resource_provider'
I0909 19:07:06.471408 18920 http.cpp:1115] HTTP POST for 
/slave(1189)/api/v1/resource_provider from 172.17.0.2:58820
I0909 19:07:06.472208 18921 manager.cpp:813] Subscribing resource provider 
{"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/mesos/mesos-1.10.0/_build/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_CreateDestroyDiskWithRecovery_v1_dj5zjj","--available_capacity=4GB","--volumes=","","--create_parameters=","--volume_metadata="],"shell":false,"value":"/mesos/mesos-1.10.0/_build/src/test-csi-plugin"},"resources":[{"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}],"services":["CONTROLLER_SERVICE","NODE_SERVICE"]}],"name":"local","type":"org.apache.mesos.csi.test"},"reconciliation_interval_seconds":0.0},"type":"org.apache.mesos.rp.local.storage"}
I0909 19:07:06.502790 18930 hierarchical.cpp:2581] Filtered offer with 
ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 for role storage/role of framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000
I0909 19:07:06.502996 18930 hierarchical.cpp:1726] Performed allocation for 1 
agents in 820435ns
I0909 19:07:06.505410 18935 slave.cpp:8481] Handling resource provider message 
'SUBSCRIBE: 
{"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"id":{"value":"ed026377-7715-4186-9441-147807a7ac94"},"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/mesos/mesos-1.10.0/_build/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_CreateDestroyDiskWithRecovery_v1_dj5zjj","--available_capacity=4GB","--volumes=","","--create_parameters=","--volume_metadata="],"shell":false,"value":"/mesos/mesos-1.10.0/_build/src/test-csi-plugin"},"resources":[{"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}],"services":["CONTROLLER_SERVICE","NODE_SERVICE"]}],"name":"local","type":"org.apache.mesos.csi.test"},"reconciliation_interval_seconds":0.0},"type":"org.apache.mesos.rp.local.storage"}'
I0909 19:07:06.507511 18923 provider.cpp:498] Received SUBSCRIBED event
I0909 19:07:06.507570 18923 provider.cpp:1309] Subscribed with ID 
ed026377-7715-4186-9441-147807a7ac94
I0909 19:07:06.508555 18932 status_update_manager_process.hpp:314] Recovering 
operation status update manager
I0909 19:07:06.554672 18929 hierarchical.cpp:2581] Filtered offer with 
ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 for role storage/role of framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000
I0909 19:07:06.554844 18929 hierarchical.cpp:1726] Performed allocation for 1 
agents in 610424ns
I0909 19:07:06.571805 18920 provider.cpp:790] Reconciling storage pools and 
volumes
I0909 19:07:06.574759 32539 test_csi_plugin.cpp:1050] ListVolumesRequest '{}'
I0909 19:07:06.576972 18937 provider.cpp:2217] Sending UPDATE_STATE call with 
resources '{}' and 0 operations to agent a0055024-74a2-47f4-8a64-e7876b603597-S0
I0909 19:07:06.577327 18937 provider.cpp:748] Resource provider 
ed026377-7715-4186-9441-147807a7ac94 is in READY state
I0909 19:07:06.577296 18917 http_connection.hpp:131] Sending UPDATE_STATE call 
to http://172.17.0.2:33926/slave(1189)/api/v1/resource_provider
I0909 19:07:06.577370 18922 status_update_manager_process.hpp:385] Resuming 
operation status update manager
I0909 19:07:06.578049 18924 provider.cpp:1235] Updating profiles { test } for 
resource provider ed026377-7715-4186-9441-147807a7ac94
I0909 19:07:06.578774 18919 process.cpp:3671] Handling HTTP event for process 
'slave(1189)' with path: '/slave(1189)/api/v1/resource_provider'
I0909 19:07:06.579282 18934 provider.cpp:790] Reconciling storage pools and 
volumes
I0909 19:07:06.580572 18922 http.cpp:1115] HTTP POST for 
/slave(1189)/api/v1/resource_provider from 172.17.0.2:58818
I0909 19:07:06.581096 18937 manager.cpp:1045] Received UPDATE_STATE call with 
resources '[]' and 0 operations from resource provider 
ed026377-7715-4186-9441-147807a7ac94
I0909 19:07:06.581311 18933 slave.cpp:8481] Handling resource provider message 
'UPDATE_STATE: ed026377-7715-4186-9441-147807a7ac94 {}'
I0909 19:07:06.581421 18933 slave.cpp:8601] Forwarding new total resources 
cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0909 19:07:06.581629 32541 test_csi_plugin.cpp:1050] ListVolumesRequest '{}'
I0909 19:07:06.582355 32541 test_csi_plugin.cpp:1078] GetCapacityRequest 
'{"volumeCapabilities":[{"mount":{},"accessMode":{"mode":"SINGLE_NODE_WRITER"}}]}'
I0909 19:07:06.583148 18921 hierarchical.cpp:992] Grew agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 by {} (total), {  } (used)
I0909 19:07:06.583575 18921 hierarchical.cpp:950] Agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 (2e411cc79614) updated with total 
resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0909 19:07:06.586309 18935 provider.cpp:808] Removing '{}' and adding 
'disk(reservations: 
[(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:4096' to the 
total resources
I0909 19:07:06.606627 18934 hierarchical.cpp:2581] Filtered offer with 
ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 for role storage/role of framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000
I0909 19:07:06.606758 18934 hierarchical.cpp:1726] Performed allocation for 1 
agents in 583417ns
I0909 19:07:06.630515 18935 provider.cpp:2217] Sending UPDATE_STATE call with 
resources 'disk(reservations: 
[(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:4096' and 0 
operations to agent a0055024-74a2-47f4-8a64-e7876b603597-S0
I0909 19:07:06.630972 18922 http_connection.hpp:131] Sending UPDATE_STATE call 
to http://172.17.0.2:33926/slave(1189)/api/v1/resource_provider
I0909 19:07:06.632127 18917 process.cpp:3671] Handling HTTP event for process 
'slave(1189)' with path: '/slave(1189)/api/v1/resource_provider'
I0909 19:07:06.658741 18923 hierarchical.cpp:2581] Filtered offer with 
ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 for role storage/role of framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000
I0909 19:07:06.658897 18923 hierarchical.cpp:1726] Performed allocation for 1 
agents in 601894ns
I0909 19:07:06.672034 18929 http.cpp:1115] HTTP POST for 
/slave(1189)/api/v1/resource_provider from 172.17.0.2:58818
I0909 19:07:06.673113 18920 manager.cpp:1045] Received UPDATE_STATE call with 
resources 
'[{"disk":{"source":{"profile":"test","type":"RAW","vendor":"org.apache.mesos.csi.test.local"}},"name":"disk","provider_id":{"value":"ed026377-7715-4186-9441-147807a7ac94"},"reservations":[{"role":"storage","type":"DYNAMIC"}],"scalar":{"value":4096.0},"type":"SCALAR"}]'
 and 0 operations from resource provider ed026377-7715-4186-9441-147807a7ac94
I0909 19:07:06.673921 18927 slave.cpp:8481] Handling resource provider message 
'UPDATE_STATE: ed026377-7715-4186-9441-147807a7ac94 disk(reservations: 
[(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:4096'
I0909 19:07:06.674191 18927 slave.cpp:8601] Forwarding new total resources 
cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: 
[(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:4096
I0909 19:07:06.678014 18925 hierarchical.cpp:950] Agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 (2e411cc79614) updated with total 
resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: 
[(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:4096
I0909 19:07:06.680271 18925 hierarchical.cpp:1726] Performed allocation for 1 
agents in 1.932477ms
I0909 19:07:06.681764 18916 master.cpp:10389] Sending offers [ 
a0055024-74a2-47f4-8a64-e7876b603597-O1 ] to framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000 (default) at 
scheduler-345c4018-e916-4fc0-9e4f-f427b22ba1a0@172.17.0.2:33926
I0909 19:07:06.683367 18936 sched.cpp:934] Scheduler::resourceOffers took 
286762ns
I0909 19:07:06.685968 18917 master.cpp:4719] Processing ACCEPT call for offers: 
[ a0055024-74a2-47f4-8a64-e7876b603597-O1 ] on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 at slave(1189)@172.17.0.2:33926 
(2e411cc79614) for framework a0055024-74a2-47f4-8a64-e7876b603597-0000 
(default) at scheduler-345c4018-e916-4fc0-9e4f-f427b22ba1a0@172.17.0.2:33926
I0909 19:07:06.686221 18917 master.cpp:3811] Authorizing principal 
'test-principal' to reserve resources 'disk(allocated: 
storage/role)(reservations: 
[(DYNAMIC,storage),(DYNAMIC,storage/role,test-principal)])[RAW(org.apache.mesos.csi.test.local,,test)]:4096'
I0909 19:07:06.686573 18917 master.cpp:4099] Authorizing principal 
'test-principal' to create a MOUNT disk from 'disk(allocated: 
storage/role)(reservations: 
[(DYNAMIC,storage),(DYNAMIC,storage/role,test-principal)])[RAW(org.apache.mesos.csi.test.local,,test)]:4096'
I0909 19:07:06.688413 18920 master.cpp:12684] Removing offer 
a0055024-74a2-47f4-8a64-e7876b603597-O1
I0909 19:07:06.689227 18920 master.cpp:5105] Applying RESERVE operation for 
resources 
[{"allocation_info":{"role":"storage/role"},"disk":{"source":{"profile":"test","type":"RAW","vendor":"org.apache.mesos.csi.test.local"}},"name":"disk","provider_id":{"value":"ed026377-7715-4186-9441-147807a7ac94"},"reservations":[{"role":"storage","type":"DYNAMIC"},{"principal":"test-principal","role":"storage/role","type":"DYNAMIC"}],"scalar":{"value":4096.0},"type":"SCALAR"}]
 from framework a0055024-74a2-47f4-8a64-e7876b603597-0000 (default) at 
scheduler-345c4018-e916-4fc0-9e4f-f427b22ba1a0@172.17.0.2:33926 to agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 at slave(1189)@172.17.0.2:33926 
(2e411cc79614)
I0909 19:07:06.690518 18920 master.cpp:12557] Sending operation '' (uuid: 
7740940e-c924-4f22-85e0-525f71eb74a5) to agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 at slave(1189)@172.17.0.2:33926 
(2e411cc79614)
I0909 19:07:06.691150 18920 master.cpp:6005] Processing CREATE_DISK operation 
with source disk(allocated: storage/role)(reservations: 
[(DYNAMIC,storage),(DYNAMIC,storage/role,test-principal)])[RAW(org.apache.mesos.csi.test.local,,test)]:4096
 from framework a0055024-74a2-47f4-8a64-e7876b603597-0000 (default) at 
scheduler-345c4018-e916-4fc0-9e4f-f427b22ba1a0@172.17.0.2:33926 to agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 at slave(1189)@172.17.0.2:33926 
(2e411cc79614)
I0909 19:07:06.691316 18919 slave.cpp:4352] Ignoring new checkpointed resources 
and operations identical to the current version
I0909 19:07:06.691890 18920 master.cpp:12557] Sending operation '' (uuid: 
e4120ec4-776e-4cf0-a712-4c7de2b31062) to agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 at slave(1189)@172.17.0.2:33926 
(2e411cc79614)
I0909 19:07:06.692586 18931 slave.cpp:4352] Ignoring new checkpointed resources 
and operations identical to the current version
I0909 19:07:06.695240 18933 provider.cpp:498] Received APPLY_OPERATION event
I0909 19:07:06.695287 18933 provider.cpp:1351] Received RESERVE operation '' 
(uuid: 7740940e-c924-4f22-85e0-525f71eb74a5)
I0909 19:07:06.695807 18918 hierarchical.cpp:1193] Updated allocation of 
framework a0055024-74a2-47f4-8a64-e7876b603597-0000 on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 from ports(allocated: 
storage/role):[31000-32000]; disk(allocated: storage/role)(reservations: 
[(DYNAMIC,storage)])[RAW(org.apache.mesos.csi.test.local,,test)]:4096; 
cpus(allocated: storage/role):2; mem(allocated: storage/role):1024; 
disk(allocated: storage/role):1024 to ports(allocated: 
storage/role):[31000-32000]; disk(allocated: storage/role):1024; 
cpus(allocated: storage/role):2; mem(allocated: storage/role):1024; 
disk(allocated: storage/role)(reservations: 
[(DYNAMIC,storage),(DYNAMIC,storage/role,test-principal)])[RAW(org.apache.mesos.csi.test.local,,test)]:4096
I0909 19:07:06.696038 18918 hierarchical.cpp:1650] Allocation paused
I0909 19:07:06.697476 18918 hierarchical.cpp:1451] Recovered ports(allocated: 
storage/role):[31000-32000]; disk(allocated: storage/role):1024; 
cpus(allocated: storage/role):2; mem(allocated: storage/role):1024 (total: 
cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: 
[(DYNAMIC,storage),(DYNAMIC,storage/role,test-principal)])[RAW(org.apache.mesos.csi.test.local,,test)]:4096,
 offered or allocated: disk(allocated: storage/role)(reservations: 
[(DYNAMIC,storage),(DYNAMIC,storage/role,test-principal)])[RAW(org.apache.mesos.csi.test.local,,test)]:4096)
 on agent a0055024-74a2-47f4-8a64-e7876b603597-S0 from framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000
I0909 19:07:06.697608 18918 hierarchical.cpp:1498] Framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000 filtered agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 for 5secs
I0909 19:07:06.697953 18918 hierarchical.cpp:1660] Allocation resumed
I0909 19:07:06.710937 18932 hierarchical.cpp:2581] Filtered offer with 
ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 for role storage/role of framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000
I0909 19:07:06.711099 18932 hierarchical.cpp:1726] Performed allocation for 1 
agents in 654073ns
I0909 19:07:06.762265 18921 hierarchical.cpp:2581] Filtered offer with 
ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 for role storage/role of framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000
I0909 19:07:06.762411 18921 hierarchical.cpp:1726] Performed allocation for 1 
agents in 432516ns
I0909 19:07:06.782212 18927 status_update_manager_process.hpp:152] Received 
operation status update OPERATION_FINISHED (Status UUID: 
6dd039be-52d1-40bb-9216-c1dcf943d0f7) for operation UUID 
7740940e-c924-4f22-85e0-525f71eb74a5 of framework 
'a0055024-74a2-47f4-8a64-e7876b603597-0000' on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0
I0909 19:07:06.782295 18927 status_update_manager_process.hpp:414] Creating 
operation status update stream 7740940e-c924-4f22-85e0-525f71eb74a5 
checkpoint=true
I0909 19:07:06.782514 18933 provider.cpp:498] Received APPLY_OPERATION event
I0909 19:07:06.782558 18933 provider.cpp:1351] Received CREATE_DISK operation 
'' (uuid: e4120ec4-776e-4cf0-a712-4c7de2b31062)
I0909 19:07:06.782781 18927 status_update_manager_process.hpp:929] 
Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status 
UUID: 6dd039be-52d1-40bb-9216-c1dcf943d0f7) for operation UUID 
7740940e-c924-4f22-85e0-525f71eb74a5 of framework 
'a0055024-74a2-47f4-8a64-e7876b603597-0000' on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0
I0909 19:07:06.813769 18919 hierarchical.cpp:2581] Filtered offer with 
ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 for role storage/role of framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000
I0909 19:07:06.813988 18919 hierarchical.cpp:1726] Performed allocation for 1 
agents in 670968ns
I0909 19:07:06.865532 18930 hierarchical.cpp:2581] Filtered offer with 
ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 for role storage/role of framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000
I0909 19:07:06.865720 18930 hierarchical.cpp:1726] Performed allocation for 1 
agents in 640282ns
I0909 19:07:06.874460 18927 status_update_manager_process.hpp:528] Forwarding 
operation status update OPERATION_FINISHED (Status UUID: 
6dd039be-52d1-40bb-9216-c1dcf943d0f7) for operation UUID 
7740940e-c924-4f22-85e0-525f71eb74a5 of framework 
'a0055024-74a2-47f4-8a64-e7876b603597-0000' on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0
I0909 19:07:06.891793 18931 v1_volume_manager.cpp:293] Creating volume with 
name 'e4120ec4-776e-4cf0-a712-4c7de2b31062'
I0909 19:07:06.893280 18935 http_connection.hpp:131] Sending 
UPDATE_OPERATION_STATUS call to 
http://172.17.0.2:33926/slave(1189)/api/v1/resource_provider
I0909 19:07:06.894968 18938 process.cpp:3671] Handling HTTP event for process 
'slave(1189)' with path: '/slave(1189)/api/v1/resource_provider'
I0909 19:07:06.895165 32541 test_csi_plugin.cpp:922] CreateVolumeRequest 
'{"name":"e4120ec4-776e-4cf0-a712-4c7de2b31062","capacityRange":{"requiredBytes":"4294967296","limitBytes":"4294967296"},"volumeCapabilities":[{"mount":{},"accessMode":{"mode":"SINGLE_NODE_WRITER"}}]}'
I0909 19:07:06.917711 18934 hierarchical.cpp:2581] Filtered offer with 
ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 for role storage/role of framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000
I0909 19:07:06.917923 18934 hierarchical.cpp:1726] Performed allocation for 1 
agents in 819150ns
I0909 19:07:06.932610 18921 http.cpp:1115] HTTP POST for 
/slave(1189)/api/v1/resource_provider from 172.17.0.2:58818
I0909 19:07:06.934427 18920 slave.cpp:8481] Handling resource provider message 
'UPDATE_OPERATION_STATUS: (uuid: 7740940e-c924-4f22-85e0-525f71eb74a5) for 
framework a0055024-74a2-47f4-8a64-e7876b603597-0000 (latest state: 
OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0909 19:07:06.934711 18920 slave.cpp:8934] Updating the state of operation 
with no ID (uuid: 7740940e-c924-4f22-85e0-525f71eb74a5) for framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000 (latest state: OPERATION_FINISHED, 
status update state: OPERATION_FINISHED)
I0909 19:07:06.934810 18920 slave.cpp:8688] Forwarding status update of 
operation with no ID (operation_uuid: 7740940e-c924-4f22-85e0-525f71eb74a5) for 
framework a0055024-74a2-47f4-8a64-e7876b603597-0000
I0909 19:07:06.935370 18927 master.cpp:12213] Updating the state of operation 
'' (uuid: 7740940e-c924-4f22-85e0-525f71eb74a5) for framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000 (latest state: OPERATION_PENDING, 
status update state: OPERATION_FINISHED)
I0909 19:07:06.936185 18933 slave.cpp:4352] Ignoring new checkpointed resources 
and operations identical to the current version
I0909 19:07:06.938401 18917 provider.cpp:498] Received 
ACKNOWLEDGE_OPERATION_STATUS event
I0909 19:07:06.938678 18939 status_update_manager_process.hpp:252] Received 
operation status update acknowledgement (UUID: 
6dd039be-52d1-40bb-9216-c1dcf943d0f7) for stream 
7740940e-c924-4f22-85e0-525f71eb74a5
I0909 19:07:06.938799 18939 status_update_manager_process.hpp:929] 
Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 
6dd039be-52d1-40bb-9216-c1dcf943d0f7) for operation UUID 
7740940e-c924-4f22-85e0-525f71eb74a5 of framework 
'a0055024-74a2-47f4-8a64-e7876b603597-0000' on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0
I0909 19:07:06.970144 18918 hierarchical.cpp:2581] Filtered offer with 
ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 for role storage/role of framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000
I0909 19:07:06.970378 18918 hierarchical.cpp:1726] Performed allocation for 1 
agents in 782600ns
I0909 19:07:07.002058 18932 provider.cpp:1653] Applying conversion from 
'disk(allocated: storage/role)(reservations: 
[(DYNAMIC,storage),(DYNAMIC,storage/role,test-principal)])[RAW(org.apache.mesos.csi.test.local,,test)]:4096'
 to 'disk(allocated: storage/role)(reservations: 
[(DYNAMIC,storage),(DYNAMIC,storage/role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_CreateDestroyDiskWithRecovery_v1_dj5zjj/4GB-e4120ec4-776e-4cf0-a712-4c7de2b31062,test)]:4096'
 for operation (uuid: e4120ec4-776e-4cf0-a712-4c7de2b31062)
I0909 19:07:07.021880 18929 hierarchical.cpp:2581] Filtered offer with 
ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 for role storage/role of framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000
I0909 19:07:07.022049 18929 hierarchical.cpp:1726] Performed allocation for 1 
agents in 587821ns
I0909 19:07:07.023916 18939 status_update_manager_process.hpp:490] Cleaning up 
operation status update stream 7740940e-c924-4f22-85e0-525f71eb74a5
I0909 19:07:07.060554 18919 status_update_manager_process.hpp:152] Received 
operation status update OPERATION_FINISHED (Status UUID: 
a9c27fc1-2a7d-4e3a-b646-675add64a33f) for operation UUID 
e4120ec4-776e-4cf0-a712-4c7de2b31062 of framework 
'a0055024-74a2-47f4-8a64-e7876b603597-0000' on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0
I0909 19:07:07.060672 18919 status_update_manager_process.hpp:414] Creating 
operation status update stream e4120ec4-776e-4cf0-a712-4c7de2b31062 
checkpoint=true
I0909 19:07:07.061365 18919 status_update_manager_process.hpp:929] 
Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status 
UUID: a9c27fc1-2a7d-4e3a-b646-675add64a33f) for operation UUID 
e4120ec4-776e-4cf0-a712-4c7de2b31062 of framework 
'a0055024-74a2-47f4-8a64-e7876b603597-0000' on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0
I0909 19:07:07.073479 18920 hierarchical.cpp:2581] Filtered offer with 
ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 for role storage/role of framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000
I0909 19:07:07.073617 18920 hierarchical.cpp:1726] Performed allocation for 1 
agents in 490121ns
I0909 19:07:07.124944 18930 hierarchical.cpp:2581] Filtered offer with 
ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 for role storage/role of framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000
I0909 19:07:07.125123 18930 hierarchical.cpp:1726] Performed allocation for 1 
agents in 608775ns
I0909 19:07:07.152719 18919 status_update_manager_process.hpp:528] Forwarding 
operation status update OPERATION_FINISHED (Status UUID: 
a9c27fc1-2a7d-4e3a-b646-675add64a33f) for operation UUID 
e4120ec4-776e-4cf0-a712-4c7de2b31062 of framework 
'a0055024-74a2-47f4-8a64-e7876b603597-0000' on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0
I0909 19:07:07.171169 18931 http_connection.hpp:131] Sending 
UPDATE_OPERATION_STATUS call to 
http://172.17.0.2:33926/slave(1189)/api/v1/resource_provider
I0909 19:07:07.172982 18916 process.cpp:3671] Handling HTTP event for process 
'slave(1189)' with path: '/slave(1189)/api/v1/resource_provider'
I0909 19:07:07.176882 18925 hierarchical.cpp:2581] Filtered offer with 
ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 for role storage/role of framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000
I0909 19:07:07.177112 18925 hierarchical.cpp:1726] Performed allocation for 1 
agents in 936565ns
I0909 19:07:07.212819 18924 http.cpp:1115] HTTP POST for 
/slave(1189)/api/v1/resource_provider from 172.17.0.2:58818
I0909 19:07:07.214370 18917 slave.cpp:8481] Handling resource provider message 
'UPDATE_OPERATION_STATUS: (uuid: e4120ec4-776e-4cf0-a712-4c7de2b31062) for 
framework a0055024-74a2-47f4-8a64-e7876b603597-0000 (latest state: 
OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
I0909 19:07:07.214669 18917 slave.cpp:8934] Updating the state of operation 
with no ID (uuid: e4120ec4-776e-4cf0-a712-4c7de2b31062) for framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000 (latest state: OPERATION_FINISHED, 
status update state: OPERATION_FINISHED)
I0909 19:07:07.215373 18917 slave.cpp:8688] Forwarding status update of 
operation with no ID (operation_uuid: e4120ec4-776e-4cf0-a712-4c7de2b31062) for 
framework a0055024-74a2-47f4-8a64-e7876b603597-0000
I0909 19:07:07.215948 18926 master.cpp:12213] Updating the state of operation 
'' (uuid: e4120ec4-776e-4cf0-a712-4c7de2b31062) for framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000 (latest state: OPERATION_PENDING, 
status update state: OPERATION_FINISHED)
I0909 19:07:07.217346 18921 slave.cpp:4352] Ignoring new checkpointed resources 
and operations identical to the current version
I0909 19:07:07.218266 18939 hierarchical.cpp:1193] Updated allocation of 
framework a0055024-74a2-47f4-8a64-e7876b603597-0000 on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 from disk(allocated: 
storage/role)(reservations: 
[(DYNAMIC,storage),(DYNAMIC,storage/role,test-principal)])[RAW(org.apache.mesos.csi.test.local,,test)]:4096
 to disk(allocated: storage/role)(reservations: 
[(DYNAMIC,storage),(DYNAMIC,storage/role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_CreateDestroyDiskWithRecovery_v1_dj5zjj/4GB-e4120ec4-776e-4cf0-a712-4c7de2b31062,test)]:4096
I0909 19:07:07.219190 18916 provider.cpp:498] Received 
ACKNOWLEDGE_OPERATION_STATUS event
I0909 19:07:07.219173 18939 hierarchical.cpp:1451] Recovered disk(allocated: 
storage/role)(reservations: 
[(DYNAMIC,storage),(DYNAMIC,storage/role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_CreateDestroyDiskWithRecovery_v1_dj5zjj/4GB-e4120ec4-776e-4cf0-a712-4c7de2b31062,test)]:4096
 (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: 
[(DYNAMIC,storage),(DYNAMIC,storage/role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_CreateDestroyDiskWithRecovery_v1_dj5zjj/4GB-e4120ec4-776e-4cf0-a712-4c7de2b31062,test)]:4096,
 offered or allocated: {}) on agent a0055024-74a2-47f4-8a64-e7876b603597-S0 
from framework a0055024-74a2-47f4-8a64-e7876b603597-0000
I0909 19:07:07.219424 18928 status_update_manager_process.hpp:252] Received 
operation status update acknowledgement (UUID: 
a9c27fc1-2a7d-4e3a-b646-675add64a33f) for stream 
e4120ec4-776e-4cf0-a712-4c7de2b31062
I0909 19:07:07.219539 18928 status_update_manager_process.hpp:929] 
Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 
a9c27fc1-2a7d-4e3a-b646-675add64a33f) for operation UUID 
e4120ec4-776e-4cf0-a712-4c7de2b31062 of framework 
'a0055024-74a2-47f4-8a64-e7876b603597-0000' on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0
I0909 19:07:07.228991 18935 hierarchical.cpp:1726] Performed allocation for 1 
agents in 1.173699ms
I0909 19:07:07.229723 18937 master.cpp:10389] Sending offers [ 
a0055024-74a2-47f4-8a64-e7876b603597-O2 ] to framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000 (default) at 
scheduler-345c4018-e916-4fc0-9e4f-f427b22ba1a0@172.17.0.2:33926
I0909 19:07:07.230551 18938 sched.cpp:934] Scheduler::resourceOffers took 
137392ns
I0909 19:07:07.231565 18917 slave.cpp:924] Agent terminating
I0909 19:07:07.232520 18917 manager.cpp:163] Terminating resource provider 
ed026377-7715-4186-9441-147807a7ac94
I0909 19:07:07.233088 18936 master.cpp:1296] Agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 at slave(1189)@172.17.0.2:33926 
(2e411cc79614) disconnected
I0909 19:07:07.233144 18936 master.cpp:3391] Disconnecting agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 at slave(1189)@172.17.0.2:33926 
(2e411cc79614)
I0909 19:07:07.233244 18936 master.cpp:3410] Deactivating agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 at slave(1189)@172.17.0.2:33926 
(2e411cc79614)
I0909 19:07:07.233566 18916 hierarchical.cpp:1038] Agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 deactivated
I0909 19:07:07.233798 18925 sched.cpp:960] Rescinded offer 
a0055024-74a2-47f4-8a64-e7876b603597-O2
I0909 19:07:07.233950 18925 sched.cpp:971] Scheduler::offerRescinded took 
54931ns
E0909 19:07:07.234266 18937 http_connection.hpp:452] End-Of-File received
I0909 19:07:07.234793 18936 master.cpp:12684] Removing offer 
a0055024-74a2-47f4-8a64-e7876b603597-O2
I0909 19:07:07.235013 18937 http_connection.hpp:217] Re-detecting endpoint
I0909 19:07:07.235638 18937 http_connection.hpp:338] Ignoring disconnection 
attempt from stale connection
I0909 19:07:07.235743 18937 http_connection.hpp:338] Ignoring disconnection 
attempt from stale connection
I0909 19:07:07.235812 18921 provider.cpp:488] Disconnected from resource 
provider manager
I0909 19:07:07.235882 18937 http_connection.hpp:227] New endpoint detected at 
http://172.17.0.2:33926/slave(1189)/api/v1/resource_provider
I0909 19:07:07.237021 18932 hierarchical.cpp:1451] Recovered ports(allocated: 
storage/role):[31000-32000]; disk(allocated: storage/role)(reservations: 
[(DYNAMIC,storage),(DYNAMIC,storage/role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_CreateDestroyDiskWithRecovery_v1_dj5zjj/4GB-e4120ec4-776e-4cf0-a712-4c7de2b31062,test)]:4096;
 cpus(allocated: storage/role):2; mem(allocated: storage/role):1024; 
disk(allocated: storage/role):1024 (total: cpus:2; mem:1024; disk:1024; 
ports:[31000-32000]; disk(reservations: 
[(DYNAMIC,storage),(DYNAMIC,storage/role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_CreateDestroyDiskWithRecovery_v1_dj5zjj/4GB-e4120ec4-776e-4cf0-a712-4c7de2b31062,test)]:4096,
 offered or allocated: {}) on agent a0055024-74a2-47f4-8a64-e7876b603597-S0 
from framework a0055024-74a2-47f4-8a64-e7876b603597-0000
I0909 19:07:07.239521 18916 http_connection.hpp:283] Connected with the remote 
endpoint at http://172.17.0.2:33926/slave(1189)/api/v1/resource_provider
W0909 19:07:07.240058 18915 process.cpp:2877] Attempted to spawn already 
running process files@172.17.0.2:33926
I0909 19:07:07.240101 18924 provider.cpp:476] Connected to resource provider 
manager
I0909 19:07:07.240732 18938 http_connection.hpp:131] Sending SUBSCRIBE call to 
http://172.17.0.2:33926/slave(1189)/api/v1/resource_provider
I0909 19:07:07.241550 18940 process.cpp:2781] Returning '404 Not Found' for 
'/slave(1189)/api/v1/resource_provider'
I0909 19:07:07.242015 18915 containerizer.cpp:318] Using isolation { 
environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni }
W0909 19:07:07.242871 18915 backend.cpp:76] Failed to create 'overlay' backend: 
OverlayBackend requires root privileges
W0909 19:07:07.242913 18915 backend.cpp:76] Failed to create 'aufs' backend: 
AufsBackend requires root privileges
E0909 19:07:07.242990 18917 provider.cpp:721] Failed to subscribe resource 
provider with type 'org.apache.mesos.rp.local.storage' and name 'test': 
Received '404 Not Found' ()
W0909 19:07:07.243089 18915 backend.cpp:76] Failed to create 'bind' backend: 
BindBackend requires root privileges
I0909 19:07:07.243144 18915 provisioner.cpp:300] Using default backend 'copy'
I0909 19:07:07.246559 18915 cluster.cpp:524] Creating default 'local' authorizer
I0909 19:07:07.249807 18932 slave.cpp:267] Mesos agent started on 
(1190)@172.17.0.2:33926
I0909 19:07:07.249846 18932 slave.cpp:268] Flags at startup: --acls="" 
--appc_simple_discovery_uri_prefix="http://"; 
--appc_store_dir="/tmp/5qNuFe/bov1nx/store/appc" 
--authenticate_http_readonly="true" --authenticate_http_readwrite="false" 
--authenticatee="crammd5" --authentication_backoff_factor="1secs" 
--authentication_timeout_max="1mins" --authentication_timeout_min="5secs" 
--authorizer="local" --cgroups_cpu_enable_pids_and_tids_count="false" 
--cgroups_destroy_timeout="1mins" --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/5qNuFe/bov1nx/credential" 
--default_role="*" --disallow_sharing_agent_ipc_namespace="false" 
--disallow_sharing_agent_pid_namespace="false" 
--disk_profile_adaptor="org_apache_mesos_UriDiskProfileAdaptor" 
--disk_watch_interval="1mins" --docker="docker" --docker_ignore_runtime="false" 
--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/5qNuFe/bov1nx/store/docker" 
--docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" 
--docker_volume_chown="false" --enforce_container_disk_quota="false" 
--executor_registration_timeout="1mins" 
--executor_reregistration_timeout="2secs" 
--executor_shutdown_grace_period="5secs" 
--fetcher_cache_dir="/tmp/5qNuFe/bov1nx/fetch" --fetcher_cache_size="2GB" 
--fetcher_stall_timeout="1mins" 
--frameworks_home="/tmp/5qNuFe/bov1nx/frameworks" --gc_delay="1weeks" 
--gc_disk_headroom="0.1" --gc_non_executor_container_sandboxes="false" 
--help="false" --hostname_lookup="true" --http_command_executor="false" 
--http_credentials="/tmp/5qNuFe/bov1nx/http_credentials" 
--http_heartbeat_interval="30secs" --initialize_driver_logging="true" 
--isolation="posix/cpu,posix/mem" --launcher="posix" 
--launcher_dir="/mesos/mesos-1.10.0/
 _build/src" --logbufsecs="0" --logging_level="INFO" 
--max_completed_executors_per_framework="150" --memory_profiling="false" 
--network_cni_metrics="true" --network_cni_root_dir_persist="false" 
--oversubscribed_resources_interval="15secs" --perf_duration="10secs" 
--perf_interval="1mins" --port="5051" --qos_correction_interval_min="0ns" 
--quiet="false" --reconfiguration_policy="equal" --recover="reconnect" 
--recovery_timeout="15mins" --registration_backoff_factor="10ms" 
--resource_provider_config_dir="/tmp/5qNuFe/resource_provider_configs" 
--resources="cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]" 
--revocable_cpu_low_priority="true" 
--runtime_dir="/tmp/CSIVersion_StorageLocalResourceProviderTest_CreateDestroyDiskWithRecovery_v1_Dq4bHs"
 --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/CSIVersion_StorageLocalResourceProviderTest_Create
 DestroyDiskWithRecovery_v1_XQun0n" --zk_session_timeout="10secs"
I0909 19:07:07.250598 18932 credentials.hpp:86] Loading credential for 
authentication from '/tmp/5qNuFe/bov1nx/credential'
I0909 19:07:07.250903 18932 slave.cpp:300] Agent using credential for: 
test-principal
I0909 19:07:07.250939 18932 credentials.hpp:37] Loading credentials for 
authentication from '/tmp/5qNuFe/bov1nx/http_credentials'
I0909 19:07:07.251273 18932 http.cpp:975] Creating default 'basic' HTTP 
authenticator for realm 'mesos-agent-readonly'
I0909 19:07:07.251783 18932 disk_profile_adaptor.cpp:82] Creating disk profile 
adaptor module 'org_apache_mesos_UriDiskProfileAdaptor'
I0909 19:07:07.253569 18931 uri_disk_profile_adaptor.cpp:305] Updated disk 
profile mapping to 1 active profiles
I0909 19:07:07.253896 18932 slave.cpp:615] Agent resources: 
[{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
I0909 19:07:07.254195 18932 slave.cpp:623] Agent attributes: [  ]
I0909 19:07:07.254216 18932 slave.cpp:632] Agent hostname: 2e411cc79614
I0909 19:07:07.254460 18933 status_update_manager_process.hpp:379] Pausing 
operation status update manager
I0909 19:07:07.254482 18925 task_status_update_manager.cpp:181] Pausing sending 
task status updates
I0909 19:07:07.256418 18936 state.cpp:67] Recovering state from 
'/tmp/CSIVersion_StorageLocalResourceProviderTest_CreateDestroyDiskWithRecovery_v1_XQun0n/meta'
I0909 19:07:07.256518 18936 state.cpp:874] No committed checkpointed resources 
and operations found at 
'/tmp/CSIVersion_StorageLocalResourceProviderTest_CreateDestroyDiskWithRecovery_v1_XQun0n/meta/resources/resources_and_operations.state'
I0909 19:07:07.256558 18936 state.cpp:880] No committed checkpointed resources 
found at 
'/tmp/CSIVersion_StorageLocalResourceProviderTest_CreateDestroyDiskWithRecovery_v1_XQun0n/meta/resources/resources.info'
I0909 19:07:07.257719 18935 slave.cpp:7491] Finished recovering checkpointed 
state from 
'/tmp/CSIVersion_StorageLocalResourceProviderTest_CreateDestroyDiskWithRecovery_v1_XQun0n/meta',
 beginning agent recovery
I0909 19:07:07.259734 18923 task_status_update_manager.cpp:207] Recovering task 
status update manager
I0909 19:07:07.260557 18927 containerizer.cpp:821] Recovering Mesos containers
I0909 19:07:07.262630 18927 containerizer.cpp:1161] Recovering isolators
I0909 19:07:07.263903 18934 containerizer.cpp:1200] Recovering provisioner
I0909 19:07:07.264797 18921 provisioner.cpp:500] Provisioner recovery complete
I0909 19:07:07.266510 18919 composing.cpp:339] Finished recovering all 
containerizers
I0909 19:07:07.267029 18926 status_update_manager_process.hpp:314] Recovering 
operation status update manager
I0909 19:07:07.267505 18936 slave.cpp:7972] Recovering executors
I0909 19:07:07.267630 18936 slave.cpp:8125] Finished recovery
I0909 19:07:07.268513 18918 task_status_update_manager.cpp:181] Pausing sending 
task status updates
I0909 19:07:07.268539 18921 status_update_manager_process.hpp:379] Pausing 
operation status update manager
I0909 19:07:07.268545 18916 slave.cpp:1351] New master detected at 
master@172.17.0.2:33926
I0909 19:07:07.268705 18916 slave.cpp:1416] Detecting new master
I0909 19:07:07.269973 18935 slave.cpp:1443] Authenticating with master 
master@172.17.0.2:33926
I0909 19:07:07.270076 18935 slave.cpp:1452] Using default CRAM-MD5 authenticatee
I0909 19:07:07.270442 18930 authenticatee.cpp:121] Creating new client SASL 
connection
I0909 19:07:07.270845 18929 master.cpp:10574] Authenticating 
slave(1190)@172.17.0.2:33926
I0909 19:07:07.271030 18917 authenticator.cpp:414] Starting authentication 
session for crammd5-authenticatee(2016)@172.17.0.2:33926
I0909 19:07:07.271344 18931 authenticator.cpp:98] Creating new server SASL 
connection
I0909 19:07:07.271605 18938 authenticatee.cpp:213] Received SASL authentication 
mechanisms: CRAM-MD5
I0909 19:07:07.271641 18938 authenticatee.cpp:239] Attempting to authenticate 
with mechanism 'CRAM-MD5'
I0909 19:07:07.271773 18937 authenticator.cpp:204] Received SASL authentication 
start
I0909 19:07:07.271845 18937 authenticator.cpp:326] Authentication requires more 
steps
I0909 19:07:07.271981 18920 authenticatee.cpp:259] Received SASL authentication 
step
I0909 19:07:07.272147 18919 authenticator.cpp:232] Received SASL authentication 
step
I0909 19:07:07.272186 18919 auxprop.cpp:109] Request to lookup properties for 
user: 'test-principal' realm: '2e411cc79614' server FQDN: '2e411cc79614' 
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false 
SASL_AUXPROP_AUTHZID: false 
I0909 19:07:07.272202 18919 auxprop.cpp:181] Looking up auxiliary property 
'*userPassword'
I0909 19:07:07.272254 18919 auxprop.cpp:181] Looking up auxiliary property 
'*cmusaslsecretCRAM-MD5'
I0909 19:07:07.272280 18919 auxprop.cpp:109] Request to lookup properties for 
user: 'test-principal' realm: '2e411cc79614' server FQDN: '2e411cc79614' 
SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false 
SASL_AUXPROP_AUTHZID: true 
I0909 19:07:07.272295 18919 auxprop.cpp:131] Skipping auxiliary property 
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0909 19:07:07.272305 18919 auxprop.cpp:131] Skipping auxiliary property 
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0909 19:07:07.272321 18919 authenticator.cpp:318] Authentication success
I0909 19:07:07.272426 18932 authenticatee.cpp:299] Authentication success
I0909 19:07:07.272523 18933 master.cpp:10606] Successfully authenticated 
principal 'test-principal' at slave(1190)@172.17.0.2:33926
I0909 19:07:07.272557 18925 authenticator.cpp:432] Authentication session 
cleanup for crammd5-authenticatee(2016)@172.17.0.2:33926
I0909 19:07:07.272799 18926 slave.cpp:1543] Successfully authenticated with 
master master@172.17.0.2:33926
I0909 19:07:07.273345 18926 slave.cpp:1993] Will retry registration in 
17.200359ms if necessary
I0909 19:07:07.273578 18918 master.cpp:7420] Received reregister agent message 
from agent a0055024-74a2-47f4-8a64-e7876b603597-S0 at 
slave(1190)@172.17.0.2:33926 (2e411cc79614)
I0909 19:07:07.274019 18918 master.cpp:4189] Authorizing agent providing 
resources 'cpus:2; mem:1024; disk:1024; ports:[31000-32000]' with principal 
'test-principal'
I0909 19:07:07.274778 18939 master.cpp:7512] Authorized re-registration of 
agent a0055024-74a2-47f4-8a64-e7876b603597-S0 at slave(1190)@172.17.0.2:33926 
(2e411cc79614)
I0909 19:07:07.274899 18939 master.cpp:7596] Agent is already marked as 
registered: a0055024-74a2-47f4-8a64-e7876b603597-S0 at 
slave(1190)@172.17.0.2:33926 (2e411cc79614)
I0909 19:07:07.275199 18939 master.cpp:8007] Registry updated for slave 
a0055024-74a2-47f4-8a64-e7876b603597-S0 at 
slave(1190)@172.17.0.2:33926(2e411cc79614)
I0909 19:07:07.275710 18939 master.cpp:3440] Reactivating agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 at slave(1190)@172.17.0.2:33926 
(2e411cc79614)
I0909 19:07:07.275857 18929 slave.cpp:1700] Re-registered with master 
master@172.17.0.2:33926
I0909 19:07:07.275985 18931 task_status_update_manager.cpp:188] Resuming 
sending task status updates
I0909 19:07:07.276016 18938 status_update_manager_process.hpp:385] Resuming 
operation status update manager
I0909 19:07:07.276183 18929 slave.cpp:1746] Forwarding agent update 
{"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"WeKGH/nnQ8Kx+YRrDR2KtA=="},"slave_id":{"value":"a0055024-74a2-47f4-8a64-e7876b603597-S0"},"update_oversubscribed_resources":false}
I0909 19:07:07.276727 18930 hierarchical.cpp:950] Agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 (2e411cc79614) updated with total 
resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0909 19:07:07.276919 18930 hierarchical.cpp:1026] Agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 reactivated
I0909 19:07:07.277448 18930 hierarchical.cpp:2581] Filtered offer with 
ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 for role storage/role of framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000
I0909 19:07:07.277596 18930 hierarchical.cpp:1726] Performed allocation for 1 
agents in 538516ns
I0909 19:07:07.280781 18925 hierarchical.cpp:2581] Filtered offer with 
ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 for role storage/role of framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000
I0909 19:07:07.280894 18925 hierarchical.cpp:1726] Performed allocation for 1 
agents in 362034ns
I0909 19:07:07.282040 18921 process.cpp:3671] Handling HTTP event for process 
'slave(1190)' with path: '/slave(1190)/api/v1'
I0909 19:07:07.283362 18938 http.cpp:1115] HTTP POST for /slave(1190)/api/v1 
from 172.17.0.2:58826
I0909 19:07:07.283891 18938 http.cpp:2146] Processing GET_CONTAINERS call
I0909 19:07:07.290014 18925 service_manager.cpp:300] Cleaning up plugin 
container 
'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0909 19:07:07.292500 18935 process.cpp:3671] Handling HTTP event for process 
'slave(1190)' with path: '/slave(1190)/api/v1'
I0909 19:07:07.293468 18920 http.cpp:1115] HTTP POST for /slave(1190)/api/v1 
from 172.17.0.2:58828
I0909 19:07:07.293889 18920 http.cpp:2995] Processing KILL_CONTAINER call for 
container 
'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0909 19:07:07.294770 18939 containerizer.cpp:3031] Sending Killed to container 
org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
 in RUNNING state
I0909 19:07:07.298002 18919 process.cpp:3671] Handling HTTP event for process 
'slave(1190)' with path: '/slave(1190)/api/v1'
I0909 19:07:07.298911 18931 http.cpp:1115] HTTP POST for /slave(1190)/api/v1 
from 172.17.0.2:58830
I0909 19:07:07.299333 18931 http.cpp:2824] Processing WAIT_CONTAINER call for 
container 
'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0909 19:07:07.332365 18933 hierarchical.cpp:2581] Filtered offer with 
ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 for role storage/role of framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000
I0909 19:07:07.332511 18933 hierarchical.cpp:1726] Performed allocation for 1 
agents in 632304ns
I0909 19:07:07.354226 18928 status_update_manager_process.hpp:490] Cleaning up 
operation status update stream e4120ec4-776e-4cf0-a712-4c7de2b31062
I0909 19:07:07.358633 18934 containerizer.cpp:3161] Container 
org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
 has exited
I0909 19:07:07.358673 18934 containerizer.cpp:2620] Destroying container 
org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
 in RUNNING state
I0909 19:07:07.358706 18934 containerizer.cpp:3323] Transitioning the state of 
container 
org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
 from RUNNING to DESTROYING after 97.06112ms
I0909 19:07:07.358779 18925 containerizer.cpp:3161] Container 
org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
 has exited
I0909 19:07:07.358819 18925 containerizer.cpp:2620] Destroying container 
org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
 in RUNNING state
I0909 19:07:07.358851 18925 containerizer.cpp:3323] Transitioning the state of 
container 
org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
 from RUNNING to DESTROYING after 1.395916032secs
I0909 19:07:07.359128 18925 launcher.cpp:161] Asked to destroy container 
org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0909 19:07:07.359128 18934 launcher.cpp:161] Asked to destroy container 
org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
*** Aborted at 1568056027 (unix time) try "date -d @1568056027" if you are 
using GNU date ***
I0909 19:07:07.365145 18927 provisioner.cpp:612] Ignoring destroy request for 
unknown container 
org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
PC: @     0x56495aca3aa8 __gnu_cxx::__atomic_add()
*** SIGSEGV (@0x0) received by PID 18915 (TID 0x2af49df81700) from PID 0; stack 
trace: ***
    @     0x2af5061938f7 (unknown)
I0909 19:07:07.369997 18932 container_daemon.cpp:121] Launching container 
'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
    @     0x2af506198249 JVM_handle_linux_signal
    @     0x2af493e86330 (unknown)
I0909 19:07:07.372951 18924 process.cpp:3671] Handling HTTP event for process 
'slave(1190)' with path: '/slave(1190)/api/v1'
    @     0x56495aca3aa8 __gnu_cxx::__atomic_add()
I0909 19:07:07.373980 18927 http.cpp:1115] HTTP POST for /slave(1190)/api/v1 
from 172.17.0.2:58832
I0909 19:07:07.374995 18927 http.cpp:2606] Processing LAUNCH_CONTAINER call for 
container 
'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
    @     0x56495aca3b66 __gnu_cxx::__atomic_add_dispatch()
I0909 19:07:07.376058 18938 http.cpp:2710] Creating sandbox 
'/tmp/CSIVersion_StorageLocalResourceProviderTest_CreateDestroyDiskWithRecovery_v1_XQun0n/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0909 19:07:07.376718 18933 containerizer.cpp:1396] Starting container 
org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0909 19:07:07.377362 18933 containerizer.cpp:3323] Transitioning the state of 
container 
org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
 from STARTING to PROVISIONING after 243968ns
I0909 19:07:07.378023 18933 containerizer.cpp:1574] Checkpointed 
ContainerConfig at 
'/tmp/CSIVersion_StorageLocalResourceProviderTest_CreateDestroyDiskWithRecovery_v1_Dq4bHs/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE/config'
I0909 19:07:07.378075 18933 containerizer.cpp:3323] Transitioning the state of 
container 
org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
 from PROVISIONING to PREPARING after 717056ns
I0909 19:07:07.381013 18939 containerizer.cpp:2100] Launching 
'mesos-containerizer' with flags '--help="false" 
--launch_info="{"command":{"arguments":["/mesos/mesos-1.10.0/_build/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_CreateDestroyDiskWithRecovery_v1_dj5zjj","--available_capacity=5GB","--volumes=","","--create_parameters=","--volume_metadata="],"shell":false,"value":"/mesos/mesos-1.10.0/_build/src/test-csi-plugin"},"environment":{"variables":[{"name":"MESOS_SANDBOX","type":"VALUE","value":"/tmp/CSIVersion_StorageLocalResourceProviderTest_CreateDestroyDiskWithRecovery_v1_XQun0n/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE"},{"name":"CSI_ENDPOINT","type":"VALUE","value":"unix:///tmp/mesos-csi-F5mOQp/endpoint.sock"}]},"task_environment":{},"working_directory":"/tmp/CSIVersion_StorageLocalResourceProviderTest_CreateDestroyDiskWithRecovery_v1_XQun0n/containe
 
rs/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE"}"
 --pipe_read="22" --pipe_write="24" 
--runtime_directory="/tmp/CSIVersion_StorageLocalResourceProviderTest_CreateDestroyDiskWithRecovery_v1_Dq4bHs/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE"
 --unshare_namespace_mnt="false"'
    @     0x56495acaa8e7 std::_Sp_counted_base<>::_M_add_ref_copy()
I0909 19:07:07.390264 18939 launcher.cpp:145] Forked child with pid '32546' for 
container 
'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0909 19:07:07.391347 18939 containerizer.cpp:3323] Transitioning the state of 
container 
org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
 from PREPARING to ISOLATING after 13.263104ms
I0909 19:07:07.391805 18920 hierarchical.cpp:2581] Filtered offer with 
ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 for role storage/role of framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000
I0909 19:07:07.392076 18920 hierarchical.cpp:1726] Performed allocation for 1 
agents in 985475ns
I0909 19:07:07.392997 18939 containerizer.cpp:3323] Transitioning the state of 
container 
org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
 from ISOLATING to FETCHING after 1.641984ms
I0909 19:07:07.393358 18935 fetcher.cpp:369] Starting to fetch URIs for 
container: 
org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE,
 directory: 
/tmp/CSIVersion_StorageLocalResourceProviderTest_CreateDestroyDiskWithRecovery_v1_XQun0n/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
I0909 19:07:07.394634 18938 containerizer.cpp:3323] Transitioning the state of 
container 
org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
 from FETCHING to RUNNING after 1.52576ms
I0909 19:07:07.397385 18936 container_daemon.cpp:140] Invoking post-start hook 
for container 
'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0909 19:07:07.397665 18932 service_manager.cpp:703] Connecting to endpoint 
'unix:///tmp/mesos-csi-F5mOQp/endpoint.sock' of CSI plugin container 
org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE
    @     0x56495aca8901 std::__shared_count<>::__shared_count()
    @     0x56495aca60a7 std::__shared_ptr<>::__shared_ptr()
    @     0x56495aca60cd std::shared_ptr<>::shared_ptr()
I0909 19:07:07.444525 18931 hierarchical.cpp:2581] Filtered offer with 
ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 for role storage/role of framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000
I0909 19:07:07.444757 18931 hierarchical.cpp:1726] Performed allocation for 1 
agents in 966811ns
    @     0x56495aca60f3 process::UPID::ID::ID()
    @     0x56495aca6140 process::UPID::UPID()
I0909 19:07:07.496099 18938 hierarchical.cpp:2581] Filtered offer with 
ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 for role storage/role of framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000
I0909 19:07:07.496282 18938 hierarchical.cpp:1726] Performed allocation for 1 
agents in 731211ns
    @     0x2af48ff64b74 process::UPID::UPID()
    @     0x56495b274e8b process::PID<>::PID()
    @     0x56495c810a67 process::Process<>::self()
I0909 19:07:07.547629 18918 hierarchical.cpp:2581] Filtered offer with 
ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 for role storage/role of framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000
I0909 19:07:07.547801 18918 hierarchical.cpp:1726] Performed allocation for 1 
agents in 726362ns
I0909 19:07:07.598968 18919 hierarchical.cpp:2581] Filtered offer with 
ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 for role storage/role of framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000
I0909 19:07:07.599143 18919 hierarchical.cpp:1726] Performed allocation for 1 
agents in 705536ns
    @     0x2af48e11c98b process::dispatch<>()
I0909 19:07:07.650477 18935 hierarchical.cpp:2581] Filtered offer with 
ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 for role storage/role of framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000
I0909 19:07:07.650646 18935 hierarchical.cpp:1726] Performed allocation for 1 
agents in 722480ns
    @     0x2af48e11c0a4 mesos::internal::PendingFutureTracker::track<>()
    @     0x2af48e1b5fd7 mesos::internal::slave::LauncherTracker::destroy()
    @     0x2af48df6f052 
mesos::internal::slave::MesosContainerizerProcess::__destroy()
I0909 19:07:07.702183 18922 hierarchical.cpp:2581] Filtered offer with 
ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 for role storage/role of framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000
I0909 19:07:07.702430 18922 hierarchical.cpp:1726] Performed allocation for 1 
agents in 786333ns
    @     0x2af48df6ec7e 
mesos::internal::slave::MesosContainerizerProcess::_destroy()
    @     0x2af48df6d9df 
_ZZN5mesos8internal5slave25MesosContainerizerProcess7destroyERKNS_11ContainerIDERK6OptionINS_5slave20ContainerTerminationEEENKUlRKSt6vectorIN7process6FutureIS9_EESaISF_EEE_clESJ_
    @     0x2af48df8209e 
_ZN5cpp176invokeIZN5mesos8internal5slave25MesosContainerizerProcess7destroyERKNS1_11ContainerIDERK6OptionINS1_5slave20ContainerTerminationEEEUlRKSt6vectorIN7process6FutureISB_EESaISH_EEE_ISJ_EEEDTclcl7forwardIT_Efp_Espcl7forwardIT0_Efp0_EEEOSN_DpOSO_
    @     0x2af48df814fc 
_ZN6lambda8internal7PartialIZN5mesos8internal5slave25MesosContainerizerProcess7destroyERKNS2_11ContainerIDERK6OptionINS2_5slave20ContainerTerminationEEEUlRKSt6vectorIN7process6FutureISC_EESaISI_EEE_ISK_EE13invoke_expandISN_St5tupleIISK_EESQ_IIEEILm0EEEEDTcl6invokecl7forwardIT_Efp_Espcl6expandcl3getIXT2_EEcl7forwardIT0_Efp0_EEcl7forwardIT1_Efp2_EEEEOST_OSU_N5cpp1416integer_sequenceImIXspT2_EEEEOSV_
    @     0x2af48df80c9c 
_ZNO6lambda8internal7PartialIZN5mesos8internal5slave25MesosContainerizerProcess7destroyERKNS2_11ContainerIDERK6OptionINS2_5slave20ContainerTerminationEEEUlRKSt6vectorIN7process6FutureISC_EESaISI_EEE_ISK_EEclIIEEEDTcl13invoke_expandcl4movedtdefpT1fEcl4movedtdefpT10bound_argsEcvN5cpp1416integer_sequenceImILm0EEEE_Ecl16forward_as_tuplespcl7forwardIT_Efp_EEEEDpOST_
    @     0x2af48df80307 
_ZN5cpp176invokeIN6lambda8internal7PartialIZN5mesos8internal5slave25MesosContainerizerProcess7destroyERKNS4_11ContainerIDERK6OptionINS4_5slave20ContainerTerminationEEEUlRKSt6vectorIN7process6FutureISE_EESaISK_EEE_ISM_EEEIEEEDTclcl7forwardIT_Efp_Espcl7forwardIT0_Efp0_EEEOSR_DpOSS_
    @     0x2af48df7f926 
_ZN6lambda8internal6InvokeIN7process6FutureI7NothingEEEclINS0_7PartialIZN5mesos8internal5slave25MesosContainerizerProcess7destroyERKNS9_11ContainerIDERK6OptionINS9_5slave20ContainerTerminationEEEUlRKSt6vectorINS3_ISJ_EESaISN_EEE_ISP_EEEIEEES5_OT_DpOT0_
    @     0x2af48df7ef50 
_ZNO6lambda12CallableOnceIFN7process6FutureI7NothingEEvEE10CallableFnINS_8internal7PartialIZN5mesos8internal5slave25MesosContainerizerProcess7destroyERKNSA_11ContainerIDERK6OptionINSA_5slave20ContainerTerminationEEEUlRKSt6vectorINS2_ISK_EESaISO_EEE_ISQ_EEEEclEv
I0909 19:07:07.754215 18932 hierarchical.cpp:2581] Filtered offer with 
ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 for role storage/role of framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000
I0909 19:07:07.754422 18932 hierarchical.cpp:1726] Performed allocation for 1 
agents in 777021ns
    @     0x56495b014c89 
_ZNO6lambda12CallableOnceIFN7process6FutureI7NothingEEvEEclEv
I0909 19:07:07.789433 18920 service_manager.cpp:545] Probing endpoint 
'unix:///tmp/mesos-csi-F5mOQp/endpoint.sock' with CSI v1
    @     0x56495affc139 
_ZZN7process8internal8DispatchINS_6FutureI7NothingEEEclIN6lambda12CallableOnceIFS4_vEEEEES4_RKNS_4UPIDEOT_ENKUlSt10unique_ptrINS_7PromiseIS3_EESt14default_deleteISI_EEOSA_PNS_11ProcessBaseEE_clESL_SM_SO_
I0909 19:07:07.804179 32550 test_csi_plugin.cpp:909] ProbeRequest '{}'
I0909 19:07:07.805948 18938 container_daemon.cpp:171] Waiting for container 
'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0909 19:07:07.806164 18935 hierarchical.cpp:2581] Filtered offer with 
ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 for role storage/role of framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000
I0909 19:07:07.806399 18935 hierarchical.cpp:1726] Performed allocation for 1 
agents in 831866ns
I0909 19:07:07.810322 32550 test_csi_plugin.cpp:895] 
GetPluginCapabilitiesRequest '{}'
I0909 19:07:07.811241 18924 process.cpp:3671] Handling HTTP event for process 
'slave(1190)' with path: '/slave(1190)/api/v1'
I0909 19:07:07.813196 18924 http.cpp:1115] HTTP POST for /slave(1190)/api/v1 
from 172.17.0.2:58842
I0909 19:07:07.813896 18924 http.cpp:2824] Processing WAIT_CONTAINER call for 
container 
'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-local--CONTROLLER_SERVICE-NODE_SERVICE'
I0909 19:07:07.814548 32551 test_csi_plugin.cpp:877] GetPluginInfoRequest '{}'
I0909 19:07:07.814800 32550 test_csi_plugin.cpp:877] GetPluginInfoRequest '{}'
I0909 19:07:07.816233 18934 v1_volume_manager.cpp:649] NODE_SERVICE loaded: 
{"name":".","vendorVersion":"1.10.0"}
I0909 19:07:07.817123 18934 v1_volume_manager.cpp:649] CONTROLLER_SERVICE 
loaded: {"name":".","vendorVersion":"1.10.0"}
I0909 19:07:07.819530 32551 test_csi_plugin.cpp:1105] 
ControllerGetCapabilitiesRequest '{}'
I0909 19:07:07.823601 32552 test_csi_plugin.cpp:1241] 
NodeGetCapabilitiesRequest '{}'
    @     0x56495b0cc543 
_ZN5cpp176invokeIZN7process8internal8DispatchINS1_6FutureI7NothingEEEclIN6lambda12CallableOnceIFS6_vEEEEES6_RKNS1_4UPIDEOT_EUlSt10unique_ptrINS1_7PromiseIS5_EESt14default_deleteISK_EEOSC_PNS1_11ProcessBaseEE_JSN_SC_SQ_EEEDTclcl7forwardIT_Efp_Espcl7forwardIT0_Efp0_EEEOSS_DpOST_
I0909 19:07:07.828114 32551 test_csi_plugin.cpp:1255] NodeGetInfoRequest '{}'
I0909 19:07:07.832068 18917 provider.cpp:676] Recovered resources 
'disk(reservations: 
[(DYNAMIC,storage),(DYNAMIC,storage/role,test-principal)])[MOUNT(org.apache.mesos.csi.test.local,/tmp/CSIVersion_StorageLocalResourceProviderTest_CreateDestroyDiskWithRecovery_v1_dj5zjj/4GB-e4120ec4-776e-4cf0-a712-4c7de2b31062,test)]:4096'
 and 1 operations for resource provider with type 
'org.apache.mesos.rp.local.storage' and name 'test'
I0909 19:07:07.832231 18938 status_update_manager_process.hpp:379] Pausing 
operation status update manager
I0909 19:07:07.832589 18935 http_connection.hpp:227] New endpoint detected at 
http://172.17.0.2:33926/slave(1190)/api/v1/resource_provider
I0909 19:07:07.836984 18916 http_connection.hpp:283] Connected with the remote 
endpoint at http://172.17.0.2:33926/slave(1190)/api/v1/resource_provider
I0909 19:07:07.837895 18931 provider.cpp:476] Connected to resource provider 
manager
I0909 19:07:07.838977 18939 http_connection.hpp:131] Sending SUBSCRIBE call to 
http://172.17.0.2:33926/slave(1190)/api/v1/resource_provider
I0909 19:07:07.840663 18928 process.cpp:3671] Handling HTTP event for process 
'slave(1190)' with path: '/slave(1190)/api/v1/resource_provider'
I0909 19:07:07.842993 18922 http.cpp:1115] HTTP POST for 
/slave(1190)/api/v1/resource_provider from 172.17.0.2:58846
    @     0x56495b0bbf9f 
_ZN6lambda8internal7PartialIZN7process8internal8DispatchINS2_6FutureI7NothingEEEclINS_12CallableOnceIFS7_vEEEEES7_RKNS2_4UPIDEOT_EUlSt10unique_ptrINS2_7PromiseIS6_EESt14default_deleteISK_EEOSC_PNS2_11ProcessBaseEE_JSN_SC_St12_PlaceholderILi1EEEE13invoke_expandISR_St5tupleIJSN_SC_ST_EESW_IJOSQ_EEJLm0ELm1ELm2EEEEDTcl6invokecl7forwardISG_Efp_Espcl6expandcl3getIXT2_EEcl7forwardIT0_Efp0_EEcl7forwardIT1_Efp2_EEEESH_OS10_N5cpp1416integer_sequenceImJXspT2_EEEEOS11_
I0909 19:07:07.843755 18935 manager.cpp:813] Subscribing resource provider 
{"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"id":{"value":"ed026377-7715-4186-9441-147807a7ac94"},"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/mesos/mesos-1.10.0/_build/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_CreateDestroyDiskWithRecovery_v1_dj5zjj","--available_capacity=5GB","--volumes=","","--create_parameters=","--volume_metadata="],"shell":false,"value":"/mesos/mesos-1.10.0/_build/src/test-csi-plugin"},"resources":[{"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}],"services":["CONTROLLER_SERVICE","NODE_SERVICE"]}],"name":"local","type":"org.apache.mesos.csi.test"},"reconciliation_interval_seconds":0.0},"type":"org.apache.mesos.rp.local.storage"}
I0909 19:07:07.844877 18934 slave.cpp:8481] Handling resource provider message 
'SUBSCRIBE: 
{"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"id":{"value":"ed026377-7715-4186-9441-147807a7ac94"},"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["/mesos/mesos-1.10.0/_build/src/test-csi-plugin","--api_version=v1","--work_dir=/tmp/CSIVersion_StorageLocalResourceProviderTest_CreateDestroyDiskWithRecovery_v1_dj5zjj","--available_capacity=5GB","--volumes=","","--create_parameters=","--volume_metadata="],"shell":false,"value":"/mesos/mesos-1.10.0/_build/src/test-csi-plugin"},"resources":[{"name":"cpus","scalar":{"value":0.1},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"}],"services":["CONTROLLER_SERVICE","NODE_SERVICE"]}],"name":"local","type":"org.apache.mesos.csi.test"},"reconciliation_interval_seconds":0.0},"type":"org.apache.mesos.rp.local.storage"}'
I0909 19:07:07.846794 18931 provider.cpp:498] Received SUBSCRIBED event
I0909 19:07:07.846855 18931 provider.cpp:1309] Subscribed with ID 
ed026377-7715-4186-9441-147807a7ac94
I0909 19:07:07.847715 18929 status_update_manager_process.hpp:314] Recovering 
operation status update manager
I0909 19:07:07.847784 18929 status_update_manager_process.hpp:443] Recovering 
operation status update stream e4120ec4-776e-4cf0-a712-4c7de2b31062
I0909 19:07:07.847975 18929 status_update_manager_process.hpp:684] Replaying 
operation status update stream e4120ec4-776e-4cf0-a712-4c7de2b31062
I0909 19:07:07.858436 18928 hierarchical.cpp:2581] Filtered offer with 
ports:[31000-32000]; cpus:2; mem:1024; disk:1024 on agent 
a0055024-74a2-47f4-8a64-e7876b603597-S0 for role storage/role of framework 
a0055024-74a2-47f4-8a64-e7876b603597-0000
I0909 19:07:07.858575 18928 hierarchical.cpp:1726] Performed allocation for 1 
agents in 611695ns
    @     0x56495b0a632d 
_ZNO6lambda8internal7PartialIZN7process8internal8DispatchINS2_6FutureI7NothingEEEclINS_12CallableOnceIFS7_vEEEEES7_RKNS2_4UPIDEOT_EUlSt10unique_ptrINS2_7PromiseIS6_EESt14default_deleteISK_EEOSC_PNS2_11ProcessBaseEE_JSN_SC_St12_PlaceholderILi1EEEEclIJSQ_EEEDTcl13invoke_expandcl4movedtdefpT1fEcl4movedtdefpT10bound_argsEcvN5cpp1416integer_sequenceImJLm0ELm1ELm2EEEE_Ecl16forward_as_tuplespcl7forwardIT_Efp_EEEEDpOSZ_
    @     0x56495b087f37 
_ZN5cpp176invokeIN6lambda8internal7PartialIZN7process8internal8DispatchINS4_6FutureI7NothingEEEclINS1_12CallableOnceIFS9_vEEEEES9_RKNS4_4UPIDEOT_EUlSt10unique_ptrINS4_7PromiseIS8_EESt14default_deleteISM_EEOSE_PNS4_11ProcessBaseEE_JSP_SE_St12_PlaceholderILi1EEEEEJSS_EEEDTclcl7forwardIT_Efp_Espcl7forwardIT0_Efp0_EEEOSX_DpOSY_
make[4]: *** [check-local] Segmentation fault (core dumped)
make[4]: Leaving directory `/mesos/mesos-1.10.0/_build/src'
make[3]: *** [check-am] Error 2
make[3]: Leaving directory `/mesos/mesos-1.10.0/_build/src'
make[2]: *** [check] Error 2
make[2]: Leaving directory `/mesos/mesos-1.10.0/_build/src'
make[1]: *** [check-recursive] Error 1
make[1]: Leaving directory `/mesos/mesos-1.10.0/_build'
make: *** [distcheck] Error 1
+ docker rmi --force mesos-1568048394-9716
Untagged: mesos-1568048394-9716:latest
Deleted: sha256:b9156edb1c23768ee7fbb6a1401a987d0864945322bf141b2d5d3a2dac2141ea
Deleted: sha256:e308514f19ab92123fc9e305b42ccbd1e9124868975e62457d63d017d7e381b7
Deleted: sha256:45f97f6a3a4abb0138089779ca90233035ec592632dd08baeb31e4be78c79fbc
Deleted: sha256:05ce3a6ec38780ab36e75b89d3fe837595f42261d26f7920d3faed6f33bbed75
Deleted: sha256:c1571b792300557bad6ffad0f71ba088184aa0ecfd6c959171d980b9472bf5fb
Deleted: sha256:54ff58453d81b46b1f6a47c3c6efe999cdbf8c9968dbc236706b82b166e36e7e
Deleted: sha256:79bf6270e7e43fbbf0876e9ce5d513b568cdab6a7bd946f24070f4d411af4b27
Deleted: sha256:da21f672edf59ed5b820e75dcee3943b07b809cda99eb982b4a84f8bb834115e
Deleted: sha256:1ffd57f13c8fb779f531f6480add62a4b37fa4c84d98802471cfcd5173b6c714
Deleted: sha256:f8eb1b18ba8512f40adece462c5ba4c5b54754148838580327aa79e83e58c74f
Deleted: sha256:c88855d13c9fcc7bfdfa460681848fde3055504c4c645c2a1933f14bc361a7e4
Deleted: sha256:e1434feb769f6aab1b9178b97b94ecd9eba1ca4b57a366c4abda619a16bb8ce5
Deleted: sha256:76c7cc4184af290ecb880cb73db4a53848c5d6a3abb9d6a63cd7569eefabc67b
Deleted: sha256:a009e21feadba4557008b6075890320068a9a3f5771e37f64b3d3ce362e610db
Deleted: sha256:35b5c5eb29abcac2c3e2519f55ab5d4514b125fbf389e3d4afdfe1808900129e
Deleted: sha256:887bb2c460ac75c336ca618ce7829386ccb61539d6c31a029ebc4d1e825e0520
Deleted: sha256:913306a82ede0cfd950588bee142cc8aab99a46860a39ef82e4051b6db7fb227
Deleted: sha256:2585fc6a6042db51187adfbd58a36c0109a4923fe896282b8e1fcc3afb603747
Deleted: sha256:3223cf6cc6e97d780d4daad1cc52b7522b31298736666a11083b89a8f12a07c8
Deleted: sha256:33ed817c6a0a371727201ee6117c86fd73c5983ffe313c29bc871abe4b6750e5
Deleted: sha256:0012256120a3b4f067297c2aec9e5d0cd8e0e3535a8fd85530ab0e28c8ea4a2a
Deleted: sha256:c3db6ed3723b0d64e565216c1680712f6800d73d910e3e0e719ee3055b3ab217
Deleted: sha256:6b270a6295dd0a2147009ae0e7c0ca4e9ca8889d82a6fbe1fbc26bbc5ccbefda
Deleted: sha256:6a910d5ed96b086b041e285cea1026c2a27fe6136b9ed347e694d4fe5dd67357
Deleted: sha256:e9d0ca07e9a9b7f1f82ac580286ba2453cf73ea0a4e43857c85f31b174d8ecae
Deleted: sha256:2c02d071d5b9f03c7ca4b8cf9e30008eed292f1996fbc7d9961f7aeda9cbef18
Deleted: sha256:d712727a0a73deb09ee7d32b3f68a29315ccf93222532e9f0045291e74c8c84b
Deleted: sha256:4fe427b2ca35a4573bdd9833b4e14bed82a14959e9182e7df3c62f0e6d512ef7
Deleted: sha256:cb3831ab23b493137cc8efea4050447596a6c4aeae08d6e1a36eafb84ec2e874
Deleted: sha256:4bd2477eecc15809e709c88c8f466ce0554588153d73348b200fc786c6711c9a

Full log: https://builds.apache.org/job/Mesos-Reviewbot-Linux/3596/console

- Mesos Reviewbot


On Sept. 9, 2019, 2:53 p.m., Andrei Budnik wrote:
> 
> -----------------------------------------------------------
> This is an automatically generated e-mail. To reply, visit:
> https://reviews.apache.org/r/71455/
> -----------------------------------------------------------
> 
> (Updated Sept. 9, 2019, 2:53 p.m.)
> 
> 
> Review request for mesos, Gilbert Song, Joseph Wu, and Qian Zhang.
> 
> 
> Bugs: MESOS-9843
>     https://issues.apache.org/jira/browse/MESOS-9843
> 
> 
> Repository: mesos
> 
> 
> Description
> -------
> 
> This test starts an agent with the MockIsolator to intercept calls to
> its `prepare` method, then it launches a task, which gets stuck.
> We check that the /containerizer/debug endpoint returns a non-empty
> list of pending futures including `MockIsolator::prepare`. After
> setting the promise for the `prepare`, the task successfully starts
> and we expect for the /containerizer/debug endpoint to return an
> empty list of pending operations.
> 
> 
> Diffs
> -----
> 
>   src/tests/slave_tests.cpp 02b65a925a52d09b0a9183d3288b9ab363b98bc5 
> 
> 
> Diff: https://reviews.apache.org/r/71455/diff/1/
> 
> 
> Testing
> -------
> 
> internal CI
> 
> 
> Thanks,
> 
> Andrei Budnik
> 
>

Reply via email to