Details
-
Bug
-
Status: Resolved
-
Major
-
Resolution: Cannot Reproduce
-
1.5.3
-
None
-
Ubuntu 14.04, SSL-enabled
Description
20:03:04 [ RUN ] StorageLocalResourceProviderTest.ROOT_NewVolumeRecovery
20:03:04 I0808 20:03:04.748040 10423 cluster.cpp:172] Creating default 'local' authorizer
20:03:04 I0808 20:03:04.749110 23206 master.cpp:467] Master 6180f181-f8df-4125-a7bd-a1b5ff9f16f1 (ip-172-16-10-204.ec2.internal) started on 172.16.10.204:57833
20:03:04 I0808 20:03:04.749131 23206 master.cpp:469] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="1secs" --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/nLxkqj/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_unreachable_tasks_per_framework="1000" --min_allocatable_resources="cpus:0.01|mem:32" --port="5050" --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="/usr/local/share/mesos/webui" --work_dir="/tmp/nLxkqj/master" --zk_session_timeout="10secs"
20:03:04 I0808 20:03:04.749269 23206 master.cpp:518] Master only allowing authenticated frameworks to register
20:03:04 I0808 20:03:04.749276 23206 master.cpp:524] Master only allowing authenticated agents to register
20:03:04 I0808 20:03:04.749281 23206 master.cpp:530] Master only allowing authenticated HTTP frameworks to register
20:03:04 I0808 20:03:04.749287 23206 credentials.hpp:37] Loading credentials for authentication from '/tmp/nLxkqj/credentials'
20:03:04 I0808 20:03:04.749378 23206 master.cpp:574] Using default 'crammd5' authenticator
20:03:04 I0808 20:03:04.749428 23206 http.cpp:1049] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
20:03:04 I0808 20:03:04.749473 23206 http.cpp:1049] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
20:03:04 I0808 20:03:04.749497 23206 http.cpp:1049] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
20:03:04 I0808 20:03:04.749522 23206 master.cpp:653] Authorization enabled
20:03:04 I0808 20:03:04.749619 23208 hierarchical.cpp:219] Initialized hierarchical allocator process
20:03:04 I0808 20:03:04.749645 23208 whitelist_watcher.cpp:77] No whitelist given
20:03:04 I0808 20:03:04.750432 23206 master.cpp:2265] Elected as the leading master!
20:03:04 I0808 20:03:04.750452 23206 master.cpp:1730] Recovering from registrar
20:03:04 I0808 20:03:04.750491 23206 registrar.cpp:347] Recovering registrar
20:03:04 I0808 20:03:04.750617 23206 registrar.cpp:391] Successfully fetched the registry (0B) in 112896ns
20:03:04 I0808 20:03:04.750648 23206 registrar.cpp:495] Applied 1 operations in 7349ns; attempting to update the registry
20:03:04 I0808 20:03:04.750763 23204 registrar.cpp:552] Successfully updated the registry in 97024ns
20:03:04 I0808 20:03:04.750794 23204 registrar.cpp:424] Successfully recovered registrar
20:03:04 I0808 20:03:04.750921 23204 master.cpp:1843] Recovered 0 agents from the registry (176B); allowing 10mins for agents to re-register
20:03:04 I0808 20:03:04.750958 23204 hierarchical.cpp:257] Skipping recovery of hierarchical allocator: nothing to recover
20:03:04 W0808 20:03:04.752594 10423 process.cpp:2745] Attempted to spawn already running process files@172.16.10.204:57833
20:03:04 I0808 20:03:04.753041 10423 containerizer.cpp:309] Using isolation { environment_secret, volume/sandbox_path, filesystem/linux, network/cni, volume/image, volume/host_path }
20:03:04 I0808 20:03:04.756779 10423 linux_launcher.cpp:145] Using /sys/fs/cgroup/freezer as the freezer hierarchy for the Linux launcher
20:03:04 I0808 20:03:04.757201 10423 provisioner.cpp:299] Using default backend 'aufs'
20:03:04 I0808 20:03:04.757702 10423 linux.cpp:152] Bind mounting '/tmp/StorageLocalResourceProviderTest_ROOT_NewVolumeRecovery_pPv7Rd' and making it a shared mount
20:03:04 I0808 20:03:04.768085 10423 cluster.cpp:460] Creating default 'local' authorizer
20:03:04 I0808 20:03:04.770094 23205 slave.cpp:255] Mesos agent started on (765)@172.16.10.204:57833
20:03:04 I0808 20:03:04.770112 23205 slave.cpp:256] Flags at startup: --acls="" --agent_features="capabilities {
20:03:04 type: MULTI_ROLE
20:03:04 }
20:03:04 capabilities {
20:03:04 type: HIERARCHICAL_ROLE
20:03:04 }
20:03:04 capabilities {
20:03:04 type: RESERVATION_REFINEMENT
20:03:04 }
20:03:04 capabilities {
20:03:04 type: RESOURCE_PROVIDER
20:03:04 }
20:03:04 " --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/nLxkqj/lT6HL2/store/appc" --authenticate_http_executors="true" --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_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/nLxkqj/lT6HL2/credential" --default_role="*" --disallow_sharing_agent_pid_namespace="false" --disk_profile_adaptor="org_apache_mesos_UriDiskProfileAdaptor" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/nLxkqj/lT6HL2/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_reregistration_timeout="2secs" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/nLxkqj/lT6HL2/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --http_command_executor="false" --http_credentials="/tmp/nLxkqj/lT6HL2/http_credentials" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="filesystem/linux" --jwt_secret_key="/tmp/nLxkqj/lT6HL2/jwt_secret_key" --launcher="linux" --launcher_dir="/home/ubuntu/workspace/mesos/Mesos_CI-build/FLAG/SSL/label/mesos-ec2-ubuntu-14.04/mesos/build/src" --logbufsecs="0" --logging_level="INFO" --max_completed_executors_per_framework="150" --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/nLxkqj/resource_provider_configs" --resources="cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]" --revocable_cpu_low_priority="true" --runtime_dir="/tmp/StorageLocalResourceProviderTest_ROOT_NewVolumeRecovery_upLUj8" --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/StorageLocalResourceProviderTest_ROOT_NewVolumeRecovery_pPv7Rd" --zk_session_timeout="10secs"
20:03:04 I0808 20:03:04.770551 23205 credentials.hpp:86] Loading credential for authentication from '/tmp/nLxkqj/lT6HL2/credential'
20:03:04 I0808 20:03:04.770617 23205 slave.cpp:288] Agent using credential for: test-principal
20:03:04 I0808 20:03:04.770630 23205 credentials.hpp:37] Loading credentials for authentication from '/tmp/nLxkqj/lT6HL2/http_credentials'
20:03:04 I0808 20:03:04.770722 23205 http.cpp:1049] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-executor'
20:03:04 I0808 20:03:04.770761 23205 http.cpp:1070] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-executor'
20:03:04 I0808 20:03:04.770813 23205 http.cpp:1049] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
20:03:04 I0808 20:03:04.770833 23205 http.cpp:1070] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-readonly'
20:03:04 I0808 20:03:04.770893 23205 disk_profile.cpp:84] Creating disk profile adaptor module 'org_apache_mesos_UriDiskProfileAdaptor'
20:03:04 I0808 20:03:04.771277 23208 uri_disk_profile.cpp:301] Updated disk profile mapping to 1 total profiles
20:03:04 I0808 20:03:04.771587 23205 slave.cpp:605] 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"}]
20:03:04 I0808 20:03:04.771665 23205 slave.cpp:613] Agent attributes: [ ]
20:03:04 I0808 20:03:04.771672 23205 slave.cpp:622] Agent hostname: ip-172-16-10-204.ec2.internal
20:03:04 I0808 20:03:04.771829 23202 task_status_update_manager.cpp:181] Pausing sending task status updates
20:03:04 I0808 20:03:04.771970 23205 state.cpp:66] Recovering state from '/tmp/StorageLocalResourceProviderTest_ROOT_NewVolumeRecovery_pPv7Rd/meta'
20:03:04 I0808 20:03:04.772053 23202 task_status_update_manager.cpp:207] Recovering task status update manager
20:03:04 I0808 20:03:04.772102 23202 containerizer.cpp:715] Recovering containerizer
20:03:04 I0808 20:03:04.773324 23205 provisioner.cpp:499] Provisioner recovery complete
20:03:04 I0808 20:03:04.773552 23203 slave.cpp:7324] Finished recovery
20:03:04 I0808 20:03:04.773855 23203 slave.cpp:1256] New master detected at master@172.16.10.204:57833
20:03:04 I0808 20:03:04.773897 23203 slave.cpp:1321] Detecting new master
20:03:04 I0808 20:03:04.774006 23207 task_status_update_manager.cpp:181] Pausing sending task status updates
20:03:04 I0808 20:03:04.780117 23205 slave.cpp:1348] Authenticating with master master@172.16.10.204:57833
20:03:04 I0808 20:03:04.780143 23205 slave.cpp:1357] Using default CRAM-MD5 authenticatee
20:03:04 I0808 20:03:04.780349 23206 authenticatee.cpp:121] Creating new client SASL connection
20:03:04 I0808 20:03:04.780757 23206 master.cpp:9122] Authenticating slave(765)@172.16.10.204:57833
20:03:04 I0808 20:03:04.780808 23206 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(1437)@172.16.10.204:57833
20:03:04 I0808 20:03:04.780864 23206 authenticator.cpp:98] Creating new server SASL connection
20:03:04 I0808 20:03:04.781193 23206 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
20:03:04 I0808 20:03:04.781210 23206 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
20:03:04 I0808 20:03:04.781249 23206 authenticator.cpp:204] Received SASL authentication start
20:03:04 I0808 20:03:04.781273 23206 authenticator.cpp:326] Authentication requires more steps
20:03:04 I0808 20:03:04.781304 23206 authenticatee.cpp:259] Received SASL authentication step
20:03:04 I0808 20:03:04.781337 23206 authenticator.cpp:232] Received SASL authentication step
20:03:04 I0808 20:03:04.781352 23206 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'ip-172-16-10-204.ec2.internal' server FQDN: 'ip-172-16-10-204.ec2.internal' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
20:03:04 I0808 20:03:04.781358 23206 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
20:03:04 I0808 20:03:04.781364 23206 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
20:03:04 I0808 20:03:04.781369 23206 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'ip-172-16-10-204.ec2.internal' server FQDN: 'ip-172-16-10-204.ec2.internal' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
20:03:04 I0808 20:03:04.781373 23206 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
20:03:04 I0808 20:03:04.781378 23206 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
20:03:04 I0808 20:03:04.781385 23206 authenticator.cpp:318] Authentication success
20:03:04 I0808 20:03:04.781508 23201 authenticatee.cpp:299] Authentication success
20:03:04 I0808 20:03:04.781533 23206 master.cpp:9154] Successfully authenticated principal 'test-principal' at slave(765)@172.16.10.204:57833
20:03:04 I0808 20:03:04.781591 23206 slave.cpp:1448] Successfully authenticated with master master@172.16.10.204:57833
20:03:04 I0808 20:03:04.781682 23206 slave.cpp:1878] Will retry registration in 17.644204ms if necessary
20:03:04 I0808 20:03:04.781731 23201 master.cpp:6194] Received register agent message from slave(765)@172.16.10.204:57833 (ip-172-16-10-204.ec2.internal)
20:03:04 I0808 20:03:04.781750 23204 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(1437)@172.16.10.204:57833
20:03:04 I0808 20:03:04.781777 23201 master.cpp:3895] Authorizing agent with principal 'test-principal'
20:03:04 I0808 20:03:04.781913 23201 master.cpp:6252] Authorized registration of agent at slave(765)@172.16.10.204:57833 (ip-172-16-10-204.ec2.internal)
20:03:04 I0808 20:03:04.781940 23201 master.cpp:6363] Registering agent at slave(765)@172.16.10.204:57833 (ip-172-16-10-204.ec2.internal) with id 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-S0
20:03:04 I0808 20:03:04.782042 23201 registrar.cpp:495] Applied 1 operations in 28648ns; attempting to update the registry
20:03:04 I0808 20:03:04.782188 23208 registrar.cpp:552] Successfully updated the registry in 121856ns
20:03:04 I0808 20:03:04.782241 23208 master.cpp:6411] Admitted agent 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-S0 at slave(765)@172.16.10.204:57833 (ip-172-16-10-204.ec2.internal)
20:03:04 I0808 20:03:04.782371 23208 master.cpp:6460] Registered agent 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-S0 at slave(765)@172.16.10.204:57833 (ip-172-16-10-204.ec2.internal) with cpus:2; mem:1024; disk:1024; ports:[31000-32000]
20:03:04 I0808 20:03:04.782500 23208 hierarchical.cpp:588] Added agent 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-S0 (ip-172-16-10-204.ec2.internal) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (allocated: {})
20:03:04 I0808 20:03:04.782560 23208 hierarchical.cpp:1536] Performed allocation for 1 agents in 18439ns
20:03:04 I0808 20:03:04.782600 23201 slave.cpp:1480] Registered with master master@172.16.10.204:57833; given agent ID 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-S0
20:03:04 I0808 20:03:04.782670 23204 task_status_update_manager.cpp:188] Resuming sending task status updates
20:03:04 I0808 20:03:04.782747 23201 slave.cpp:1500] Checkpointing SlaveInfo to '/tmp/StorageLocalResourceProviderTest_ROOT_NewVolumeRecovery_pPv7Rd/meta/slaves/6180f181-f8df-4125-a7bd-a1b5ff9f16f1-S0/slave.info'
20:03:04 I0808 20:03:04.782970 23201 slave.cpp:1547] Forwarding agent update {"operations":{},"resource_version_uuid":{"value":"R11PC5r+R1i9nSAP\/FivEA=="},"slave_id":{"value":"6180f181-f8df-4125-a7bd-a1b5ff9f16f1-S0"},"update_oversubscribed_resources":true}
20:03:04 I0808 20:03:04.783152 23201 master.cpp:7387] Received update of agent 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-S0 at slave(765)@172.16.10.204:57833 (ip-172-16-10-204.ec2.internal) with total oversubscribed resources {}
20:03:04 I0808 20:03:04.783205 23201 master.cpp:7481] Ignoring update on agent 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-S0 at slave(765)@172.16.10.204:57833 (ip-172-16-10-204.ec2.internal) as it reports no changes
20:03:04 W0808 20:03:04.783514 10423 process.cpp:2745] Attempted to spawn already running process version@172.16.10.204:57833
20:03:04 I0808 20:03:04.784072 23203 container_daemon.cpp:162] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-slrp_test--CONTROLLER_SERVICE-NODE_SERVICE'
20:03:04 I0808 20:03:04.784901 10423 sched.cpp:232] Version: 1.5.4
20:03:04 I0808 20:03:04.785104 23207 process.cpp:3512] Handling HTTP event for process 'slave(765)' with path: '/slave(765)/api/v1'
20:03:04 I0808 20:03:04.785249 23201 sched.cpp:336] New master detected at master@172.16.10.204:57833
20:03:04 I0808 20:03:04.785274 23201 sched.cpp:401] Authenticating with master master@172.16.10.204:57833
20:03:04 I0808 20:03:04.785281 23201 sched.cpp:408] Using default CRAM-MD5 authenticatee
20:03:04 I0808 20:03:04.785342 23201 authenticatee.cpp:121] Creating new client SASL connection
20:03:04 I0808 20:03:04.785436 23207 http.cpp:1189] HTTP POST for /slave(765)/api/v1 from 172.16.10.204:43047
20:03:04 I0808 20:03:04.785578 23207 http.cpp:2617] Processing LAUNCH_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-slrp_test--CONTROLLER_SERVICE-NODE_SERVICE'
20:03:04 I0808 20:03:04.785807 23205 containerizer.cpp:1258] Starting container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-slrp_test--CONTROLLER_SERVICE-NODE_SERVICE
20:03:04 I0808 20:03:04.786041 23201 master.cpp:9122] Authenticating scheduler-0d99c794-89d1-49f8-8104-14c85a836e26@172.16.10.204:57833
20:03:04 I0808 20:03:04.786083 23201 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(1438)@172.16.10.204:57833
20:03:04 I0808 20:03:04.786331 23205 containerizer.cpp:1430] Checkpointed ContainerConfig at '/tmp/StorageLocalResourceProviderTest_ROOT_NewVolumeRecovery_upLUj8/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-slrp_test--CONTROLLER_SERVICE-NODE_SERVICE/config'
20:03:04 I0808 20:03:04.786350 23205 containerizer.cpp:3053] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-slrp_test--CONTROLLER_SERVICE-NODE_SERVICE from PROVISIONING to PREPARING
20:03:04 I0808 20:03:04.786130 23201 authenticator.cpp:98] Creating new server SASL connection
20:03:04 I0808 20:03:04.786748 23201 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
20:03:04 I0808 20:03:04.786767 23201 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
20:03:04 I0808 20:03:04.787004 23201 authenticator.cpp:204] Received SASL authentication start
20:03:04 I0808 20:03:04.787040 23201 authenticator.cpp:326] Authentication requires more steps
20:03:04 I0808 20:03:04.787067 23201 authenticatee.cpp:259] Received SASL authentication step
20:03:04 I0808 20:03:04.787093 23201 authenticator.cpp:232] Received SASL authentication step
20:03:04 I0808 20:03:04.787108 23201 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'ip-172-16-10-204.ec2.internal' server FQDN: 'ip-172-16-10-204.ec2.internal' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
20:03:04 I0808 20:03:04.787115 23201 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
20:03:04 I0808 20:03:04.787124 23201 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
20:03:04 I0808 20:03:04.787132 23201 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'ip-172-16-10-204.ec2.internal' server FQDN: 'ip-172-16-10-204.ec2.internal' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
20:03:04 I0808 20:03:04.787138 23201 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
20:03:04 I0808 20:03:04.787143 23201 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
20:03:04 I0808 20:03:04.787154 23201 authenticator.cpp:318] Authentication success
20:03:04 I0808 20:03:04.787184 23201 authenticatee.cpp:299] Authentication success
20:03:04 I0808 20:03:04.787199 23208 host_path.cpp:295] Mark '/tmp/StorageLocalResourceProviderTest_ROOT_NewVolumeRecovery_pPv7Rd' as shared for container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-slrp_test--CONTROLLER_SERVICE-NODE_SERVICE
20:03:04 I0808 20:03:04.787215 23201 master.cpp:9154] Successfully authenticated principal 'test-principal' at scheduler-0d99c794-89d1-49f8-8104-14c85a836e26@172.16.10.204:57833
20:03:04 I0808 20:03:04.787235 23201 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(1438)@172.16.10.204:57833
20:03:04 I0808 20:03:04.787286 23201 sched.cpp:514] Successfully authenticated with master master@172.16.10.204:57833
20:03:04 I0808 20:03:04.787297 23201 sched.cpp:819] Sending SUBSCRIBE call to master@172.16.10.204:57833
20:03:04 I0808 20:03:04.787333 23201 sched.cpp:852] Will retry registration in 179.43827ms if necessary
20:03:04 I0808 20:03:04.787405 23201 master.cpp:3026] Received SUBSCRIBE call for framework 'default' at scheduler-0d99c794-89d1-49f8-8104-14c85a836e26@172.16.10.204:57833
20:03:04 I0808 20:03:04.787425 23201 master.cpp:2337] Authorizing framework principal 'test-principal' to receive offers for roles '{ storage }'
20:03:04 I0808 20:03:04.787866 23208 containerizer.cpp:1916] Launching 'mesos-containerizer' with flags '--help="false" --launch_info="{"clone_namespaces":[131072],"command":{"arguments":["\/home\/ubuntu\/workspace\/mesos\/Mesos_CI-build\/FLAG\/SSL\/label\/mesos-ec2-ubuntu-14.04\/mesos\/build\/src\/test-csi-plugin","--available_capacity=2GB","--volumes=volume1:1GB;volume2:1GB","--work_dir=\/tmp\/nLxkqj\/test"],"shell":false,"value":"\/home\/ubuntu\/workspace\/mesos\/Mesos_CI-build\/FLAG\/SSL\/label\/mesos-ec2-ubuntu-14.04\/mesos\/build\/src\/test-csi-plugin"},"environment":{"variables":[{"name":"MESOS_SANDBOX","type":"VALUE","value":"\/tmp\/StorageLocalResourceProviderTest_ROOT_NewVolumeRecovery_pPv7Rd\/containers\/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-slrp_test--CONTROLLER_SERVICE-NODE_SERVICE"},{"name":"CSI_ENDPOINT","type":"VALUE","value":"unix:\/\/\/tmp\/mesos-csi-vwcgkM\/endpoint.sock"}]},"mounts":[{"flags":1048576,"target":"\/tmp\/StorageLocalResourceProviderTest_ROOT_NewVolumeRecovery_pPv7Rd"}],"task_environment":{},"working_directory":"\/tmp\/StorageLocalResourceProviderTest_ROOT_NewVolumeRecovery_pPv7Rd\/containers\/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-slrp_test--CONTROLLER_SERVICE-NODE_SERVICE"}" --pipe_read="33" --pipe_write="57" --runtime_directory="/tmp/StorageLocalResourceProviderTest_ROOT_NewVolumeRecovery_upLUj8/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-slrp_test--CONTROLLER_SERVICE-NODE_SERVICE" --unshare_namespace_mnt="false"'
20:03:04 I0808 20:03:04.788069 23203 linux_launcher.cpp:434] Launching container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-slrp_test--CONTROLLER_SERVICE-NODE_SERVICE and cloning with namespaces CLONE_NEWNS
20:03:04 I0808 20:03:04.788239 23201 master.cpp:3106] Subscribing framework default with checkpointing disabled and capabilities [ MULTI_ROLE, RESERVATION_REFINEMENT ]
20:03:04 I0808 20:03:04.791267 23201 master.cpp:9352] Adding framework 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-0000 (default) at scheduler-0d99c794-89d1-49f8-8104-14c85a836e26@172.16.10.204:57833 with roles { } suppressed
20:03:04 I0808 20:03:04.791826 23201 sched.cpp:746] Framework registered with 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-0000
20:03:04 I0808 20:03:04.791885 23201 sched.cpp:760] Scheduler::registered took 38145ns
20:03:04 I0808 20:03:04.791975 23206 hierarchical.cpp:343] Added framework 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-0000
20:03:04 I0808 20:03:04.792418 23206 hierarchical.cpp:1536] Performed allocation for 1 agents in 377148ns
20:03:04 I0808 20:03:04.792971 23207 master.cpp:8951] Sending offers [ 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-O0 ] to framework 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-0000 (default) at scheduler-0d99c794-89d1-49f8-8104-14c85a836e26@172.16.10.204:57833
20:03:04 I0808 20:03:04.793269 23207 sched.cpp:916] Scheduler::resourceOffers took 26377ns
20:03:04 I0808 20:03:04.793362 23207 master.cpp:5587] Processing DECLINE call for offers: [ 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-O0 ] for framework 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-0000 (default) at scheduler-0d99c794-89d1-49f8-8104-14c85a836e26@172.16.10.204:57833
20:03:04 I0808 20:03:04.793448 23207 master.cpp:10914] Removing offer 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-O0
20:03:04 I0808 20:03:04.793548 23206 hierarchical.cpp:1188] Recovered cpus(allocated: storage):2; mem(allocated: storage):1024; disk(allocated: storage):1024; ports(allocated: storage):[31000-32000] (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000], allocated: {}) on agent 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-S0 from framework 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-0000
20:03:04 I0808 20:03:04.793578 23206 hierarchical.cpp:1234] Framework 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-0000 filtered agent 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-S0 for 5secs
20:03:04 I0808 20:03:04.795635 23208 containerizer.cpp:3053] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-slrp_test--CONTROLLER_SERVICE-NODE_SERVICE from PREPARING to ISOLATING
20:03:04 I0808 20:03:04.796067 23208 containerizer.cpp:3053] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-slrp_test--CONTROLLER_SERVICE-NODE_SERVICE from ISOLATING to FETCHING
20:03:04 I0808 20:03:04.796133 23208 fetcher.cpp:369] Starting to fetch URIs for container: org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-slrp_test--CONTROLLER_SERVICE-NODE_SERVICE, directory: /tmp/StorageLocalResourceProviderTest_ROOT_NewVolumeRecovery_pPv7Rd/containers/org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-slrp_test--CONTROLLER_SERVICE-NODE_SERVICE
20:03:04 I0808 20:03:04.796397 23203 containerizer.cpp:3053] Transitioning the state of container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-slrp_test--CONTROLLER_SERVICE-NODE_SERVICE from FETCHING to RUNNING
20:03:04 I0808 20:03:04.902194 27872 test_csi_plugin.cpp:273] GetSupportedVersionsRequest '{}'
20:03:04 I0808 20:03:04.902760 23201 container_daemon.cpp:205] Waiting for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-slrp_test--CONTROLLER_SERVICE-NODE_SERVICE'
20:03:04 I0808 20:03:04.902992 27872 test_csi_plugin.cpp:286] GetPluginInfoRequest '{"version":{"minor":1}}'
20:03:04 I0808 20:03:04.903316 23207 provider.cpp:1919] Controller plugin loaded: {"name":"org.apache.mesos.csi.test","vendorVersion":"1.5.4"}
20:03:04 I0808 20:03:04.903700 23208 process.cpp:3512] Handling HTTP event for process 'slave(765)' with path: '/slave(765)/api/v1'
20:03:04 I0808 20:03:04.903828 27873 test_csi_plugin.cpp:616] ControllerProbeRequest '{"version":{"minor":1}}'
20:03:04 I0808 20:03:04.903915 23208 http.cpp:1189] HTTP POST for /slave(765)/api/v1 from 172.16.10.204:43048
20:03:04 I0808 20:03:04.903993 23208 http.cpp:2827] Processing WAIT_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-slrp_test--CONTROLLER_SERVICE-NODE_SERVICE'
20:03:04 I0808 20:03:04.904489 27872 test_csi_plugin.cpp:632] ControllerGetCapabilitiesRequest '{"version":{"minor":1}}'
20:03:04 I0808 20:03:04.904973 27873 test_csi_plugin.cpp:286] GetPluginInfoRequest '{"version":{"minor":1}}'
20:03:04 I0808 20:03:04.905308 23206 provider.cpp:1977] Node plugin loaded: {"name":"org.apache.mesos.csi.test","vendorVersion":"1.5.4"}
20:03:04 I0808 20:03:04.905596 27873 test_csi_plugin.cpp:806] NodeProbeRequest '{"version":{"minor":1}}'
20:03:04 I0808 20:03:04.906024 27872 test_csi_plugin.cpp:788] GetNodeIDRequest '{"version":{"minor":1}}'
20:03:04 I0808 20:03:04.906499 23208 provider.cpp:621] Finished recovery for resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test
20:03:04 I0808 20:03:04.906612 23208 status_update_manager_process.hpp:379] Pausing operation status update manager
20:03:04 I0808 20:03:04.906656 23208 http_connection.hpp:221] New endpoint detected at http://172.16.10.204:57833/slave(765)/api/v1/resource_provider
20:03:04 I0808 20:03:04.906859 23203 provider.cpp:1239] Updating metadata for profiles: { default }
20:03:04 I0808 20:03:04.907429 23204 http_connection.hpp:277] Connected with the remote endpoint at http://172.16.10.204:57833/slave(765)/api/v1/resource_provider
20:03:04 I0808 20:03:04.907550 23204 provider.cpp:482] Connected to resource provider manager
20:03:04 I0808 20:03:04.907688 23201 http_connection.hpp:129] Sending 1 call to http://172.16.10.204:57833/slave(765)/api/v1/resource_provider
20:03:04 I0808 20:03:04.908044 23204 process.cpp:3512] Handling HTTP event for process 'slave(765)' with path: '/slave(765)/api/v1/resource_provider'
20:03:04 I0808 20:03:04.908238 23204 http.cpp:1189] HTTP POST for /slave(765)/api/v1/resource_provider from 172.16.10.204:43050
20:03:04 I0808 20:03:04.908385 23204 manager.cpp:570] Subscribing resource provider {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["\/home\/ubuntu\/workspace\/mesos\/Mesos_CI-build\/FLAG\/SSL\/label\/mesos-ec2-ubuntu-14.04\/mesos\/build\/src\/test-csi-plugin","--available_capacity=2GB","--volumes=volume1:1GB;volume2:1GB","--work_dir=\/tmp\/nLxkqj\/test"],"shell":false,"value":"\/home\/ubuntu\/workspace\/mesos\/Mesos_CI-build\/FLAG\/SSL\/label\/mesos-ec2-ubuntu-14.04\/mesos\/build\/src\/test-csi-plugin"},"services":["CONTROLLER_SERVICE","NODE_SERVICE"]}],"name":"slrp_test","type":"org.apache.mesos.csi.test"}},"type":"org.apache.mesos.rp.local.storage"}
20:03:04 I0808 20:03:04.909065 23208 provider.cpp:504] Received SUBSCRIBED event
20:03:04 I0808 20:03:04.909090 23208 provider.cpp:1332] Subscribed with ID b3235abf-9b76-4380-88f2-a0c4b625ff1a
20:03:04 I0808 20:03:04.909371 23207 status_update_manager_process.hpp:314] Recovering operation status update manager
20:03:04 I0808 20:03:04.909865 27872 test_csi_plugin.cpp:549] ListVolumesRequest '{"version":{"minor":1}}'
20:03:04 I0808 20:03:04.909929 27873 test_csi_plugin.cpp:582] GetCapacityRequest '{"version":{"minor":1},"volumeCapabilities":[{"mount":{},"accessMode":{"mode":"SINGLE_NODE_WRITER"}}]}'
20:03:04 I0808 20:03:04.911087 23205 provider.cpp:1031] Removing '{}' and adding 'disk(reservations: [(DYNAMIC,storage)])[RAW(volume1,)]:1024; disk(reservations: [(DYNAMIC,storage)])[RAW(volume2,)]:1024; disk(reservations: [(DYNAMIC,storage)])[RAW(,default)]:2048' to the total resources
20:03:04 I0808 20:03:04.911448 23205 provider.cpp:3075] Sending UPDATE_STATE call with resources 'disk(reservations: [(DYNAMIC,storage)])[RAW(volume1,)]:1024; disk(reservations: [(DYNAMIC,storage)])[RAW(volume2,)]:1024; disk(reservations: [(DYNAMIC,storage)])[RAW(,default)]:2048' and 0 operations to agent 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-S0
20:03:04 I0808 20:03:04.911558 23205 provider.cpp:1045] Resource provider b3235abf-9b76-4380-88f2-a0c4b625ff1a is in READY state
20:03:04 I0808 20:03:04.911636 23205 http_connection.hpp:129] Sending 3 call to http://172.16.10.204:57833/slave(765)/api/v1/resource_provider
20:03:04 I0808 20:03:04.911720 23202 status_update_manager_process.hpp:385] Resuming operation status update manager
20:03:04 I0808 20:03:04.911927 23208 process.cpp:3512] Handling HTTP event for process 'slave(765)' with path: '/slave(765)/api/v1/resource_provider'
20:03:04 I0808 20:03:04.912112 23208 http.cpp:1189] HTTP POST for /slave(765)/api/v1/resource_provider from 172.16.10.204:43049
20:03:04 I0808 20:03:04.912214 23202 manager.cpp:679] Received UPDATE_STATE call with resources '[{"disk":{"source":{"id":"volume1","metadata":{"labels":[{"key":"path","value":"\/tmp\/nLxkqj\/test\/1GB-volume1"}]},"type":"RAW"}},"name":"disk","provider_id":{"value":"b3235abf-9b76-4380-88f2-a0c4b625ff1a"},"reservations":[{"role":"storage","type":"DYNAMIC"}],"scalar":{"value":1024.0},"type":"SCALAR"},{"disk":{"source":{"id":"volume2","metadata":{"labels":[{"key":"path","value":"\/tmp\/nLxkqj\/test\/1GB-volume2"}]},"type":"RAW"}},"name":"disk","provider_id":{"value":"b3235abf-9b76-4380-88f2-a0c4b625ff1a"},"reservations":[{"role":"storage","type":"DYNAMIC"}],"scalar":{"value":1024.0},"type":"SCALAR"},{"disk":{"source":{"profile":"default","type":"RAW"}},"name":"disk","provider_id":{"value":"b3235abf-9b76-4380-88f2-a0c4b625ff1a"},"reservations":[{"role":"storage","type":"DYNAMIC"}],"scalar":{"value":2048.0},"type":"SCALAR"}]' and 0 operations from resource provider b3235abf-9b76-4380-88f2-a0c4b625ff1a
20:03:04 I0808 20:03:04.912587 23208 slave.cpp:7669] Handling resource provider message 'UPDATE_STATE: b3235abf-9b76-4380-88f2-a0c4b625ff1a disk(reservations: [(DYNAMIC,storage)])[RAW(volume1,)]:1024; disk(reservations: [(DYNAMIC,storage)])[RAW(volume2,)]:1024; disk(reservations: [(DYNAMIC,storage)])[RAW(,default)]:2048'
20:03:04 I0808 20:03:04.912648 23208 slave.cpp:7786] Forwarding new total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage)])[RAW(volume1,)]:1024; disk(reservations: [(DYNAMIC,storage)])[RAW(volume2,)]:1024; disk(reservations: [(DYNAMIC,storage)])[RAW(,default)]:2048
20:03:04 I0808 20:03:04.913347 23205 hierarchical.cpp:724] Grew agent 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-S0 by disk(reservations: [(DYNAMIC,storage)])[RAW(volume1,)]:1024; disk(reservations: [(DYNAMIC,storage)])[RAW(volume2,)]:1024; disk(reservations: [(DYNAMIC,storage)])[RAW(,default)]:2048 (total), { } (used)
20:03:04 I0808 20:03:04.913465 23205 hierarchical.cpp:681] Agent 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-S0 (ip-172-16-10-204.ec2.internal) updated with total resources disk(reservations: [(DYNAMIC,storage)])[RAW(,default)]:2048; disk(reservations: [(DYNAMIC,storage)])[RAW(volume2,)]:1024; disk(reservations: [(DYNAMIC,storage)])[RAW(volume1,)]:1024; cpus:2; mem:1024; disk:1024; ports:[31000-32000]
20:03:05 I0808 20:03:05.750963 23204 hierarchical.cpp:1536] Performed allocation for 1 agents in 384697ns
20:03:05 I0808 20:03:05.751261 23208 master.cpp:8951] Sending offers [ 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-O1 ] to framework 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-0000 (default) at scheduler-0d99c794-89d1-49f8-8104-14c85a836e26@172.16.10.204:57833
20:03:05 I0808 20:03:05.751926 23208 sched.cpp:916] Scheduler::resourceOffers took 49160ns
20:03:05 I0808 20:03:05.752527 23208 master.cpp:10914] Removing offer 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-O1
20:03:05 I0808 20:03:05.752708 23208 master.cpp:4320] Processing ACCEPT call for offers: [ 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-O1 ] on agent 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-S0 at slave(765)@172.16.10.204:57833 (ip-172-16-10-204.ec2.internal) for framework 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-0000 (default) at scheduler-0d99c794-89d1-49f8-8104-14c85a836e26@172.16.10.204:57833
20:03:05 I0808 20:03:05.752945 23208 master.cpp:5340] Processing CREATE_VOLUME operation with source disk(allocated: storage)(reservations: [(DYNAMIC,storage)])[RAW(,default)]:2048 from framework 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-0000 (default) at scheduler-0d99c794-89d1-49f8-8104-14c85a836e26@172.16.10.204:57833 to agent 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-S0 at slave(765)@172.16.10.204:57833 (ip-172-16-10-204.ec2.internal)
20:03:05 I0808 20:03:05.753125 23208 master.cpp:10805] Sending operation '' (uuid: 65045eb1-ec70-41f4-b436-2ccdcd9aa326) to agent 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-S0 at slave(765)@172.16.10.204:57833 (ip-172-16-10-204.ec2.internal)
20:03:05 I0808 20:03:05.753815 23208 hierarchical.cpp:1188] Recovered cpus(allocated: storage):2; mem(allocated: storage):1024; disk(allocated: storage):1024; ports(allocated: storage):[31000-32000]; disk(allocated: storage)(reservations: [(DYNAMIC,storage)])[RAW(volume1,)]:1024; disk(allocated: storage)(reservations: [(DYNAMIC,storage)])[RAW(volume2,)]:1024 (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage)])[RAW(volume1,)]:1024; disk(reservations: [(DYNAMIC,storage)])[RAW(volume2,)]:1024; disk(reservations: [(DYNAMIC,storage)])[RAW(,default)]:2048, allocated: disk(allocated: storage)(reservations: [(DYNAMIC,storage)])[RAW(,default)]:2048) on agent 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-S0 from framework 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-0000
20:03:05 I0808 20:03:05.753965 23201 provider.cpp:504] Received APPLY_OPERATION event
20:03:05 I0808 20:03:05.754106 23201 provider.cpp:1370] Received CREATE_VOLUME operation '' (uuid: 65045eb1-ec70-41f4-b436-2ccdcd9aa326)
20:03:05 I0808 20:03:05.755082 27874 test_csi_plugin.cpp:305] CreateVolumeRequest '{"version":{"minor":1},"name":"65045eb1-ec70-41f4-b436-2ccdcd9aa326","capacityRange":{"requiredBytes":"2147483648","limitBytes":"2147483648"},"volumeCapabilities":[{"mount":{},"accessMode":{"mode":"SINGLE_NODE_WRITER"}}]}'
20:03:05 I0808 20:03:05.755800 23205 provider.cpp:2644] Applying conversion from 'disk(allocated: storage)(reservations: [(DYNAMIC,storage)])[RAW(,default)]:2048' to 'disk(allocated: storage)(reservations: [(DYNAMIC,storage)])[MOUNT(65045eb1-ec70-41f4-b436-2ccdcd9aa326,default):./csi/org.apache.mesos.csi.test/slrp_test/mounts/65045eb1-ec70-41f4-b436-2ccdcd9aa326]:2048' for operation (uuid: 65045eb1-ec70-41f4-b436-2ccdcd9aa326)
20:03:05 I0808 20:03:05.756256 23208 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: bc55e266-fab5-4883-a85f-e654daef295a) for operation UUID 65045eb1-ec70-41f4-b436-2ccdcd9aa326 of framework '6180f181-f8df-4125-a7bd-a1b5ff9f16f1-0000' on agent 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-S0
20:03:05 I0808 20:03:05.756440 23208 status_update_manager_process.hpp:414] Creating operation status update stream 65045eb1-ec70-41f4-b436-2ccdcd9aa326 checkpoint=true
20:03:05 I0808 20:03:05.756642 23208 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: bc55e266-fab5-4883-a85f-e654daef295a) for operation UUID 65045eb1-ec70-41f4-b436-2ccdcd9aa326 of framework '6180f181-f8df-4125-a7bd-a1b5ff9f16f1-0000' on agent 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-S0
20:03:05 I0808 20:03:05.761147 23208 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: bc55e266-fab5-4883-a85f-e654daef295a) for operation UUID 65045eb1-ec70-41f4-b436-2ccdcd9aa326 of framework '6180f181-f8df-4125-a7bd-a1b5ff9f16f1-0000' on agent 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-S0
20:03:05 I0808 20:03:05.761373 23208 http_connection.hpp:129] Sending 2 call to http://172.16.10.204:57833/slave(765)/api/v1/resource_provider
20:03:05 I0808 20:03:05.761699 23207 process.cpp:3512] Handling HTTP event for process 'slave(765)' with path: '/slave(765)/api/v1/resource_provider'
20:03:05 I0808 20:03:05.798554 23208 http.cpp:1189] HTTP POST for /slave(765)/api/v1/resource_provider from 172.16.10.204:43049
20:03:05 I0808 20:03:05.798925 23208 slave.cpp:7669] Handling resource provider message 'UPDATE_OPERATION_STATUS: (uuid: 65045eb1-ec70-41f4-b436-2ccdcd9aa326) for framework 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-0000 (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)'
20:03:05 I0808 20:03:05.799458 23208 slave.cpp:8003] Updating the state of operation '' (uuid: 65045eb1-ec70-41f4-b436-2ccdcd9aa326) of framework 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-0000 (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
20:03:05 I0808 20:03:05.799753 23208 slave.cpp:7848] Forwarding status update of operation '' (uuid: 65045eb1-ec70-41f4-b436-2ccdcd9aa326) for framework 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-0000
20:03:05 I0808 20:03:05.800042 23202 master.cpp:10565] Updating the state of operation '' (uuid: 65045eb1-ec70-41f4-b436-2ccdcd9aa326) for framework 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-0000 (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
20:03:05 I0808 20:03:05.800802 23206 hierarchical.cpp:929] Updated allocation of framework 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-0000 on agent 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-S0 from disk(allocated: storage)(reservations: [(DYNAMIC,storage)])[RAW(,default)]:2048 to disk(allocated: storage)(reservations: [(DYNAMIC,storage)])[MOUNT(65045eb1-ec70-41f4-b436-2ccdcd9aa326,default):./csi/org.apache.mesos.csi.test/slrp_test/mounts/65045eb1-ec70-41f4-b436-2ccdcd9aa326]:2048
20:03:05 I0808 20:03:05.800969 23206 hierarchical.cpp:1188] Recovered disk(allocated: storage)(reservations: [(DYNAMIC,storage)])[MOUNT(65045eb1-ec70-41f4-b436-2ccdcd9aa326,default):./csi/org.apache.mesos.csi.test/slrp_test/mounts/65045eb1-ec70-41f4-b436-2ccdcd9aa326]:2048 (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage)])[RAW(volume1,)]:1024; disk(reservations: [(DYNAMIC,storage)])[RAW(volume2,)]:1024; disk(reservations: [(DYNAMIC,storage)])[MOUNT(65045eb1-ec70-41f4-b436-2ccdcd9aa326,default):./csi/org.apache.mesos.csi.test/slrp_test/mounts/65045eb1-ec70-41f4-b436-2ccdcd9aa326]:2048, allocated: {}) on agent 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-S0 from framework 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-0000
20:03:05 I0808 20:03:05.801568 23201 provider.cpp:504] Received ACKNOWLEDGE_OPERATION_STATUS event
20:03:05 I0808 20:03:05.801626 23201 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: bc55e266-fab5-4883-a85f-e654daef295a) for stream 65045eb1-ec70-41f4-b436-2ccdcd9aa326
20:03:05 I0808 20:03:05.801668 23201 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: bc55e266-fab5-4883-a85f-e654daef295a) for operation UUID 65045eb1-ec70-41f4-b436-2ccdcd9aa326 of framework '6180f181-f8df-4125-a7bd-a1b5ff9f16f1-0000' on agent 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-S0
20:03:05 I0808 20:03:05.804919 23201 status_update_manager_process.hpp:490] Cleaning up operation status update stream 65045eb1-ec70-41f4-b436-2ccdcd9aa326
20:03:06 I0808 20:03:06.751966 23204 hierarchical.cpp:1536] Performed allocation for 1 agents in 416060ns
20:03:06 I0808 20:03:06.752295 23203 master.cpp:8951] Sending offers [ 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-O2 ] to framework 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-0000 (default) at scheduler-0d99c794-89d1-49f8-8104-14c85a836e26@172.16.10.204:57833
20:03:06 I0808 20:03:06.752741 23203 sched.cpp:916] Scheduler::resourceOffers took 55193ns
20:03:06 I0808 20:03:06.752930 10423 slave.cpp:915] Agent terminating
20:03:06 I0808 20:03:06.753037 23202 master.cpp:1346] Agent 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-S0 at slave(765)@172.16.10.204:57833 (ip-172-16-10-204.ec2.internal) disconnected
20:03:06 I0808 20:03:06.753053 23202 master.cpp:3433] Disconnecting agent 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-S0 at slave(765)@172.16.10.204:57833 (ip-172-16-10-204.ec2.internal)
20:03:06 I0808 20:03:06.753069 23202 master.cpp:3452] Deactivating agent 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-S0 at slave(765)@172.16.10.204:57833 (ip-172-16-10-204.ec2.internal)
20:03:06 I0808 20:03:06.753320 23202 master.cpp:10914] Removing offer 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-O2
20:03:06 I0808 20:03:06.753371 23202 hierarchical.cpp:770] Agent 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-S0 deactivated
20:03:06 I0808 20:03:06.753579 23206 sched.cpp:942] Rescinded offer 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-O2
20:03:06 I0808 20:03:06.753607 23206 sched.cpp:953] Scheduler::offerRescinded took 10031ns
20:03:06 I0808 20:03:06.754020 23202 hierarchical.cpp:1188] Recovered cpus(allocated: storage):2; mem(allocated: storage):1024; disk(allocated: storage):1024; ports(allocated: storage):[31000-32000]; disk(allocated: storage)(reservations: [(DYNAMIC,storage)])[RAW(volume1,)]:1024; disk(allocated: storage)(reservations: [(DYNAMIC,storage)])[RAW(volume2,)]:1024; disk(allocated: storage)(reservations: [(DYNAMIC,storage)])[MOUNT(65045eb1-ec70-41f4-b436-2ccdcd9aa326,default):./csi/org.apache.mesos.csi.test/slrp_test/mounts/65045eb1-ec70-41f4-b436-2ccdcd9aa326]:2048 (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000]; disk(reservations: [(DYNAMIC,storage)])[RAW(volume1,)]:1024; disk(reservations: [(DYNAMIC,storage)])[RAW(volume2,)]:1024; disk(reservations: [(DYNAMIC,storage)])[MOUNT(65045eb1-ec70-41f4-b436-2ccdcd9aa326,default):./csi/org.apache.mesos.csi.test/slrp_test/mounts/65045eb1-ec70-41f4-b436-2ccdcd9aa326]:2048, allocated: {}) on agent 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-S0 from framework 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-0000
20:03:06 W0808 20:03:06.754457 10423 process.cpp:2745] Attempted to spawn already running process files@172.16.10.204:57833
20:03:06 I0808 20:03:06.754849 10423 containerizer.cpp:309] Using isolation { environment_secret, volume/sandbox_path, filesystem/linux, network/cni, volume/image, volume/host_path }
20:03:06 I0808 20:03:06.758759 10423 linux_launcher.cpp:145] Using /sys/fs/cgroup/freezer as the freezer hierarchy for the Linux launcher
20:03:06 I0808 20:03:06.759169 10423 provisioner.cpp:299] Using default backend 'aufs'
20:03:06 I0808 20:03:06.760213 10423 cluster.cpp:460] Creating default 'local' authorizer
20:03:06 I0808 20:03:06.760903 23207 slave.cpp:255] Mesos agent started on (766)@172.16.10.204:57833
20:03:06 I0808 20:03:06.760918 23207 slave.cpp:256] Flags at startup: --acls="" --agent_features="capabilities {
20:03:06 type: MULTI_ROLE
20:03:06 }
20:03:06 capabilities {
20:03:06 type: HIERARCHICAL_ROLE
20:03:06 }
20:03:06 capabilities {
20:03:06 type: RESERVATION_REFINEMENT
20:03:06 }
20:03:06 capabilities {
20:03:06 type: RESOURCE_PROVIDER
20:03:06 }
20:03:06 " --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/nLxkqj/lT6HL2/store/appc" --authenticate_http_executors="true" --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_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" --cgroups_limit_swap="false" --cgroups_root="mesos" --container_disk_watch_interval="15secs" --containerizers="mesos" --credential="/tmp/nLxkqj/lT6HL2/credential" --default_role="*" --disallow_sharing_agent_pid_namespace="false" --disk_profile_adaptor="org_apache_mesos_UriDiskProfileAdaptor" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/nLxkqj/lT6HL2/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_reregistration_timeout="2secs" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/nLxkqj/lT6HL2/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --http_command_executor="false" --http_credentials="/tmp/nLxkqj/lT6HL2/http_credentials" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="filesystem/linux" --jwt_secret_key="/tmp/nLxkqj/lT6HL2/jwt_secret_key" --launcher="linux" --launcher_dir="/home/ubuntu/workspace/mesos/Mesos_CI-build/FLAG/SSL/label/mesos-ec2-ubuntu-14.04/mesos/build/src" --logbufsecs="0" --logging_level="INFO" --max_completed_executors_per_framework="150" --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/nLxkqj/resource_provider_configs" --resources="cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]" --revocable_cpu_low_priority="true" --runtime_dir="/tmp/StorageLocalResourceProviderTest_ROOT_NewVolumeRecovery_upLUj8" --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/StorageLocalResourceProviderTest_ROOT_NewVolumeRecovery_pPv7Rd" --zk_session_timeout="10secs"
20:03:06 I0808 20:03:06.761119 23207 credentials.hpp:86] Loading credential for authentication from '/tmp/nLxkqj/lT6HL2/credential'
20:03:06 I0808 20:03:06.761171 23207 slave.cpp:288] Agent using credential for: test-principal
20:03:06 I0808 20:03:06.761178 23207 credentials.hpp:37] Loading credentials for authentication from '/tmp/nLxkqj/lT6HL2/http_credentials'
20:03:06 I0808 20:03:06.761240 23207 http.cpp:1049] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-executor'
20:03:06 I0808 20:03:06.761274 23207 http.cpp:1070] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-executor'
20:03:06 I0808 20:03:06.761327 23207 http.cpp:1049] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
20:03:06 I0808 20:03:06.761346 23207 http.cpp:1070] Creating default 'jwt' HTTP authenticator for realm 'mesos-agent-readonly'
20:03:06 I0808 20:03:06.761406 23207 disk_profile.cpp:84] Creating disk profile adaptor module 'org_apache_mesos_UriDiskProfileAdaptor'
20:03:06 I0808 20:03:06.761806 23202 uri_disk_profile.cpp:301] Updated disk profile mapping to 1 total profiles
20:03:06 I0808 20:03:06.762171 23207 slave.cpp:605] 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"}]
20:03:06 I0808 20:03:06.762264 23207 slave.cpp:613] Agent attributes: [ ]
20:03:06 I0808 20:03:06.762271 23207 slave.cpp:622] Agent hostname: ip-172-16-10-204.ec2.internal
20:03:06 I0808 20:03:06.762332 23205 task_status_update_manager.cpp:181] Pausing sending task status updates
20:03:06 I0808 20:03:06.762598 23203 state.cpp:66] Recovering state from '/tmp/StorageLocalResourceProviderTest_ROOT_NewVolumeRecovery_pPv7Rd/meta'
20:03:06 I0808 20:03:06.762630 23203 state.cpp:742] No committed checkpointed resources found at '/tmp/StorageLocalResourceProviderTest_ROOT_NewVolumeRecovery_pPv7Rd/meta/resources/resources.info'
20:03:06 I0808 20:03:06.763535 23206 task_status_update_manager.cpp:207] Recovering task status update manager
20:03:06 I0808 20:03:06.763589 23206 containerizer.cpp:715] Recovering containerizer
20:03:06 I0808 20:03:06.770737 23204 linux_launcher.cpp:297] Recovered container org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-slrp_test--CONTROLLER_SERVICE-NODE_SERVICE
20:03:06 I0808 20:03:06.771550 23204 manager.cpp:134] Terminating resource provider b3235abf-9b76-4380-88f2-a0c4b625ff1a
20:03:06 I0808 20:03:06.771693 23205 provisioner.cpp:499] Provisioner recovery complete
20:03:06 I0808 20:03:06.771977 23201 slave.cpp:7324] Finished recovery
20:03:06 I0808 20:03:06.772483 23202 task_status_update_manager.cpp:181] Pausing sending task status updates
20:03:06 I0808 20:03:06.772740 23201 slave.cpp:1256] New master detected at master@172.16.10.204:57833
20:03:06 I0808 20:03:06.772779 23201 slave.cpp:1321] Detecting new master
20:03:06 I0808 20:03:06.781061 23201 slave.cpp:1348] Authenticating with master master@172.16.10.204:57833
20:03:06 I0808 20:03:06.781091 23201 slave.cpp:1357] Using default CRAM-MD5 authenticatee
20:03:06 I0808 20:03:06.781332 23203 authenticatee.cpp:121] Creating new client SASL connection
20:03:06 I0808 20:03:06.786196 23203 master.cpp:9122] Authenticating slave(766)@172.16.10.204:57833
20:03:06 I0808 20:03:06.786396 23203 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(1439)@172.16.10.204:57833
20:03:06 I0808 20:03:06.786602 23203 authenticator.cpp:98] Creating new server SASL connection
20:03:06 I0808 20:03:06.787078 23203 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
20:03:06 I0808 20:03:06.787235 23203 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
20:03:06 I0808 20:03:06.787374 23203 authenticator.cpp:204] Received SASL authentication start
20:03:06 I0808 20:03:06.787518 23203 authenticator.cpp:326] Authentication requires more steps
20:03:06 I0808 20:03:06.787665 23203 authenticatee.cpp:259] Received SASL authentication step
20:03:06 I0808 20:03:06.787824 23203 authenticator.cpp:232] Received SASL authentication step
20:03:06 I0808 20:03:06.787956 23203 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'ip-172-16-10-204.ec2.internal' server FQDN: 'ip-172-16-10-204.ec2.internal' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
20:03:06 I0808 20:03:06.788046 23203 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
20:03:06 I0808 20:03:06.788141 23203 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
20:03:06 I0808 20:03:06.788259 23203 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'ip-172-16-10-204.ec2.internal' server FQDN: 'ip-172-16-10-204.ec2.internal' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
20:03:06 I0808 20:03:06.788363 23203 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
20:03:06 I0808 20:03:06.788481 23203 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
20:03:06 I0808 20:03:06.788569 23203 authenticator.cpp:318] Authentication success
20:03:06 I0808 20:03:06.788686 23203 authenticatee.cpp:299] Authentication success
20:03:06 I0808 20:03:06.788837 23203 master.cpp:9154] Successfully authenticated principal 'test-principal' at slave(766)@172.16.10.204:57833
20:03:06 I0808 20:03:06.788941 23207 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(1439)@172.16.10.204:57833
20:03:06 I0808 20:03:06.794243 23203 slave.cpp:1448] Successfully authenticated with master master@172.16.10.204:57833
20:03:06 I0808 20:03:06.794580 23203 slave.cpp:1878] Will retry registration in 9.406669ms if necessary
20:03:06 I0808 20:03:06.794687 23208 master.cpp:6536] Received re-register agent message from agent 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-S0 at slave(766)@172.16.10.204:57833 (ip-172-16-10-204.ec2.internal)
20:03:06 I0808 20:03:06.795007 23208 master.cpp:3895] Authorizing agent with principal 'test-principal'
20:03:06 I0808 20:03:06.795212 23201 master.cpp:6619] Authorized re-registration of agent 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-S0 at slave(766)@172.16.10.204:57833 (ip-172-16-10-204.ec2.internal)
20:03:06 I0808 20:03:06.795254 23201 master.cpp:6703] Agent is already marked as registered: 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-S0 at slave(766)@172.16.10.204:57833 (ip-172-16-10-204.ec2.internal)
20:03:06 I0808 20:03:06.795570 23201 master.cpp:7058] Registry updated for slave 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-S0 at slave(766)@172.16.10.204:57833(ip-172-16-10-204.ec2.internal)
20:03:06 I0808 20:03:06.795832 23201 slave.cpp:1583] Re-registered with master master@172.16.10.204:57833
20:03:06 I0808 20:03:06.795897 23201 slave.cpp:1628] Forwarding agent update {"operations":{},"resource_version_uuid":{"value":"C3qnTAQ7SXqtjxntwrkMww=="},"slave_id":{"value":"6180f181-f8df-4125-a7bd-a1b5ff9f16f1-S0"},"update_oversubscribed_resources":true}
20:03:06 I0808 20:03:06.795951 23201 task_status_update_manager.cpp:188] Resuming sending task status updates
20:03:06 I0808 20:03:06.796130 23202 hierarchical.cpp:681] Agent 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-S0 (ip-172-16-10-204.ec2.internal) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
20:03:06 I0808 20:03:06.796180 23202 hierarchical.cpp:758] Agent 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-S0 reactivated
20:03:06 I0808 20:03:06.796268 23202 hierarchical.cpp:2437] Filtered offer with cpus:2; mem:1024; disk:1024; ports:[31000-32000] on agent 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-S0 for role storage of framework 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-0000
20:03:06 I0808 20:03:06.796299 23202 hierarchical.cpp:1536] Performed allocation for 1 agents in 98797ns
20:03:06 I0808 20:03:06.796391 23202 master.cpp:7387] Received update of agent 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-S0 at slave(766)@172.16.10.204:57833 (ip-172-16-10-204.ec2.internal) with total oversubscribed resources {}
20:03:06 I0808 20:03:06.796556 23202 hierarchical.cpp:681] Agent 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-S0 (ip-172-16-10-204.ec2.internal) updated with total resources cpus:2; mem:1024; disk:1024; ports:[31000-32000]
20:03:06 I0808 20:03:06.796744 23202 container_daemon.cpp:162] Launching container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-slrp_test--CONTROLLER_SERVICE-NODE_SERVICE'
20:03:06 I0808 20:03:06.797343 23202 process.cpp:3512] Handling HTTP event for process 'slave(766)' with path: '/slave(766)/api/v1'
20:03:06 I0808 20:03:06.797519 23202 http.cpp:1189] HTTP POST for /slave(766)/api/v1 from 172.16.10.204:43051
20:03:06 I0808 20:03:06.797657 23202 http.cpp:2617] Processing LAUNCH_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-slrp_test--CONTROLLER_SERVICE-NODE_SERVICE'
20:03:06 I0808 20:03:06.799037 27872 test_csi_plugin.cpp:273] GetSupportedVersionsRequest '{}'
20:03:06 I0808 20:03:06.799849 27872 test_csi_plugin.cpp:286] GetPluginInfoRequest '{"version":{"minor":1}}'
20:03:06 I0808 20:03:06.800175 23207 container_daemon.cpp:205] Waiting for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-slrp_test--CONTROLLER_SERVICE-NODE_SERVICE'
20:03:06 I0808 20:03:06.800937 23204 process.cpp:3512] Handling HTTP event for process 'slave(766)' with path: '/slave(766)/api/v1'
20:03:06 I0808 20:03:06.801170 23207 http.cpp:1189] HTTP POST for /slave(766)/api/v1 from 172.16.10.204:43052
20:03:06 I0808 20:03:06.801249 23207 http.cpp:2827] Processing WAIT_CONTAINER call for container 'org-apache-mesos-rp-local-storage-test--org-apache-mesos-csi-test-slrp_test--CONTROLLER_SERVICE-NODE_SERVICE'
20:03:06 I0808 20:03:06.801726 23208 provider.cpp:1919] Controller plugin loaded: {"name":"org.apache.mesos.csi.test","vendorVersion":"1.5.4"}
20:03:06 I0808 20:03:06.802009 27872 test_csi_plugin.cpp:616] ControllerProbeRequest '{"version":{"minor":1}}'
20:03:06 I0808 20:03:06.802513 27872 test_csi_plugin.cpp:632] ControllerGetCapabilitiesRequest '{"version":{"minor":1}}'
20:03:06 I0808 20:03:06.803017 27872 test_csi_plugin.cpp:286] GetPluginInfoRequest '{"version":{"minor":1}}'
20:03:06 I0808 20:03:06.803380 23201 provider.cpp:1977] Node plugin loaded: {"name":"org.apache.mesos.csi.test","vendorVersion":"1.5.4"}
20:03:06 I0808 20:03:06.803668 27872 test_csi_plugin.cpp:806] NodeProbeRequest '{"version":{"minor":1}}'
20:03:06 I0808 20:03:06.804136 27872 test_csi_plugin.cpp:788] GetNodeIDRequest '{"version":{"minor":1}}'
20:03:06 I0808 20:03:06.804978 23202 provider.cpp:621] Finished recovery for resource provider with type 'org.apache.mesos.rp.local.storage' and name 'test
20:03:06 I0808 20:03:06.805292 23208 status_update_manager_process.hpp:379] Pausing operation status update manager
20:03:06 I0808 20:03:06.805517 23204 provider.cpp:1239] Updating metadata for profiles: { default }
20:03:06 I0808 20:03:06.805523 23205 http_connection.hpp:221] New endpoint detected at http://172.16.10.204:57833/slave(766)/api/v1/resource_provider
20:03:06 I0808 20:03:06.806005 23204 http_connection.hpp:277] Connected with the remote endpoint at http://172.16.10.204:57833/slave(766)/api/v1/resource_provider
20:03:06 I0808 20:03:06.806113 23203 provider.cpp:482] Connected to resource provider manager
20:03:06 I0808 20:03:06.806321 23203 http_connection.hpp:129] Sending 1 call to http://172.16.10.204:57833/slave(766)/api/v1/resource_provider
20:03:06 I0808 20:03:06.806715 23204 process.cpp:3512] Handling HTTP event for process 'slave(766)' with path: '/slave(766)/api/v1/resource_provider'
20:03:06 I0808 20:03:06.806882 23204 http.cpp:1189] HTTP POST for /slave(766)/api/v1/resource_provider from 172.16.10.204:43054
20:03:06 I0808 20:03:06.807055 23204 manager.cpp:570] Subscribing resource provider {"default_reservations":[{"role":"storage","type":"DYNAMIC"}],"id":{"value":"b3235abf-9b76-4380-88f2-a0c4b625ff1a"},"name":"test","storage":{"plugin":{"containers":[{"command":{"arguments":["\/home\/ubuntu\/workspace\/mesos\/Mesos_CI-build\/FLAG\/SSL\/label\/mesos-ec2-ubuntu-14.04\/mesos\/build\/src\/test-csi-plugin","--available_capacity=2GB","--volumes=volume1:1GB;volume2:1GB","--work_dir=\/tmp\/nLxkqj\/test"],"shell":false,"value":"\/home\/ubuntu\/workspace\/mesos\/Mesos_CI-build\/FLAG\/SSL\/label\/mesos-ec2-ubuntu-14.04\/mesos\/build\/src\/test-csi-plugin"},"services":["CONTROLLER_SERVICE","NODE_SERVICE"]}],"name":"slrp_test","type":"org.apache.mesos.csi.test"}},"type":"org.apache.mesos.rp.local.storage"}
20:03:06 I0808 20:03:06.807765 23204 provider.cpp:504] Received SUBSCRIBED event
20:03:06 I0808 20:03:06.807788 23204 provider.cpp:1332] Subscribed with ID b3235abf-9b76-4380-88f2-a0c4b625ff1a
20:03:06 I0808 20:03:06.808023 23208 status_update_manager_process.hpp:314] Recovering operation status update manager
20:03:06 I0808 20:03:06.808228 23201 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: bc55e266-fab5-4883-a85f-e654daef295a) for operation UUID 65045eb1-ec70-41f4-b436-2ccdcd9aa326 of framework '6180f181-f8df-4125-a7bd-a1b5ff9f16f1-0000' on agent 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-S0
20:03:06 I0808 20:03:06.808259 23201 status_update_manager_process.hpp:414] Creating operation status update stream 65045eb1-ec70-41f4-b436-2ccdcd9aa326 checkpoint=true
20:03:06 I0808 20:03:06.808377 23201 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: bc55e266-fab5-4883-a85f-e654daef295a) for operation UUID 65045eb1-ec70-41f4-b436-2ccdcd9aa326 of framework '6180f181-f8df-4125-a7bd-a1b5ff9f16f1-0000' on agent 6180f181-f8df-4125-a7bd-a1b5ff9f16f1-S0
20:03:06 F0808 20:03:06.808439 23208 provider.cpp:2530] Check failed: profileInfos.contains(profile)
20:03:06 I0808 20:03:06.808537 27872 test_csi_plugin.cpp:549] ListVolumesRequest '{"version":{"minor":1}}'
20:03:06 *** Check failure stack trace: ***
20:03:06 @ 0x7f4ddcd16a4d google::LogMessage::Fail()
20:03:06 @ 0x7f4ddcd1887d google::LogMessage::SendToLog()
20:03:06 @ 0x7f4ddcd1663c google::LogMessage::Flush()
20:03:06 @ 0x7f4ddcd19179 google::LogMessageFatal::~LogMessageFatal()
20:03:06 @ 0x7f4ddc55d527 _ZZN5mesos8internal35StorageLocalResourceProviderProcess13getCapacitiesEvENKUlNS_3csi6ClientEE_clES3_
20:03:06 @ 0x7f4ddc55d85b _ZNO6lambda12CallableOnceIFN7process6FutureIN5mesos9ResourcesEEEvEE10CallableFnINS_8internal7PartialIZNS3_8internal35StorageLocalResourceProviderProcess13getCapacitiesEvEUlNS3_3csi6ClientEE_ISE_EEEEclEv
20:03:06 @ 0x7f4ddc58c377 _ZNO6lambda12CallableOnceIFvPN7process11ProcessBaseEEE10CallableFnINS_8internal7PartialIZNS1_8internal8DispatchINS1_6FutureIN5mesos9ResourcesEEEEclINS0_IFSE_vEEEEESE_RKNS1_4UPIDEOT_EUlSt10unique_ptrINS1_7PromiseISD_EESt14default_deleteISQ_EEOSI_S3_E_IST_SI_St12_PlaceholderILi1EEEEEEclEOS3_
20:03:06 @ 0x7f4ddcc67551 process::ProcessBase::consume()
20:03:06 @ 0x7f4ddcc7e16c process::ProcessManager::resume()
20:03:06 @ 0x7f4ddcc839a6 _ZNSt6thread5_ImplISt12_Bind_simpleIFZN7process14ProcessManager12init_threadsEvEUlvE_vEEE6_M_runEv
20:03:06 @ 0x7f4dd96f7a60 (unknown)
20:03:06 @ 0x7f4dd8f14184 start_thread
20:03:06 @ 0x7f4dd8c4103d (unknown)