[
https://issues.apache.org/jira/browse/MESOS-7971?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Meng Zhu updated MESOS-7971:
----------------------------
Comment: was deleted
(was: This test is flaky because due to a race.
The test expects the offer to be sent out after the reserve and create
operations have finished. But it only waits for the 202 returned by both calls.
When the offer is sent while the agent is processing the create operation, the
offer does not contain the expected volume resource. Failing the test.
Adding manual clock control and properly settle should fix the test.
)
> PersistentVolumeEndpointsTest.EndpointCreateThenOfferRemove test is flaky
> -------------------------------------------------------------------------
>
> Key: MESOS-7971
> URL: https://issues.apache.org/jira/browse/MESOS-7971
> Project: Mesos
> Issue Type: Bug
> Components: allocation
> Affects Versions: 1.4.0, 1.6.0, 1.7.0, 1.8.0
> Reporter: Vinod Kone
> Assignee: Meng Zhu
> Priority: Critical
> Labels: flaky-test, mesosphere
> Attachments: ApacheJenkinsConsoleText_autotools_gcc_ubuntu16.txt
>
>
> Saw this when testing 1.4.0-rc5
> {code}
> [ RUN ] PersistentVolumeEndpointsTest.EndpointCreateThenOfferRemove
> I0912 05:40:27.335222 30860 cluster.cpp:162] Creating default 'local'
> authorizer
> I0912 05:40:27.338429 30867 master.cpp:442] Master
> 2bd1e8eb-e314-4181-9ed3-d397ec1dbede (6aa774430302) started on
> 172.17.0.3:54639
> I0912 05:40:27.338472 30867 master.cpp:444] 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/hH0YXe/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" --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" --roles="role1"
> --root_submissions="true" --user_sorter="drf" --version="false"
> --webui_dir="/usr/local/share/mesos/webui" --work_dir="/tmp/hH0YXe/master"
> --zk_session_timeout="10secs"
> I0912 05:40:27.338778 30867 master.cpp:494] Master only allowing
> authenticated frameworks to register
> I0912 05:40:27.338788 30867 master.cpp:508] Master only allowing
> authenticated agents to register
> I0912 05:40:27.338793 30867 master.cpp:521] Master only allowing
> authenticated HTTP frameworks to register
> I0912 05:40:27.338799 30867 credentials.hpp:37] Loading credentials for
> authentication from '/tmp/hH0YXe/credentials'
> I0912 05:40:27.353009 30867 master.cpp:566] Using default 'crammd5'
> authenticator
> I0912 05:40:27.353183 30867 http.cpp:1026] Creating default 'basic' HTTP
> authenticator for realm 'mesos-master-readonly'
> I0912 05:40:27.353364 30867 http.cpp:1026] Creating default 'basic' HTTP
> authenticator for realm 'mesos-master-readwrite'
> I0912 05:40:27.353482 30867 http.cpp:1026] Creating default 'basic' HTTP
> authenticator for realm 'mesos-master-scheduler'
> I0912 05:40:27.353588 30867 master.cpp:646] Authorization enabled
> W0912 05:40:27.353605 30867 master.cpp:709] The '--roles' flag is deprecated.
> This flag will be removed in the future. See the Mesos 0.27 upgrade notes for
> more information
> I0912 05:40:27.353742 30868 hierarchical.cpp:171] Initialized hierarchical
> allocator process
> I0912 05:40:27.353775 30872 whitelist_watcher.cpp:77] No whitelist given
> I0912 05:40:27.356655 30873 master.cpp:2163] Elected as the leading master!
> I0912 05:40:27.356675 30873 master.cpp:1702] Recovering from registrar
> I0912 05:40:27.356868 30874 registrar.cpp:347] Recovering registrar
> I0912 05:40:27.357390 30874 registrar.cpp:391] Successfully fetched the
> registry (0B) in 494080ns
> I0912 05:40:27.357483 30874 registrar.cpp:495] Applied 1 operations in
> 31911ns; attempting to update the registry
> I0912 05:40:27.357919 30874 registrar.cpp:552] Successfully updated the
> registry in 391936ns
> I0912 05:40:27.358018 30874 registrar.cpp:424] Successfully recovered
> registrar
> I0912 05:40:27.358413 30868 master.cpp:1801] Recovered 0 agents from the
> registry (129B); allowing 10mins for agents to re-register
> I0912 05:40:27.358482 30867 hierarchical.cpp:209] Skipping recovery of
> hierarchical allocator: nothing to recover
> W0912 05:40:27.364050 30860 process.cpp:3196] Attempted to spawn already
> running process [email protected]:54639
> I0912 05:40:27.365372 30860 containerizer.cpp:246] Using isolation:
> posix/cpu,posix/mem,filesystem/posix,network/cni,environment_secret
> W0912 05:40:27.365909 30860 backend.cpp:76] Failed to create 'aufs' backend:
> AufsBackend requires root privileges
> W0912 05:40:27.366032 30860 backend.cpp:76] Failed to create 'bind' backend:
> BindBackend requires root privileges
> I0912 05:40:27.366077 30860 provisioner.cpp:255] Using default backend 'copy'
> I0912 05:40:27.368383 30860 cluster.cpp:448] Creating default 'local'
> authorizer
> I0912 05:40:27.370293 30869 slave.cpp:250] Mesos agent started on
> (466)@172.17.0.3:54639
> I0912 05:40:27.370338 30869 slave.cpp:251] Flags at startup: --acls=""
> --appc_simple_discovery_uri_prefix="http://";
> --appc_store_dir="/tmp/PersistentVolumeEndpointsTest_EndpointCreateThenOfferRemove_5fHlSl/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_5fHlSl/credential"
> --default_role="*" --disallow_sharing_agent_pid_namespace="false"
> --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/PersistentVolumeEndpointsTest_EndpointCreateThenOfferRemove_5fHlSl/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/PersistentVolumeEndpointsTest_EndpointCreateThenOfferRemove_5fHlSl/fetch"
> --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks"
> --gc_disk_headroom="0.1" --hadoop_home="" --help="false"
> --hostname_lookup="true" --http_command_executor="false"
> --http_credentials="/tmp/PersistentVolumeEndpointsTest_EndpointCreateThenOfferRemove_5fHlSl/http_credentials"
> --http_heartbeat_interval="30secs" --initialize_driver_logging="true"
> --isolation="posix/cpu,posix/mem" --launcher="posix"
> --launcher_dir="/mesos/build/src" --logbufsecs="0" --logging_level="INFO"
> --max_completed_executors_per_framework="150"
> --oversubscribed_resources_interval="15secs" --perf_duration="10secs"
> --perf_interval="1mins" --port="5051" --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_5fHlSl"
> --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_PsL9pN"
> I0912 05:40:27.371112 30869 credentials.hpp:86] Loading credential for
> authentication from
> '/tmp/PersistentVolumeEndpointsTest_EndpointCreateThenOfferRemove_5fHlSl/credential'
> I0912 05:40:27.385258 30869 slave.cpp:283] Agent using credential for:
> test-principal
> I0912 05:40:27.385282 30869 credentials.hpp:37] Loading credentials for
> authentication from
> '/tmp/PersistentVolumeEndpointsTest_EndpointCreateThenOfferRemove_5fHlSl/http_credentials'
> I0912 05:40:27.385558 30869 http.cpp:1026] Creating default 'basic' HTTP
> authenticator for realm 'mesos-agent-readonly'
> I0912 05:40:27.385725 30869 http.cpp:1026] Creating default 'basic' HTTP
> authenticator for realm 'mesos-agent-readwrite'
> I0912 05:40:27.387053 30869 slave.cpp:565] Agent resources:
> [{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"cpus","scalar":{"value":16.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":47270.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
> I0912 05:40:27.387289 30869 slave.cpp:573] Agent attributes: [ ]
> I0912 05:40:27.387310 30869 slave.cpp:582] Agent hostname: 6aa774430302
> I0912 05:40:27.387544 30865 status_update_manager.cpp:177] Pausing sending
> status updates
> I0912 05:40:27.388907 30875 state.cpp:64] Recovering state from
> '/tmp/PersistentVolumeEndpointsTest_EndpointCreateThenOfferRemove_PsL9pN/meta'
> I0912 05:40:27.389266 30862 status_update_manager.cpp:203] Recovering status
> update manager
> I0912 05:40:27.389451 30874 containerizer.cpp:609] Recovering containerizer
> I0912 05:40:27.390908 30875 provisioner.cpp:416] Provisioner recovery complete
> I0912 05:40:27.391261 30863 slave.cpp:6295] Finished recovery
> I0912 05:40:27.391703 30863 slave.cpp:6477] Querying resource estimator for
> oversubscribable resources
> I0912 05:40:27.392042 30864 status_update_manager.cpp:177] Pausing sending
> status updates
> I0912 05:40:27.392040 30872 slave.cpp:971] New master detected at
> [email protected]:54639
> I0912 05:40:27.392168 30872 slave.cpp:1006] Detecting new master
> I0912 05:40:27.392290 30872 slave.cpp:6491] Received oversubscribable
> resources {} from the resource estimator
> I0912 05:40:27.393498 30868 slave.cpp:1033] Authenticating with master
> [email protected]:54639
> I0912 05:40:27.393575 30868 slave.cpp:1044] Using default CRAM-MD5
> authenticatee
> I0912 05:40:27.393834 30867 authenticatee.cpp:121] Creating new client SASL
> connection
> I0912 05:40:27.394254 30867 master.cpp:7832] Authenticating
> slave(466)@172.17.0.3:54639
> I0912 05:40:27.394435 30870 authenticator.cpp:414] Starting authentication
> session for crammd5-authenticatee(954)@172.17.0.3:54639
> I0912 05:40:27.394685 30876 authenticator.cpp:98] Creating new server SASL
> connection
> I0912 05:40:27.394943 30869 authenticatee.cpp:213] Received SASL
> authentication mechanisms: CRAM-MD5
> I0912 05:40:27.394976 30869 authenticatee.cpp:239] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0912 05:40:27.395109 30871 authenticator.cpp:204] Received SASL
> authentication start
> I0912 05:40:27.395171 30871 authenticator.cpp:326] Authentication requires
> more steps
> I0912 05:40:27.395287 30862 authenticatee.cpp:259] Received SASL
> authentication step
> I0912 05:40:27.395421 30862 authenticator.cpp:232] Received SASL
> authentication step
> I0912 05:40:27.395453 30862 auxprop.cpp:109] Request to lookup properties for
> user: 'test-principal' realm: '6aa774430302' server FQDN: '6aa774430302'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0912 05:40:27.395467 30862 auxprop.cpp:181] Looking up auxiliary property
> '*userPassword'
> I0912 05:40:27.395514 30862 auxprop.cpp:181] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0912 05:40:27.395539 30862 auxprop.cpp:109] Request to lookup properties for
> user: 'test-principal' realm: '6aa774430302' server FQDN: '6aa774430302'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0912 05:40:27.395552 30862 auxprop.cpp:131] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0912 05:40:27.395565 30862 auxprop.cpp:131] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0912 05:40:27.395588 30862 authenticator.cpp:318] Authentication success
> I0912 05:40:27.395728 30861 authenticatee.cpp:299] Authentication success
> I0912 05:40:27.395784 30863 master.cpp:7862] Successfully authenticated
> principal 'test-principal' at slave(466)@172.17.0.3:54639
> I0912 05:40:27.395830 30865 authenticator.cpp:432] Authentication session
> cleanup for crammd5-authenticatee(954)@172.17.0.3:54639
> I0912 05:40:27.396013 30873 slave.cpp:1128] Successfully authenticated with
> master [email protected]:54639
> I0912 05:40:27.396206 30873 slave.cpp:1607] Will retry registration in
> 10.142802ms if necessary
> I0912 05:40:27.396468 30874 master.cpp:5714] Received register agent message
> from slave(466)@172.17.0.3:54639 (6aa774430302)
> I0912 05:40:27.396510 30874 master.cpp:3803] Authorizing agent with principal
> 'test-principal'
> I0912 05:40:27.396941 30867 master.cpp:5774] Authorized registration of agent
> at slave(466)@172.17.0.3:54639 (6aa774430302)
> I0912 05:40:27.397068 30867 master.cpp:5867] Registering agent at
> slave(466)@172.17.0.3:54639 (6aa774430302) with id
> 2bd1e8eb-e314-4181-9ed3-d397ec1dbede-S0
> I0912 05:40:27.397487 30876 registrar.cpp:495] Applied 1 operations in
> 76281ns; attempting to update the registry
> I0912 05:40:27.398087 30876 registrar.cpp:552] Successfully updated the
> registry in 534016ns
> I0912 05:40:27.398342 30861 master.cpp:5914] Admitted agent
> 2bd1e8eb-e314-4181-9ed3-d397ec1dbede-S0 at slave(466)@172.17.0.3:54639
> (6aa774430302)
> I0912 05:40:27.398921 30863 slave.cpp:4970] Received ping from
> slave-observer(459)@172.17.0.3:54639
> I0912 05:40:27.398897 30861 master.cpp:5945] Registered agent
> 2bd1e8eb-e314-4181-9ed3-d397ec1dbede-S0 at slave(466)@172.17.0.3:54639
> (6aa774430302) with
> [{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"cpus","scalar":{"value":16.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":47270.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
> I0912 05:40:27.399139 30863 slave.cpp:1174] Registered with master
> [email protected]:54639; given agent ID
> 2bd1e8eb-e314-4181-9ed3-d397ec1dbede-S0
> I0912 05:40:27.399278 30872 hierarchical.cpp:593] Added agent
> 2bd1e8eb-e314-4181-9ed3-d397ec1dbede-S0 (6aa774430302) with disk:1024;
> cpus:16; mem:47270; ports:[31000-32000] (allocated: {})
> I0912 05:40:27.399333 30865 status_update_manager.cpp:184] Resuming sending
> status updates
> I0912 05:40:27.399612 30872 hierarchical.cpp:1925] No allocations performed
> I0912 05:40:27.399689 30872 hierarchical.cpp:1468] Performed allocation for 1
> agents in 218878ns
> I0912 05:40:27.402381 30875 process.cpp:3927] Handling HTTP event for process
> 'master' with path: '/master/reserve'
> I0912 05:40:27.403935 30870 http.cpp:1166] HTTP POST for /master/reserve from
> 172.17.0.3:38703
> I0912 05:40:27.404425 30870 master.cpp:3588] Authorizing principal
> 'test-principal' to reserve resources
> '[{"name":"disk","reservations":[{"principal":"test-principal","role":"role1","type":"DYNAMIC"}],"scalar":{"value":512.0},"type":"SCALAR"}]'
> I0912 05:40:27.404688 30872 hierarchical.cpp:1925] No allocations performed
> I0912 05:40:27.404744 30872 hierarchical.cpp:1468] Performed allocation for 1
> agents in 164212ns
> I0912 05:40:27.407155 30876 master.cpp:9105] Sending updated checkpointed
> resources disk(reservations: [(DYNAMIC,role1,test-principal)]):512 to agent
> 2bd1e8eb-e314-4181-9ed3-d397ec1dbede-S0 at slave(466)@172.17.0.3:54639
> (6aa774430302)
> I0912 05:40:27.410841 30871 process.cpp:3927] Handling HTTP event for process
> 'master' with path: '/master/create-volumes'
> I0912 05:40:27.412400 30873 http.cpp:1166] HTTP POST for
> /master/create-volumes from 172.17.0.3:38704
> I0912 05:40:27.413215 30873 master.cpp:3723] Authorizing principal
> 'test-principal' to create volumes
> '[{"disk":{"persistence":{"id":"id1","principal":"test-principal"},"volume":{"container_path":"volume_path","mode":"RW"}},"name":"disk","reservations":[{"principal":"test-principal","role":"role1","type":"DYNAMIC"}],"scalar":{"value":1.0},"type":"SCALAR"}]'
> I0912 05:40:27.414523 30863 slave.cpp:1194] Checkpointing SlaveInfo to
> '/tmp/PersistentVolumeEndpointsTest_EndpointCreateThenOfferRemove_PsL9pN/meta/slaves/2bd1e8eb-e314-4181-9ed3-d397ec1dbede-S0/slave.info'
> I0912 05:40:27.414891 30863 slave.cpp:1243] Forwarding total oversubscribed
> resources {}
> I0912 05:40:27.415109 30867 master.cpp:6683] Received update of agent
> 2bd1e8eb-e314-4181-9ed3-d397ec1dbede-S0 at slave(466)@172.17.0.3:54639
> (6aa774430302) with total oversubscribed resources {}
> I0912 05:40:27.415563 30863 slave.cpp:3503] Updated checkpointed resources
> from {} to disk(reservations: [(DYNAMIC,role1,test-principal)]):512
> I0912 05:40:27.415956 30869 master.cpp:9105] Sending updated checkpointed
> resources disk(reservations: [(DYNAMIC,role1,test-principal)]):511;
> disk(reservations: [(DYNAMIC,role1,test-principal)])[id1:volume_path]:1 to
> agent 2bd1e8eb-e314-4181-9ed3-d397ec1dbede-S0 at slave(466)@172.17.0.3:54639
> (6aa774430302)
> I0912 05:40:27.416842 30872 hierarchical.cpp:660] Agent
> 2bd1e8eb-e314-4181-9ed3-d397ec1dbede-S0 (6aa774430302) updated with total
> resources disk:512; cpus:16; mem:47270; ports:[31000-32000];
> disk(reservations: [(DYNAMIC,role1,test-principal)]):512
> I0912 05:40:27.417115 30872 hierarchical.cpp:1925] No allocations performed
> I0912 05:40:27.417158 30872 hierarchical.cpp:1468] Performed allocation for 1
> agents in 154796ns
> W0912 05:40:27.417163 30860 process.cpp:3196] Attempted to spawn already
> running process [email protected]:54639
> I0912 05:40:27.418258 30860 sched.cpp:232] Version: 1.4.0
> I0912 05:40:27.418874 30876 sched.cpp:336] New master detected at
> [email protected]:54639
> I0912 05:40:27.418973 30876 sched.cpp:407] Authenticating with master
> [email protected]:54639
> I0912 05:40:27.418992 30876 sched.cpp:414] Using default CRAM-MD5
> authenticatee
> I0912 05:40:27.419255 30868 authenticatee.cpp:121] Creating new client SASL
> connection
> I0912 05:40:27.419570 30868 master.cpp:7832] Authenticating
> [email protected]:54639
> I0912 05:40:27.419756 30861 authenticator.cpp:414] Starting authentication
> session for crammd5-authenticatee(955)@172.17.0.3:54639
> I0912 05:40:27.419981 30866 authenticator.cpp:98] Creating new server SASL
> connection
> I0912 05:40:27.420142 30873 authenticatee.cpp:213] Received SASL
> authentication mechanisms: CRAM-MD5
> I0912 05:40:27.420168 30873 authenticatee.cpp:239] Attempting to authenticate
> with mechanism 'CRAM-MD5'
> I0912 05:40:27.420254 30872 authenticator.cpp:204] Received SASL
> authentication start
> I0912 05:40:27.420313 30872 authenticator.cpp:326] Authentication requires
> more steps
> I0912 05:40:27.420420 30874 authenticatee.cpp:259] Received SASL
> authentication step
> I0912 05:40:27.420528 30870 authenticator.cpp:232] Received SASL
> authentication step
> I0912 05:40:27.420552 30870 auxprop.cpp:109] Request to lookup properties for
> user: 'test-principal' realm: '6aa774430302' server FQDN: '6aa774430302'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: false
> I0912 05:40:27.420563 30870 auxprop.cpp:181] Looking up auxiliary property
> '*userPassword'
> I0912 05:40:27.420598 30870 auxprop.cpp:181] Looking up auxiliary property
> '*cmusaslsecretCRAM-MD5'
> I0912 05:40:27.420614 30870 auxprop.cpp:109] Request to lookup properties for
> user: 'test-principal' realm: '6aa774430302' server FQDN: '6aa774430302'
> SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false
> SASL_AUXPROP_AUTHZID: true
> I0912 05:40:27.420622 30870 auxprop.cpp:131] Skipping auxiliary property
> '*userPassword' since SASL_AUXPROP_AUTHZID == true
> I0912 05:40:27.420631 30870 auxprop.cpp:131] Skipping auxiliary property
> '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
> I0912 05:40:27.420647 30870 authenticator.cpp:318] Authentication success
> I0912 05:40:27.420723 30865 authenticatee.cpp:299] Authentication success
> I0912 05:40:27.420791 30863 master.cpp:7862] Successfully authenticated
> principal 'test-principal' at
> [email protected]:54639
> I0912 05:40:27.420835 30865 authenticator.cpp:432] Authentication session
> cleanup for crammd5-authenticatee(955)@172.17.0.3:54639
> I0912 05:40:27.420963 30871 sched.cpp:513] Successfully authenticated with
> master [email protected]:54639
> I0912 05:40:27.420979 30871 sched.cpp:836] Sending SUBSCRIBE call to
> [email protected]:54639
> I0912 05:40:27.421097 30871 sched.cpp:869] Will retry registration in
> 1.648431276secs if necessary
> I0912 05:40:27.421262 30862 master.cpp:2894] Received SUBSCRIBE call for
> framework 'default' at
> [email protected]:54639
> I0912 05:40:27.421283 30862 master.cpp:2228] Authorizing framework principal
> 'test-principal' to receive offers for roles '{ role1 }'
> I0912 05:40:27.421728 30868 master.cpp:2974] Subscribing framework default
> with checkpointing disabled and capabilities [ RESERVATION_REFINEMENT ]
> I0912 05:40:27.422307 30873 sched.cpp:759] Framework registered with
> 2bd1e8eb-e314-4181-9ed3-d397ec1dbede-0000
> I0912 05:40:27.422361 30873 sched.cpp:773] Scheduler::registered took 36801ns
> I0912 05:40:27.422507 30866 hierarchical.cpp:303] Added framework
> 2bd1e8eb-e314-4181-9ed3-d397ec1dbede-0000
> I0912 05:40:27.423943 30866 hierarchical.cpp:2015] No inverse offers to send
> out!
> I0912 05:40:27.423990 30866 hierarchical.cpp:1468] Performed allocation for 1
> agents in 1.383883ms
> I0912 05:40:27.424603 30870 master.cpp:7662] Sending 1 offers to framework
> 2bd1e8eb-e314-4181-9ed3-d397ec1dbede-0000 (default) at
> [email protected]:54639
> I0912 05:40:27.425202 30875 sched.cpp:933] Scheduler::resourceOffers took
> 151124ns
> /mesos/src/tests/persistent_volume_endpoints_tests.cpp:1729: Failure
> Value of: Resources(offer.resources()).contains( allocatedResources(volume,
> frameworkInfo.role()))
> Actual: false
> Expected: true
> I0912 05:40:27.427381 30871 master.cpp:9159] Removing offer
> 2bd1e8eb-e314-4181-9ed3-d397ec1dbede-O0
> I0912 05:40:27.427520 30871 master.cpp:4153] Processing ACCEPT call for
> offers: [ 2bd1e8eb-e314-4181-9ed3-d397ec1dbede-O0 ] on agent
> 2bd1e8eb-e314-4181-9ed3-d397ec1dbede-S0 at slave(466)@172.17.0.3:54639
> (6aa774430302) for framework 2bd1e8eb-e314-4181-9ed3-d397ec1dbede-0000
> (default) at [email protected]:54639
> I0912 05:40:27.427686 30871 master.cpp:3775] Authorizing principal
> 'test-principal' to destroy volumes
> '[{"allocation_info":{"role":"role1"},"disk":{"persistence":{"id":"id1","principal":"test-principal"},"volume":{"container_path":"volume_path","mode":"RW"}},"name":"disk","reservations":[{"principal":"test-principal","role":"role1","type":"DYNAMIC"}],"scalar":{"value":1.0},"type":"SCALAR"}]'
> W0912 05:40:27.428877 30871 master.cpp:2313] Dropping DESTROY offer operation
> from framework 2bd1e8eb-e314-4181-9ed3-d397ec1dbede-0000 (default) at
> [email protected]:54639: Invalid
> DESTROY Operation: Persistent volume does not exist
> I0912 05:40:27.430284 30870 hierarchical.cpp:1152] Recovered disk(allocated:
> role1):512; cpus(allocated: role1):16; mem(allocated: role1):47270;
> ports(allocated: role1):[31000-32000]; disk(allocated: role1)(reservations:
> [(DYNAMIC,role1,test-principal)]):512 (total: disk:512; cpus:16; mem:47270;
> ports:[31000-32000]; disk(reservations:
> [(DYNAMIC,role1,test-principal)]):512, allocated: {}) on agent
> 2bd1e8eb-e314-4181-9ed3-d397ec1dbede-S0 from framework
> 2bd1e8eb-e314-4181-9ed3-d397ec1dbede-0000
> I0912 05:40:27.436583 30869 slave.cpp:3503] Updated checkpointed resources
> from disk(reservations: [(DYNAMIC,role1,test-principal)]):512 to
> disk(reservations: [(DYNAMIC,role1,test-principal)]):511; disk(reservations:
> [(DYNAMIC,role1,test-principal)])[id1:volume_path]:1
> I0912 05:40:27.457546 30864 hierarchical.cpp:2015] No inverse offers to send
> out!
> I0912 05:40:27.457602 30864 hierarchical.cpp:1468] Performed allocation for 1
> agents in 1.471076ms
> I0912 05:40:27.458061 30863 master.cpp:7662] Sending 1 offers to framework
> 2bd1e8eb-e314-4181-9ed3-d397ec1dbede-0000 (default) at
> [email protected]:54639
> I0912 05:40:27.458436 30863 sched.cpp:933] Scheduler::resourceOffers took
> 91992ns
> I0912 05:40:27.460006 30872 master.cpp:9159] Removing offer
> 2bd1e8eb-e314-4181-9ed3-d397ec1dbede-O1
> I0912 05:40:27.460094 30872 master.cpp:4153] Processing ACCEPT call for
> offers: [ 2bd1e8eb-e314-4181-9ed3-d397ec1dbede-O1 ] on agent
> 2bd1e8eb-e314-4181-9ed3-d397ec1dbede-S0 at slave(466)@172.17.0.3:54639
> (6aa774430302) for framework 2bd1e8eb-e314-4181-9ed3-d397ec1dbede-0000
> (default) at [email protected]:54639
> I0912 05:40:27.460188 30872 master.cpp:3656] Authorizing principal
> 'test-principal' to unreserve resources
> '[{"allocation_info":{"role":"role1"},"name":"disk","reservations":[{"principal":"test-principal","role":"role1","type":"DYNAMIC"}],"scalar":{"value":512.0},"type":"SCALAR"}]'
> I0912 05:40:27.460947 30872 master.cpp:4511] Applying UNRESERVE operation for
> resources
> [{"allocation_info":{"role":"role1"},"name":"disk","reservations":[{"principal":"test-principal","role":"role1","type":"DYNAMIC"}],"scalar":{"value":512.0},"type":"SCALAR"}]
> from framework 2bd1e8eb-e314-4181-9ed3-d397ec1dbede-0000 (default) at
> [email protected]:54639 to agent
> 2bd1e8eb-e314-4181-9ed3-d397ec1dbede-S0 at slave(466)@172.17.0.3:54639
> (6aa774430302)
> F0912 05:40:27.461275 30872 master.cpp:9855] CHECK_SOME(resources): Invalid
> UNRESERVE Operation: disk:512; cpus:16; mem:47270; ports:[31000-32000];
> disk(reservations: [(DYNAMIC,role1,test-principal)]):511; disk(reservations:
> [(DYNAMIC,role1,test-principal)])[id1:volume_path]:1 does not contain
> disk(reservations: [(DYNAMIC,role1,test-principal)]):512
> *** Check failure stack trace: ***
> @ 0x2b006f42aa53 google::LogMessage::SendToLog()
> @ 0x2b006f42aecf google::LogMessage::Flush()
> @ 0x2b006f42e95d google::LogMessageFatal::~LogMessageFatal()
> @ 0x1b70b07 _CheckFatal::~_CheckFatal()
> @ 0x2b006aa7f221 mesos::internal::master::Slave::apply()
> @ 0x2b006aa659f5 mesos::internal::master::Master::_apply()
> @ 0x2b006aa5f7c8 mesos::internal::master::Master::_accept()
> @ 0x2b006ab1d9d7
> _ZZN7process8dispatchIN5mesos8internal6master6MasterERKNS1_11FrameworkIDERKNS1_7SlaveIDERKNS1_9ResourcesERKNS1_9scheduler11Call_AcceptERKNS_6FutureISt4listINSI_IbEESaISK_EEEES7_SA_SD_SH_SP_EEvRKNS_3PIDIT_EEMSR_FvT0_T1_T2_T3_T4_EOT5_OT6_OT7_OT8_OT9_ENKUlRS5_RS8_RSB_RSF_RSN_PNS_11ProcessBaseEE_clES1C_S1D_S1E_S1F_S1G_S1I_
> I0912 05:40:27.508661 30864 hierarchical.cpp:1925] No allocations performed
> I0912 05:40:27.508711 30864 hierarchical.cpp:2015] No inverse offers to send
> out!
> I0912 05:40:27.508744 30864 hierarchical.cpp:1468] Performed allocation for 1
> agents in 243976ns
> @ 0x2b006ab1d851
> _ZNSt5_BindIFZN7process8dispatchIN5mesos8internal6master6MasterERKNS2_11FrameworkIDERKNS2_7SlaveIDERKNS2_9ResourcesERKNS2_9scheduler11Call_AcceptERKNS0_6FutureISt4listINSJ_IbEESaISL_EEEES8_SB_SE_SI_SQ_EEvRKNS0_3PIDIT_EEMSS_FvT0_T1_T2_T3_T4_EOT5_OT6_OT7_OT8_OT9_EUlRS6_RS9_RSC_RSG_RSO_PNS0_11ProcessBaseEE_S6_S9_SC_SG_SO_St12_PlaceholderILi1EEEE6__callIvJOS1J_EJLm0ELm1ELm2ELm3ELm4ELm5EEEESS_OSt5tupleIJDpT0_EESt12_Index_tupleIJXspT1_EEE
> @ 0x2b006ab1d71d
> _ZNSt5_BindIFZN7process8dispatchIN5mesos8internal6master6MasterERKNS2_11FrameworkIDERKNS2_7SlaveIDERKNS2_9ResourcesERKNS2_9scheduler11Call_AcceptERKNS0_6FutureISt4listINSJ_IbEESaISL_EEEES8_SB_SE_SI_SQ_EEvRKNS0_3PIDIT_EEMSS_FvT0_T1_T2_T3_T4_EOT5_OT6_OT7_OT8_OT9_EUlRS6_RS9_RSC_RSG_RSO_PNS0_11ProcessBaseEE_S6_S9_SC_SG_SO_St12_PlaceholderILi1EEEEclIJS1J_EvEESW_DpOT_
> @ 0x2b006ab1d1f2
> _ZNSt17_Function_handlerIFvPN7process11ProcessBaseEESt5_BindIFZNS0_8dispatchIN5mesos8internal6master6MasterERKNS6_11FrameworkIDERKNS6_7SlaveIDERKNS6_9ResourcesERKNS6_9scheduler11Call_AcceptERKNS0_6FutureISt4listINSN_IbEESaISP_EEEESC_SF_SI_SM_SU_EEvRKNS0_3PIDIT_EEMSW_FvT0_T1_T2_T3_T4_EOT5_OT6_OT7_OT8_OT9_EUlRSA_RSD_RSG_RSK_RSS_S2_E_SA_SD_SG_SK_SS_St12_PlaceholderILi1EEEEE9_M_invokeERKSt9_Any_dataS2_
> @ 0x2b006cfde9f8 std::function<>::operator()()
> @ 0x2b006cfc3ad4 process::ProcessBase::visit()
> @ 0x2b006d065c1e process::DispatchEvent::visit()
> @ 0x1bb32a1 process::ProcessBase::serve()
> @ 0x2b006cfc170b process::ProcessManager::resume()
> @ 0x2b006cfd03f1
> process::ProcessManager::init_threads()::$_8::operator()()
> @ 0x2b006cfd0335
> _ZNSt12_Bind_simpleIFZN7process14ProcessManager12init_threadsEvE3$_8vEE9_M_invokeIJEEEvSt12_Index_tupleIJXspT_EEE
> @ 0x2b006cfd0305 std::_Bind_simple<>::operator()()
> @ 0x2b006cfd02dc std::thread::_Impl<>::_M_run()
> @ 0x2b0071089a60 (unknown)
> @ 0x2b0070dc2184 start_thread
> @ 0x2b00718f5ffd (unknown)
> make[3]: *** [CMakeFiles/check] Aborted
> make[3]: Leaving directory `/mesos/build'
> make[2]: *** [CMakeFiles/check.dir/all] Error 2
> make[2]: Leaving directory `/mesos/build'
> make[1]: *** [CMakeFiles/check.dir/rule] Error 2
> make[1]: Leaving directory `/mesos/build'
> make: *** [check] Error 2
> {code}
> Looks a bit different than the flakiness observed in MESOS-6086
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
