[MESOS-6086] PersistentVolumeEndpointsTest.EndpointCreateThenOfferRemove is flaky. - ASF JIRA

XML

Word

Printable

JSON

Details

Type: Bug
Status: Resolved
Priority: Major
Resolution: Fixed
Affects Version/s: None
Fix Version/s: 1.5.0
Component/s: None
Labels:
- flaky-test
- tech-debt

Description

Observed this when running on a CentOS 7 machine.

Good Run:

[ RUN      ] PersistentVolumeEndpointsTest.EndpointCreateThenOfferRemove
I0824 14:24:15.585021 19320 cluster.cpp:157] Creating default 'local' authorizer
I0824 14:24:15.590765 19320 replica.cpp:776] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0824 14:24:15.593570 19370 recover.cpp:451] Starting replica recovery
I0824 14:24:15.594476 19370 recover.cpp:477] Replica is in EMPTY status
I0824 14:24:15.597961 19352 replica.cpp:673] Replica in EMPTY status received a broadcasted recover request from __req_res__(1)@10.0.49.2:38017
I0824 14:24:15.599189 19351 recover.cpp:197] Received a recover response from a replica in EMPTY status
I0824 14:24:15.600607 19364 recover.cpp:568] Updating replica status to STARTING
I0824 14:24:15.601824 19336 replica.cpp:320] Persisted replica status to STARTING
I0824 14:24:15.602224 19351 recover.cpp:477] Replica is in STARTING status
I0824 14:24:15.603526 19373 replica.cpp:673] Replica in STARTING status received a broadcasted recover request from __req_res__(2)@10.0.49.2:38017
I0824 14:24:15.603824 19375 recover.cpp:197] Received a recover response from a replica in STARTING status
I0824 14:24:15.604395 19380 recover.cpp:568] Updating replica status to VOTING
I0824 14:24:15.605470 19334 replica.cpp:320] Persisted replica status to VOTING
I0824 14:24:15.605612 19375 recover.cpp:582] Successfully joined the Paxos group
I0824 14:24:15.607223 19367 master.cpp:379] Master dff6317e-46bf-4bf1-8a56-3fcdfb3df5e5 (core-dev) started on 10.0.49.2:38017
I0824 14:24:15.607286 19367 master.cpp:381] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="50ms" --allocator="HierarchicalDRF" --authenticate_agents="true" --authenticate_frameworks="true" --authenticate_http_frameworks="true" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/DZsoQK/credentials" --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" --quiet="false" --recovery_agent_removal_limit="100%" --registry="replicated_log" --registry_fetch_timeout="1mins" --registry_store_timeout="100secs" --registry_strict="true" --roles="role1" --root_submissions="true" --user_sorter="drf" --version="false" --webui_dir="/usr/local/share/mesos/webui" --work_dir="/tmp/DZsoQK/master" --zk_session_timeout="10secs"
I0824 14:24:15.609459 19367 master.cpp:431] Master only allowing authenticated frameworks to register
I0824 14:24:15.609486 19367 master.cpp:445] Master only allowing authenticated agents to register
I0824 14:24:15.609566 19367 master.cpp:458] Master only allowing authenticated HTTP frameworks to register
I0824 14:24:15.609591 19367 credentials.hpp:37] Loading credentials for authentication from '/tmp/DZsoQK/credentials'
I0824 14:24:15.610335 19367 master.cpp:503] Using default 'crammd5' authenticator
I0824 14:24:15.610589 19367 authenticator.cpp:519] Initializing server SASL
I0824 14:24:15.611868 19367 http.cpp:883] Using default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
I0824 14:24:15.612370 19367 http.cpp:883] Using default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
I0824 14:24:15.612555 19367 http.cpp:883] Using default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
I0824 14:24:15.612905 19367 master.cpp:583] Authorization enabled
W0824 14:24:15.612949 19367 master.cpp:646] The '--roles' flag is deprecated. This flag will be removed in the future. See the Mesos 0.27 upgrade notes for more information
I0824 14:24:15.624155 19356 master.cpp:1855] Elected as the leading master!
I0824 14:24:15.624238 19356 master.cpp:1551] Recovering from registrar
I0824 14:24:15.626255 19336 log.cpp:553] Attempting to start the writer
I0824 14:24:15.628974 19335 replica.cpp:493] Replica received implicit promise request from __req_res__(3)@10.0.49.2:38017 with proposal 1
I0824 14:24:15.629642 19335 replica.cpp:342] Persisted promised to 1
I0824 14:24:15.631093 19351 coordinator.cpp:238] Coordinator attempting to fill missing positions
I0824 14:24:15.633769 19372 replica.cpp:388] Replica received explicit promise request from __req_res__(4)@10.0.49.2:38017 for position 0 with proposal 2
I0824 14:24:15.637004 19340 replica.cpp:537] Replica received write request for position 0 from __req_res__(5)@10.0.49.2:38017
I0824 14:24:15.639485 19379 replica.cpp:691] Replica received learned notice for position 0 from @0.0.0.0:0
I0824 14:24:15.641111 19376 log.cpp:569] Writer started with ending position 0
I0824 14:24:15.648370 19347 registrar.cpp:365] Successfully fetched the registry (0B) in 23.694848ms
I0824 14:24:15.648638 19347 registrar.cpp:464] Applied 1 operations in 44445ns; attempting to update the registry
I0824 14:24:15.653192 19376 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
I0824 14:24:15.654696 19374 replica.cpp:537] Replica received write request for position 1 from __req_res__(6)@10.0.49.2:38017
I0824 14:24:15.656363 19340 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0
I0824 14:24:15.658630 19369 registrar.cpp:509] Successfully updated the registry in 9.836032ms
I0824 14:24:15.658879 19369 registrar.cpp:395] Successfully recovered registrar
I0824 14:24:15.659145 19356 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
I0824 14:24:15.659734 19348 master.cpp:1659] Recovered 0 agents from the registry (119B); allowing 10mins for agents to re-register
I0824 14:24:15.660775 19377 replica.cpp:537] Replica received write request for position 2 from __req_res__(7)@10.0.49.2:38017
I0824 14:24:15.662303 19376 replica.cpp:691] Replica received learned notice for position 2 from @0.0.0.0:0
I0824 14:24:15.677554 19320 containerizer.cpp:216] Using isolation: posix/cpu,posix/mem,filesystem/posix,network/cni
W0824 14:24:15.679026 19320 backend.cpp:75] Failed to create 'overlay' backend: OverlayBackend requires root privileges, but is running as user bmahler
W0824 14:24:15.679424 19320 backend.cpp:75] Failed to create 'bind' backend: BindBackend requires root privileges
I0824 14:24:15.682468 19320 cluster.cpp:436] Creating default 'local' authorizer
I0824 14:24:15.684484 19372 slave.cpp:199] Mesos agent started on (1)@10.0.49.2:38017
I0824 14:24:15.684520 19372 slave.cpp:200] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/mesos/store/appc" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authenticatee="crammd5" --authentication_backoff_factor="1secs" --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/PersistentVolumeEndpointsTest_EndpointCreateThenOfferRemove_xPnrXA/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/PersistentVolumeEndpointsTest_EndpointCreateThenOfferRemove_xPnrXA/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_command_executor="false" --http_credentials="/tmp/PersistentVolumeEndpointsTest_EndpointCreateThenOfferRemove_xPnrXA/http_credentials" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/home/bmahler/git/mesos/build/src" --logbufsecs="0" --logging_level="INFO" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="disk(*):1024" --revocable_cpu_low_priority="true" --runtime_dir="/tmp/PersistentVolumeEndpointsTest_EndpointCreateThenOfferRemove_xPnrXA" --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/PersistentVolumeEndpointsTest_EndpointCreateThenOfferRemove_D74TTF"
I0824 14:24:15.685137 19372 credentials.hpp:86] Loading credential for authentication from '/tmp/PersistentVolumeEndpointsTest_EndpointCreateThenOfferRemove_xPnrXA/credential'
I0824 14:24:15.685360 19372 slave.cpp:337] Agent using credential for: test-principal
I0824 14:24:15.685410 19372 credentials.hpp:37] Loading credentials for authentication from '/tmp/PersistentVolumeEndpointsTest_EndpointCreateThenOfferRemove_xPnrXA/http_credentials'
I0824 14:24:15.685664 19372 http.cpp:883] Using default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
I0824 14:24:15.685804 19372 http.cpp:883] Using default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite'
I0824 14:24:15.692296 19372 slave.cpp:520] Agent resources: disk(*):1024; cpus(*):48; mem(*):63128; ports(*):[31000-32000]
I0824 14:24:15.692464 19372 slave.cpp:528] Agent attributes: [  ]
I0824 14:24:15.692500 19372 slave.cpp:533] Agent hostname: core-dev
I0824 14:24:15.696684 19367 state.cpp:57] Recovering state from '/tmp/PersistentVolumeEndpointsTest_EndpointCreateThenOfferRemove_D74TTF/meta'
I0824 14:24:15.697312 19358 status_update_manager.cpp:203] Recovering status update manager
I0824 14:24:15.697715 19352 containerizer.cpp:561] Recovering containerizer
I0824 14:24:15.701367 19381 provisioner.cpp:254] Provisioner recovery complete
I0824 14:24:15.701902 19367 slave.cpp:4873] Finished recovery
I0824 14:24:15.703158 19363 status_update_manager.cpp:177] Pausing sending status updates
I0824 14:24:15.703198 19367 slave.cpp:896] New master detected at master@10.0.49.2:38017
I0824 14:24:15.703301 19367 slave.cpp:955] Authenticating with master master@10.0.49.2:38017
I0824 14:24:15.703395 19367 slave.cpp:966] Using default CRAM-MD5 authenticatee
I0824 14:24:15.703701 19367 slave.cpp:928] Detecting new master
I0824 14:24:15.703907 19379 authenticatee.cpp:97] Initializing client SASL
I0824 14:24:15.704079 19379 authenticatee.cpp:121] Creating new client SASL connection
I0824 14:24:15.731495 19369 master.cpp:6129] Authenticating slave(1)@10.0.49.2:38017
I0824 14:24:15.732084 19363 authenticator.cpp:98] Creating new server SASL connection
I0824 14:24:15.789010 19342 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0824 14:24:15.789079 19342 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0824 14:24:15.789310 19342 authenticator.cpp:204] Received SASL authentication start
I0824 14:24:15.789444 19342 authenticator.cpp:326] Authentication requires more steps
I0824 14:24:15.789722 19345 authenticatee.cpp:259] Received SASL authentication step
I0824 14:24:15.789907 19366 authenticator.cpp:232] Received SASL authentication step
I0824 14:24:15.790118 19366 authenticator.cpp:318] Authentication success
I0824 14:24:15.790267 19348 authenticatee.cpp:299] Authentication success
I0824 14:24:15.790457 19354 master.cpp:6159] Successfully authenticated principal 'test-principal' at slave(1)@10.0.49.2:38017
I0824 14:24:15.790727 19369 slave.cpp:1050] Successfully authenticated with master master@10.0.49.2:38017
I0824 14:24:15.791779 19341 master.cpp:4781] Registering agent at slave(1)@10.0.49.2:38017 (core-dev) with id dff6317e-46bf-4bf1-8a56-3fcdfb3df5e5-S0
I0824 14:24:15.792768 19348 registrar.cpp:464] Applied 1 operations in 75274ns; attempting to update the registry
I0824 14:24:15.796705 19337 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3
I0824 14:24:15.797868 19372 replica.cpp:537] Replica received write request for position 3 from __req_res__(8)@10.0.49.2:38017
I0824 14:24:15.799914 19358 replica.cpp:691] Replica received learned notice for position 3 from @0.0.0.0:0
I0824 14:24:15.801987 19359 registrar.cpp:509] Successfully updated the registry in 9.140992ms
I0824 14:24:15.802391 19374 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 4
I0824 14:24:15.803843 19379 replica.cpp:537] Replica received write request for position 4 from __req_res__(9)@10.0.49.2:38017
I0824 14:24:15.804782 19336 hierarchical.cpp:478] Added agent dff6317e-46bf-4bf1-8a56-3fcdfb3df5e5-S0 (core-dev) with disk(*):1024; cpus(*):48; mem(*):63128; ports(*):[31000-32000] (allocated: )
I0824 14:24:15.805063 19360 master.cpp:4851] Registered agent dff6317e-46bf-4bf1-8a56-3fcdfb3df5e5-S0 at slave(1)@10.0.49.2:38017 (core-dev) with disk(*):1024; cpus(*):48; mem(*):63128; ports(*):[31000-32000]
I0824 14:24:15.805197 19348 slave.cpp:1096] Registered with master master@10.0.49.2:38017; given agent ID dff6317e-46bf-4bf1-8a56-3fcdfb3df5e5-S0
I0824 14:24:15.805397 19372 status_update_manager.cpp:184] Resuming sending status updates
I0824 14:24:15.805424 19360 master.cpp:4751] Agent dff6317e-46bf-4bf1-8a56-3fcdfb3df5e5-S0 at slave(1)@10.0.49.2:38017 (core-dev) already registered, resending acknowledgement
I0824 14:24:15.805593 19344 replica.cpp:691] Replica received learned notice for position 4 from @0.0.0.0:0
I0824 14:24:15.806385 19348 slave.cpp:1156] Forwarding total oversubscribed resources
W0824 14:24:15.806596 19348 slave.cpp:1142] Already registered with master master@10.0.49.2:38017
I0824 14:24:15.806648 19348 slave.cpp:1156] Forwarding total oversubscribed resources
I0824 14:24:15.806682 19344 master.cpp:5235] Received update of agent dff6317e-46bf-4bf1-8a56-3fcdfb3df5e5-S0 at slave(1)@10.0.49.2:38017 (core-dev) with total oversubscribed resources
I0824 14:24:15.807118 19344 master.cpp:5235] Received update of agent dff6317e-46bf-4bf1-8a56-3fcdfb3df5e5-S0 at slave(1)@10.0.49.2:38017 (core-dev) with total oversubscribed resources
I0824 14:24:15.807147 19373 hierarchical.cpp:542] Agent dff6317e-46bf-4bf1-8a56-3fcdfb3df5e5-S0 (core-dev) updated with oversubscribed resources  (total: disk(*):1024; cpus(*):48; mem(*):63128; ports(*):[31000-32000], allocated: )
I0824 14:24:15.807507 19373 hierarchical.cpp:542] Agent dff6317e-46bf-4bf1-8a56-3fcdfb3df5e5-S0 (core-dev) updated with oversubscribed resources  (total: disk(*):1024; cpus(*):48; mem(*):63128; ports(*):[31000-32000], allocated: )
I0824 14:24:15.810902 19379 http.cpp:381] HTTP POST for /master/reserve from 10.0.49.2:56754
I0824 14:24:15.811697 19379 master.cpp:3023] Authorizing principal 'test-principal' to reserve resources 'disk(role1, test-principal):512'
I0824 14:24:15.814442 19346 master.cpp:7215] Sending checkpointed resources disk(role1, test-principal):512 to agent dff6317e-46bf-4bf1-8a56-3fcdfb3df5e5-S0 at slave(1)@10.0.49.2:38017 (core-dev)
I0824 14:24:15.815196 19352 slave.cpp:2491] Updated checkpointed resources from  to disk(role1, test-principal):512
I0824 14:24:15.819640 19338 http.cpp:381] HTTP POST for /master/create-volumes from 10.0.49.2:56755
I0824 14:24:15.820581 19338 master.cpp:3132] Authorizing principal 'test-principal' to create volumes
I0824 14:24:15.822346 19335 master.cpp:7215] Sending checkpointed resources disk(role1, test-principal):511; disk(role1, test-principal)[id1:volume_path]:1 to agent dff6317e-46bf-4bf1-8a56-3fcdfb3df5e5-S0 at slave(1)@10.0.49.2:38017 (core-dev)
I0824 14:24:15.823479 19346 slave.cpp:2491] Updated checkpointed resources from disk(role1, test-principal):512 to disk(role1, test-principal):511; disk(role1, test-principal)[id1:volume_path]:1
I0824 14:24:15.855994 19320 sched.cpp:226] Version: 1.1.0
I0824 14:24:15.857439 19377 sched.cpp:330] New master detected at master@10.0.49.2:38017
I0824 14:24:15.857543 19377 sched.cpp:396] Authenticating with master master@10.0.49.2:38017
I0824 14:24:15.857620 19377 sched.cpp:403] Using default CRAM-MD5 authenticatee
I0824 14:24:15.857844 19355 authenticatee.cpp:121] Creating new client SASL connection
I0824 14:24:15.882874 19373 master.cpp:6129] Authenticating scheduler-7079a306-33cf-4899-91e7-9d0a1d9db3cd@10.0.49.2:38017
I0824 14:24:15.883219 19334 authenticator.cpp:98] Creating new server SASL connection
I0824 14:24:15.910420 19343 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0824 14:24:15.910475 19343 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0824 14:24:15.910646 19344 authenticator.cpp:204] Received SASL authentication start
I0824 14:24:15.910732 19344 authenticator.cpp:326] Authentication requires more steps
I0824 14:24:15.911080 19363 authenticatee.cpp:259] Received SASL authentication step
I0824 14:24:15.911298 19379 authenticator.cpp:232] Received SASL authentication step
I0824 14:24:15.911437 19379 authenticator.cpp:318] Authentication success
I0824 14:24:15.911581 19368 authenticatee.cpp:299] Authentication success
I0824 14:24:15.911617 19343 master.cpp:6159] Successfully authenticated principal 'test-principal' at scheduler-7079a306-33cf-4899-91e7-9d0a1d9db3cd@10.0.49.2:38017
I0824 14:24:15.912122 19364 sched.cpp:502] Successfully authenticated with master master@10.0.49.2:38017
I0824 14:24:15.912609 19360 master.cpp:2429] Received SUBSCRIBE call for framework 'default' at scheduler-7079a306-33cf-4899-91e7-9d0a1d9db3cd@10.0.49.2:38017
I0824 14:24:15.912806 19360 master.cpp:1891] Authorizing framework principal 'test-principal' to receive offers for role 'role1'
I0824 14:24:15.913406 19349 master.cpp:2505] Subscribing framework default with checkpointing disabled and capabilities [  ]
I0824 14:24:15.914554 19363 sched.cpp:743] Framework registered with dff6317e-46bf-4bf1-8a56-3fcdfb3df5e5-0000
I0824 14:24:15.914861 19342 hierarchical.cpp:271] Added framework dff6317e-46bf-4bf1-8a56-3fcdfb3df5e5-0000
I0824 14:24:15.916927 19343 master.cpp:5958] Sending 1 offers to framework dff6317e-46bf-4bf1-8a56-3fcdfb3df5e5-0000 (default) at scheduler-7079a306-33cf-4899-91e7-9d0a1d9db3cd@10.0.49.2:38017
I0824 14:24:15.920830 19369 master.cpp:3360] Processing ACCEPT call for offers: [ dff6317e-46bf-4bf1-8a56-3fcdfb3df5e5-O0 ] on agent dff6317e-46bf-4bf1-8a56-3fcdfb3df5e5-S0 at slave(1)@10.0.49.2:38017 (core-dev) for framework dff6317e-46bf-4bf1-8a56-3fcdfb3df5e5-0000 (default) at scheduler-7079a306-33cf-4899-91e7-9d0a1d9db3cd@10.0.49.2:38017
I0824 14:24:15.921041 19369 master.cpp:3183] Authorizing principal 'test-principal' to destroy volumes 'disk(role1, test-principal)[id1:volume_path]:1'
I0824 14:24:15.922654 19369 master.cpp:3771] Applying DESTROY operation for volumes  from framework dff6317e-46bf-4bf1-8a56-3fcdfb3df5e5-0000 (default) at scheduler-7079a306-33cf-4899-91e7-9d0a1d9db3cd@10.0.49.2:38017 to agent dff6317e-46bf-4bf1-8a56-3fcdfb3df5e5-S0 at slave(1)@10.0.49.2:38017 (core-dev)
I0824 14:24:15.923033 19369 master.cpp:7215] Sending checkpointed resources disk(role1, test-principal):512 to agent dff6317e-46bf-4bf1-8a56-3fcdfb3df5e5-S0 at slave(1)@10.0.49.2:38017 (core-dev)
I0824 14:24:15.923863 19371 slave.cpp:2556] Deleting persistent volume 'id1' at '/tmp/PersistentVolumeEndpointsTest_EndpointCreateThenOfferRemove_D74TTF/volumes/roles/role1/id1'
I0824 14:24:15.924170 19371 slave.cpp:2491] Updated checkpointed resources from disk(role1, test-principal):511; disk(role1, test-principal)[id1:volume_path]:1 to disk(role1, test-principal):512
I0824 14:24:15.924695 19361 hierarchical.cpp:683] Updated allocation of framework dff6317e-46bf-4bf1-8a56-3fcdfb3df5e5-0000 on agent dff6317e-46bf-4bf1-8a56-3fcdfb3df5e5-S0 from disk(role1, test-principal):511; disk(role1, test-principal)[id1:volume_path]:1; disk(*):512; cpus(*):48; mem(*):63128; ports(*):[31000-32000] to disk(role1, test-principal):512; ports(*):[31000-32000]; disk(*):512; cpus(*):48; mem(*):63128
I0824 14:24:15.967829 19338 master.cpp:5958] Sending 1 offers to framework dff6317e-46bf-4bf1-8a56-3fcdfb3df5e5-0000 (default) at scheduler-7079a306-33cf-4899-91e7-9d0a1d9db3cd@10.0.49.2:38017
I0824 14:24:15.970705 19346 master.cpp:3360] Processing ACCEPT call for offers: [ dff6317e-46bf-4bf1-8a56-3fcdfb3df5e5-O1 ] on agent dff6317e-46bf-4bf1-8a56-3fcdfb3df5e5-S0 at slave(1)@10.0.49.2:38017 (core-dev) for framework dff6317e-46bf-4bf1-8a56-3fcdfb3df5e5-0000 (default) at scheduler-7079a306-33cf-4899-91e7-9d0a1d9db3cd@10.0.49.2:38017
I0824 14:24:15.970857 19346 master.cpp:3080] Authorizing principal 'test-principal' to unreserve resources 'disk(role1, test-principal):512'
I0824 14:24:15.971807 19349 master.cpp:3667] Applying UNRESERVE operation for resources disk(role1, test-principal):512 from framework dff6317e-46bf-4bf1-8a56-3fcdfb3df5e5-0000 (default) at scheduler-7079a306-33cf-4899-91e7-9d0a1d9db3cd@10.0.49.2:38017 to agent dff6317e-46bf-4bf1-8a56-3fcdfb3df5e5-S0 at slave(1)@10.0.49.2:38017 (core-dev)
I0824 14:24:15.972204 19349 master.cpp:7215] Sending checkpointed resources  to agent dff6317e-46bf-4bf1-8a56-3fcdfb3df5e5-S0 at slave(1)@10.0.49.2:38017 (core-dev)
I0824 14:24:15.972703 19358 slave.cpp:2491] Updated checkpointed resources from disk(role1, test-principal):512 to
I0824 14:24:15.973289 19367 hierarchical.cpp:683] Updated allocation of framework dff6317e-46bf-4bf1-8a56-3fcdfb3df5e5-0000 on agent dff6317e-46bf-4bf1-8a56-3fcdfb3df5e5-S0 from disk(role1, test-principal):512; disk(*):512; cpus(*):48; mem(*):63128; ports(*):[31000-32000] to ports(*):[31000-32000]; disk(*):1024; cpus(*):48; mem(*):63128
I0824 14:24:16.019147 19381 master.cpp:5958] Sending 1 offers to framework dff6317e-46bf-4bf1-8a56-3fcdfb3df5e5-0000 (default) at scheduler-7079a306-33cf-4899-91e7-9d0a1d9db3cd@10.0.49.2:38017
I0824 14:24:16.020548 19320 sched.cpp:1987] Asked to stop the driver
I0824 14:24:16.020828 19348 sched.cpp:1187] Stopping framework dff6317e-46bf-4bf1-8a56-3fcdfb3df5e5-0000
I0824 14:24:16.021116 19356 master.cpp:6534] Processing TEARDOWN call for framework dff6317e-46bf-4bf1-8a56-3fcdfb3df5e5-0000 (default) at scheduler-7079a306-33cf-4899-91e7-9d0a1d9db3cd@10.0.49.2:38017
I0824 14:24:16.021183 19356 master.cpp:6546] Removing framework dff6317e-46bf-4bf1-8a56-3fcdfb3df5e5-0000 (default) at scheduler-7079a306-33cf-4899-91e7-9d0a1d9db3cd@10.0.49.2:38017
I0824 14:24:16.021869 19379 hierarchical.cpp:382] Deactivated framework dff6317e-46bf-4bf1-8a56-3fcdfb3df5e5-0000
I0824 14:24:16.021997 19363 slave.cpp:2219] Asked to shut down framework dff6317e-46bf-4bf1-8a56-3fcdfb3df5e5-0000 by master@10.0.49.2:38017
W0824 14:24:16.022130 19363 slave.cpp:2234] Cannot shut down unknown framework dff6317e-46bf-4bf1-8a56-3fcdfb3df5e5-0000
I0824 14:24:16.023952 19360 hierarchical.cpp:333] Removed framework dff6317e-46bf-4bf1-8a56-3fcdfb3df5e5-0000
I0824 14:24:16.024428 19378 slave.cpp:768] Agent terminating
I0824 14:24:16.024955 19365 master.cpp:1249] Agent dff6317e-46bf-4bf1-8a56-3fcdfb3df5e5-S0 at slave(1)@10.0.49.2:38017 (core-dev) disconnected
I0824 14:24:16.025012 19365 master.cpp:2789] Disconnecting agent dff6317e-46bf-4bf1-8a56-3fcdfb3df5e5-S0 at slave(1)@10.0.49.2:38017 (core-dev)
I0824 14:24:16.025180 19365 master.cpp:2808] Deactivating agent dff6317e-46bf-4bf1-8a56-3fcdfb3df5e5-S0 at slave(1)@10.0.49.2:38017 (core-dev)
I0824 14:24:16.025640 19353 hierarchical.cpp:571] Agent dff6317e-46bf-4bf1-8a56-3fcdfb3df5e5-S0 deactivated
I0824 14:24:16.030956 19378 master.cpp:1096] Master terminating
I0824 14:24:16.031435 19368 hierarchical.cpp:510] Removed agent dff6317e-46bf-4bf1-8a56-3fcdfb3df5e5-S0
[       OK ] PersistentVolumeEndpointsTest.EndpointCreateThenOfferRemove (469 ms)

