Benjamin Bannier created MESOS-6820:
---------------------------------------
Summary: FaultToleranceTest.FrameworkReregister is flaky
Key: MESOS-6820
URL: https://issues.apache.org/jira/browse/MESOS-6820
Project: Mesos
Issue Type: Bug
Components: test
Environment: Debian 8, OS X
Reporter: Benjamin Bannier
I just saw {{FaultToleranceTest.FrameworkReregister}} fail in internal CI on a
Debian 8 system. Running the test in repetition on my OS X machine I was able
to reproduce the issue on OS X as well.
{noformat}
[ RUN ] FaultToleranceTest.FrameworkReregister
I1219 23:04:12.914769 23530 cluster.cpp:160] Creating default 'local' authorizer
I1219 23:04:12.915388 23545 master.cpp:380] Master
4daa3046-9990-49c7-b601-958964306799 (ip-172-16-10-223.mesosphere.io) started
on 172.16.10.223:52614
I1219 23:04:12.915400 23545 master.cpp:382] Flags at startup: --acls=""
--agent_ping_timeout="15secs" --agent_reregister_timeout="10mins"
--allocation_interval="1secs" --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="/mnt/teamcity/temp/buildTmp/4KpUDy/credentials"
--framework_sorter="drf" --help="false" --hostname_lookup="true"
--http_authenticators="basic" --http_framework_authenticators="basic"
--initialize_driver_logging="true" --log_auto_initialize="true"
--logbufsecs="0" --logging_level="INFO" --max_agent_ping_timeouts="5"
--max_completed_frameworks="50" --max_completed_tasks_per_framework="1000"
--quiet="false" --recovery_agent_removal_limit="100%" --registry="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="/mnt/teamcity/temp/buildTmp/4KpUDy/master"
--zk_session_timeout="10secs"
I1219 23:04:12.915504 23545 master.cpp:432] Master only allowing authenticated
frameworks to register
I1219 23:04:12.915509 23545 master.cpp:446] Master only allowing authenticated
agents to register
I1219 23:04:12.915511 23545 master.cpp:459] Master only allowing authenticated
HTTP frameworks to register
I1219 23:04:12.915514 23545 credentials.hpp:37] Loading credentials for
authentication from '/mnt/teamcity/temp/buildTmp/4KpUDy/credentials'
I1219 23:04:12.915570 23545 master.cpp:504] Using default 'crammd5'
authenticator
I1219 23:04:12.915597 23545 http.cpp:922] Using default 'basic' HTTP
authenticator for realm 'mesos-master-readonly'
I1219 23:04:12.915617 23545 http.cpp:922] Using default 'basic' HTTP
authenticator for realm 'mesos-master-readwrite'
I1219 23:04:12.915658 23545 http.cpp:922] Using default 'basic' HTTP
authenticator for realm 'mesos-master-scheduler'
I1219 23:04:12.915688 23545 master.cpp:584] Authorization enabled
I1219 23:04:12.915725 23546 whitelist_watcher.cpp:77] No whitelist given
I1219 23:04:12.915737 23547 hierarchical.cpp:149] Initialized hierarchical
allocator process
I1219 23:04:12.916110 23545 master.cpp:2046] Elected as the leading master!
I1219 23:04:12.916118 23545 master.cpp:1568] Recovering from registrar
I1219 23:04:12.916179 23548 registrar.cpp:329] Recovering registrar
I1219 23:04:12.916311 23545 registrar.cpp:362] Successfully fetched the
registry (0B) in 115968ns
I1219 23:04:12.916334 23545 registrar.cpp:461] Applied 1 operations in 1982ns;
attempting to update the registry
I1219 23:04:12.916554 23547 registrar.cpp:506] Successfully updated the
registry in 208896ns
I1219 23:04:12.916770 23547 registrar.cpp:392] Successfully recovered registrar
I1219 23:04:12.916853 23547 master.cpp:1684] Recovered 0 agents from the
registry (174B); allowing 10mins for agents to re-register
I1219 23:04:12.916956 23544 hierarchical.cpp:176] Skipping recovery of
hierarchical allocator: nothing to recover
I1219 23:04:12.918097 23530 containerizer.cpp:220] Using isolation:
posix/cpu,posix/mem,filesystem/posix,network/cni
I1219 23:04:12.920801 23530 linux_launcher.cpp:150] Using
/sys/fs/cgroup/freezer as the freezer hierarchy for the Linux launcher
I1219 23:04:12.921478 23530 cluster.cpp:446] Creating default 'local' authorizer
I1219 23:04:12.921813 23546 slave.cpp:209] Mesos agent started on
(36)@172.16.10.223:52614
I1219 23:04:12.921823 23546 slave.cpp:210] Flags at startup: --acls=""
--appc_simple_discovery_uri_prefix="http://";
--appc_store_dir="/mnt/teamcity/temp/buildTmp/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="/mnt/teamcity/temp/buildTmp/FaultToleranceTest_FrameworkReregister_PIW1QY/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="/mnt/teamcity/temp/buildTmp/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="/mnt/teamcity/temp/buildTmp/FaultToleranceTest_FrameworkReregister_PIW1QY/fetch"
--fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks"
--gc_disk_headroom="0.1" --hadoop_home="" --help="false"
--hostname_lookup="true" --http_authenticators="basic"
--http_command_executor="false"
--http_credentials="/mnt/teamcity/temp/buildTmp/FaultToleranceTest_FrameworkReregister_PIW1QY/http_credentials"
--http_heartbeat_interval="30secs" --image_provisioner_backend="copy"
--initialize_driver_logging="true" --isolation="posix/cpu,posix/mem"
--launcher="linux"
--launcher_dir="/mnt/teamcity/work/4240ba9ddd0997c3/build/src" --logbufsecs="0"
--logging_level="INFO" --max_completed_executors_per_framework="150"
--oversubscribed_resources_interval="15secs" --perf_duration="10secs"
--perf_interval="1mins" --qos_correction_interval_min="0ns" --quiet="false"
--recover="reconnect" --recovery_timeout="15mins"
--registration_backoff_factor="10ms"
--resources="cpus:2;gpus:0;mem:1024;disk:1024;ports:[31000-32000]"
--revocable_cpu_low_priority="true"
--runtime_dir="/mnt/teamcity/temp/buildTmp/FaultToleranceTest_FrameworkReregister_PIW1QY"
--sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true"
--systemd_enable_support="true"
--systemd_runtime_directory="/run/systemd/system" --version="false"
--work_dir="/mnt/teamcity/temp/buildTmp/FaultToleranceTest_FrameworkReregister_ytYsKg"
I1219 23:04:12.922118 23546 credentials.hpp:86] Loading credential for
authentication from
'/mnt/teamcity/temp/buildTmp/FaultToleranceTest_FrameworkReregister_PIW1QY/credential'
I1219 23:04:12.922175 23546 slave.cpp:352] Agent using credential for:
test-principal
I1219 23:04:12.922183 23546 credentials.hpp:37] Loading credentials for
authentication from
'/mnt/teamcity/temp/buildTmp/FaultToleranceTest_FrameworkReregister_PIW1QY/http_credentials'
I1219 23:04:12.922237 23546 http.cpp:922] Using default 'basic' HTTP
authenticator for realm 'mesos-agent-readonly'
I1219 23:04:12.922269 23546 http.cpp:922] Using default 'basic' HTTP
authenticator for realm 'mesos-agent-readwrite'
I1219 23:04:12.922341 23530 sched.cpp:232] Version: 1.2.0
I1219 23:04:12.922451 23551 sched.cpp:336] New master detected at
master@172.16.10.223:52614
I1219 23:04:12.922477 23551 sched.cpp:402] Authenticating with master
master@172.16.10.223:52614
I1219 23:04:12.922487 23551 sched.cpp:409] Using default CRAM-MD5 authenticatee
I1219 23:04:12.922564 23545 authenticatee.cpp:121] Creating new client SASL
connection
I1219 23:04:12.922552 23546 slave.cpp:539] Agent resources: cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I1219 23:04:12.922590 23546 slave.cpp:547] Agent attributes: [ ]
I1219 23:04:12.922596 23546 slave.cpp:552] Agent hostname:
ip-172-16-10-223.mesosphere.io
I1219 23:04:12.922739 23545 master.cpp:6751] Authenticating
scheduler-09a58709-8c77-40d4-a431-5faba5cbbe7d@172.16.10.223:52614
I1219 23:04:12.922794 23547 authenticator.cpp:414] Starting authentication
session for crammd5-authenticatee(100)@172.16.10.223:52614
I1219 23:04:12.922869 23545 authenticator.cpp:98] Creating new server SASL
connection
I1219 23:04:12.922893 23546 state.cpp:57] Recovering state from
'/mnt/teamcity/temp/buildTmp/FaultToleranceTest_FrameworkReregister_ytYsKg/meta'
I1219 23:04:12.923012 23546 status_update_manager.cpp:203] Recovering status
update manager
I1219 23:04:12.923072 23545 authenticatee.cpp:213] Received SASL authentication
mechanisms: CRAM-MD5
I1219 23:04:12.923086 23545 authenticatee.cpp:239] Attempting to authenticate
with mechanism 'CRAM-MD5'
I1219 23:04:12.923137 23545 authenticator.cpp:204] Received SASL authentication
start
I1219 23:04:12.923156 23548 containerizer.cpp:599] Recovering containerizer
I1219 23:04:12.923158 23545 authenticator.cpp:326] Authentication requires more
steps
I1219 23:04:12.923212 23545 authenticatee.cpp:259] Received SASL authentication
step
I1219 23:04:12.923260 23545 authenticator.cpp:232] Received SASL authentication
step
I1219 23:04:12.923276 23545 auxprop.cpp:109] Request to lookup properties for
user: 'test-principal' realm: 'ip-172-16-10-223.mesosphere.io' server FQDN:
'ip-172-16-10-223.mesosphere.io' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1219 23:04:12.923283 23545 auxprop.cpp:181] Looking up auxiliary property
'*userPassword'
I1219 23:04:12.923292 23545 auxprop.cpp:181] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I1219 23:04:12.923300 23545 auxprop.cpp:109] Request to lookup properties for
user: 'test-principal' realm: 'ip-172-16-10-223.mesosphere.io' server FQDN:
'ip-172-16-10-223.mesosphere.io' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1219 23:04:12.923306 23545 auxprop.cpp:131] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I1219 23:04:12.923312 23545 auxprop.cpp:131] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1219 23:04:12.923322 23545 authenticator.cpp:318] Authentication success
I1219 23:04:12.923377 23548 authenticatee.cpp:299] Authentication success
I1219 23:04:12.923403 23550 authenticator.cpp:432] Authentication session
cleanup for crammd5-authenticatee(100)@172.16.10.223:52614
I1219 23:04:12.923434 23545 master.cpp:6781] Successfully authenticated
principal 'test-principal' at
scheduler-09a58709-8c77-40d4-a431-5faba5cbbe7d@172.16.10.223:52614
I1219 23:04:12.923477 23548 sched.cpp:508] Successfully authenticated with
master master@172.16.10.223:52614
I1219 23:04:12.923485 23548 sched.cpp:826] Sending SUBSCRIBE call to
master@172.16.10.223:52614
I1219 23:04:12.923519 23548 sched.cpp:859] Will retry registration in
1.760040858secs if necessary
I1219 23:04:12.923565 23551 master.cpp:2634] Received SUBSCRIBE call for
framework 'default' at
scheduler-09a58709-8c77-40d4-a431-5faba5cbbe7d@172.16.10.223:52614
I1219 23:04:12.923579 23551 master.cpp:2082] Authorizing framework principal
'test-principal' to receive offers for role '*'
I1219 23:04:12.923686 23551 master.cpp:2710] Subscribing framework default with
checkpointing disabled and capabilities [ ]
I1219 23:04:12.923876 23551 sched.cpp:749] Framework registered with
4daa3046-9990-49c7-b601-958964306799-0000
I1219 23:04:12.923877 23547 hierarchical.cpp:277] Added framework
4daa3046-9990-49c7-b601-958964306799-0000
I1219 23:04:12.923913 23547 hierarchical.cpp:1690] No allocations performed
I1219 23:04:12.923918 23551 sched.cpp:763] Scheduler::registered took 21516ns
I1219 23:04:12.923923 23547 hierarchical.cpp:1785] No inverse offers to send
out!
I1219 23:04:12.923933 23547 hierarchical.cpp:1292] Performed allocation for 0
agents in 27585ns
I1219 23:04:12.924137 23548 provisioner.cpp:253] Provisioner recovery complete
I1219 23:04:12.924263 23545 slave.cpp:5407] Finished recovery
I1219 23:04:12.924439 23545 slave.cpp:5581] Querying resource estimator for
oversubscribable resources
I1219 23:04:12.924515 23545 slave.cpp:924] New master detected at
master@172.16.10.223:52614
I1219 23:04:12.924522 23547 status_update_manager.cpp:177] Pausing sending
status updates
I1219 23:04:12.924528 23545 slave.cpp:983] Authenticating with master
master@172.16.10.223:52614
I1219 23:04:12.924545 23545 slave.cpp:994] Using default CRAM-MD5 authenticatee
I1219 23:04:12.924588 23545 slave.cpp:956] Detecting new master
I1219 23:04:12.924609 23551 authenticatee.cpp:121] Creating new client SASL
connection
I1219 23:04:12.924648 23545 slave.cpp:5595] Received oversubscribable resources
{} from the resource estimator
I1219 23:04:12.924757 23551 master.cpp:6751] Authenticating
slave(36)@172.16.10.223:52614
I1219 23:04:12.924804 23551 authenticator.cpp:414] Starting authentication
session for crammd5-authenticatee(101)@172.16.10.223:52614
I1219 23:04:12.924855 23551 authenticator.cpp:98] Creating new server SASL
connection
I1219 23:04:12.924983 23551 authenticatee.cpp:213] Received SASL authentication
mechanisms: CRAM-MD5
I1219 23:04:12.924993 23551 authenticatee.cpp:239] Attempting to authenticate
with mechanism 'CRAM-MD5'
I1219 23:04:12.925047 23547 authenticator.cpp:204] Received SASL authentication
start
I1219 23:04:12.925068 23547 authenticator.cpp:326] Authentication requires more
steps
I1219 23:04:12.925098 23547 authenticatee.cpp:259] Received SASL authentication
step
I1219 23:04:12.925143 23547 authenticator.cpp:232] Received SASL authentication
step
I1219 23:04:12.925158 23547 auxprop.cpp:109] Request to lookup properties for
user: 'test-principal' realm: 'ip-172-16-10-223.mesosphere.io' server FQDN:
'ip-172-16-10-223.mesosphere.io' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1219 23:04:12.925165 23547 auxprop.cpp:181] Looking up auxiliary property
'*userPassword'
I1219 23:04:12.925171 23547 auxprop.cpp:181] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I1219 23:04:12.925176 23547 auxprop.cpp:109] Request to lookup properties for
user: 'test-principal' realm: 'ip-172-16-10-223.mesosphere.io' server FQDN:
'ip-172-16-10-223.mesosphere.io' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1219 23:04:12.925180 23547 auxprop.cpp:131] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I1219 23:04:12.925184 23547 auxprop.cpp:131] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1219 23:04:12.925189 23547 authenticator.cpp:318] Authentication success
I1219 23:04:12.925221 23547 authenticatee.cpp:299] Authentication success
I1219 23:04:12.925243 23545 master.cpp:6781] Successfully authenticated
principal 'test-principal' at slave(36)@172.16.10.223:52614
I1219 23:04:12.925264 23546 authenticator.cpp:432] Authentication session
cleanup for crammd5-authenticatee(101)@172.16.10.223:52614
I1219 23:04:12.925400 23547 slave.cpp:1078] Successfully authenticated with
master master@172.16.10.223:52614
I1219 23:04:12.925447 23547 slave.cpp:1493] Will retry registration in
8.623943ms if necessary
I1219 23:04:12.925516 23545 master.cpp:5162] Registering agent at
slave(36)@172.16.10.223:52614 (ip-172-16-10-223.mesosphere.io) with id
4daa3046-9990-49c7-b601-958964306799-S0
I1219 23:04:12.925616 23547 registrar.cpp:461] Applied 1 operations in 8538ns;
attempting to update the registry
I1219 23:04:12.925874 23548 registrar.cpp:506] Successfully updated the
registry in 0ns
I1219 23:04:12.926054 23548 slave.cpp:4263] Received ping from
slave-observer(30)@172.16.10.223:52614
I1219 23:04:12.926064 23547 master.cpp:5233] Registered agent
4daa3046-9990-49c7-b601-958964306799-S0 at slave(36)@172.16.10.223:52614
(ip-172-16-10-223.mesosphere.io) with cpus(*):2; mem(*):1024; disk(*):1024;
ports(*):[31000-32000]
I1219 23:04:12.926103 23548 slave.cpp:1124] Registered with master
master@172.16.10.223:52614; given agent ID
4daa3046-9990-49c7-b601-958964306799-S0
I1219 23:04:12.926118 23548 fetcher.cpp:90] Clearing fetcher cache
I1219 23:04:12.926123 23550 hierarchical.cpp:491] Added agent
4daa3046-9990-49c7-b601-958964306799-S0 (ip-172-16-10-223.mesosphere.io) with
cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: {})
I1219 23:04:12.926188 23547 status_update_manager.cpp:184] Resuming sending
status updates
I1219 23:04:12.926255 23548 slave.cpp:1147] Checkpointing SlaveInfo to
'/mnt/teamcity/temp/buildTmp/FaultToleranceTest_FrameworkReregister_ytYsKg/meta/slaves/4daa3046-9990-49c7-b601-958964306799-S0/slave.info'
I1219 23:04:12.926273 23550 hierarchical.cpp:1785] No inverse offers to send
out!
I1219 23:04:12.926287 23550 hierarchical.cpp:1315] Performed allocation for
agent 4daa3046-9990-49c7-b601-958964306799-S0 in 148466ns
I1219 23:04:12.926336 23548 slave.cpp:1184] Forwarding total oversubscribed
resources {}
I1219 23:04:12.926396 23549 master.cpp:6580] Sending 1 offers to framework
4daa3046-9990-49c7-b601-958964306799-0000 (default) at
scheduler-09a58709-8c77-40d4-a431-5faba5cbbe7d@172.16.10.223:52614
I1219 23:04:12.926475 23549 master.cpp:5636] Received update of agent
4daa3046-9990-49c7-b601-958964306799-S0 at slave(36)@172.16.10.223:52614
(ip-172-16-10-223.mesosphere.io) with total oversubscribed resources {}
I1219 23:04:12.926549 23550 sched.cpp:923] Scheduler::resourceOffers took
13898ns
I1219 23:04:12.926579 23548 hierarchical.cpp:561] Agent
4daa3046-9990-49c7-b601-958964306799-S0 (ip-172-16-10-223.mesosphere.io)
updated with oversubscribed resources {} (total: cpus(*):2; mem(*):1024;
disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024;
disk(*):1024; ports(*):[31000-32000])
I1219 23:04:12.926609 23548 hierarchical.cpp:1690] No allocations performed
I1219 23:04:12.926614 23548 hierarchical.cpp:1785] No inverse offers to send
out!
I1219 23:04:12.926620 23548 hierarchical.cpp:1315] Performed allocation for
agent 4daa3046-9990-49c7-b601-958964306799-S0 in 22643ns
I1219 23:04:12.926808 23547 sched.cpp:330] Scheduler::disconnected took 5874ns
I1219 23:04:12.926820 23547 sched.cpp:336] New master detected at
master@172.16.10.223:52614
I1219 23:04:12.926839 23547 sched.cpp:402] Authenticating with master
master@172.16.10.223:52614
I1219 23:04:12.926846 23547 sched.cpp:409] Using default CRAM-MD5 authenticatee
I1219 23:04:12.926908 23547 authenticatee.cpp:121] Creating new client SASL
connection
I1219 23:04:12.927048 23547 master.cpp:6751] Authenticating
scheduler-09a58709-8c77-40d4-a431-5faba5cbbe7d@172.16.10.223:52614
I1219 23:04:12.927093 23547 authenticator.cpp:414] Starting authentication
session for crammd5-authenticatee(102)@172.16.10.223:52614
I1219 23:04:12.927150 23550 authenticator.cpp:98] Creating new server SASL
connection
I1219 23:04:12.927280 23550 authenticatee.cpp:213] Received SASL authentication
mechanisms: CRAM-MD5
I1219 23:04:12.927294 23550 authenticatee.cpp:239] Attempting to authenticate
with mechanism 'CRAM-MD5'
I1219 23:04:12.927328 23550 authenticator.cpp:204] Received SASL authentication
start
I1219 23:04:12.927351 23550 authenticator.cpp:326] Authentication requires more
steps
I1219 23:04:12.927383 23550 authenticatee.cpp:259] Received SASL authentication
step
I1219 23:04:12.927435 23547 authenticator.cpp:232] Received SASL authentication
step
I1219 23:04:12.927450 23547 auxprop.cpp:109] Request to lookup properties for
user: 'test-principal' realm: 'ip-172-16-10-223.mesosphere.io' server FQDN:
'ip-172-16-10-223.mesosphere.io' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false
I1219 23:04:12.927456 23547 auxprop.cpp:181] Looking up auxiliary property
'*userPassword'
I1219 23:04:12.927461 23547 auxprop.cpp:181] Looking up auxiliary property
'*cmusaslsecretCRAM-MD5'
I1219 23:04:12.927466 23547 auxprop.cpp:109] Request to lookup properties for
user: 'test-principal' realm: 'ip-172-16-10-223.mesosphere.io' server FQDN:
'ip-172-16-10-223.mesosphere.io' SASL_AUXPROP_VERIFY_AGAINST_HASH: false
SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true
I1219 23:04:12.927471 23547 auxprop.cpp:131] Skipping auxiliary property
'*userPassword' since SASL_AUXPROP_AUTHZID == true
I1219 23:04:12.927474 23547 auxprop.cpp:131] Skipping auxiliary property
'*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1219 23:04:12.927482 23547 authenticator.cpp:318] Authentication success
I1219 23:04:12.927520 23547 master.cpp:6781] Successfully authenticated
principal 'test-principal' at
scheduler-09a58709-8c77-40d4-a431-5faba5cbbe7d@172.16.10.223:52614
I1219 23:04:12.927542 23544 authenticator.cpp:432] Authentication session
cleanup for crammd5-authenticatee(102)@172.16.10.223:52614
I1219 23:04:12.927557 23550 authenticatee.cpp:299] Authentication success
I1219 23:04:12.927649 23549 sched.cpp:508] Successfully authenticated with
master master@172.16.10.223:52614
I1219 23:04:12.927662 23549 sched.cpp:826] Sending SUBSCRIBE call to
master@172.16.10.223:52614
I1219 23:04:12.927709 23549 sched.cpp:859] Will retry registration in
880.434321ms if necessary
I1219 23:04:12.927744 23548 master.cpp:2634] Received SUBSCRIBE call for
framework 'default' at
scheduler-09a58709-8c77-40d4-a431-5faba5cbbe7d@172.16.10.223:52614
I1219 23:04:12.927759 23548 master.cpp:2082] Authorizing framework principal
'test-principal' to receive offers for role '*'
I1219 23:04:12.927870 23545 master.cpp:2710] Subscribing framework default with
checkpointing disabled and capabilities [ ]
I1219 23:04:12.927881 23545 master.cpp:2788] Updating info for framework
4daa3046-9990-49c7-b601-958964306799-0000
I1219 23:04:12.927911 23545 master.cpp:2804] Allowing framework
4daa3046-9990-49c7-b601-958964306799-0000 (default) at
scheduler-09a58709-8c77-40d4-a431-5faba5cbbe7d@172.16.10.223:52614 to subscribe
with an already used id
I1219 23:04:12.928001 23549 sched.cpp:826] Sending SUBSCRIBE call to
master@172.16.10.223:52614
I1219 23:04:12.928040 23549 sched.cpp:859] Will retry registration in
1.080834119secs if necessary
I1219 23:04:12.928081 23548 hierarchical.cpp:1024] Recovered cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: {}) on agent
4daa3046-9990-49c7-b601-958964306799-S0 from framework
4daa3046-9990-49c7-b601-958964306799-0000
I1219 23:04:12.928102 23549 sched.cpp:935] Ignoring rescind offer message
because the driver is disconnected!
I1219 23:04:12.928150 23549 sched.cpp:791] Framework re-registered with
4daa3046-9990-49c7-b601-958964306799-0000
I1219 23:04:12.928181 23549 sched.cpp:805] Scheduler::reregistered took 18438ns
I1219 23:04:12.928247 23548 hierarchical.cpp:1785] No inverse offers to send
out!
I1219 23:04:12.928254 23545 master.cpp:2634] Received SUBSCRIBE call for
framework 'default' at
scheduler-09a58709-8c77-40d4-a431-5faba5cbbe7d@172.16.10.223:52614
I1219 23:04:12.928261 23548 hierarchical.cpp:1292] Performed allocation for 1
agents in 109229ns
I1219 23:04:12.928268 23545 master.cpp:2082] Authorizing framework principal
'test-principal' to receive offers for role '*'
I1219 23:04:12.928400 23545 master.cpp:6580] Sending 1 offers to framework
4daa3046-9990-49c7-b601-958964306799-0000 (default) at
scheduler-09a58709-8c77-40d4-a431-5faba5cbbe7d@172.16.10.223:52614
I1219 23:04:12.928444 23545 master.cpp:2710] Subscribing framework default with
checkpointing disabled and capabilities [ ]
I1219 23:04:12.928453 23545 master.cpp:2788] Updating info for framework
4daa3046-9990-49c7-b601-958964306799-0000
I1219 23:04:12.928472 23545 master.cpp:2804] Allowing framework
4daa3046-9990-49c7-b601-958964306799-0000 (default) at
scheduler-09a58709-8c77-40d4-a431-5faba5cbbe7d@172.16.10.223:52614 to subscribe
with an already used id
I1219 23:04:12.928524 23546 sched.cpp:923] Scheduler::resourceOffers took
26359ns
I1219 23:04:12.928570 23546 sched.cpp:949] Rescinded offer
4daa3046-9990-49c7-b601-958964306799-O1
I1219 23:04:12.928592 23546 sched.cpp:960] Scheduler::offerRescinded took 9442ns
I1219 23:04:12.928618 23546 sched.cpp:778] Ignoring framework re-registered
message because the driver is already connected!
I1219 23:04:12.928642 23547 hierarchical.cpp:1024] Recovered cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: {}) on agent
4daa3046-9990-49c7-b601-958964306799-S0 from framework
4daa3046-9990-49c7-b601-958964306799-0000
I1219 23:04:12.929006 23548 hierarchical.cpp:1785] No inverse offers to send
out!
I1219 23:04:12.929029 23548 hierarchical.cpp:1292] Performed allocation for 1
agents in 150224ns
I1219 23:04:12.929085 23545 master.cpp:6580] Sending 1 offers to framework
4daa3046-9990-49c7-b601-958964306799-0000 (default) at
scheduler-09a58709-8c77-40d4-a431-5faba5cbbe7d@172.16.10.223:52614
../../src/tests/fault_tolerance_tests.cpp:833: Failure
Mock function called more times than expected - returning directly.
Function call: resourceOffers(0x7ffc5fce0260, @0x7f7e348a4ba0 { 152-byte
object <90-E5 85-3F 7E-7F 00-00 00-00 00-00 00-00 00-00 1F-00 00-00 00-00 00-00
10-0A 01-24 7E-7F 00-00 40-0A 01-24 7E-7F 00-00 C0-24 00-24 7E-7F 00-00 A0-65
00-24 7E-7F 00-00 B0-93 00-24 7E-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 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00
00-00> })
Expected: to be called once
Actual: called twice - over-saturated and active
I1219 23:04:12.929224 23545 sched.cpp:923] Scheduler::resourceOffers took
69622ns
I1219 23:04:12.929244 23544 process.cpp:3679] Handling HTTP event for process
'master' with path: '/master/state'
I1219 23:04:12.929577 23551 http.cpp:402] HTTP GET for /master/state from
172.16.10.223:49741
I1219 23:04:12.930861 23530 sched.cpp:2008] Asked to stop the driver
I1219 23:04:12.930907 23550 sched.cpp:1193] Stopping framework
4daa3046-9990-49c7-b601-958964306799-0000
I1219 23:04:12.930974 23551 master.cpp:7291] Processing TEARDOWN call for
framework 4daa3046-9990-49c7-b601-958964306799-0000 (default) at
scheduler-09a58709-8c77-40d4-a431-5faba5cbbe7d@172.16.10.223:52614
I1219 23:04:12.930989 23551 master.cpp:7303] Removing framework
4daa3046-9990-49c7-b601-958964306799-0000 (default) at
scheduler-09a58709-8c77-40d4-a431-5faba5cbbe7d@172.16.10.223:52614
I1219 23:04:12.931046 23548 slave.cpp:2581] Asked to shut down framework
4daa3046-9990-49c7-b601-958964306799-0000 by master@172.16.10.223:52614
I1219 23:04:12.931061 23548 slave.cpp:2596] Cannot shut down unknown framework
4daa3046-9990-49c7-b601-958964306799-0000
I1219 23:04:12.931068 23550 hierarchical.cpp:392] Deactivated framework
4daa3046-9990-49c7-b601-958964306799-0000
I1219 23:04:12.931175 23550 hierarchical.cpp:1024] Recovered cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2;
mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: {}) on agent
4daa3046-9990-49c7-b601-958964306799-S0 from framework
4daa3046-9990-49c7-b601-958964306799-0000
I1219 23:04:12.931290 23550 hierarchical.cpp:343] Removed framework
4daa3046-9990-49c7-b601-958964306799-0000
I1219 23:04:12.931711 23547 slave.cpp:796] Agent terminating
I1219 23:04:12.931782 23544 master.cpp:1258] Agent
4daa3046-9990-49c7-b601-958964306799-S0 at slave(36)@172.16.10.223:52614
(ip-172-16-10-223.mesosphere.io) disconnected
I1219 23:04:12.931797 23544 master.cpp:2978] Disconnecting agent
4daa3046-9990-49c7-b601-958964306799-S0 at slave(36)@172.16.10.223:52614
(ip-172-16-10-223.mesosphere.io)
I1219 23:04:12.931813 23544 master.cpp:2997] Deactivating agent
4daa3046-9990-49c7-b601-958964306799-S0 at slave(36)@172.16.10.223:52614
(ip-172-16-10-223.mesosphere.io)
I1219 23:04:12.931854 23548 hierarchical.cpp:590] Agent
4daa3046-9990-49c7-b601-958964306799-S0 deactivated
I1219 23:04:12.933393 23530 master.cpp:1097] Master terminating
I1219 23:04:12.933498 23544 hierarchical.cpp:523] Removed agent
4daa3046-9990-49c7-b601-958964306799-S0
[ FAILED ] FaultToleranceTest.FrameworkReregister (20 ms)
{noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
