You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@mesos.apache.org by "Neil Conway (JIRA)" <ji...@apache.org> on 2017/05/16 18:18:04 UTC
[jira] [Created] (MESOS-7514)
ReservationTest.PreventUnreservingAlienResources is flaky
Neil Conway created MESOS-7514:
----------------------------------
Summary: ReservationTest.PreventUnreservingAlienResources is flaky
Key: MESOS-7514
URL: https://issues.apache.org/jira/browse/MESOS-7514
Project: Mesos
Issue Type: Bug
Reporter: Neil Conway
Assignee: Gastón Kleiman
This repros consistently for me on a many-core box:
{noformat}
[ RUN ] ReservationTest.PreventUnreservingAlienResources
I0516 11:15:51.562351 26940 cluster.cpp:162] Creating default 'local' authorizer
I0516 11:15:51.656114 26996 master.cpp:436] Master 0495c63b-8319-43fb-809c-6a18c7005548 (core-dev) started on 10.0.49.2:33500
I0516 11:15:51.656159 26996 master.cpp:438] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="5ms" --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/PGp9GX/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" --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" --root_submissions="true" --user_sorter="drf" --version="false" --webui_dir="/usr/local/share/mesos/webui" --work_dir="/tmp/PGp9GX/master" --zk_session_timeout="10secs"
I0516 11:15:51.658516 26996 master.cpp:488] Master only allowing authenticated frameworks to register
I0516 11:15:51.658540 26996 master.cpp:502] Master only allowing authenticated agents to register
I0516 11:15:51.658597 26996 master.cpp:515] Master only allowing authenticated HTTP frameworks to register
I0516 11:15:51.658615 26996 credentials.hpp:37] Loading credentials for authentication from '/tmp/PGp9GX/credentials'
I0516 11:15:51.659363 26996 master.cpp:560] Using default 'crammd5' authenticator
I0516 11:15:51.659560 26996 authenticator.cpp:519] Initializing server SASL
I0516 11:15:51.660568 26996 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
I0516 11:15:51.660923 26996 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
I0516 11:15:51.661057 26996 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
I0516 11:15:51.661219 26996 master.cpp:640] Authorization enabled
I0516 11:15:51.672745 26976 master.cpp:2161] Elected as the leading master!
I0516 11:15:51.672835 26976 master.cpp:1700] Recovering from registrar
I0516 11:15:51.676582 26987 registrar.cpp:389] Successfully fetched the registry (0B) in 3.4112ms
I0516 11:15:51.676875 26987 registrar.cpp:493] Applied 1 operations in 56756ns; attempting to update the registry
I0516 11:15:51.680197 26987 registrar.cpp:550] Successfully updated the registry in 3.24608ms
I0516 11:15:51.680672 26987 registrar.cpp:422] Successfully recovered registrar
I0516 11:15:51.681761 26964 master.cpp:1799] Recovered 0 agents from the registry (119B); allowing 10mins for agents to re-register
I0516 11:15:51.779008 26940 containerizer.cpp:221] Using isolation: posix/cpu,posix/mem,filesystem/posix,network/cni
W0516 11:15:51.779985 26940 backend.cpp:76] Failed to create 'overlay' backend: OverlayBackend requires root privileges
W0516 11:15:51.780287 26940 backend.cpp:76] Failed to create 'bind' backend: BindBackend requires root privileges
I0516 11:15:51.780387 26940 provisioner.cpp:249] Using default backend 'copy'
I0516 11:15:51.783296 26940 cluster.cpp:448] Creating default 'local' authorizer
I0516 11:15:51.785317 26971 slave.cpp:225] Mesos agent started on (1)@10.0.49.2:33500
I0516 11:15:51.785373 26971 slave.cpp:226] 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/ReservationTest_PreventUnreservingAlienResources_dpHyhe/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/ReservationTest_PreventUnreservingAlienResources_dpHyhe/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/ReservationTest_PreventUnreservingAlienResources_dpHyhe/http_credentials" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="posix" --launcher_dir="/home/nrc/build-mesos-default-opts/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="cpus:1;mem:512" --revocable_cpu_low_priority="true" --runtime_dir="/tmp/ReservationTest_PreventUnreservingAlienResources_dpHyhe" --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/ReservationTest_PreventUnreservingAlienResources_HKalZ5"
I0516 11:15:51.785936 26971 credentials.hpp:86] Loading credential for authentication from '/tmp/ReservationTest_PreventUnreservingAlienResources_dpHyhe/credential'
I0516 11:15:51.786228 26971 slave.cpp:258] Agent using credential for: test-principal
I0516 11:15:51.786305 26971 credentials.hpp:37] Loading credentials for authentication from '/tmp/ReservationTest_PreventUnreservingAlienResources_dpHyhe/http_credentials'
I0516 11:15:51.786649 26971 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
I0516 11:15:51.786824 26971 http.cpp:975] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readwrite'
I0516 11:15:52.054072 26940 sched.cpp:232] Version: 1.4.0
I0516 11:15:52.055325 26986 sched.cpp:336] New master detected at master@10.0.49.2:33500
I0516 11:15:52.055464 26986 sched.cpp:407] Authenticating with master master@10.0.49.2:33500
I0516 11:15:52.055497 26986 sched.cpp:414] Using default CRAM-MD5 authenticatee
I0516 11:15:52.056046 26957 authenticatee.cpp:97] Initializing client SASL
I0516 11:15:52.056252 26957 authenticatee.cpp:121] Creating new client SASL connection
I0516 11:15:52.148576 26994 master.cpp:7475] Authenticating scheduler-7c9e7904-3ce1-4327-9b2c-cb37f8bfd427@10.0.49.2:33500
I0516 11:15:52.149430 26981 authenticator.cpp:98] Creating new server SASL connection
I0516 11:15:52.225440 26982 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0516 11:15:52.225495 26982 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0516 11:15:52.225762 26969 authenticator.cpp:204] Received SASL authentication start
I0516 11:15:52.225909 26969 authenticator.cpp:326] Authentication requires more steps
I0516 11:15:52.226101 26963 authenticatee.cpp:259] Received SASL authentication step
I0516 11:15:52.226349 26961 authenticator.cpp:232] Received SASL authentication step
I0516 11:15:52.226532 26961 authenticator.cpp:318] Authentication success
I0516 11:15:52.226686 26984 authenticatee.cpp:299] Authentication success
I0516 11:15:52.227181 26954 sched.cpp:513] Successfully authenticated with master master@10.0.49.2:33500
I0516 11:15:52.227304 26999 master.cpp:7505] Successfully authenticated principal 'test-principal' at scheduler-7c9e7904-3ce1-4327-9b2c-cb37f8bfd427@10.0.49.2:33500
I0516 11:15:52.227702 26999 master.cpp:2813] Received SUBSCRIBE call for framework 'framework2' at scheduler-7c9e7904-3ce1-4327-9b2c-cb37f8bfd427@10.0.49.2:33500
I0516 11:15:52.227875 26999 master.cpp:2197] Authorizing framework principal 'test-principal' to receive offers for roles '{ role1 }'
I0516 11:15:52.228842 26959 master.cpp:2890] Subscribing framework framework2 with checkpointing disabled and capabilities [ ]
I0516 11:15:52.230041 27003 sched.cpp:759] Framework registered with 0495c63b-8319-43fb-809c-6a18c7005548-0000
I0516 11:15:52.230589 26983 hierarchical.cpp:273] Added framework 0495c63b-8319-43fb-809c-6a18c7005548-0000
I0516 11:15:56.888407 26971 slave.cpp:529] Agent resources: cpus(*):1; mem(*):512; disk(*):46053; ports(*):[31000-32000]
I0516 11:15:56.888525 26971 slave.cpp:537] Agent attributes: [ ]
I0516 11:15:56.888556 26971 slave.cpp:542] Agent hostname: core-dev
I0516 11:15:56.888842 26969 status_update_manager.cpp:177] Pausing sending status updates
I0516 11:15:56.893031 26965 state.cpp:62] Recovering state from '/tmp/ReservationTest_PreventUnreservingAlienResources_HKalZ5/meta'
I0516 11:15:56.893909 26965 status_update_manager.cpp:203] Recovering status update manager
I0516 11:15:56.894201 26957 containerizer.cpp:608] Recovering containerizer
I0516 11:15:56.897639 26985 provisioner.cpp:410] Provisioner recovery complete
I0516 11:15:56.898098 26958 slave.cpp:5974] Finished recovery
I0516 11:15:56.899045 26958 slave.cpp:922] New master detected at master@10.0.49.2:33500
I0516 11:15:56.899058 26975 status_update_manager.cpp:177] Pausing sending status updates
I0516 11:15:56.899153 26958 slave.cpp:957] Detecting new master
I0516 11:15:56.901453 26994 slave.cpp:984] Authenticating with master master@10.0.49.2:33500
I0516 11:15:56.901533 26994 slave.cpp:995] Using default CRAM-MD5 authenticatee
I0516 11:15:56.901800 26991 authenticatee.cpp:121] Creating new client SASL connection
I0516 11:15:56.985676 26991 master.cpp:7475] Authenticating slave(1)@10.0.49.2:33500
I0516 11:15:56.985977 27002 authenticator.cpp:98] Creating new server SASL connection
I0516 11:15:57.082128 26956 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0516 11:15:57.082173 26956 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0516 11:15:57.082321 26964 authenticator.cpp:204] Received SASL authentication start
I0516 11:15:57.082424 26964 authenticator.cpp:326] Authentication requires more steps
I0516 11:15:57.083065 26960 authenticatee.cpp:259] Received SASL authentication step
I0516 11:15:57.083237 26960 authenticator.cpp:232] Received SASL authentication step
I0516 11:15:57.083328 26960 authenticator.cpp:318] Authentication success
I0516 11:15:57.083468 26971 authenticatee.cpp:299] Authentication success
I0516 11:15:57.083508 26969 master.cpp:7505] Successfully authenticated principal 'test-principal' at slave(1)@10.0.49.2:33500
I0516 11:15:57.084012 26960 slave.cpp:1079] Successfully authenticated with master master@10.0.49.2:33500
I0516 11:15:57.084687 26999 master.cpp:5429] Received register agent message from slave(1)@10.0.49.2:33500 (core-dev)
I0516 11:15:57.084975 26999 master.cpp:3659] Authorizing agent with principal 'test-principal'
I0516 11:15:57.085680 26985 master.cpp:5564] Registering agent at slave(1)@10.0.49.2:33500 (core-dev) with id 0495c63b-8319-43fb-809c-6a18c7005548-S0
I0516 11:15:57.086575 26961 registrar.cpp:493] Applied 1 operations in 99854ns; attempting to update the registry
I0516 11:15:57.089735 26961 registrar.cpp:550] Successfully updated the registry in 3.078912ms
I0516 11:15:57.091326 26983 master.cpp:5639] Registered agent 0495c63b-8319-43fb-809c-6a18c7005548-S0 at slave(1)@10.0.49.2:33500 (core-dev) with cpus(*):1; mem(*):512; disk(*):46053; ports(*):[31000-32000]
I0516 11:15:57.091648 27001 slave.cpp:1125] Registered with master master@10.0.49.2:33500; given agent ID 0495c63b-8319-43fb-809c-6a18c7005548-S0
I0516 11:15:57.091702 26960 hierarchical.cpp:525] Added agent 0495c63b-8319-43fb-809c-6a18c7005548-S0 (core-dev) with cpus(*):1; mem(*):512; disk(*):46053; ports(*):[31000-32000] (allocated: {})
I0516 11:15:57.091833 26995 status_update_manager.cpp:184] Resuming sending status updates
I0516 11:15:57.092473 27001 slave.cpp:1191] Forwarding total oversubscribed resources {}
I0516 11:15:57.092727 26976 master.cpp:6324] Received update of agent 0495c63b-8319-43fb-809c-6a18c7005548-S0 at slave(1)@10.0.49.2:33500 (core-dev) with total oversubscribed resources {}
I0516 11:15:57.093745 26990 master.cpp:7305] Sending 1 offers to framework 0495c63b-8319-43fb-809c-6a18c7005548-0000 (framework2) at scheduler-7c9e7904-3ce1-4327-9b2c-cb37f8bfd427@10.0.49.2:33500
I0516 11:15:57.097033 26995 master.cpp:3875] Processing ACCEPT call for offers: [ 0495c63b-8319-43fb-809c-6a18c7005548-O0 ] on agent 0495c63b-8319-43fb-809c-6a18c7005548-S0 at slave(1)@10.0.49.2:33500 (core-dev) for framework 0495c63b-8319-43fb-809c-6a18c7005548-0000 (framework2) at scheduler-7c9e7904-3ce1-4327-9b2c-cb37f8bfd427@10.0.49.2:33500
I0516 11:15:57.097271 26995 master.cpp:3466] Authorizing principal 'test-principal' to reserve resources 'mem(role1, test-principal)(allocated: role1):256'
I0516 11:15:57.098811 26995 master.cpp:4173] Applying RESERVE operation for resources mem(role1, test-principal)(allocated: role1):256 from framework 0495c63b-8319-43fb-809c-6a18c7005548-0000 (framework2) at scheduler-7c9e7904-3ce1-4327-9b2c-cb37f8bfd427@10.0.49.2:33500 to agent 0495c63b-8319-43fb-809c-6a18c7005548-S0 at slave(1)@10.0.49.2:33500 (core-dev)
I0516 11:15:57.099071 26995 master.cpp:8721] Sending checkpointed resources mem(role1, test-principal):256 to agent 0495c63b-8319-43fb-809c-6a18c7005548-S0 at slave(1)@10.0.49.2:33500 (core-dev)
I0516 11:15:57.099925 26983 slave.cpp:3348] Updated checkpointed resources from {} to mem(role1, test-principal):256
I0516 11:15:57.101491 27003 hierarchical.cpp:850] Updated allocation of framework 0495c63b-8319-43fb-809c-6a18c7005548-0000 on agent 0495c63b-8319-43fb-809c-6a18c7005548-S0 from cpus(*)(allocated: role1):1; mem(*)(allocated: role1):512; disk(*)(allocated: role1):46053; ports(*)(allocated: role1):[31000-32000] to cpus(*)(allocated: role1):1; mem(*)(allocated: role1):256; disk(*)(allocated: role1):46053; ports(*)(allocated: role1):[31000-32000]; mem(role1, test-principal)(allocated: role1):256
I0516 11:15:57.103813 27001 master.cpp:7305] Sending 1 offers to framework 0495c63b-8319-43fb-809c-6a18c7005548-0000 (framework2) at scheduler-7c9e7904-3ce1-4327-9b2c-cb37f8bfd427@10.0.49.2:33500
I0516 11:15:57.105666 26997 master.cpp:4836] Processing DECLINE call for offers: [ 0495c63b-8319-43fb-809c-6a18c7005548-O1 ] for framework 0495c63b-8319-43fb-809c-6a18c7005548-0000 (framework2) at scheduler-7c9e7904-3ce1-4327-9b2c-cb37f8bfd427@10.0.49.2:33500
I0516 11:15:57.105686 26940 sched.cpp:232] Version: 1.4.0
I0516 11:15:57.106356 26999 sched.cpp:336] New master detected at master@10.0.49.2:33500
I0516 11:15:57.106465 26999 sched.cpp:407] Authenticating with master master@10.0.49.2:33500
I0516 11:15:57.106505 26999 sched.cpp:414] Using default CRAM-MD5 authenticatee
I0516 11:15:57.106715 26959 authenticatee.cpp:121] Creating new client SASL connection
W0516 11:15:57.107017 26996 hierarchical.cpp:1135] Using the default value of 'refuse_seconds' to create the refused resources filter because the input value is invalid: Argument out of the range that a Duration can represent due to int64_t's size limit
W0516 11:16:02.107826 26970 sched.cpp:537] Authentication timed out
I0516 11:16:02.111680 26970 master.cpp:7305] Sending 1 offers to framework 0495c63b-8319-43fb-809c-6a18c7005548-0000 (framework2) at scheduler-7c9e7904-3ce1-4327-9b2c-cb37f8bfd427@10.0.49.2:33500
../../mesos/src/tests/reservation_tests.cpp:2292: Failure
Mock function called more times than expected - returning directly.
Function call: resourceOffers(0x7ffe88cc88a0, @0x7f2a61651950 { 152-byte object <70-B1 78-7B 2A-7F 00-00 00-00 00-00 00-00 00-00 1F-02 00-00 00-00 00-00 00-2A 00-14 2A-7F 00-00 A0-2A 00-14 2A-7F 00-00 40-2B 00-14 2A-7F 00-00 E0-2B 00-14 2A-7F 00-00 20-11 00-14 2A-7F 00-00 ... 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 2A-7F 00-00 00-00 00-00 00-00 00-00 70-2D 00-14 2A-7F 00-00> })
Expected: to be called once
Actual: called twice - over-saturated and active
*** Aborted at 1494958562 (unix time) try "date -d @1494958562" if you are using GNU date ***
PC: @ 0x1f872d6 testing::UnitTest::AddTestPartResult()
*** SIGSEGV (@0x0) received by PID 26940 (TID 0x7f2a61652700) from PID 0; stack trace: ***
@ 0x7f2a72a6d370 (unknown)
@ 0x1f872d6 testing::UnitTest::AddTestPartResult()
@ 0x1f7be4d testing::internal::AssertHelper::operator=()
@ 0x1f9df1c testing::internal::GoogleTestFailureReporter::ReportFailure()
@ 0xbc4388 testing::internal::Expect()
@ 0x1f9540e testing::internal::UntypedFunctionMockerBase::UntypedInvokeWith()
@ 0x160227f testing::internal::FunctionMockerBase<>::InvokeWith()
@ 0x15fcdb3 testing::internal::FunctionMocker<>::Invoke()
@ 0x15fb65d mesos::internal::tests::MockScheduler::resourceOffers()
@ 0x7f2a791de6c4 mesos::internal::SchedulerProcess::resourceOffers()
@ 0x7f2a791f0aa7 ProtobufProcess<>::handler2<>()
@ 0x7f2a7920b60c _ZNSt5_BindIFPFvPN5mesos8internal16SchedulerProcessEMS2_FvRKN7process4UPIDERKSt6vectorINS0_5OfferESaIS9_EERKS8_ISsSaISsEEEMNS1_21ResourceOffersMessageEKFRKN6google8protobuf16RepeatedPtrFieldIS9_EEvEMSK_KFRKNSN_ISsEEvES7_RKSsES3_SJ_SS_SX_St12_PlaceholderILi1EES12_ILi2EEEE6__callIvIS7_SZ_EILm0ELm1ELm2ELm3ELm4ELm5EEEET_OSt5tupleIIDpT0_EESt12_Index_tupleIIXspT1_EEE
@ 0x7f2a792066f1 std::_Bind<>::operator()<>()
@ 0x7f2a79200120 std::_Function_handler<>::_M_invoke()
@ 0x134ccdd std::function<>::operator()()
@ 0x7f2a7920d623 ProtobufProcess<>::visit()
@ 0x7f2a78f6f57a process::MessageEvent::visit()
@ 0xb0531a process::ProcessBase::serve()
I0516 11:16:02.348495 26983 master.cpp:7475] Authenticating scheduler-6d72583d-dd86-4945-aa3d-92e0822fcfbb@10.0.49.2:33500
I0516 11:16:02.348753 26957 sched.cpp:477] Failed to authenticate with master master@10.0.49.2:33500: Authentication discarded
W0516 11:16:02.349424 26974 master.cpp:7502] Failed to authenticate scheduler-6d72583d-dd86-4945-aa3d-92e0822fcfbb@10.0.49.2:33500: Failed to communicate with authenticatee
@ 0x7f2a7a28e94f process::ProcessManager::resume()
@ 0x7f2a7a28b100 _ZZN7process14ProcessManager12init_threadsEvENKUt_clEv
@ 0x7f2a7a29d36a _ZNSt12_Bind_simpleIFZN7process14ProcessManager12init_threadsEvEUt_vEE9_M_invokeIIEEEvSt12_Index_tupleIIXspT_EEE
@ 0x7f2a7a29d2ae _ZNSt12_Bind_simpleIFZN7process14ProcessManager12init_threadsEvEUt_vEEclEv
@ 0x7f2a7a29d238 _ZNSt6thread5_ImplISt12_Bind_simpleIFZN7process14ProcessManager12init_threadsEvEUt_vEEE6_M_runEv
@ 0x7f2a721e8230 (unknown)
@ 0x7f2a72a65dc5 start_thread
@ 0x7f2a7195173d __clone
zsh: segmentation fault (core dumped) ./src/mesos-tests --verbose --gtest_repeat=100 --gtest_break_on_failure
{noformat}
--
This message was sent by Atlassian JIRA
(v6.3.15#6346)