[
https://issues.apache.org/jira/browse/MESOS-8879?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16901999#comment-16901999
]
Andrei Sekretenko commented on MESOS-8879:
------------------------------------------
Observed again in an internal CI:
{code}
[ RUN ] SlaveTest.HTTPExecutorBadAuthentication
I0806 19:47:36.422247 21850 cluster.cpp:177] Creating default 'local' authorizer
I0806 19:47:36.423265 21853 master.cpp:440] Master
72aa280d-6cd9-4e61-823b-48b59fdbae4a (localhost) started on 127.0.0.1:40941
I0806 19:47:36.423283 21853 master.cpp:443] Flags at startup: --acls=""
--agent_ping_timeout="15secs" --agent_reregister_timeout="10mins"
--allocation_interval="1secs" --allocator="hierarchical"
--authenticate_agents="true" --authenticate_frameworks="true"
--authenticate_http_frameworks="true" --authenticate_http_readonly="true"
--authenticate_http_readwrite="true" --authentication_v0_timeout="15secs"
--authenticators="crammd5" --authorizers="local"
--credentials="/tmp/SGimql/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/SGimql/master" --zk_session_timeout="10secs"
W0806 19:47:36.423420 21853 master.cpp:446]
**************************************************
Master bound to loopback interface! Cannot communicate with remote schedulers
or agents. You might want to set '--ip' flag to a routable IP address.
**************************************************
I0806 19:47:36.423445 21853 master.cpp:492] Master only allowing authenticated
frameworks to register
I0806 19:47:36.423452 21853 master.cpp:498] Master only allowing authenticated
agents to register
I0806 19:47:36.423457 21853 master.cpp:504] Master only allowing authenticated
HTTP frameworks to register
I0806 19:47:36.423463 21853 credentials.hpp:37] Loading credentials for
authentication from '/tmp/SGimql/credentials'
I0806 19:47:36.423555 21853 master.cpp:548] Using default 'crammd5'
authenticator
I0806 19:47:36.423599 21853 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-readonly'
I0806 19:47:36.423638 21853 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-readwrite'
I0806 19:47:36.423662 21853 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-master-scheduler'
I0806 19:47:36.423691 21853 master.cpp:629] Authorization enabled
I0806 19:47:36.424396 21858 hierarchical.cpp:241] Initialized hierarchical
allocator process
I0806 19:47:36.424439 21853 master.cpp:2168] Elected as the leading master!
I0806 19:47:36.424453 21853 master.cpp:1664] Recovering from registrar
I0806 19:47:36.424485 21853 registrar.cpp:339] Recovering registrar
I0806 19:47:36.424626 21853 registrar.cpp:383] Successfully fetched the
registry (0B) in 126976ns
I0806 19:47:36.424659 21853 registrar.cpp:487] Applied 1 operations in 8685ns;
attempting to update the registry
I0806 19:47:36.424399 21857 whitelist_watcher.cpp:77] No whitelist given
I0806 19:47:36.425123 21853 registrar.cpp:544] Successfully updated the
registry in 446208ns
I0806 19:47:36.425156 21853 registrar.cpp:416] Successfully recovered registrar
I0806 19:47:36.425269 21853 master.cpp:1817] Recovered 0 agents from the
registry (135B); allowing 10mins for agents to reregister
I0806 19:47:36.425326 21853 hierarchical.cpp:280] Skipping recovery of
hierarchical allocator: nothing to recover
W0806 19:47:36.427067 21850 process.cpp:2877] Attempted to spawn already
running process [email protected]:40941
I0806 19:47:36.427402 21850 cluster.cpp:518] Creating default 'local' authorizer
I0806 19:47:36.428055 21857 slave.cpp:267] Mesos agent started on
(644)@127.0.0.1:40941
W0806 19:47:36.428203 21850 scheduler.cpp:174]
**************************************************
Scheduler driver bound to loopback interface! Cannot communicate with remote
master(s). You might want to set 'LIBPROCESS_IP' environment variable to use a
routable IP address.
**************************************************
I0806 19:47:36.428071 21857 slave.cpp:268] Flags at startup: --acls=""
--appc_simple_discovery_uri_prefix="http://";
--appc_store_dir="/tmp/SGimql/ND3UTT/store/appc"
--authenticate_http_executors="true" --authenticate_http_readonly="true"
--authenticate_http_readwrite="true" --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_test_8b3314d3-70e1-4488-9da4-880d73a7295c"
--container_disk_watch_interval="15secs" --containerizers="mesos"
--credential="/tmp/SGimql/ND3UTT/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/SGimql/ND3UTT/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/SGimql/ND3UTT/fetch" --fetcher_cache_size="2GB"
--fetcher_stall_timeout="1mins"
--frameworks_home="/tmp/SGimql/ND3UTT/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/SGimql/ND3UTT/http_credentials"
--http_heartbeat_interval="30secs" --initialize_driver_logging="true"
--isolation="cgroups/cpu,cgroups/mem"
--jwt_secret_key="/tmp/SGimql/ND3UTT/jwt_secret_key" --launcher="linux"
--launcher_dir="/home/admin/workspace/mesos/Mesos_CI-build/FLAG/SSL/label/mesos-ec2-debian-9/mesos/build/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/SlaveTest_HTTPExecutorBadAuthentication_iX9I42"
--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/SlaveTest_HTTPExecutorBadAuthentication_jaCxfc"
--zk_session_timeout="10secs"
W0806 19:47:36.428256 21857 slave.cpp:271]
**************************************************
Agent bound to loopback interface! Cannot communicate with remote master(s).
You might want to set '--ip' flag to a routable IP address.
**************************************************
I0806 19:47:36.428267 21857 credentials.hpp:86] Loading credential for
authentication from '/tmp/SGimql/ND3UTT/credential'
I0806 19:47:36.428311 21857 slave.cpp:300] Agent using credential for:
test-principal
I0806 19:47:36.428323 21857 credentials.hpp:37] Loading credentials for
authentication from '/tmp/SGimql/ND3UTT/http_credentials'
I0806 19:47:36.428383 21857 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-executor'
I0806 19:47:36.428416 21857 http.cpp:996] Creating default 'jwt' HTTP
authenticator for realm 'mesos-agent-executor'
I0806 19:47:36.428462 21857 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-readonly'
I0806 19:47:36.428503 21857 http.cpp:996] Creating default 'jwt' HTTP
authenticator for realm 'mesos-agent-readonly'
I0806 19:47:36.428537 21857 http.cpp:975] Creating default 'basic' HTTP
authenticator for realm 'mesos-agent-readwrite'
I0806 19:47:36.428555 21857 http.cpp:996] Creating default 'jwt' HTTP
authenticator for realm 'mesos-agent-readwrite'
I0806 19:47:36.428608 21857 disk_profile_adaptor.cpp:78] Creating default disk
profile adaptor module
I0806 19:47:36.428230 21850 scheduler.cpp:189] Version: 1.9.0
I0806 19:47:36.429250 21857 slave.cpp:615] 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"}]
I0806 19:47:36.429324 21857 slave.cpp:623] Agent attributes: [ ]
I0806 19:47:36.429333 21857 slave.cpp:632] Agent hostname: localhost
I0806 19:47:36.429574 21857 scheduler.cpp:342] Using default 'basic' HTTP
authenticatee
I0806 19:47:36.429625 21857 task_status_update_manager.cpp:181] Pausing sending
task status updates
I0806 19:47:36.429661 21857 status_update_manager_process.hpp:379] Pausing
operation status update manager
I0806 19:47:36.429810 21857 state.cpp:67] Recovering state from
'/tmp/SlaveTest_HTTPExecutorBadAuthentication_jaCxfc/meta'
I0806 19:47:36.429883 21857 slave.cpp:7444] Finished recovering checkpointed
state from '/tmp/SlaveTest_HTTPExecutorBadAuthentication_jaCxfc/meta',
beginning agent recovery
I0806 19:47:36.429957 21857 scheduler.cpp:525] New master detected at
[email protected]:40941
I0806 19:47:36.429973 21857 scheduler.cpp:534] Waiting for 0ns before
initiating a re-(connection) attempt with the master
I0806 19:47:36.430037 21857 task_status_update_manager.cpp:207] Recovering task
status update manager
I0806 19:47:36.430233 21857 composing.cpp:339] Finished recovering all
containerizers
I0806 19:47:36.430289 21857 slave.cpp:7908] Recovering executors
I0806 19:47:36.430308 21857 slave.cpp:8061] Finished recovery
I0806 19:47:36.430665 21857 slave.cpp:1351] New master detected at
[email protected]:40941
I0806 19:47:36.430694 21857 slave.cpp:1416] Detecting new master
I0806 19:47:36.430719 21857 task_status_update_manager.cpp:181] Pausing sending
task status updates
I0806 19:47:36.430732 21857 status_update_manager_process.hpp:379] Pausing
operation status update manager
I0806 19:47:36.431175 21858 scheduler.cpp:416] Connected with the master at
http://127.0.0.1:40941/master/api/v1/scheduler
I0806 19:47:36.431641 21856 scheduler.cpp:246] Adding authentication headers to
SUBSCRIBE call to http://127.0.0.1:40941/master/api/v1/scheduler
I0806 19:47:36.431751 21856 scheduler.cpp:600] Sending SUBSCRIBE call to
http://127.0.0.1:40941/master/api/v1/scheduler
I0806 19:47:36.432022 21852 process.cpp:3671] Handling HTTP event for process
'master' with path: '/master/api/v1/scheduler'
I0806 19:47:36.432335 21852 http.cpp:1115] HTTP POST for
/master/api/v1/scheduler from 127.0.0.1:60978
I0806 19:47:36.432431 21852 master.cpp:2668] Received subscription request for
HTTP framework 'default'
I0806 19:47:36.432457 21852 master.cpp:2240] Authorizing framework principal
'test-principal' to receive offers for roles '\{ * }'
I0806 19:47:36.432740 21852 master.cpp:2740] Subscribing framework 'default'
with checkpointing disabled and capabilities [ MULTI_ROLE,
RESERVATION_REFINEMENT ]
I0806 19:47:36.433220 21852 master.cpp:10808] Adding framework
72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000 (default) with roles \{ } suppressed
I0806 19:47:36.433341 21858 hierarchical.cpp:368] Added framework
72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000
I0806 19:47:36.433388 21858 hierarchical.cpp:1508] Performed allocation for 0
agents in 14817ns
I0806 19:47:36.433614 21856 scheduler.cpp:847] Enqueuing event SUBSCRIBED
received from http://127.0.0.1:40941/master/api/v1/scheduler
I0806 19:47:36.433951 21851 scheduler.cpp:847] Enqueuing event HEARTBEAT
received from http://127.0.0.1:40941/master/api/v1/scheduler
I0806 19:47:36.439100 21855 slave.cpp:1443] Authenticating with master
[email protected]:40941
I0806 19:47:36.439131 21855 slave.cpp:1452] Using default CRAM-MD5 authenticatee
I0806 19:47:36.439205 21855 authenticatee.cpp:121] Creating new client SASL
connection
I0806 19:47:36.439311 21855 master.cpp:10578] Authenticating
slave(644)@127.0.0.1:40941
I0806 19:47:36.439353 21855 authenticator.cpp:414] Starting authentication
session for crammd5-authenticatee(1269)@127.0.0.1:40941
I0806 19:47:36.439404 21855 authenticator.cpp:98] Creating new server SASL
connection
I0806 19:47:36.439476 21855 authenticatee.cpp:213] Received SASL authentication
mechanisms: CRAM-MD5
I0806 19:47:36.439489 21855 authenticatee.cpp:239] Attempting to authenticate
with mechanism 'CRAM-MD5'
I0806 19:47:36.439515 21855 authenticator.cpp:204] Received SASL authentication
start
I0806 19:47:36.439546 21855 authenticator.cpp:326] Authentication requires more
steps
I0806 19:47:36.439572 21855 authenticatee.cpp:259] Received SASL authentication
step
I0806 19:47:36.439626 21855 authenticator.cpp:232] Received SASL authentication
step
I0806 19:47:36.439643 21855 auxprop.cpp:109] Request to lookup properties for
user: 'test-principal' realm: 'ip-172-16-10-241' server FQDN:
'ip-172-16-10-241' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I0806 19:47:36.439651 21855 auxprop.cpp:181] Looking up auxiliary property
'*userPassword'
I0806 19:47:36.439661 21855 auxprop.cpp:181] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I0806 19:47:36.439669 21855 auxprop.cpp:109] Request to lookup properties for
user: 'test-principal' realm: 'ip-172-16-10-241' server FQDN:
'ip-172-16-10-241' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I0806 19:47:36.439676 21855 auxprop.cpp:131] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I0806 19:47:36.439682 21855 auxprop.cpp:131] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I0806 19:47:36.439693 21855 authenticator.cpp:318] Authentication success
I0806 19:47:36.439728 21855 authenticatee.cpp:299] Authentication success
I0806 19:47:36.439764 21855 master.cpp:10610] Successfully authenticated
principal 'test-principal' at slave(644)@127.0.0.1:40941
I0806 19:47:36.439785 21855 authenticator.cpp:432] Authentication session
cleanup for crammd5-authenticatee(1269)@127.0.0.1:40941
I0806 19:47:36.439839 21855 slave.cpp:1543] Successfully authenticated with
master [email protected]:40941
I0806 19:47:36.439930 21855 slave.cpp:1993] Will retry registration in
12.090275ms if necessary
I0806 19:47:36.440026 21855 master.cpp:7086] Received register agent message
from slave(644)@127.0.0.1:40941 (localhost)
I0806 19:47:36.440083 21855 master.cpp:4202] Authorizing agent providing
resources 'cpus:2; mem:1024; disk:1024; ports:[31000-32000]' with principal
'test-principal'
I0806 19:47:36.440192 21855 master.cpp:7153] Authorized registration of agent
at slave(644)@127.0.0.1:40941 (localhost)
I0806 19:47:36.440222 21855 master.cpp:7265] Registering agent at
slave(644)@127.0.0.1:40941 (localhost) with id
72aa280d-6cd9-4e61-823b-48b59fdbae4a-S0
I0806 19:47:36.440327 21855 registrar.cpp:487] Applied 1 operations in 35302ns;
attempting to update the registry
I0806 19:47:36.440435 21855 registrar.cpp:544] Successfully updated the
registry in 93184ns
I0806 19:47:36.440481 21855 master.cpp:7313] Admitted agent
72aa280d-6cd9-4e61-823b-48b59fdbae4a-S0 at slave(644)@127.0.0.1:40941
(localhost)
I0806 19:47:36.440580 21855 master.cpp:7358] Registered agent
72aa280d-6cd9-4e61-823b-48b59fdbae4a-S0 at slave(644)@127.0.0.1:40941
(localhost) with cpus:2; mem:1024; disk:1024; ports:[31000-32000]
I0806 19:47:36.440660 21855 hierarchical.cpp:617] Added agent
72aa280d-6cd9-4e61-823b-48b59fdbae4a-S0 (localhost) with cpus:2; mem:1024;
disk:1024; ports:[31000-32000] (allocated: {})
I0806 19:47:36.440762 21854 slave.cpp:1576] Registered with master
[email protected]:40941; given agent ID 72aa280d-6cd9-4e61-823b-48b59fdbae4a-S0
I0806 19:47:36.440961 21854 slave.cpp:1611] Checkpointing SlaveInfo to
'/tmp/SlaveTest_HTTPExecutorBadAuthentication_jaCxfc/meta/slaves/72aa280d-6cd9-4e61-823b-48b59fdbae4a-S0/slave.info'
I0806 19:47:36.441267 21854 slave.cpp:1663] Forwarding agent update
\{"operations":{},"resource_providers":{},"resource_version_uuid":\{"value":"DPrGHezwSsazBvWPYJI+Cg=="},"slave_id":\{"value":"72aa280d-6cd9-4e61-823b-48b59fdbae4a-S0"},"update_oversubscribed_resources":false}
I0806 19:47:36.441360 21854 task_status_update_manager.cpp:188] Resuming
sending task status updates
I0806 19:47:36.441386 21854 status_update_manager_process.hpp:385] Resuming
operation status update manager
I0806 19:47:36.441905 21858 master.cpp:8457] Ignoring update on agent
72aa280d-6cd9-4e61-823b-48b59fdbae4a-S0 at slave(644)@127.0.0.1:40941
(localhost) as it reports no changes
I0806 19:47:36.442016 21855 hierarchical.cpp:1508] Performed allocation for 1
agents in 1.314949ms
I0806 19:47:36.442122 21851 master.cpp:10393] Sending offers [
72aa280d-6cd9-4e61-823b-48b59fdbae4a-O0 ] to framework
72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000 (default)
I0806 19:47:36.442622 21857 scheduler.cpp:847] Enqueuing event OFFERS received
from http://127.0.0.1:40941/master/api/v1/scheduler
I0806 19:47:36.443130 21858 scheduler.cpp:246] Adding authentication headers to
ACCEPT call to http://127.0.0.1:40941/master/api/v1/scheduler
I0806 19:47:36.443274 21858 scheduler.cpp:600] Sending ACCEPT call to
http://127.0.0.1:40941/master/api/v1/scheduler
I0806 19:47:36.443531 21855 process.cpp:3671] Handling HTTP event for process
'master' with path: '/master/api/v1/scheduler'
I0806 19:47:36.443856 21855 http.cpp:1115] HTTP POST for
/master/api/v1/scheduler from 127.0.0.1:60976
I0806 19:47:36.444042 21855 master.cpp:12685] Removing offer
72aa280d-6cd9-4e61-823b-48b59fdbae4a-O0
I0806 19:47:36.444165 21855 master.cpp:4739] Processing ACCEPT call for offers:
[ 72aa280d-6cd9-4e61-823b-48b59fdbae4a-O0 ] on agent
72aa280d-6cd9-4e61-823b-48b59fdbae4a-S0 at slave(644)@127.0.0.1:40941
(localhost) for framework 72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000 (default)
I0806 19:47:36.444212 21855 master.cpp:3756] Authorizing framework principal
'test-principal' to launch task fa7228d9-f532-40e7-81ac-e99231f68242
I0806 19:47:36.445125 21855 master.cpp:4274] Adding executor 'default' with
resources cpus(allocated: *):0.1; mem(allocated: *):32; disk(allocated: *):32
of framework 72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000 (default) on agent
72aa280d-6cd9-4e61-823b-48b59fdbae4a-S0 at slave(644)@127.0.0.1:40941
(localhost)
I0806 19:47:36.445219 21855 master.cpp:4300] Adding task
fa7228d9-f532-40e7-81ac-e99231f68242 with resources cpus(allocated: *):0.1;
mem(allocated: *):32; disk(allocated: *):32 of framework
72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000 (default) on agent
72aa280d-6cd9-4e61-823b-48b59fdbae4a-S0 at slave(644)@127.0.0.1:40941
(localhost)
I0806 19:47:36.445284 21855 master.cpp:5941] Launching task group \{
fa7228d9-f532-40e7-81ac-e99231f68242 } of framework
72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000 (default) with resources
cpus(allocated: *):0.1; mem(allocated: *):32; disk(allocated: *):32 on agent
72aa280d-6cd9-4e61-823b-48b59fdbae4a-S0 at slave(644)@127.0.0.1:40941
(localhost) on new executor
I0806 19:47:36.445540 21856 slave.cpp:2130] Got assigned task group containing
tasks [ fa7228d9-f532-40e7-81ac-e99231f68242 ] for framework
72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000
I0806 19:47:36.445950 21856 slave.cpp:2504] Authorizing task group containing
tasks [ fa7228d9-f532-40e7-81ac-e99231f68242 ] for framework
72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000
I0806 19:47:36.445982 21856 slave.cpp:9400] Authorizing framework principal
'test-principal' to launch task fa7228d9-f532-40e7-81ac-e99231f68242
I0806 19:47:36.446281 21856 hierarchical.cpp:1432] Allocation paused
I0806 19:47:36.446732 21856 slave.cpp:2977] Launching task group containing
tasks [ fa7228d9-f532-40e7-81ac-e99231f68242 ] for framework
72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000
I0806 19:47:36.446780 21856 paths.cpp:810] Creating sandbox
'/tmp/SlaveTest_HTTPExecutorBadAuthentication_jaCxfc/slaves/72aa280d-6cd9-4e61-823b-48b59fdbae4a-S0/frameworks/72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000/executors/default/runs/d4fa8cc7-925a-4bf5-a418-22f0ce6a27ab'
for user 'root'
I0806 19:47:36.447218 21856 slave.cpp:9938] Launching executor 'default' of
framework 72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000 with resources
[\{"allocation_info":{"role":"*"},"name":"cpus","scalar":\{"value":0.1},"type":"SCALAR"},\{"allocation_info":{"role":"*"},"name":"mem","scalar":\{"value":32.0},"type":"SCALAR"},\{"allocation_info":{"role":"*"},"name":"disk","scalar":\{"value":32.0},"type":"SCALAR"}]
in work directory
'/tmp/SlaveTest_HTTPExecutorBadAuthentication_jaCxfc/slaves/72aa280d-6cd9-4e61-823b-48b59fdbae4a-S0/frameworks/72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000/executors/default/runs/d4fa8cc7-925a-4bf5-a418-22f0ce6a27ab'
I0806 19:47:36.447486 21856 slave.cpp:3203] Queued task group containing tasks
[ fa7228d9-f532-40e7-81ac-e99231f68242 ] for executor 'default' of framework
72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000
I0806 19:47:36.447711 21858 slave.cpp:1084] Successfully attached
'/tmp/SlaveTest_HTTPExecutorBadAuthentication_jaCxfc/slaves/72aa280d-6cd9-4e61-823b-48b59fdbae4a-S0/frameworks/72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000/executors/default/runs/d4fa8cc7-925a-4bf5-a418-22f0ce6a27ab'
to virtual path
'/tmp/SlaveTest_HTTPExecutorBadAuthentication_jaCxfc/slaves/72aa280d-6cd9-4e61-823b-48b59fdbae4a-S0/frameworks/72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000/executors/default/runs/latest'
I0806 19:47:36.447732 21858 slave.cpp:1084] Successfully attached
'/tmp/SlaveTest_HTTPExecutorBadAuthentication_jaCxfc/slaves/72aa280d-6cd9-4e61-823b-48b59fdbae4a-S0/frameworks/72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000/executors/default/runs/d4fa8cc7-925a-4bf5-a418-22f0ce6a27ab'
to virtual path
'/frameworks/72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000/executors/default/runs/latest'
I0806 19:47:36.447759 21858 slave.cpp:1084] Successfully attached
'/tmp/SlaveTest_HTTPExecutorBadAuthentication_jaCxfc/slaves/72aa280d-6cd9-4e61-823b-48b59fdbae4a-S0/frameworks/72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000/executors/default/runs/d4fa8cc7-925a-4bf5-a418-22f0ce6a27ab'
to virtual path
'/tmp/SlaveTest_HTTPExecutorBadAuthentication_jaCxfc/slaves/72aa280d-6cd9-4e61-823b-48b59fdbae4a-S0/frameworks/72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000/executors/default/runs/d4fa8cc7-925a-4bf5-a418-22f0ce6a27ab'
I0806 19:47:36.447968 21851 hierarchical.cpp:1218] Recovered cpus(allocated:
*):1.8; mem(allocated: *):960; disk(allocated: *):960; ports(allocated:
*):[31000-32000] (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000],
allocated: cpus(allocated: *):0.2; mem(allocated: *):64; disk(allocated: *):64)
on agent 72aa280d-6cd9-4e61-823b-48b59fdbae4a-S0 from framework
72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000
I0806 19:47:36.448001 21851 hierarchical.cpp:1264] Framework
72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000 filtered agent
72aa280d-6cd9-4e61-823b-48b59fdbae4a-S0 for 5secs
I0806 19:47:36.448076 21855 hierarchical.cpp:1442] Allocation resumed
I0806 19:47:36.448894 21856 slave.cpp:3651] Launching container
d4fa8cc7-925a-4bf5-a418-22f0ce6a27ab for executor 'default' of framework
72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000
I0806 19:47:36.449193 21856 executor.cpp:206] Version: 1.9.0
W0806 19:47:36.449209 21856 process.cpp:2877] Attempted to spawn already
running process [email protected]:40941
I0806 19:47:36.450008 21853 executor.cpp:432] Connected with the agent
I0806 19:47:36.450322 21853 executor.cpp:328] Sending SUBSCRIBE call to
http://127.0.0.1:40941/slave(644)/api/v1/executor
I0806 19:47:36.450701 21851 process.cpp:3671] Handling HTTP event for process
'slave(644)' with path: '/slave(644)/api/v1/executor'
I0806 19:47:36.451416 21852 executor.cpp:745] Enqueuing locally injected event
ERROR
GMOCK WARNING:
Uninteresting mock function call - returning directly.
Function call: error(0x7f131c01b360, @0x7f13180680c0 32-byte object <38-AB
9A-37 13-7F 00-00 00-00 00-00 00-00 00-00 01-00 00-00 00-00 00-00 E0-21 08-18
13-7F 00-00>)
NOTE: You can safely ignore the above warning unless this call should not
happen. Do not suppress it by blindly adding an EXPECT_CALL() if you don't mean
to enforce the call. See
https://github.com/google/googletest/blob/master/googlemock/docs/CookBook.md#knowing-when-to-expect
for details.
I0806 19:47:37.425055 21853 hierarchical.cpp:2358] Filtered offer with
cpus:1.8; mem:960; disk:960; ports:[31000-32000] on agent
72aa280d-6cd9-4e61-823b-48b59fdbae4a-S0 for role * of framework
72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000
I0806 19:47:37.425132 21853 hierarchical.cpp:1508] Performed allocation for 1
agents in 158354ns
I0806 19:47:38.425976 21854 hierarchical.cpp:2358] Filtered offer with
cpus:1.8; mem:960; disk:960; ports:[31000-32000] on agent
72aa280d-6cd9-4e61-823b-48b59fdbae4a-S0 for role * of framework
72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000
I0806 19:47:38.426054 21854 hierarchical.cpp:1508] Performed allocation for 1
agents in 150287ns
I0806 19:47:39.426796 21851 hierarchical.cpp:2358] Filtered offer with
cpus:1.8; mem:960; disk:960; ports:[31000-32000] on agent
72aa280d-6cd9-4e61-823b-48b59fdbae4a-S0 for role * of framework
72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000
I0806 19:47:39.426869 21851 hierarchical.cpp:1508] Performed allocation for 1
agents in 145876ns
I0806 19:47:40.427855 21855 hierarchical.cpp:2358] Filtered offer with
cpus:1.8; mem:960; disk:960; ports:[31000-32000] on agent
72aa280d-6cd9-4e61-823b-48b59fdbae4a-S0 for role * of framework
72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000
I0806 19:47:40.427932 21855 hierarchical.cpp:1508] Performed allocation for 1
agents in 151233ns
I0806 19:47:41.428932 21851 hierarchical.cpp:2358] Filtered offer with
cpus:1.8; mem:960; disk:960; ports:[31000-32000] on agent
72aa280d-6cd9-4e61-823b-48b59fdbae4a-S0 for role * of framework
72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000
I0806 19:47:41.429009 21851 hierarchical.cpp:1508] Performed allocation for 1
agents in 149721ns
I0806 19:47:42.430246 21857 hierarchical.cpp:1508] Performed allocation for 1
agents in 151390ns
I0806 19:47:42.430390 21855 master.cpp:10393] Sending offers [
72aa280d-6cd9-4e61-823b-48b59fdbae4a-O1 ] to framework
72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000 (default)
I0806 19:47:42.431067 21854 scheduler.cpp:847] Enqueuing event OFFERS received
from http://127.0.0.1:40941/master/api/v1/scheduler
I0806 19:47:43.431192 21851 hierarchical.cpp:1508] Performed allocation for 1
agents in 39612ns
I0806 19:47:44.432204 21857 hierarchical.cpp:1508] Performed allocation for 1
agents in 38561ns
I0806 19:47:45.433198 21855 hierarchical.cpp:1508] Performed allocation for 1
agents in 39192ns
I0806 19:47:46.434304 21852 hierarchical.cpp:1508] Performed allocation for 1
agents in 37364ns
I0806 19:47:47.435331 21853 hierarchical.cpp:1508] Performed allocation for 1
agents in 38244ns
I0806 19:47:48.436272 21856 hierarchical.cpp:1508] Performed allocation for 1
agents in 37444ns
I0806 19:47:49.437196 21854 hierarchical.cpp:1508] Performed allocation for 1
agents in 37574ns
I0806 19:47:50.437824 21851 hierarchical.cpp:1508] Performed allocation for 1
agents in 39073ns
I0806 19:47:51.434033 21851 scheduler.cpp:847] Enqueuing event HEARTBEAT
received from http://127.0.0.1:40941/master/api/v1/scheduler
I0806 19:47:51.438400 21856 hierarchical.cpp:1508] Performed allocation for 1
agents in 34741ns
../../src/tests/slave_tests.cpp:2158: Failure
Failed to wait 15secs for error
I0806 19:47:51.453059 21855 master.cpp:1410] Framework
72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000 (default) disconnected
I0806 19:47:51.453083 21855 master.cpp:3360] Deactivating framework
72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000 (default)
W0806 19:47:51.453205 21855 master.hpp:2708] Unable to send message to
framework 72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000 (default): connection closed
I0806 19:47:51.453218 21855 master.cpp:12685] Removing offer
72aa280d-6cd9-4e61-823b-48b59fdbae4a-O1
I0806 19:47:51.453238 21855 master.cpp:3337] Disconnecting framework
72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000 (default)
I0806 19:47:51.453248 21855 master.cpp:1425] Giving framework
72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000 (default) 0ns to failover
I0806 19:47:51.453284 21855 hierarchical.cpp:475] Deactivated framework
72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000
I0806 19:47:51.453384 21855 hierarchical.cpp:1218] Recovered cpus(allocated:
*):1.8; mem(allocated: *):960; disk(allocated: *):960; ports(allocated:
*):[31000-32000] (total: cpus:2; mem:1024; disk:1024; ports:[31000-32000],
allocated: cpus(allocated: *):0.2; mem(allocated: *):64; disk(allocated: *):64)
on agent 72aa280d-6cd9-4e61-823b-48b59fdbae4a-S0 from framework
72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000
I0806 19:47:51.453774 21853 master.cpp:10185] Framework failover timeout,
removing framework 72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000 (default)
I0806 19:47:51.453794 21853 master.cpp:11184] Removing framework
72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000 (default)
I0806 19:47:51.453852 21853 master.cpp:12034] Updating the state of task
fa7228d9-f532-40e7-81ac-e99231f68242 of framework
72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000 (latest state: TASK_KILLED, status
update state: TASK_KILLED)
I0806 19:47:51.453855 21856 slave.cpp:4056] Asked to shut down framework
72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000 by [email protected]:40941
I0806 19:47:51.453873 21856 slave.cpp:4081] Shutting down framework
72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000
I0806 19:47:51.453884 21856 slave.cpp:7175] Shutting down executor 'default' of
framework 72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000
W0806 19:47:51.453892 21856 slave.hpp:1004] Unable to send event to executor
'default' of framework 72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000: unknown
connection type
I0806 19:47:51.453943 21853 master.cpp:12132] Removing task
fa7228d9-f532-40e7-81ac-e99231f68242 with resources cpus(allocated: *):0.1;
mem(allocated: *):32; disk(allocated: *):32 of framework
72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000 on agent
72aa280d-6cd9-4e61-823b-48b59fdbae4a-S0 at slave(644)@127.0.0.1:40941
(localhost)
I0806 19:47:51.453974 21856 hierarchical.cpp:1218] Recovered cpus(allocated:
*):0.1; mem(allocated: *):32; disk(allocated: *):32 (total: cpus:2; mem:1024;
disk:1024; ports:[31000-32000], allocated: cpus(allocated: *):0.1;
mem(allocated: *):32; disk(allocated: *):32) on agent
72aa280d-6cd9-4e61-823b-48b59fdbae4a-S0 from framework
72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000
I0806 19:47:51.454030 21853 master.cpp:12172] Removing executor 'default' with
resources cpus(allocated: *):0.1; mem(allocated: *):32; disk(allocated: *):32
of framework 72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000 on agent
72aa280d-6cd9-4e61-823b-48b59fdbae4a-S0 at slave(644)@127.0.0.1:40941
(localhost)
I0806 19:47:51.454185 21853 hierarchical.cpp:1218] Recovered cpus(allocated:
*):0.1; mem(allocated: *):32; disk(allocated: *):32 (total: cpus:2; mem:1024;
disk:1024; ports:[31000-32000], allocated: {}) on agent
72aa280d-6cd9-4e61-823b-48b59fdbae4a-S0 from framework
72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000
I0806 19:47:51.454223 21853 hierarchical.cpp:1432] Allocation paused
I0806 19:47:51.454277 21853 hierarchical.cpp:417] Removed framework
72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000
I0806 19:47:51.454298 21853 hierarchical.cpp:1442] Allocation resumed
I0806 19:47:51.454691 21858 slave.cpp:924] Agent terminating
I0806 19:47:51.454712 21858 slave.cpp:4056] Asked to shut down framework
72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000 by @0.0.0.0:0
W0806 19:47:51.454723 21858 slave.cpp:4077] Ignoring shutdown framework
72aa280d-6cd9-4e61-823b-48b59fdbae4a-0000 because it is terminating
I0806 19:47:51.454890 21858 master.cpp:1295] Agent
72aa280d-6cd9-4e61-823b-48b59fdbae4a-S0 at slave(644)@127.0.0.1:40941
(localhost) disconnected
I0806 19:47:51.454907 21858 master.cpp:3397] Disconnecting agent
72aa280d-6cd9-4e61-823b-48b59fdbae4a-S0 at slave(644)@127.0.0.1:40941
(localhost)
I0806 19:47:51.454921 21858 master.cpp:3416] Deactivating agent
72aa280d-6cd9-4e61-823b-48b59fdbae4a-S0 at slave(644)@127.0.0.1:40941
(localhost)
I0806 19:47:51.454962 21858 hierarchical.cpp:799] Agent
72aa280d-6cd9-4e61-823b-48b59fdbae4a-S0 deactivated
../../src/tests/slave_tests.cpp:2155: Failure
Actual function call count doesn't match EXPECT_CALL(*executor, error(_, _))...
Expected: to be called once
Actual: never called - unsatisfied and active
I0806 19:47:51.464138 21850 master.cpp:1135] Master terminating
I0806 19:47:51.464393 21856 hierarchical.cpp:775] Removed all filters for agent
72aa280d-6cd9-4e61-823b-48b59fdbae4a-S0
I0806 19:47:51.464411 21856 hierarchical.cpp:650] Removed agent
72aa280d-6cd9-4e61-823b-48b59fdbae4a-S0
[ FAILED ] SlaveTest.HTTPExecutorBadAuthentication (15113 ms)
{code}
> SlaveTest.HTTPExecutorBadAuthentication is flaky.
> -------------------------------------------------
>
> Key: MESOS-8879
> URL: https://issues.apache.org/jira/browse/MESOS-8879
> Project: Mesos
> Issue Type: Bug
> Components: test
> Affects Versions: 1.6.0
> Reporter: Chun-Hung Hsiao
> Priority: Major
> Labels: flaky-test
> Attachments:
> SlaveTest_HTTPExecutorBadAuthentication_SSL_mesos-ec2-debian-9.txt
>
>
> This test is flaky on CI:
> {noformat}
> ../../src/tests/slave_tests.cpp:2320
> Failed to wait 15secs for error
> {noformat}
--
This message was sent by Atlassian JIRA
(v7.6.14#76016)
