Greg Mann created MESOS-9931:
--------------------------------
Summary: StorageLocalResourceProviderTest.ROOT_NewVolumeRecovery
is flaky
Key: MESOS-9931
URL: https://issues.apache.org/jira/browse/MESOS-9931
Project: Mesos
Issue Type: Bug
Components: resource provider, test
Environment: Ubuntu 14.04, SSL-enabled
Reporter: Greg Mann
{noformat}
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 [email protected]: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
[email protected]: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
[email protected]: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 [email protected]: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
[email protected]: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 [email protected]: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
[email protected]:57833
20:03:04 I0808 20:03:04.785274 23201 sched.cpp:401] Authenticating with master
[email protected]: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
[email protected]: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
[email protected]: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 [email protected]:57833
20:03:04 I0808 20:03:04.787297 23201 sched.cpp:819] Sending SUBSCRIBE call to
[email protected]: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
[email protected]: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
[email protected]: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
[email protected]: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
[email protected]: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
[email protected]: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
[email protected]: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
[email protected]: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
[email protected]: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 [email protected]: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
[email protected]: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
[email protected]: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 [email protected]: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
[email protected]: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)
{noformat}
--
This message was sent by Atlassian JIRA
(v7.6.14#76016)