Bad Run:

[ RUN      ] PersistentVolumeEndpointsTest.EndpointCreateThenOfferRemove
I0824 13:33:12.085065 10910 cluster.cpp:157] Creating default 'local' authorizer
I0824 13:33:12.089478 10910 replica.cpp:776] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I0824 13:33:12.090317 10969 recover.cpp:451] Starting replica recovery
I0824 13:33:12.090553 10969 recover.cpp:477] Replica is in EMPTY status
I0824 13:33:12.091928 10950 replica.cpp:673] Replica in EMPTY status received a broadcasted recover request from __req_res__(3577)@10.0.49.2:35633
I0824 13:33:12.092355 10962 recover.cpp:197] Received a recover response from a replica in EMPTY status
I0824 13:33:12.093035 10924 recover.cpp:568] Updating replica status to STARTING
I0824 13:33:12.094388 10928 replica.cpp:320] Persisted replica status to STARTING
I0824 13:33:12.094609 10946 recover.cpp:477] Replica is in STARTING status
I0824 13:33:12.095708 10944 replica.cpp:673] Replica in STARTING status received a broadcasted recover request from __req_res__(3578)@10.0.49.2:35633
I0824 13:33:12.096287 10956 recover.cpp:197] Received a recover response from a replica in STARTING status
I0824 13:33:12.096701 10936 recover.cpp:568] Updating replica status to VOTING
I0824 13:33:12.097501 10933 replica.cpp:320] Persisted replica status to VOTING
I0824 13:33:12.097638 10957 recover.cpp:582] Successfully joined the Paxos group
I0824 13:33:12.099105 10960 master.cpp:379] Master 274756b2-3ffa-438d-b366-a825de787eb4 (core-dev) started on 10.0.49.2:35633
I0824 13:33:12.099164 10960 master.cpp:381] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="50ms" --allocator="HierarchicalDRF" --authenticate_agents="true" --authenticate_frameworks="true" --authenticate_http_frameworks="true" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/emTA8d/credentials" --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" --quiet="false" --recovery_agent_removal_limit="100%" --registry="replicated_log" --registry_fetch_timeout="1mins" --registry_store_timeout="100secs" --registry_strict="true" --roles="role1" --root_submissions="true" --user_sorter="drf" --version="false" --webui_dir="/usr/local/share/mesos/webui" --work_dir="/tmp/emTA8d/master" --zk_session_timeout="10secs"
I0824 13:33:12.099606 10960 master.cpp:431] Master only allowing authenticated frameworks to register
I0824 13:33:12.099638 10960 master.cpp:445] Master only allowing authenticated agents to register
I0824 13:33:12.099666 10960 master.cpp:458] Master only allowing authenticated HTTP frameworks to register
I0824 13:33:12.099700 10960 credentials.hpp:37] Loading credentials for authentication from '/tmp/emTA8d/credentials'
I0824 13:33:12.099995 10960 master.cpp:503] Using default 'crammd5' authenticator
I0824 13:33:12.100158 10960 http.cpp:883] Using default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
I0824 13:33:12.100335 10960 http.cpp:883] Using default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
I0824 13:33:12.100481 10960 http.cpp:883] Using default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
I0824 13:33:12.100992 10960 master.cpp:583] Authorization enabled
W0824 13:33:12.101033 10960 master.cpp:646] The '--roles' flag is deprecated. This flag will be removed in the future. See the Mesos 0.27 upgrade notes for more information
I0824 13:33:12.103193 10950 master.cpp:1855] Elected as the leading master!
I0824 13:33:12.103250 10950 master.cpp:1551] Recovering from registrar
I0824 13:33:12.103965 10954 log.cpp:553] Attempting to start the writer
I0824 13:33:12.106070 10954 replica.cpp:493] Replica received implicit promise request from __req_res__(3579)@10.0.49.2:35633 with proposal 1
I0824 13:33:12.106729 10954 replica.cpp:342] Persisted promised to 1
I0824 13:33:12.107802 10953 coordinator.cpp:238] Coordinator attempting to fill missing positions
I0824 13:33:12.110280 10942 replica.cpp:388] Replica received explicit promise request from __req_res__(3580)@10.0.49.2:35633 for position 0 with proposal 2
I0824 13:33:12.112277 10949 replica.cpp:537] Replica received write request for position 0 from __req_res__(3581)@10.0.49.2:35633
I0824 13:33:12.113651 10961 replica.cpp:691] Replica received learned notice for position 0 from @0.0.0.0:0
I0824 13:33:12.115490 10951 log.cpp:569] Writer started with ending position 0
I0824 13:33:12.118218 10959 registrar.cpp:365] Successfully fetched the registry (0B) in 14.77504ms
I0824 13:33:12.118325 10959 registrar.cpp:464] Applied 1 operations in 13930ns; attempting to update the registry
I0824 13:33:12.119077 10959 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1
I0824 13:33:12.120400 10950 replica.cpp:537] Replica received write request for position 1 from __req_res__(3582)@10.0.49.2:35633
I0824 13:33:12.121675 10954 replica.cpp:691] Replica received learned notice for position 1 from @0.0.0.0:0
I0824 13:33:12.123524 10935 registrar.cpp:509] Successfully updated the registry in 5.124864ms
I0824 13:33:12.123692 10935 registrar.cpp:395] Successfully recovered registrar
I0824 13:33:12.123884 10948 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 2
I0824 13:33:12.124984 10929 master.cpp:1659] Recovered 0 agents from the registry (119B); allowing 10mins for agents to re-register
I0824 13:33:12.125665 10957 replica.cpp:537] Replica received write request for position 2 from __req_res__(3583)@10.0.49.2:35633
I0824 13:33:12.127629 10936 replica.cpp:691] Replica received learned notice for position 2 from @0.0.0.0:0
I0824 13:33:12.137732 10910 containerizer.cpp:216] Using isolation: posix/cpu,posix/mem,filesystem/posix,network/cni
W0824 13:33:12.138512 10910 backend.cpp:75] Failed to create 'overlay' backend: OverlayBackend requires root privileges, but is running as user bmahler
W0824 13:33:12.138664 10910 backend.cpp:75] Failed to create 'bind' backend: BindBackend requires root privileges
I0824 13:33:12.140044 10910 cluster.cpp:436] Creating default 'local' authorizer
I0824 13:33:12.141716 10952 slave.cpp:199] Mesos agent started on (254)@10.0.49.2:35633
I0824 13:33:12.141752 10952 slave.cpp:200] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/mesos/store/appc" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authenticatee="crammd5" --authentication_backoff_factor="1secs" --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/PersistentVolumeEndpointsTest_EndpointCreateThenOfferRemove_iMRQHK/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_registry="https://registry-1.docker.io" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/PersistentVolumeEndpointsTest_EndpointCreateThenOfferRemove_iMRQHK/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --http_authenticators="basic" --http_command_executor="false" --http_credentials="/tmp/PersistentVolumeEndpointsTest_EndpointCreateThenOfferRemove_iMRQHK/http_credentials" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/home/bmahler/git/mesos/build/src" --logbufsecs="0" --logging_level="INFO" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --qos_correction_interval_min="0ns" --quiet="false" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="disk(*):1024" --revocable_cpu_low_priority="true" --runtime_dir="/tmp/PersistentVolumeEndpointsTest_EndpointCreateThenOfferRemove_iMRQHK" --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/PersistentVolumeEndpointsTest_EndpointCreateThenOfferRemove_uBedqu"
I0824 13:33:12.142221 10952 credentials.hpp:86] Loading credential for authentication from '/tmp/PersistentVolumeEndpointsTest_EndpointCreateThenOfferRemove_iMRQHK/credential'
I0824 13:33:12.142369 10952 slave.cpp:337] Agent using credential for: test-principal
I0824 13:33:12.142400 10952 credentials.hpp:37] Loading credentials for authentication from '/tmp/PersistentVolumeEndpointsTest_EndpointCreateThenOfferRemove_iMRQHK/http_credentials'
I0824 13:33:12.142607 10952 http.cpp:883] Using default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
I0824 13:33:12.142750 10952 http.cpp:883] Using default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite'
I0824 13:33:12.150123 10952 slave.cpp:520] Agent resources: disk(*):1024; cpus(*):48; mem(*):63128; ports(*):[31000-32000]
I0824 13:33:12.150198 10952 slave.cpp:528] Agent attributes: [  ]
I0824 13:33:12.150213 10952 slave.cpp:533] Agent hostname: core-dev
I0824 13:33:12.152101 10932 state.cpp:57] Recovering state from '/tmp/PersistentVolumeEndpointsTest_EndpointCreateThenOfferRemove_uBedqu/meta'
I0824 13:33:12.152415 10936 status_update_manager.cpp:203] Recovering status update manager
I0824 13:33:12.152654 10957 containerizer.cpp:561] Recovering containerizer
I0824 13:33:12.154229 10970 provisioner.cpp:254] Provisioner recovery complete
I0824 13:33:12.154938 10935 slave.cpp:4873] Finished recovery
I0824 13:33:12.155788 10969 status_update_manager.cpp:177] Pausing sending status updates
I0824 13:33:12.155809 10968 slave.cpp:896] New master detected at master@10.0.49.2:35633
I0824 13:33:12.155856 10968 slave.cpp:955] Authenticating with master master@10.0.49.2:35633
I0824 13:33:12.155907 10968 slave.cpp:966] Using default CRAM-MD5 authenticatee
I0824 13:33:12.156497 10963 authenticatee.cpp:121] Creating new client SASL connection
I0824 13:33:12.156504 10968 slave.cpp:928] Detecting new master
I0824 13:33:12.162750 10943 master.cpp:6129] Authenticating slave(254)@10.0.49.2:35633
I0824 13:33:12.163079 10963 authenticator.cpp:98] Creating new server SASL connection
I0824 13:33:12.169266 10963 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0824 13:33:12.169304 10963 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0824 13:33:12.169375 10963 authenticator.cpp:204] Received SASL authentication start
I0824 13:33:12.169436 10963 authenticator.cpp:326] Authentication requires more steps
I0824 13:33:12.169595 10941 authenticatee.cpp:259] Received SASL authentication step
I0824 13:33:12.169761 10944 authenticator.cpp:232] Received SASL authentication step
I0824 13:33:12.169860 10944 authenticator.cpp:318] Authentication success
I0824 13:33:12.170001 10966 authenticatee.cpp:299] Authentication success
I0824 13:33:12.170316 10939 master.cpp:6159] Successfully authenticated principal 'test-principal' at slave(254)@10.0.49.2:35633
I0824 13:33:12.171747 10933 slave.cpp:1050] Successfully authenticated with master master@10.0.49.2:35633
I0824 13:33:12.172895 10965 master.cpp:4781] Registering agent at slave(254)@10.0.49.2:35633 (core-dev) with id 274756b2-3ffa-438d-b366-a825de787eb4-S0
I0824 13:33:12.173287 10939 registrar.cpp:464] Applied 1 operations in 43658ns; attempting to update the registry
I0824 13:33:12.174149 10960 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3
I0824 13:33:12.175477 10948 master.cpp:4769] Ignoring register agent message from slave(254)@10.0.49.2:35633 (core-dev) as admission is already in progress
I0824 13:33:12.175514 10927 replica.cpp:537] Replica received write request for position 3 from __req_res__(3584)@10.0.49.2:35633
I0824 13:33:12.176823 10957 replica.cpp:691] Replica received learned notice for position 3 from @0.0.0.0:0
I0824 13:33:12.178824 10943 registrar.cpp:509] Successfully updated the registry in 5472us
I0824 13:33:12.179616 10945 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 4
I0824 13:33:12.179896 10952 slave.cpp:1096] Registered with master master@10.0.49.2:35633; given agent ID 274756b2-3ffa-438d-b366-a825de787eb4-S0
I0824 13:33:12.179824 10947 master.cpp:4851] Registered agent 274756b2-3ffa-438d-b366-a825de787eb4-S0 at slave(254)@10.0.49.2:35633 (core-dev) with disk(*):1024; cpus(*):48; mem(*):63128; ports(*):[31000-32000]
I0824 13:33:12.179915 10940 hierarchical.cpp:478] Added agent 274756b2-3ffa-438d-b366-a825de787eb4-S0 (core-dev) with disk(*):1024; cpus(*):48; mem(*):63128; ports(*):[31000-32000] (allocated: )
I0824 13:33:12.180651 10967 status_update_manager.cpp:184] Resuming sending status updates
I0824 13:33:12.181068 10952 slave.cpp:1156] Forwarding total oversubscribed resources
I0824 13:33:12.181550 10937 replica.cpp:537] Replica received write request for position 4 from __req_res__(3585)@10.0.49.2:35633
I0824 13:33:12.181797 10929 master.cpp:5235] Received update of agent 274756b2-3ffa-438d-b366-a825de787eb4-S0 at slave(254)@10.0.49.2:35633 (core-dev) with total oversubscribed resources
I0824 13:33:12.182140 10953 hierarchical.cpp:542] Agent 274756b2-3ffa-438d-b366-a825de787eb4-S0 (core-dev) updated with oversubscribed resources  (total: disk(*):1024; cpus(*):48; mem(*):63128; ports(*):[31000-32000], allocated: )
I0824 13:33:12.183524 10928 replica.cpp:691] Replica received learned notice for position 4 from @0.0.0.0:0
I0824 13:33:12.183537 10933 http.cpp:381] HTTP POST for /master/reserve from 10.0.49.2:33705
I0824 13:33:12.183977 10933 master.cpp:3023] Authorizing principal 'test-principal' to reserve resources 'disk(role1, test-principal):512'
I0824 13:33:12.185431 10962 master.cpp:7215] Sending checkpointed resources disk(role1, test-principal):512 to agent 274756b2-3ffa-438d-b366-a825de787eb4-S0 at slave(254)@10.0.49.2:35633 (core-dev)
../../src/tests/persistent_volume_endpoints_tests.cpp:1738: Failure
I0824 13:34:12.151188 10925 slave.cpp:4645] Current disk usage 30.58%. Max allowed age: 4.159642627704063days
Failed to wait 15secs for response
I0824 13:34:34.769788 10925 slave.cpp:2491] Updated checkpointed resources from  to disk(role1, test-principal):512
I0824 13:34:34.770484 10938 http.cpp:381] HTTP POST for /master/create-volumes from 10.0.49.2:33706
I0824 13:34:34.771497 10938 master.cpp:3132] Authorizing principal 'test-principal' to create volumes
I0824 13:34:34.773593 10969 master.cpp:7215] Sending checkpointed resources disk(role1, test-principal):511; disk(role1, test-principal)[id1:volume_path]:1 to agent 274756b2-3ffa-438d-b366-a825de787eb4-S0 at slave(254)@10.0.49.2:35633 (core-dev)
I0824 13:34:34.774938 10957 slave.cpp:2491] Updated checkpointed resources from disk(role1, test-principal):512 to disk(role1, test-principal):511; disk(role1, test-principal)[id1:volume_path]:1
I0824 13:34:34.781796 10910 sched.cpp:226] Version: 1.1.0
I0824 13:34:34.782795 10926 sched.cpp:330] New master detected at master@10.0.49.2:35633
I0824 13:34:34.782920 10926 sched.cpp:396] Authenticating with master master@10.0.49.2:35633
I0824 13:34:34.782968 10926 sched.cpp:403] Using default CRAM-MD5 authenticatee
I0824 13:34:34.783552 10963 authenticatee.cpp:121] Creating new client SASL connection
I0824 13:34:34.808987 10943 master.cpp:6129] Authenticating scheduler-19ec6edc-00d0-4f95-b3bc-d207c0f981f8@10.0.49.2:35633
I0824 13:34:34.809420 10961 authenticator.cpp:98] Creating new server SASL connection
I0824 13:34:34.815667 10951 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0824 13:34:34.815732 10951 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0824 13:34:34.815946 10930 authenticator.cpp:204] Received SASL authentication start
I0824 13:34:34.816094 10930 authenticator.cpp:326] Authentication requires more steps
I0824 13:34:34.816341 10966 authenticatee.cpp:259] Received SASL authentication step
I0824 13:34:34.816604 10939 authenticator.cpp:232] Received SASL authentication step
I0824 13:34:34.816721 10939 authenticator.cpp:318] Authentication success
I0824 13:34:34.817044 10949 master.cpp:6159] Successfully authenticated principal 'test-principal' at scheduler-19ec6edc-00d0-4f95-b3bc-d207c0f981f8@10.0.49.2:35633
I0824 13:34:34.817097 10942 authenticatee.cpp:299] Authentication success
I0824 13:34:34.817566 10932 sched.cpp:502] Successfully authenticated with master master@10.0.49.2:35633
I0824 13:34:34.817984 10958 master.cpp:2429] Received SUBSCRIBE call for framework 'default' at scheduler-19ec6edc-00d0-4f95-b3bc-d207c0f981f8@10.0.49.2:35633
I0824 13:34:34.818089 10958 master.cpp:1891] Authorizing framework principal 'test-principal' to receive offers for role 'role1'
I0824 13:34:34.818500 10948 master.cpp:2505] Subscribing framework default with checkpointing disabled and capabilities [  ]
I0824 13:34:34.819201 10927 sched.cpp:743] Framework registered with 274756b2-3ffa-438d-b366-a825de787eb4-0000
I0824 13:34:34.819335 10962 hierarchical.cpp:271] Added framework 274756b2-3ffa-438d-b366-a825de787eb4-0000
I0824 13:34:34.820972 10955 master.cpp:5958] Sending 1 offers to framework 274756b2-3ffa-438d-b366-a825de787eb4-0000 (default) at scheduler-19ec6edc-00d0-4f95-b3bc-d207c0f981f8@10.0.49.2:35633
I0824 13:34:34.824378 10929 master.cpp:3360] Processing ACCEPT call for offers: [ 274756b2-3ffa-438d-b366-a825de787eb4-O0 ] on agent 274756b2-3ffa-438d-b366-a825de787eb4-S0 at slave(254)@10.0.49.2:35633 (core-dev) for framework 274756b2-3ffa-438d-b366-a825de787eb4-0000 (default) at scheduler-19ec6edc-00d0-4f95-b3bc-d207c0f981f8@10.0.49.2:35633
I0824 13:34:34.824599 10929 master.cpp:3183] Authorizing principal 'test-principal' to destroy volumes 'disk(role1, test-principal)[id1:volume_path]:1'
I0824 13:34:34.826257 10942 master.cpp:3771] Applying DESTROY operation for volumes  from framework 274756b2-3ffa-438d-b366-a825de787eb4-0000 (default) at scheduler-19ec6edc-00d0-4f95-b3bc-d207c0f981f8@10.0.49.2:35633 to agent 274756b2-3ffa-438d-b366-a825de787eb4-S0 at slave(254)@10.0.49.2:35633 (core-dev)
I0824 13:34:34.826757 10942 master.cpp:7215] Sending checkpointed resources disk(role1, test-principal):512 to agent 274756b2-3ffa-438d-b366-a825de787eb4-S0 at slave(254)@10.0.49.2:35633 (core-dev)
I0824 13:34:34.827440 10933 slave.cpp:2556] Deleting persistent volume 'id1' at '/tmp/PersistentVolumeEndpointsTest_EndpointCreateThenOfferRemove_uBedqu/volumes/roles/role1/id1'
I0824 13:34:34.827671 10933 slave.cpp:2491] Updated checkpointed resources from disk(role1, test-principal):511; disk(role1, test-principal)[id1:volume_path]:1 to disk(role1, test-principal):512
I0824 13:34:34.827986 10950 hierarchical.cpp:683] Updated allocation of framework 274756b2-3ffa-438d-b366-a825de787eb4-0000 on agent 274756b2-3ffa-438d-b366-a825de787eb4-S0 from disk(role1, test-principal):511; disk(role1, test-principal)[id1:volume_path]:1; disk(*):512; cpus(*):48; mem(*):63128; ports(*):[31000-32000] to disk(role1, test-principal):512; ports(*):[31000-32000]; disk(*):512; cpus(*):48; mem(*):63128
I0824 13:34:34.830799 10937 master.cpp:5958] Sending 1 offers to framework 274756b2-3ffa-438d-b366-a825de787eb4-0000 (default) at scheduler-19ec6edc-00d0-4f95-b3bc-d207c0f981f8@10.0.49.2:35633
I0824 13:34:34.833567 10940 master.cpp:3360] Processing ACCEPT call for offers: [ 274756b2-3ffa-438d-b366-a825de787eb4-O1 ] on agent 274756b2-3ffa-438d-b366-a825de787eb4-S0 at slave(254)@10.0.49.2:35633 (core-dev) for framework 274756b2-3ffa-438d-b366-a825de787eb4-0000 (default) at scheduler-19ec6edc-00d0-4f95-b3bc-d207c0f981f8@10.0.49.2:35633
I0824 13:34:34.833739 10940 master.cpp:3080] Authorizing principal 'test-principal' to unreserve resources 'disk(role1, test-principal):512'
I0824 13:34:34.835120 10961 master.cpp:3667] Applying UNRESERVE operation for resources disk(role1, test-principal):512 from framework 274756b2-3ffa-438d-b366-a825de787eb4-0000 (default) at scheduler-19ec6edc-00d0-4f95-b3bc-d207c0f981f8@10.0.49.2:35633 to agent 274756b2-3ffa-438d-b366-a825de787eb4-S0 at slave(254)@10.0.49.2:35633 (core-dev)
I0824 13:34:34.835544 10961 master.cpp:7215] Sending checkpointed resources  to agent 274756b2-3ffa-438d-b366-a825de787eb4-S0 at slave(254)@10.0.49.2:35633 (core-dev)
I0824 13:34:34.836091 10933 slave.cpp:2491] Updated checkpointed resources from disk(role1, test-principal):512 to
I0824 13:34:34.836417 10936 hierarchical.cpp:683] Updated allocation of framework 274756b2-3ffa-438d-b366-a825de787eb4-0000 on agent 274756b2-3ffa-438d-b366-a825de787eb4-S0 from disk(role1, test-principal):512; disk(*):512; cpus(*):48; mem(*):63128; ports(*):[31000-32000] to ports(*):[31000-32000]; disk(*):1024; cpus(*):48; mem(*):63128
I0824 13:34:34.882081 10949 master.cpp:5958] Sending 1 offers to framework 274756b2-3ffa-438d-b366-a825de787eb4-0000 (default) at scheduler-19ec6edc-00d0-4f95-b3bc-d207c0f981f8@10.0.49.2:35633
I0824 13:34:34.884217 10910 sched.cpp:1987] Asked to stop the driver
I0824 13:34:34.884667 10967 sched.cpp:1187] Stopping framework 274756b2-3ffa-438d-b366-a825de787eb4-0000
I0824 13:34:34.884984 10926 master.cpp:6534] Processing TEARDOWN call for framework 274756b2-3ffa-438d-b366-a825de787eb4-0000 (default) at scheduler-19ec6edc-00d0-4f95-b3bc-d207c0f981f8@10.0.49.2:35633
I0824 13:34:34.885058 10926 master.cpp:6546] Removing framework 274756b2-3ffa-438d-b366-a825de787eb4-0000 (default) at scheduler-19ec6edc-00d0-4f95-b3bc-d207c0f981f8@10.0.49.2:35633
I0824 13:34:34.885362 10935 hierarchical.cpp:382] Deactivated framework 274756b2-3ffa-438d-b366-a825de787eb4-0000
I0824 13:34:34.885404 10962 slave.cpp:2219] Asked to shut down framework 274756b2-3ffa-438d-b366-a825de787eb4-0000 by master@10.0.49.2:35633
W0824 13:34:34.885543 10962 slave.cpp:2234] Cannot shut down unknown framework 274756b2-3ffa-438d-b366-a825de787eb4-0000
I0824 13:34:34.886610 10966 hierarchical.cpp:333] Removed framework 274756b2-3ffa-438d-b366-a825de787eb4-0000
I0824 13:34:34.887817 10954 slave.cpp:768] Agent terminating
I0824 13:34:34.888538 10965 master.cpp:1249] Agent 274756b2-3ffa-438d-b366-a825de787eb4-S0 at slave(254)@10.0.49.2:35633 (core-dev) disconnected
I0824 13:34:34.888607 10965 master.cpp:2789] Disconnecting agent 274756b2-3ffa-438d-b366-a825de787eb4-S0 at slave(254)@10.0.49.2:35633 (core-dev)
I0824 13:34:34.888723 10965 master.cpp:2808] Deactivating agent 274756b2-3ffa-438d-b366-a825de787eb4-S0 at slave(254)@10.0.49.2:35633 (core-dev)
I0824 13:34:34.888906 10966 hierarchical.cpp:571] Agent 274756b2-3ffa-438d-b366-a825de787eb4-S0 deactivated
I0824 13:34:34.896528 10936 master.cpp:1096] Master terminating
I0824 13:34:34.897037 10943 hierarchical.cpp:510] Removed agent 274756b2-3ffa-438d-b366-a825de787eb4-S0
[  FAILED  ] PersistentVolumeEndpointsTest.EndpointCreateThenOfferRemove (82823 ms)

Attachments

Issue Links

is blocked by

MESOS-8082 updateAvailable races with a periodic allocation and leads to flaky tests.

Resolved

is related to

MESOS-7784 MasterTestPrePostReservationRefinement.CreateAndDestroyVolumesV1 is flaky

Resolved

Activity

People

Assignee:: Alex R

Reporter:: Benjamin Mahler

Votes:: 0 Vote for this issue

Watchers:: 3 Start watching this issue

Dates

Created:: 24/Aug/16 21:30

Updated:: 05/Dec/17 13:51

Resolved:: 21/Oct/17 02:44