Details
-
Bug
-
Status: Resolved
-
Major
-
Resolution: Fixed
-
1.10.0
-
None
-
None
Description
There seems to be two kinds of flakes:
[ RUN ] ContentType/MasterAPITest.ReservationUpdate/0
I0306 13:09:52.496989 3096 cluster.cpp:186] Creating default 'local' authorizer
I0306 13:09:52.498562 3112 master.cpp:443] Master 6ca18692-2b4b-4219-8e2f-78bdf56dc5d8 (core1.hw.ca1.mesosphere.com) started on 66.70.182.167:35079
I0306 13:09:52.498643 3112 master.cpp:446] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="1000secs" --allocator="hierarchical" --authenticate_agents="true" --authenticate_frameworks="true" --authenticate_http_frameworks="true" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authentication_v0_timeout="15secs" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/VOU6Oj/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_operator_event_stream_subscribers="1000" --max_unreachable_tasks_per_framework="1000" --memory_profiling="false" --min_allocatable_resources="cpus:0.01|mem:32" --port="5050" --publish_per_framework_metrics="true" --quiet="false" --recovery_agent_removal_limit="100%" --registry="in_memory" --registry_fetch_timeout="1mins" --registry_gc_interval="15mins" --registry_max_agent_age="2weeks" --registry_max_agent_count="102400" --registry_store_timeout="100secs" --registry_strict="false" --require_agent_domain="false" --role_sorter="drf" --root_submissions="true" --version="false" --webui_dir="/usr/local/share/mesos/webui" --work_dir="/tmp/VOU6Oj/master" --zk_session_timeout="10secs"
I0306 13:09:52.498890 3112 master.cpp:495] Master only allowing authenticated frameworks to register
I0306 13:09:52.498986 3112 master.cpp:501] Master only allowing authenticated agents to register
I0306 13:09:52.499089 3112 master.cpp:507] Master only allowing authenticated HTTP frameworks to register
I0306 13:09:52.499109 3112 credentials.hpp:37] Loading credentials for authentication from '/tmp/VOU6Oj/credentials'
I0306 13:09:52.499182 3112 master.cpp:551] Using default 'crammd5' authenticator
I0306 13:09:52.499311 3112 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
I0306 13:09:52.499446 3112 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
I0306 13:09:52.499575 3112 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
I0306 13:09:52.499667 3112 master.cpp:632] Authorization enabled
I0306 13:09:52.500351 3112 hierarchical.cpp:567] Initialized hierarchical allocator process
I0306 13:09:52.500371 3153 whitelist_watcher.cpp:77] No whitelist given
I0306 13:09:52.500718 3149 master.cpp:2165] Elected as the leading master!
I0306 13:09:52.500874 3149 master.cpp:1661] Recovering from registrar
I0306 13:09:52.500926 3149 registrar.cpp:339] Recovering registrar
I0306 13:09:52.501082 3149 registrar.cpp:383] Successfully fetched the registry (0B) in 117248ns
I0306 13:09:52.501142 3149 registrar.cpp:487] Applied 1 operations in 14299ns; attempting to update the registry
I0306 13:09:52.501288 3142 registrar.cpp:544] Successfully updated the registry in 127744ns
I0306 13:09:52.501333 3142 registrar.cpp:416] Successfully recovered registrar
I0306 13:09:52.501436 3142 master.cpp:1814] Recovered 0 agents from the registry (181B); allowing 10mins for agents to reregister
I0306 13:09:52.501466 3148 hierarchical.cpp:606] Skipping recovery of hierarchical allocator: nothing to recover
W0306 13:09:52.503216 3096 process.cpp:2877] Attempted to spawn already running process files@66.70.182.167:35079
I0306 13:09:52.503903 3096 containerizer.cpp:317] Using isolation { environment_secret, filesystem/posix, network/cni, posix/cpu, posix/mem }
I0306 13:09:52.508648 3096 linux_launcher.cpp:144] Using /sys/fs/cgroup/freezer as the freezer hierarchy for the Linux launcher
I0306 13:09:52.509362 3096 provisioner.cpp:277] Provisioner backend 'overlay' is not supported on '/tmp/ContentType_MasterAPITest_ReservationUpdate_0_gt8tzQ/provisioner': Backend 'overlay' is not supported due to missing d_type support on the underlying filesystem
I0306 13:09:52.509479 3096 provisioner.cpp:294] Using default backend 'copy'
I0306 13:09:52.510510 3096 cluster.cpp:533] Creating default 'local' authorizer
I0306 13:09:52.511289 3151 slave.cpp:274] Mesos agent started on (3249)@66.70.182.167:35079
I0306 13:09:52.511371 3151 slave.cpp:275] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/VOU6Oj/qxKg4T/store/appc" --authenticate_http_readonly="true" --authenticate_http_readwrite="false" --authenticatee="crammd5" --authentication_backoff_factor="1secs" --authentication_timeout_max="1mins" --authentication_timeout_min="5secs" --authorizer="local" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_destroy_timeout="1mins" --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/VOU6Oj/qxKg4T/credential" --default_role="*" --disallow_sharing_agent_ipc_namespace="false" --disallow_sharing_agent_pid_namespace="false" --disk_watch_interval="1mins" --docker="docker" --docker_ignore_runtime="false" --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/VOU6Oj/qxKg4T/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --docker_volume_chown="false" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_reregistration_timeout="2secs" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/VOU6Oj/qxKg4T/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/tmp/VOU6Oj/qxKg4T/frameworks" --gc_delay="1weeks" --gc_disk_headroom="0.1" --gc_non_executor_container_sandboxes="false" --help="false" --hostname_lookup="true" --http_command_executor="false" --http_credentials="/tmp/VOU6Oj/qxKg4T/http_credentials" --http_executor_domain_sockets="false" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="linux" --launcher_dir="/home/asekretenko/b/mesos_cmake/src" --logbufsecs="0" --logging_level="INFO" --max_completed_executors_per_framework="150" --memory_profiling="false" --network_cni_metrics="true" --network_cni_root_dir_persist="false" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --port="5051" --qos_correction_interval_min="0ns" --quiet="false" --reconfiguration_policy="equal" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]" --revocable_cpu_low_priority="true" --runtime_dir="/tmp/ContentType_MasterAPITest_ReservationUpdate_0_Q9aSjn" --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/ContentType_MasterAPITest_ReservationUpdate_0_gt8tzQ" --zk_session_timeout="10secs"
I0306 13:09:52.511754 3151 credentials.hpp:86] Loading credential for authentication from '/tmp/VOU6Oj/qxKg4T/credential'
I0306 13:09:52.511914 3151 slave.cpp:307] Agent using credential for: test-principal
I0306 13:09:52.512038 3151 credentials.hpp:37] Loading credentials for authentication from '/tmp/VOU6Oj/qxKg4T/http_credentials'
I0306 13:09:52.512202 3151 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
I0306 13:09:52.512348 3151 disk_profile_adaptor.cpp:78] Creating default disk profile adaptor module
I0306 13:09:52.512687 3151 slave.cpp:622] Agent resources: [{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
I0306 13:09:52.512864 3151 slave.cpp:630] Agent attributes: [ ]
I0306 13:09:52.512979 3151 slave.cpp:639] Agent hostname: core1.hw.ca1.mesosphere.com
I0306 13:09:52.513382 3151 task_status_update_manager.cpp:181] Pausing sending task status updates
I0306 13:09:52.513412 3104 status_update_manager_process.hpp:379] Pausing operation status update manager
I0306 13:09:52.513572 3150 state.cpp:68] Recovering state from '/tmp/ContentType_MasterAPITest_ReservationUpdate_0_gt8tzQ/meta'
I0306 13:09:52.513773 3150 slave.cpp:7606] Finished recovering checkpointed state from '/tmp/ContentType_MasterAPITest_ReservationUpdate_0_gt8tzQ/meta', beginning agent recovery
I0306 13:09:52.513873 3150 task_status_update_manager.cpp:207] Recovering task status update manager
I0306 13:09:52.513978 3150 containerizer.cpp:820] Recovering Mesos containers
I0306 13:09:52.514060 3150 linux_launcher.cpp:286] Recovering Linux launcher
I0306 13:09:52.514261 3150 containerizer.cpp:1160] Recovering isolators
I0306 13:09:52.514606 3165 containerizer.cpp:1199] Recovering provisioner
I0306 13:09:52.514755 3165 provisioner.cpp:518] Provisioner recovery complete
I0306 13:09:52.514951 3165 composing.cpp:339] Finished recovering all containerizers
I0306 13:09:52.515048 3165 slave.cpp:8088] Recovering executors
I0306 13:09:52.515100 3165 slave.cpp:8241] Finished recovery
I0306 13:09:52.515558 3165 slave.cpp:1454] New master detected at master@66.70.182.167:35079
I0306 13:09:52.515693 3165 slave.cpp:1519] Detecting new master
I0306 13:09:52.515602 3128 status_update_manager_process.hpp:379] Pausing operation status update manager
I0306 13:09:52.515588 3129 task_status_update_manager.cpp:181] Pausing sending task status updates
I0306 13:09:52.537189 3132 slave.cpp:1546] Authenticating with master master@66.70.182.167:35079
I0306 13:09:52.537283 3132 slave.cpp:1555] Using default CRAM-MD5 authenticatee
I0306 13:09:52.537426 3132 authenticatee.cpp:121] Creating new client SASL connection
I0306 13:09:52.537626 3132 master.cpp:9676] Authenticating slave(3249)@66.70.182.167:35079
I0306 13:09:52.537786 3132 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(3249)@66.70.182.167:35079
I0306 13:09:52.537964 3132 authenticator.cpp:98] Creating new server SASL connection
I0306 13:09:52.538143 3132 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0306 13:09:52.538264 3132 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0306 13:09:52.538404 3132 authenticator.cpp:204] Received SASL authentication start
I0306 13:09:52.538553 3132 authenticator.cpp:326] Authentication requires more steps
I0306 13:09:52.538658 3132 authenticatee.cpp:259] Received SASL authentication step
I0306 13:09:52.538777 3132 authenticator.cpp:232] Received SASL authentication step
I0306 13:09:52.538908 3132 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'core1.hw.ca1.mesosphere.com' server FQDN: 'core1.hw.ca1.mesosphere.com' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0306 13:09:52.538987 3132 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0306 13:09:52.539018 3132 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0306 13:09:52.539093 3132 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'core1.hw.ca1.mesosphere.com' server FQDN: 'core1.hw.ca1.mesosphere.com' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0306 13:09:52.539166 3132 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0306 13:09:52.539186 3132 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0306 13:09:52.539206 3132 authenticator.cpp:318] Authentication success
I0306 13:09:52.539314 3132 authenticatee.cpp:299] Authentication success
I0306 13:09:52.539345 3103 master.cpp:9708] Successfully authenticated principal 'test-principal' at slave(3249)@66.70.182.167:35079
I0306 13:09:52.539366 3131 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(3249)@66.70.182.167:35079
I0306 13:09:52.539508 3125 slave.cpp:1646] Successfully authenticated with master master@66.70.182.167:35079
I0306 13:09:52.539616 3125 slave.cpp:2096] Will retry registration in 6.629717ms if necessary
I0306 13:09:52.539661 3159 master.cpp:6174] Received register agent message from slave(3249)@66.70.182.167:35079 (core1.hw.ca1.mesosphere.com)
I0306 13:09:52.539732 3159 master.cpp:3705] Authorizing principal 'test-principal' to perform action REGISTER_AGENT on ANY object
I0306 13:09:52.539860 3159 master.cpp:6241] Authorized registration of agent at slave(3249)@66.70.182.167:35079 (core1.hw.ca1.mesosphere.com)
I0306 13:09:52.539891 3159 master.cpp:6353] Registering agent at slave(3249)@66.70.182.167:35079 (core1.hw.ca1.mesosphere.com) with id 6ca18692-2b4b-4219-8e2f-78bdf56dc5d8-S0
I0306 13:09:52.540021 3159 registrar.cpp:487] Applied 1 operations in 51485ns; attempting to update the registry
I0306 13:09:52.540145 3159 registrar.cpp:544] Successfully updated the registry in 106240ns
I0306 13:09:52.540196 3159 master.cpp:6401] Admitted agent 6ca18692-2b4b-4219-8e2f-78bdf56dc5d8-S0 at slave(3249)@66.70.182.167:35079 (core1.hw.ca1.mesosphere.com)
I0306 13:09:52.540336 3159 master.cpp:6446] Registered agent 6ca18692-2b4b-4219-8e2f-78bdf56dc5d8-S0 at slave(3249)@66.70.182.167:35079 (core1.hw.ca1.mesosphere.com) with cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0306 13:09:52.540423 3159 hierarchical.cpp:959] Added agent 6ca18692-2b4b-4219-8e2f-78bdf56dc5d8-S0 (core1.hw.ca1.mesosphere.com) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (offered or allocated: {})
I0306 13:09:52.540477 3159 hierarchical.cpp:1853] Performed allocation for 1 agents in 17277ns
I0306 13:09:52.540519 3159 slave.cpp:1679] Registered with master master@66.70.182.167:35079; given agent ID 6ca18692-2b4b-4219-8e2f-78bdf56dc5d8-S0
I0306 13:09:52.540838 3159 slave.cpp:1714] Checkpointing SlaveInfo to '/tmp/ContentType_MasterAPITest_ReservationUpdate_0_gt8tzQ/meta/slaves/6ca18692-2b4b-4219-8e2f-78bdf56dc5d8-S0/slave.info'
I0306 13:09:52.541118 3140 task_status_update_manager.cpp:188] Resuming sending task status updates
I0306 13:09:52.541126 3159 slave.cpp:1766] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"wu2uRb4sS++ThCnAQ5fKUg=="},"slave_id":{"value":"6ca18692-2b4b-4219-8e2f-78bdf56dc5d8-S0"},"update_oversubscribed_resources":false}
I0306 13:09:52.541409 3159 master.cpp:7584] Ignoring update on agent 6ca18692-2b4b-4219-8e2f-78bdf56dc5d8-S0 at slave(3249)@66.70.182.167:35079 (core1.hw.ca1.mesosphere.com) as it reports no changes
I0306 13:09:52.541151 3150 status_update_manager_process.hpp:385] Resuming operation status update manager
I0306 13:09:52.542691 3163 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1'
I0306 13:09:52.542994 3163 http.cpp:1405] HTTP POST for /master/api/v1 from 66.70.182.167:37076
I0306 13:09:52.543073 3163 http.cpp:277] Processing call RESERVE_RESOURCES
I0306 13:09:52.543253 3163 master.cpp:3705] Authorizing principal 'test-principal' to perform action UNRESERVE_RESOURCES on object {"value":"test-principal","resource":{"name":"cpus","type":"SCALAR","scalar":{"value":1.0},"reservations":[{"type":"DYNAMIC","role":"role","principal":"test-principal"},{"type":"DYNAMIC","role":"role/bar","principal":"test-principal"}]}}
I0306 13:09:52.543299 3163 master.cpp:3705] Authorizing principal 'test-principal' to perform action UNRESERVE_RESOURCES on object {"value":"test-principal","resource":{"name":"mem","type":"SCALAR","scalar":{"value":10.0},"reservations":[{"type":"DYNAMIC","role":"role","principal":"test-principal"},{"type":"DYNAMIC","role":"role/bar","principal":"test-principal"}]}}
I0306 13:09:52.543326 3163 master.cpp:3705] Authorizing principal 'test-principal' to perform action RESERVE_RESOURCES on object {"value":"role/foo","resource":{"name":"cpus","type":"SCALAR","scalar":{"value":1.0},"reservations":[{"type":"DYNAMIC","role":"role","principal":"test-principal"},{"type":"DYNAMIC","role":"role/foo","principal":"test-principal"}]}}
I0306 13:09:52.543602 3163 hierarchical.cpp:1346] Failed to update available resources on agent 6ca18692-2b4b-4219-8e2f-78bdf56dc5d8-S0: cpus:2; mem:1024; disk:1024; ports:[31000-32000] does not contain cpus(reservations: [(DYNAMIC,role,test-principal),(DYNAMIC,role/bar,test-principal)]):1; mem(reservations: [(DYNAMIC,role,test-principal),(DYNAMIC,role/bar,test-principal)]):10
I0306 13:09:52.545033 3145 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1'
I0306 13:09:52.545262 3145 http.cpp:1405] HTTP POST for /master/api/v1 from 66.70.182.167:37078
I0306 13:09:52.545316 3145 http.cpp:277] Processing call RESERVE_RESOURCES
I0306 13:09:52.545456 3145 master.cpp:3705] Authorizing principal 'test-principal' to perform action RESERVE_RESOURCES on object {"value":"role","resource":{"name":"cpus","type":"SCALAR","scalar":{"value":1.0},"reservations":[{"type":"DYNAMIC","role":"role","principal":"test-principal"}]}}
I0306 13:09:52.545492 3145 master.cpp:3705] Authorizing principal 'test-principal' to perform action RESERVE_RESOURCES on object {"value":"role/foo","resource":{"name":"cpus","type":"SCALAR","scalar":{"value":1.0},"reservations":[{"type":"DYNAMIC","role":"role","principal":"test-principal"},{"type":"DYNAMIC","role":"role/foo","principal":"test-principal"}]}}
I0306 13:09:52.546684 3105 process.cpp:3671] Handling HTTP event for process 'slave(3249)' with path: '/slave(3249)/state'
I0306 13:09:52.546962 3138 http.cpp:1405] HTTP GET for /slave(3249)/state from 66.70.182.167:37080
I0306 13:09:52.547515 3138 http.cpp:1422] HTTP GET for /slave(3249)/state from 66.70.182.167:37080: '200 OK' after 0.907776ms
/home/asekretenko/lsyncd/mesos/src/tests/api_tests.cpp:1541: Failure
Expected: reservations->values.size()
Which is: 0
To be equal to: 1u
Which is: 1
*** Aborted at 1583518192 (unix time) try "date -d @1583518192" if you are using GNU date ***
PC: @ 0x0 (unknown)
*** SIGSEGV (@0x0) received by PID 3096 (TID 0x7f8bae146140) from PID 0; stack trace: ***
@ 0x7f8ba9a83fb0 (unknown)
I0306 13:09:52.555222 3108 master.cpp:11649] Sending operation '' (uuid: 3a67d7b4-512a-40b3-aded-79676aa2ec76) to agent 6ca18692-2b4b-4219-8e2f-78bdf56dc5d8-S0 at slave(3249)@66.70.182.167:35079 (core1.hw.ca1.mesosphere.com)
I0306 13:09:52.555321 3108 slave.cpp:4466] Ignoring new checkpointed resources and operations identical to the current version
I0306 13:09:52.555375 3108 slave.cpp:9050] Updating the state of operation with no ID (uuid: 3a67d7b4-512a-40b3-aded-79676aa2ec76) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0306 13:09:52.555825 3108 slave.cpp:4554] Updated checkpointed resources from {} to cpus(reservations: [(DYNAMIC,role,test-principal),(DYNAMIC,role/foo,test-principal)]):1; mem(reservations: [(DYNAMIC,role,test-principal),(DYNAMIC,role/foo,test-principal)]):10
I0306 13:09:52.555869 3108 slave.cpp:4578] Updated checkpointed operations from [ ] to [ 3a67d7b4-512a-40b3-aded-79676aa2ec76 (RESERVE, latest state: OPERATION_FINISHED) ]
I0306 13:09:52.555932 3109 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: 240cbed9-0d41-4193-a0b0-b564ab9d4e55) for operation UUID 3a67d7b4-512a-40b3-aded-79676aa2ec76 on agent 6ca18692-2b4b-4219-8e2f-78bdf56dc5d8-S0
I0306 13:09:52.555951 3109 status_update_manager_process.hpp:414] Creating operation status update stream 3a67d7b4-512a-40b3-aded-79676aa2ec76 checkpoint=true
I0306 13:09:52.556180 3109 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: 240cbed9-0d41-4193-a0b0-b564ab9d4e55) for operation UUID 3a67d7b4-512a-40b3-aded-79676aa2ec76 on agent 6ca18692-2b4b-4219-8e2f-78bdf56dc5d8-S0
@ 0x32eb210 testing::UnitTest::AddTestPartResult()
@ 0x32eae5d testing::internal::AssertHelper::operator=()
@ 0xb1f98e mesos::internal::tests::MasterAPITest_ReservationUpdate_Test::TestBody()::$_1::operator()()
I0306 13:09:52.572075 3109 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: 240cbed9-0d41-4193-a0b0-b564ab9d4e55) for operation UUID 3a67d7b4-512a-40b3-aded-79676aa2ec76 on agent 6ca18692-2b4b-4219-8e2f-78bdf56dc5d8-S0
I0306 13:09:52.572214 3116 slave.cpp:9050] Updating the state of operation with no ID (uuid: 3a67d7b4-512a-40b3-aded-79676aa2ec76) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0306 13:09:52.572235 3116 slave.cpp:6441] Forwarding status update of operation with no ID (operation_uuid: 3a67d7b4-512a-40b3-aded-79676aa2ec76) for an operator API call
I0306 13:09:52.572284 3116 master.cpp:11301] Updating the state of operation '' (uuid: 3a67d7b4-512a-40b3-aded-79676aa2ec76) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0306 13:09:52.572373 3116 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: 240cbed9-0d41-4193-a0b0-b564ab9d4e55) for stream 3a67d7b4-512a-40b3-aded-79676aa2ec76
I0306 13:09:52.572397 3116 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: 240cbed9-0d41-4193-a0b0-b564ab9d4e55) for operation UUID 3a67d7b4-512a-40b3-aded-79676aa2ec76 on agent 6ca18692-2b4b-4219-8e2f-78bdf56dc5d8-S0
I0306 13:09:52.572896 3116 status_update_manager_process.hpp:490] Cleaning up operation status update stream 3a67d7b4-512a-40b3-aded-79676aa2ec76
I0306 13:09:52.573267 3116 slave.cpp:4578] Updated checkpointed operations from [ 3a67d7b4-512a-40b3-aded-79676aa2ec76 (RESERVE, latest state: OPERATION_FINISHED) ] to [ ]
@ 0xb1c242 mesos::internal::tests::MasterAPITest_ReservationUpdate_Test::TestBody()
@ 0x330e494 testing::internal::HandleExceptionsInMethodIfSupported<>()
@ 0x32f4ff1 testing::Test::Run()
@ 0x32f5f90 testing::TestInfo::Run()
@ 0x32f6707 testing::TestCase::Run()
@ 0x32fea87 testing::internal::UnitTestImpl::RunAllTests()
@ 0x330ef54 testing::internal::HandleExceptionsInMethodIfSupported<>()
@ 0x32fe65a testing::UnitTest::Run()
@ 0x7f7224 main
@ 0x7f8ba56d411b __libc_start_main
@ 0x70465a _start
@ 0x0 (unknown)
[ RUN ] ContentType/MasterAPITest.ReservationUpdate/0
I0306 13:14:00.626860 18861 cluster.cpp:186] Creating default 'local' authorizer
I0306 13:14:00.628518 18906 master.cpp:443] Master 13016c18-4e40-461e-b9b5-43006bae2bf8 (core1.hw.ca1.mesosphere.com) started on 66.70.182.167:44211
I0306 13:14:00.628603 18906 master.cpp:446] Flags at startup: --acls="" --agent_ping_timeout="15secs" --agent_reregister_timeout="10mins" --allocation_interval="1000secs" --allocator="hierarchical" --authenticate_agents="true" --authenticate_frameworks="true" --authenticate_http_frameworks="true" --authenticate_http_readonly="true" --authenticate_http_readwrite="true" --authentication_v0_timeout="15secs" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/hL920v/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_operator_event_stream_subscribers="1000" --max_unreachable_tasks_per_framework="1000" --memory_profiling="false" --min_allocatable_resources="cpus:0.01|mem:32" --port="5050" --publish_per_framework_metrics="true" --quiet="false" --recovery_agent_removal_limit="100%" --registry="in_memory" --registry_fetch_timeout="1mins" --registry_gc_interval="15mins" --registry_max_agent_age="2weeks" --registry_max_agent_count="102400" --registry_store_timeout="100secs" --registry_strict="false" --require_agent_domain="false" --role_sorter="drf" --root_submissions="true" --version="false" --webui_dir="/usr/local/share/mesos/webui" --work_dir="/tmp/hL920v/master" --zk_session_timeout="10secs"
I0306 13:14:00.628851 18906 master.cpp:495] Master only allowing authenticated frameworks to register
I0306 13:14:00.628949 18906 master.cpp:501] Master only allowing authenticated agents to register
I0306 13:14:00.629029 18906 master.cpp:507] Master only allowing authenticated HTTP frameworks to register
I0306 13:14:00.629091 18906 credentials.hpp:37] Loading credentials for authentication from '/tmp/hL920v/credentials'
I0306 13:14:00.629184 18906 master.cpp:551] Using default 'crammd5' authenticator
I0306 13:14:00.629318 18906 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readonly'
I0306 13:14:00.629472 18906 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-readwrite'
I0306 13:14:00.629639 18906 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-master-scheduler'
I0306 13:14:00.629781 18906 master.cpp:632] Authorization enabled
I0306 13:14:00.629961 18887 hierarchical.cpp:567] Initialized hierarchical allocator process
I0306 13:14:00.629983 18930 whitelist_watcher.cpp:77] No whitelist given
I0306 13:14:00.630923 18906 master.cpp:2165] Elected as the leading master!
I0306 13:14:00.631055 18906 master.cpp:1661] Recovering from registrar
I0306 13:14:00.631192 18908 registrar.cpp:339] Recovering registrar
I0306 13:14:00.631314 18908 registrar.cpp:383] Successfully fetched the registry (0B) in 99072ns
I0306 13:14:00.631363 18908 registrar.cpp:487] Applied 1 operations in 21429ns; attempting to update the registry
I0306 13:14:00.631484 18910 registrar.cpp:544] Successfully updated the registry in 100096ns
I0306 13:14:00.631520 18910 registrar.cpp:416] Successfully recovered registrar
I0306 13:14:00.631659 18907 hierarchical.cpp:606] Skipping recovery of hierarchical allocator: nothing to recover
I0306 13:14:00.631660 18910 master.cpp:1814] Recovered 0 agents from the registry (181B); allowing 10mins for agents to reregister
W0306 13:14:00.633738 18861 process.cpp:2877] Attempted to spawn already running process files@66.70.182.167:44211
I0306 13:14:00.634596 18861 containerizer.cpp:317] Using isolation { environment_secret, filesystem/posix, network/cni, posix/cpu, posix/mem }
I0306 13:14:00.640466 18861 linux_launcher.cpp:144] Using /sys/fs/cgroup/freezer as the freezer hierarchy for the Linux launcher
I0306 13:14:00.641263 18861 provisioner.cpp:277] Provisioner backend 'overlay' is not supported on '/tmp/ContentType_MasterAPITest_ReservationUpdate_0_nvt6G5/provisioner': Backend 'overlay' is not supported due to missing d_type support on the underlying filesystem
I0306 13:14:00.641384 18861 provisioner.cpp:294] Using default backend 'copy'
I0306 13:14:00.642643 18861 cluster.cpp:533] Creating default 'local' authorizer
I0306 13:14:00.643729 18902 slave.cpp:274] Mesos agent started on (725)@66.70.182.167:44211
I0306 13:14:00.643817 18902 slave.cpp:275] Flags at startup: --acls="" --appc_simple_discovery_uri_prefix="http://" --appc_store_dir="/tmp/hL920v/Kuof3e/store/appc" --authenticate_http_readonly="true" --authenticate_http_readwrite="false" --authenticatee="crammd5" --authentication_backoff_factor="1secs" --authentication_timeout_max="1mins" --authentication_timeout_min="5secs" --authorizer="local" --cgroups_cpu_enable_pids_and_tids_count="false" --cgroups_destroy_timeout="1mins" --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/hL920v/Kuof3e/credential" --default_role="*" --disallow_sharing_agent_ipc_namespace="false" --disallow_sharing_agent_pid_namespace="false" --disk_watch_interval="1mins" --docker="docker" --docker_ignore_runtime="false" --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/hL920v/Kuof3e/store/docker" --docker_volume_checkpoint_dir="/var/run/mesos/isolators/docker/volume" --docker_volume_chown="false" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_reregistration_timeout="2secs" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/hL920v/Kuof3e/fetch" --fetcher_cache_size="2GB" --fetcher_stall_timeout="1mins" --frameworks_home="/tmp/hL920v/Kuof3e/frameworks" --gc_delay="1weeks" --gc_disk_headroom="0.1" --gc_non_executor_container_sandboxes="false" --help="false" --hostname_lookup="true" --http_command_executor="false" --http_credentials="/tmp/hL920v/Kuof3e/http_credentials" --http_executor_domain_sockets="false" --http_heartbeat_interval="30secs" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher="linux" --launcher_dir="/home/asekretenko/b/mesos_cmake/src" --logbufsecs="0" --logging_level="INFO" --max_completed_executors_per_framework="150" --memory_profiling="false" --network_cni_metrics="true" --network_cni_root_dir_persist="false" --oversubscribed_resources_interval="15secs" --perf_duration="10secs" --perf_interval="1mins" --port="5051" --qos_correction_interval_min="0ns" --quiet="false" --reconfiguration_policy="equal" --recover="reconnect" --recovery_timeout="15mins" --registration_backoff_factor="10ms" --resources="cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]" --revocable_cpu_low_priority="true" --runtime_dir="/tmp/ContentType_MasterAPITest_ReservationUpdate_0_1DzanF" --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/ContentType_MasterAPITest_ReservationUpdate_0_nvt6G5" --zk_session_timeout="10secs"
I0306 13:14:00.644186 18902 credentials.hpp:86] Loading credential for authentication from '/tmp/hL920v/Kuof3e/credential'
I0306 13:14:00.644345 18902 slave.cpp:307] Agent using credential for: test-principal
I0306 13:14:00.644450 18902 credentials.hpp:37] Loading credentials for authentication from '/tmp/hL920v/Kuof3e/http_credentials'
I0306 13:14:00.644613 18902 http.cpp:1265] Creating default 'basic' HTTP authenticator for realm 'mesos-agent-readonly'
I0306 13:14:00.644784 18902 disk_profile_adaptor.cpp:78] Creating default disk profile adaptor module
I0306 13:14:00.645176 18902 slave.cpp:622] Agent resources: [{"name":"cpus","scalar":{"value":2.0},"type":"SCALAR"},{"name":"mem","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"disk","scalar":{"value":1024.0},"type":"SCALAR"},{"name":"ports","ranges":{"range":[{"begin":31000,"end":32000}]},"type":"RANGES"}]
I0306 13:14:00.645345 18902 slave.cpp:630] Agent attributes: [ ]
I0306 13:14:00.645447 18902 slave.cpp:639] Agent hostname: core1.hw.ca1.mesosphere.com
I0306 13:14:00.645829 18902 task_status_update_manager.cpp:181] Pausing sending task status updates
I0306 13:14:00.645859 18904 status_update_manager_process.hpp:379] Pausing operation status update manager
I0306 13:14:00.646015 18883 state.cpp:68] Recovering state from '/tmp/ContentType_MasterAPITest_ReservationUpdate_0_nvt6G5/meta'
I0306 13:14:00.646224 18908 slave.cpp:7606] Finished recovering checkpointed state from '/tmp/ContentType_MasterAPITest_ReservationUpdate_0_nvt6G5/meta', beginning agent recovery
I0306 13:14:00.646306 18908 task_status_update_manager.cpp:207] Recovering task status update manager
I0306 13:14:00.646412 18917 containerizer.cpp:820] Recovering Mesos containers
I0306 13:14:00.646478 18917 linux_launcher.cpp:286] Recovering Linux launcher
I0306 13:14:00.646674 18876 containerizer.cpp:1160] Recovering isolators
I0306 13:14:00.646968 18914 containerizer.cpp:1199] Recovering provisioner
I0306 13:14:00.647114 18914 provisioner.cpp:518] Provisioner recovery complete
I0306 13:14:00.647282 18914 composing.cpp:339] Finished recovering all containerizers
I0306 13:14:00.647363 18914 slave.cpp:8088] Recovering executors
I0306 13:14:00.647413 18914 slave.cpp:8241] Finished recovery
I0306 13:14:00.648025 18914 slave.cpp:1454] New master detected at master@66.70.182.167:44211
I0306 13:14:00.648125 18914 slave.cpp:1519] Detecting new master
I0306 13:14:00.648073 18881 status_update_manager_process.hpp:379] Pausing operation status update manager
I0306 13:14:00.648057 18928 task_status_update_manager.cpp:181] Pausing sending task status updates
I0306 13:14:00.656507 18920 slave.cpp:1546] Authenticating with master master@66.70.182.167:44211
I0306 13:14:00.656548 18920 slave.cpp:1555] Using default CRAM-MD5 authenticatee
I0306 13:14:00.656635 18920 authenticatee.cpp:121] Creating new client SASL connection
I0306 13:14:00.656757 18920 master.cpp:9676] Authenticating slave(725)@66.70.182.167:44211
I0306 13:14:00.656816 18920 authenticator.cpp:414] Starting authentication session for crammd5-authenticatee(725)@66.70.182.167:44211
I0306 13:14:00.656884 18920 authenticator.cpp:98] Creating new server SASL connection
I0306 13:14:00.656949 18920 authenticatee.cpp:213] Received SASL authentication mechanisms: CRAM-MD5
I0306 13:14:00.656972 18920 authenticatee.cpp:239] Attempting to authenticate with mechanism 'CRAM-MD5'
I0306 13:14:00.657023 18920 authenticator.cpp:204] Received SASL authentication start
I0306 13:14:00.657076 18920 authenticator.cpp:326] Authentication requires more steps
I0306 13:14:00.657109 18920 authenticatee.cpp:259] Received SASL authentication step
I0306 13:14:00.657150 18920 authenticator.cpp:232] Received SASL authentication step
I0306 13:14:00.657174 18920 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'core1.hw.ca1.mesosphere.com' server FQDN: 'core1.hw.ca1.mesosphere.com' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0306 13:14:00.657189 18920 auxprop.cpp:181] Looking up auxiliary property '*userPassword'
I0306 13:14:00.657207 18920 auxprop.cpp:181] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I0306 13:14:00.657219 18920 auxprop.cpp:109] Request to lookup properties for user: 'test-principal' realm: 'core1.hw.ca1.mesosphere.com' server FQDN: 'core1.hw.ca1.mesosphere.com' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0306 13:14:00.657232 18920 auxprop.cpp:131] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I0306 13:14:00.657243 18920 auxprop.cpp:131] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0306 13:14:00.657259 18920 authenticator.cpp:318] Authentication success
I0306 13:14:00.657313 18926 authenticatee.cpp:299] Authentication success
I0306 13:14:00.657349 18920 master.cpp:9708] Successfully authenticated principal 'test-principal' at slave(725)@66.70.182.167:44211
I0306 13:14:00.657415 18926 slave.cpp:1646] Successfully authenticated with master master@66.70.182.167:44211
I0306 13:14:00.657687 18926 slave.cpp:2096] Will retry registration in 4.732327ms if necessary
I0306 13:14:00.657754 18891 master.cpp:6174] Received register agent message from slave(725)@66.70.182.167:44211 (core1.hw.ca1.mesosphere.com)
I0306 13:14:00.657842 18891 master.cpp:3705] Authorizing principal 'test-principal' to perform action REGISTER_AGENT on ANY object
I0306 13:14:00.657974 18891 master.cpp:6241] Authorized registration of agent at slave(725)@66.70.182.167:44211 (core1.hw.ca1.mesosphere.com)
I0306 13:14:00.658053 18891 master.cpp:6353] Registering agent at slave(725)@66.70.182.167:44211 (core1.hw.ca1.mesosphere.com) with id 13016c18-4e40-461e-b9b5-43006bae2bf8-S0
I0306 13:14:00.658183 18891 registrar.cpp:487] Applied 1 operations in 45486ns; attempting to update the registry
I0306 13:14:00.658290 18891 registrar.cpp:544] Successfully updated the registry in 76032ns
I0306 13:14:00.658349 18891 master.cpp:6401] Admitted agent 13016c18-4e40-461e-b9b5-43006bae2bf8-S0 at slave(725)@66.70.182.167:44211 (core1.hw.ca1.mesosphere.com)
I0306 13:14:00.658491 18891 master.cpp:6446] Registered agent 13016c18-4e40-461e-b9b5-43006bae2bf8-S0 at slave(725)@66.70.182.167:44211 (core1.hw.ca1.mesosphere.com) with cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0306 13:14:00.658558 18917 hierarchical.cpp:959] Added agent 13016c18-4e40-461e-b9b5-43006bae2bf8-S0 (core1.hw.ca1.mesosphere.com) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] (offered or allocated: {})
I0306 13:14:00.658672 18917 hierarchical.cpp:1853] Performed allocation for 1 agents in 19027ns
I0306 13:14:00.657557 18882 authenticator.cpp:432] Authentication session cleanup for crammd5-authenticatee(725)@66.70.182.167:44211
I0306 13:14:00.658584 18901 slave.cpp:1679] Registered with master master@66.70.182.167:44211; given agent ID 13016c18-4e40-461e-b9b5-43006bae2bf8-S0
I0306 13:14:00.658953 18922 task_status_update_manager.cpp:188] Resuming sending task status updates
I0306 13:14:00.659323 18901 slave.cpp:1714] Checkpointing SlaveInfo to '/tmp/ContentType_MasterAPITest_ReservationUpdate_0_nvt6G5/meta/slaves/13016c18-4e40-461e-b9b5-43006bae2bf8-S0/slave.info'
I0306 13:14:00.659822 18901 slave.cpp:1766] Forwarding agent update {"operations":{},"resource_providers":{},"resource_version_uuid":{"value":"9xMrJiRbTpG0XhVd1l1SeQ=="},"slave_id":{"value":"13016c18-4e40-461e-b9b5-43006bae2bf8-S0"},"update_oversubscribed_resources":false}
I0306 13:14:00.659508 18909 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1'
I0306 13:14:00.659359 18876 status_update_manager_process.hpp:385] Resuming operation status update manager
I0306 13:14:00.660755 18909 master.cpp:7584] Ignoring update on agent 13016c18-4e40-461e-b9b5-43006bae2bf8-S0 at slave(725)@66.70.182.167:44211 (core1.hw.ca1.mesosphere.com) as it reports no changes
I0306 13:14:00.660984 18905 http.cpp:1405] HTTP POST for /master/api/v1 from 66.70.182.167:54982
I0306 13:14:00.661098 18905 http.cpp:277] Processing call RESERVE_RESOURCES
I0306 13:14:00.661291 18905 master.cpp:3705] Authorizing principal 'test-principal' to perform action UNRESERVE_RESOURCES on object {"value":"test-principal","resource":{"name":"cpus","type":"SCALAR","scalar":{"value":1.0},"reservations":[{"type":"DYNAMIC","role":"role","principal":"test-principal"},{"type":"DYNAMIC","role":"role/bar","principal":"test-principal"}]}}
I0306 13:14:00.661343 18905 master.cpp:3705] Authorizing principal 'test-principal' to perform action UNRESERVE_RESOURCES on object {"value":"test-principal","resource":{"name":"mem","type":"SCALAR","scalar":{"value":10.0},"reservations":[{"type":"DYNAMIC","role":"role","principal":"test-principal"},{"type":"DYNAMIC","role":"role/bar","principal":"test-principal"}]}}
I0306 13:14:00.661366 18905 master.cpp:3705] Authorizing principal 'test-principal' to perform action RESERVE_RESOURCES on object {"value":"role/foo","resource":{"name":"cpus","type":"SCALAR","scalar":{"value":1.0},"reservations":[{"type":"DYNAMIC","role":"role","principal":"test-principal"},{"type":"DYNAMIC","role":"role/foo","principal":"test-principal"}]}}
I0306 13:14:00.661682 18933 hierarchical.cpp:1346] Failed to update available resources on agent 13016c18-4e40-461e-b9b5-43006bae2bf8-S0: cpus:2; mem:1024; disk:1024; ports:[31000-32000] does not contain cpus(reservations: [(DYNAMIC,role,test-principal),(DYNAMIC,role/bar,test-principal)]):1; mem(reservations: [(DYNAMIC,role,test-principal),(DYNAMIC,role/bar,test-principal)]):10
I0306 13:14:00.671203 18866 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1'
I0306 13:14:00.671648 18866 http.cpp:1405] HTTP POST for /master/api/v1 from 66.70.182.167:54984
I0306 13:14:00.671725 18866 http.cpp:277] Processing call RESERVE_RESOURCES
I0306 13:14:00.671916 18866 master.cpp:3705] Authorizing principal 'test-principal' to perform action RESERVE_RESOURCES on object {"value":"role","resource":{"name":"cpus","type":"SCALAR","scalar":{"value":1.0},"reservations":[{"type":"DYNAMIC","role":"role","principal":"test-principal"}]}}
I0306 13:14:00.671968 18866 master.cpp:3705] Authorizing principal 'test-principal' to perform action RESERVE_RESOURCES on object {"value":"role/foo","resource":{"name":"cpus","type":"SCALAR","scalar":{"value":1.0},"reservations":[{"type":"DYNAMIC","role":"role","principal":"test-principal"},{"type":"DYNAMIC","role":"role/foo","principal":"test-principal"}]}}
I0306 13:14:00.672778 18893 master.cpp:11649] Sending operation '' (uuid: ff59e995-b3c8-4ac4-8abb-a9cebe651801) to agent 13016c18-4e40-461e-b9b5-43006bae2bf8-S0 at slave(725)@66.70.182.167:44211 (core1.hw.ca1.mesosphere.com)
I0306 13:14:00.673084 18893 slave.cpp:4466] Ignoring new checkpointed resources and operations identical to the current version
I0306 13:14:00.673434 18893 slave.cpp:9050] Updating the state of operation with no ID (uuid: ff59e995-b3c8-4ac4-8abb-a9cebe651801) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0306 13:14:00.673995 18893 slave.cpp:4554] Updated checkpointed resources from {} to cpus(reservations: [(DYNAMIC,role,test-principal),(DYNAMIC,role/foo,test-principal)]):1; mem(reservations: [(DYNAMIC,role,test-principal),(DYNAMIC,role/foo,test-principal)]):10
I0306 13:14:00.674307 18893 slave.cpp:4578] Updated checkpointed operations from [ ] to [ ff59e995-b3c8-4ac4-8abb-a9cebe651801 (RESERVE, latest state: OPERATION_FINISHED) ]
I0306 13:14:00.674473 18893 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: a420030d-7468-43c4-9c3b-d57326fb8d07) for operation UUID ff59e995-b3c8-4ac4-8abb-a9cebe651801 on agent 13016c18-4e40-461e-b9b5-43006bae2bf8-S0
I0306 13:14:00.674605 18893 status_update_manager_process.hpp:414] Creating operation status update stream ff59e995-b3c8-4ac4-8abb-a9cebe651801 checkpoint=true
I0306 13:14:00.674919 18893 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: a420030d-7468-43c4-9c3b-d57326fb8d07) for operation UUID ff59e995-b3c8-4ac4-8abb-a9cebe651801 on agent 13016c18-4e40-461e-b9b5-43006bae2bf8-S0
I0306 13:14:00.674983 18913 process.cpp:3671] Handling HTTP event for process 'slave(725)' with path: '/slave(725)/state'
I0306 13:14:00.675457 18910 http.cpp:1405] HTTP GET for /slave(725)/state from 66.70.182.167:54986
I0306 13:14:00.676162 18911 http.cpp:1422] HTTP GET for /slave(725)/state from 66.70.182.167:54986: '200 OK' after 1.2672ms
I0306 13:14:00.676312 18893 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: a420030d-7468-43c4-9c3b-d57326fb8d07) for operation UUID ff59e995-b3c8-4ac4-8abb-a9cebe651801 on agent 13016c18-4e40-461e-b9b5-43006bae2bf8-S0
I0306 13:14:00.676508 18893 slave.cpp:9050] Updating the state of operation with no ID (uuid: ff59e995-b3c8-4ac4-8abb-a9cebe651801) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0306 13:14:00.676625 18893 slave.cpp:6441] Forwarding status update of operation with no ID (operation_uuid: ff59e995-b3c8-4ac4-8abb-a9cebe651801) for an operator API call
I0306 13:14:00.676798 18893 master.cpp:11301] Updating the state of operation '' (uuid: ff59e995-b3c8-4ac4-8abb-a9cebe651801) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0306 13:14:00.677024 18893 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: a420030d-7468-43c4-9c3b-d57326fb8d07) for stream ff59e995-b3c8-4ac4-8abb-a9cebe651801
I0306 13:14:00.677151 18893 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: a420030d-7468-43c4-9c3b-d57326fb8d07) for operation UUID ff59e995-b3c8-4ac4-8abb-a9cebe651801 on agent 13016c18-4e40-461e-b9b5-43006bae2bf8-S0
I0306 13:14:00.677781 18889 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1'
I0306 13:14:00.677976 18893 status_update_manager_process.hpp:490] Cleaning up operation status update stream ff59e995-b3c8-4ac4-8abb-a9cebe651801
I0306 13:14:00.678164 18889 http.cpp:1405] HTTP POST for /master/api/v1 from 66.70.182.167:54988
I0306 13:14:00.678257 18889 http.cpp:277] Processing call RESERVE_RESOURCES
I0306 13:14:00.678463 18893 slave.cpp:4578] Updated checkpointed operations from [ ff59e995-b3c8-4ac4-8abb-a9cebe651801 (RESERVE, latest state: OPERATION_FINISHED) ] to [ ]
I0306 13:14:00.678462 18889 master.cpp:3705] Authorizing principal 'test-principal' to perform action UNRESERVE_RESOURCES on object {"value":"test-principal","resource":{"name":"cpus","type":"SCALAR","scalar":{"value":1.0},"reservations":[{"type":"DYNAMIC","role":"role","principal":"test-principal"},{"type":"DYNAMIC","role":"role/bar","principal":"test-principal"}]}}
I0306 13:14:00.678541 18889 master.cpp:3705] Authorizing principal 'test-principal' to perform action UNRESERVE_RESOURCES on object {"value":"test-principal","resource":{"name":"mem","type":"SCALAR","scalar":{"value":10.0},"reservations":[{"type":"DYNAMIC","role":"role","principal":"test-principal"},{"type":"DYNAMIC","role":"role/bar","principal":"test-principal"}]}}
I0306 13:14:00.678623 18889 master.cpp:3705] Authorizing principal 'test-principal' to perform action RESERVE_RESOURCES on object {"value":"role/foo","resource":{"name":"cpus","type":"SCALAR","scalar":{"value":1.0},"reservations":[{"type":"DYNAMIC","role":"role","principal":"test-principal"},{"type":"DYNAMIC","role":"role/foo","principal":"test-principal"}]}}
I0306 13:14:00.679316 18889 hierarchical.cpp:1346] Failed to update available resources on agent 13016c18-4e40-461e-b9b5-43006bae2bf8-S0: cpus:1; mem:1014; disk:1024; ports:[31000-32000]; cpus(reservations: [(DYNAMIC,role,test-principal),(DYNAMIC,role/foo,test-principal)]):1; mem(reservations: [(DYNAMIC,role,test-principal),(DYNAMIC,role/foo,test-principal)]):10 does not contain cpus(reservations: [(DYNAMIC,role,test-principal),(DYNAMIC,role/bar,test-principal)]):1; mem(reservations: [(DYNAMIC,role,test-principal),(DYNAMIC,role/bar,test-principal)]):10
I0306 13:14:00.680538 18906 process.cpp:3671] Handling HTTP event for process 'master' with path: '/master/api/v1'
I0306 13:14:00.680794 18908 http.cpp:1405] HTTP POST for /master/api/v1 from 66.70.182.167:54990
I0306 13:14:00.680856 18908 http.cpp:277] Processing call RESERVE_RESOURCES
I0306 13:14:00.681062 18908 master.cpp:3705] Authorizing principal 'test-principal' to perform action UNRESERVE_RESOURCES on object {"value":"test-principal","resource":{"name":"cpus","type":"SCALAR","scalar":{"value":1.0},"reservations":[{"type":"DYNAMIC","role":"role","principal":"test-principal"},{"type":"DYNAMIC","role":"role/foo","principal":"test-principal"}]}}
I0306 13:14:00.681102 18908 master.cpp:3705] Authorizing principal 'test-principal' to perform action UNRESERVE_RESOURCES on object {"value":"test-principal","resource":{"name":"mem","type":"SCALAR","scalar":{"value":10.0},"reservations":[{"type":"DYNAMIC","role":"role","principal":"test-principal"},{"type":"DYNAMIC","role":"role/foo","principal":"test-principal"}]}}
I0306 13:14:00.681121 18908 master.cpp:3705] Authorizing principal 'test-principal' to perform action RESERVE_RESOURCES on object {"value":"role/bar","resource":{"name":"cpus","type":"SCALAR","scalar":{"value":1.0},"reservations":[{"type":"DYNAMIC","role":"role","principal":"test-principal"},{"type":"DYNAMIC","role":"role/bar","principal":"test-principal"}]}}
I0306 13:14:00.682327 18872 process.cpp:3671] Handling HTTP event for process 'slave(725)' with path: '/slave(725)/state'
I0306 13:14:00.682566 18911 http.cpp:1405] HTTP GET for /slave(725)/state from 66.70.182.167:54992
I0306 13:14:00.682682 18869 master.cpp:11649] Sending operation '' (uuid: ee788636-a6cc-4b79-8a89-6e466a0aa4ca) to agent 13016c18-4e40-461e-b9b5-43006bae2bf8-S0 at slave(725)@66.70.182.167:44211 (core1.hw.ca1.mesosphere.com)
I0306 13:14:00.683116 18905 http.cpp:1422] HTTP GET for /slave(725)/state from 66.70.182.167:54992: '200 OK' after 0.876288ms
I0306 13:14:00.683246 18905 slave.cpp:4466] Ignoring new checkpointed resources and operations identical to the current version
I0306 13:14:00.683300 18905 slave.cpp:9050] Updating the state of operation with no ID (uuid: ee788636-a6cc-4b79-8a89-6e466a0aa4ca) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
/home/asekretenko/lsyncd/mesos/src/tests/api_tests.cpp:1547: Failure
Expected: role
Which is: "role/foo"
To be equal to: intendedRole
Which is: "role/bar"
*** Aborted at 1583518440 (unix time) try "date -d @1583518440" if you are using GNU date ***
I0306 13:14:00.684623 18905 slave.cpp:4554] Updated checkpointed resources from cpus(reservations: [(DYNAMIC,role,test-principal),(DYNAMIC,role/foo,test-principal)]):1; mem(reservations: [(DYNAMIC,role,test-principal),(DYNAMIC,role/foo,test-principal)]):10 to cpus(reservations: [(DYNAMIC,role,test-principal),(DYNAMIC,role/bar,test-principal)]):1; mem(reservations: [(DYNAMIC,role,test-principal),(DYNAMIC,role/bar,test-principal)]):10
I0306 13:14:00.684702 18905 slave.cpp:4578] Updated checkpointed operations from [ ] to [ ee788636-a6cc-4b79-8a89-6e466a0aa4ca (RESERVE, latest state: OPERATION_FINISHED) ]
I0306 13:14:00.684764 18905 status_update_manager_process.hpp:152] Received operation status update OPERATION_FINISHED (Status UUID: fa7b9b59-94b5-401b-bf74-1fe4f0872d40) for operation UUID ee788636-a6cc-4b79-8a89-6e466a0aa4ca on agent 13016c18-4e40-461e-b9b5-43006bae2bf8-S0
I0306 13:14:00.684780 18905 status_update_manager_process.hpp:414] Creating operation status update stream ee788636-a6cc-4b79-8a89-6e466a0aa4ca checkpoint=true
I0306 13:14:00.684937 18905 status_update_manager_process.hpp:929] Checkpointing UPDATE for operation status update OPERATION_FINISHED (Status UUID: fa7b9b59-94b5-401b-bf74-1fe4f0872d40) for operation UUID ee788636-a6cc-4b79-8a89-6e466a0aa4ca on agent 13016c18-4e40-461e-b9b5-43006bae2bf8-S0
I0306 13:14:00.685716 18905 status_update_manager_process.hpp:528] Forwarding operation status update OPERATION_FINISHED (Status UUID: fa7b9b59-94b5-401b-bf74-1fe4f0872d40) for operation UUID ee788636-a6cc-4b79-8a89-6e466a0aa4ca on agent 13016c18-4e40-461e-b9b5-43006bae2bf8-S0
I0306 13:14:00.685777 18905 slave.cpp:9050] Updating the state of operation with no ID (uuid: ee788636-a6cc-4b79-8a89-6e466a0aa4ca) for an operation API call (latest state: OPERATION_FINISHED, status update state: OPERATION_FINISHED)
I0306 13:14:00.685789 18905 slave.cpp:6441] Forwarding status update of operation with no ID (operation_uuid: ee788636-a6cc-4b79-8a89-6e466a0aa4ca) for an operator API call
I0306 13:14:00.685825 18905 master.cpp:11301] Updating the state of operation '' (uuid: ee788636-a6cc-4b79-8a89-6e466a0aa4ca) for an operator API call (latest state: OPERATION_PENDING, status update state: OPERATION_FINISHED)
I0306 13:14:00.685895 18905 status_update_manager_process.hpp:252] Received operation status update acknowledgement (UUID: fa7b9b59-94b5-401b-bf74-1fe4f0872d40) for stream ee788636-a6cc-4b79-8a89-6e466a0aa4ca
I0306 13:14:00.685914 18905 status_update_manager_process.hpp:929] Checkpointing ACK for operation status update OPERATION_FINISHED (Status UUID: fa7b9b59-94b5-401b-bf74-1fe4f0872d40) for operation UUID ee788636-a6cc-4b79-8a89-6e466a0aa4ca on agent 13016c18-4e40-461e-b9b5-43006bae2bf8-S0
PC: @ 0x0 (unknown)
*** SIGSEGV (@0x0) received by PID 18861 (TID 0x7fcb66479140) from PID 0; stack trace: ***
I0306 13:14:00.686733 18905 status_update_manager_process.hpp:490] Cleaning up operation status update stream ee788636-a6cc-4b79-8a89-6e466a0aa4ca
I0306 13:14:00.687050 18905 slave.cpp:4578] Updated checkpointed operations from [ ee788636-a6cc-4b79-8a89-6e466a0aa4ca (RESERVE, latest state: OPERATION_FINISHED) ] to [ ]
@ 0x7fcb61db6fb0 (unknown)
@ 0x32eb210 testing::UnitTest::AddTestPartResult()
@ 0x32eae5d testing::internal::AssertHelper::operator=()
@ 0xb1fad2 mesos::internal::tests::MasterAPITest_ReservationUpdate_Test::TestBody()::$_1::operator()()
@ 0xb1c2c4 mesos::internal::tests::MasterAPITest_ReservationUpdate_Test::TestBody()
@ 0x330e494 testing::internal::HandleExceptionsInMethodIfSupported<>()
@ 0x32f4ff1 testing::Test::Run()
@ 0x32f5f90 testing::TestInfo::Run()
@ 0x32f6707 testing::TestCase::Run()
@ 0x32fea87 testing::internal::UnitTestImpl::RunAllTests()
@ 0x330ef54 testing::internal::HandleExceptionsInMethodIfSupported<>()
@ 0x32fe65a testing::UnitTest::Run()
@ 0x7f7224 main
@ 0x7fcb5da0711b __libc_start_main
@ 0x70465a _start
@ 0x0 (unknown)
Segmentation fault
The most likely cause of these flakes is the fact that the test calls Agent API to validate the result of reservation update, but actually never waits for the agent to apply the operation.