[ https://issues.apache.org/jira/browse/MESOS-8485?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16341377#comment-16341377 ]
Benno Evers commented on MESOS-8485: ------------------------------------ Review posted at: https://reviews.apache.org/r/65354 > MasterTest.RegistryGcByCount is flaky > ------------------------------------- > > Key: MESOS-8485 > URL: https://issues.apache.org/jira/browse/MESOS-8485 > Project: Mesos > Issue Type: Bug > Components: test > Affects Versions: 1.5.0 > Reporter: Vinod Kone > Assignee: Benno Evers > Priority: Major > Labels: flaky-test > > Observed this while testing Mesos 1.5.0-rc1 in ASF CI. > > {code} > 3: [ RUN ] MasterTest.RegistryGcByCount > ..............snip........................... > 3: I0123 19:22:05.929347 15994 slave.cpp:1201] Detecting new master > 3: I0123 19:22:05.931701 15988 slave.cpp:1228] Authenticating with master > master@172.17.0.2:45634 > 3: I0123 19:22:05.931838 15988 slave.cpp:1237] Using default CRAM-MD5 > authenticatee > 3: I0123 19:22:05.932153 15999 authenticatee.cpp:121] Creating new client > SASL connection > 3: I0123 19:22:05.932580 15992 master.cpp:8958] Authenticating > slave(442)@172.17.0.2:45634 > 3: I0123 19:22:05.932822 15990 authenticator.cpp:414] Starting authentication > session for crammd5-authenticatee(870)@172.17.0.2:45634 > 3: I0123 19:22:05.933163 15989 authenticator.cpp:98] Creating new server SASL > connection > 3: I0123 19:22:05.933465 16001 authenticatee.cpp:213] Received SASL > authentication mechanisms: CRAM-MD5 > 3: I0123 19:22:05.933495 16001 authenticatee.cpp:239] Attempting to > authenticate with mechanism 'CRAM-MD5' > 3: I0123 19:22:05.933631 15987 authenticator.cpp:204] Received SASL > authentication start > 3: I0123 19:22:05.933712 15987 authenticator.cpp:326] Authentication requires > more steps > 3: I0123 19:22:05.933851 15987 authenticatee.cpp:259] Received SASL > authentication step > 3: I0123 19:22:05.934006 15987 authenticator.cpp:232] Received SASL > authentication step > 3: I0123 19:22:05.934041 15987 auxprop.cpp:109] Request to lookup properties > for user: 'test-principal' realm: '455912973e2c' server FQDN: '455912973e2c' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: false > 3: I0123 19:22:05.934095 15987 auxprop.cpp:181] Looking up auxiliary property > '*userPassword' > 3: I0123 19:22:05.934147 15987 auxprop.cpp:181] Looking up auxiliary property > '*cmusaslsecretCRAM-MD5' > 3: I0123 19:22:05.934279 15987 auxprop.cpp:109] Request to lookup properties > for user: 'test-principal' realm: '455912973e2c' server FQDN: '455912973e2c' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: true > 3: I0123 19:22:05.934298 15987 auxprop.cpp:131] Skipping auxiliary property > '*userPassword' since SASL_AUXPROP_AUTHZID == true > 3: I0123 19:22:05.934307 15987 auxprop.cpp:131] Skipping auxiliary property > '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true > 3: I0123 19:22:05.934324 15987 authenticator.cpp:318] Authentication success > 3: I0123 19:22:05.934463 15995 authenticatee.cpp:299] Authentication success > 3: I0123 19:22:05.934563 16002 master.cpp:8988] Successfully authenticated > principal 'test-principal' at slave(442)@172.17.0.2:45634 > 3: I0123 19:22:05.934708 15993 authenticator.cpp:432] Authentication session > cleanup for crammd5-authenticatee(870)@172.17.0.2:45634 > 3: I0123 19:22:05.934891 15995 slave.cpp:1320] Successfully authenticated > with master master@172.17.0.2:45634 > 3: I0123 19:22:05.935261 15995 slave.cpp:1764] Will retry registration in > 2.234083ms if necessary > 3: I0123 19:22:05.935436 15999 master.cpp:6061] Received register agent > message from slave(442)@172.17.0.2:45634 (455912973e2c) > 3: I0123 19:22:05.935662 15999 master.cpp:3867] Authorizing agent with > principal 'test-principal' > 3: I0123 19:22:05.936161 15992 master.cpp:6123] Authorized registration of > agent at slave(442)@172.17.0.2:45634 (455912973e2c) > 3: I0123 19:22:05.936261 15992 master.cpp:6234] Registering agent at > slave(442)@172.17.0.2:45634 (455912973e2c) with id > eef8ea11-9247-44f3-84cf-340b24df3a52-S0 > 3: I0123 19:22:05.936993 15989 registrar.cpp:495] Applied 1 operations in > 227911ns; attempting to update the registry > 3: I0123 19:22:05.937814 15989 registrar.cpp:552] Successfully updated the > registry in 743168ns > 3: I0123 19:22:05.938057 15991 master.cpp:6282] Admitted agent > eef8ea11-9247-44f3-84cf-340b24df3a52-S0 at slave(442)@172.17.0.2:45634 > (455912973e2c) > 3: I0123 19:22:05.938891 15991 master.cpp:6331] Registered agent > eef8ea11-9247-44f3-84cf-340b24df3a52-S0 at slave(442)@172.17.0.2:45634 > (455912973e2c) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] > 3: I0123 19:22:05.939159 16002 slave.cpp:1764] Will retry registration in > 26.332876ms if necessary > 3: I0123 19:22:05.939349 15994 master.cpp:6061] Received register agent > message from slave(442)@172.17.0.2:45634 (455912973e2c) > 3: I0123 19:22:05.939347 15998 hierarchical.cpp:574] Added agent > eef8ea11-9247-44f3-84cf-340b24df3a52-S0 (455912973e2c) with cpus:2; mem:1024; > disk:1024; ports:[31000-32000] (allocated: {}) > 3: I0123 19:22:05.939574 15994 master.cpp:3867] Authorizing agent with > principal 'test-principal' > 3: I0123 19:22:05.939704 16002 slave.cpp:1366] Registered with master > master@172.17.0.2:45634; given agent ID > eef8ea11-9247-44f3-84cf-340b24df3a52-S0 > 3: I0123 19:22:05.939894 15999 task_status_update_manager.cpp:188] Resuming > sending task status updates > 3: I0123 19:22:05.940163 15998 hierarchical.cpp:1517] Performed allocation > for 1 agents in 231470ns > 3: I0123 19:22:05.940194 16001 master.cpp:6123] Authorized registration of > agent at slave(442)@172.17.0.2:45634 (455912973e2c) > 3: I0123 19:22:05.940263 16001 master.cpp:6213] Agent > eef8ea11-9247-44f3-84cf-340b24df3a52-S0 at slave(442)@172.17.0.2:45634 > (455912973e2c) already registered, resending acknowledgement > 3: I0123 19:22:05.942983 15994 process.cpp:3515] Handling HTTP event for > process 'master' with path: '/master/api/v1' > 3: I0123 19:22:05.944905 15995 http.cpp:1185] HTTP POST for /master/api/v1 > from 172.17.0.2:33442 > 3: I0123 19:22:05.945107 15995 http.cpp:682] Processing call MARK_AGENT_GONE > 3: I0123 19:22:05.945749 16001 http.cpp:5363] Marking agent > 'eef8ea11-9247-44f3-84cf-340b24df3a52-S0' as gone > 3: I0123 19:22:05.946480 15997 registrar.cpp:495] Applied 1 operations in > 186752ns; attempting to update the registry > 3: I0123 19:22:05.947284 15997 registrar.cpp:552] Successfully updated the > registry in 730112ns > 3: I0123 19:22:05.948225 15988 hierarchical.cpp:609] Removed agent > eef8ea11-9247-44f3-84cf-340b24df3a52-S0 > 3: I0123 19:22:05.952500 16002 slave.cpp:1386] Checkpointing SlaveInfo to > '/tmp/MasterTest_RegistryGcByCount_HbzHl2/meta/slaves/eef8ea11-9247-44f3-84cf-340b24df3a52-S0/slave.info' > 3: I0123 19:22:05.953299 16002 slave.cpp:1433] Forwarding agent update > \{"operations":{},"resource_version_uuid":\{"value":"nekTyNfGT1S5DNQZxKJ72A=="},"slave_id":\{"value":"eef8ea11-9247-44f3-84cf-340b24df3a52-S0"},"update_oversubscribed_resources":true} > 3: W0123 19:22:05.953675 16002 slave.cpp:1415] Already registered with master > master@172.17.0.2:45634 > 3: I0123 19:22:05.953790 16002 slave.cpp:1433] Forwarding agent update > \{"operations":{},"resource_version_uuid":\{"value":"nekTyNfGT1S5DNQZxKJ72A=="},"slave_id":\{"value":"eef8ea11-9247-44f3-84cf-340b24df3a52-S0"},"update_oversubscribed_resources":true} > 3: I0123 19:22:05.954031 16002 slave.cpp:964] Agent asked to shut down by > master@172.17.0.2:45634 because 'Agent has been marked gone' > 3: I0123 19:22:05.954082 16002 slave.cpp:931] Agent terminating > 3: W0123 19:22:05.954145 15993 master.cpp:7235] Ignoring update on removed > agent eef8ea11-9247-44f3-84cf-340b24df3a52-S0 > 3: W0123 19:22:05.954636 15993 master.cpp:7235] Ignoring update on removed > agent eef8ea11-9247-44f3-84cf-340b24df3a52-S0 > 3: W0123 19:22:05.955550 15986 process.cpp:2756] Attempted to spawn already > running process files@172.17.0.2:45634 > 3: I0123 19:22:05.956634 15986 containerizer.cpp:304] Using isolation \{ > environment_secret, posix/cpu, posix/mem, filesystem/posix, network/cni } > 3: W0123 19:22:05.957228 15986 backend.cpp:76] Failed to create 'aufs' > backend: AufsBackend requires root privileges > 3: W0123 19:22:05.957363 15986 backend.cpp:76] Failed to create 'bind' > backend: BindBackend requires root privileges > 3: I0123 19:22:05.957401 15986 provisioner.cpp:299] Using default backend > 'copy' > 3: I0123 19:22:05.959393 15986 cluster.cpp:460] Creating default 'local' > authorizer > 3: I0123 19:22:05.961545 15998 slave.cpp:262] Mesos agent started on > (443)@172.17.0.2:45634 > 3: I0123 19:22:05.961560 15998 slave.cpp:263] Flags at startup: --acls="" > --appc_simple_discovery_uri_prefix="http://" > --appc_store_dir="/tmp/MasterTest_RegistryGcByCount_2Nh5JR/store/appc" > --authenticate_http_readonly="true" --authenticate_http_readwrite="false" > --authenticatee="crammd5" --authentication_backoff_factor="1secs" > --authorizer="local" --cgroups_cpu_enable_pids_and_tids_count="false" > --cgroups_enable_cfs="false" --cgroups_hierarchy="/sys/fs/cgroup" > --cgroups_limit_swap="false" --cgroups_root="mesos" > --container_disk_watch_interval="15secs" --containerizers="mesos" > --credential="/tmp/MasterTest_RegistryGcByCount_2Nh5JR/credential" > --default_role="*" --disallow_sharing_agent_pid_namespace="false" > --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" > --docker_registry="https://registry-1.docker.io" --docker_remove_delay="6hrs" > --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" > --docker_store_dir="/tmp/MasterTest_RegistryGcByCount_2Nh5JR/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/MasterTest_RegistryGcByCount_2Nh5JR/fetch" > --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" > --gc_disk_headroom="0.1" --hadoop_home="" --help="false" > --hostname_lookup="true" --http_command_executor="false" > --http_credentials="/tmp/MasterTest_RegistryGcByCount_2Nh5JR/http_credentials" > --http_heartbeat_interval="30secs" --initialize_driver_logging="true" > --isolation="posix/cpu,posix/mem" --launcher="posix" > --launcher_dir="/mesos/build/src" --logbufsecs="0" --logging_level="INFO" > --max_completed_executors_per_framework="150" > --oversubscribed_resources_interval="15secs" --perf_duration="10secs" > --perf_interval="1mins" --port="5051" --qos_correction_interval_min="0ns" > --quiet="false" --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/MasterTest_RegistryGcByCount_2Nh5JR" > --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/MasterTest_RegistryGcByCount_FyzIlU" > --zk_session_timeout="10secs" > 3: I0123 19:22:05.961917 15998 credentials.hpp:86] Loading credential for > authentication from '/tmp/MasterTest_RegistryGcByCount_2Nh5JR/credential' > 3: I0123 19:22:05.962070 15998 slave.cpp:295] Agent using credential for: > test-principal > 3: I0123 19:22:05.962090 15998 credentials.hpp:37] Loading credentials for > authentication from > '/tmp/MasterTest_RegistryGcByCount_2Nh5JR/http_credentials' > 3: I0123 19:22:05.962347 15998 http.cpp:1045] Creating default 'basic' HTTP > authenticator for realm 'mesos-agent-readonly' > 3: I0123 19:22:05.964292 15988 process.cpp:3515] Handling HTTP event for > process 'master' with path: '/master/api/v1' > 3: I0123 19:22:05.964375 15998 slave.cpp:612] 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"}] > 3: I0123 19:22:05.964591 15998 slave.cpp:620] Agent attributes: [ ] > 3: I0123 19:22:05.964601 15998 slave.cpp:629] Agent hostname: 455912973e2c > 3: I0123 19:22:05.964753 15995 task_status_update_manager.cpp:181] Pausing > sending task status updates > 3: I0123 19:22:05.966159 16002 http.cpp:1185] HTTP POST for /master/api/v1 > from 172.17.0.2:33443 > 3: I0123 19:22:05.966327 16002 http.cpp:682] Processing call MARK_AGENT_GONE > 3: I0123 19:22:05.966898 15990 http.cpp:5363] Marking agent > 'eef8ea11-9247-44f3-84cf-340b24df3a52-S0' as gone > 3: W0123 19:22:05.966939 15990 http.cpp:5366] Not marking agent > 'eef8ea11-9247-44f3-84cf-340b24df3a52-S0' as gone because it has already > transitioned to gone > 3: I0123 19:22:05.966969 15992 state.cpp:66] Recovering state from > '/tmp/MasterTest_RegistryGcByCount_FyzIlU/meta' > 3: I0123 19:22:05.967445 15995 task_status_update_manager.cpp:207] Recovering > task status update manager > 3: I0123 19:22:05.967747 15991 containerizer.cpp:674] Recovering containerizer > 3: I0123 19:22:05.969804 15999 provisioner.cpp:493] Provisioner recovery > complete > 3: I0123 19:22:05.970371 16002 slave.cpp:6822] Finished recovery > 3: I0123 19:22:05.971616 16000 task_status_update_manager.cpp:181] Pausing > sending task status updates > 3: I0123 19:22:05.971608 15987 slave.cpp:1146] New master detected at > master@172.17.0.2:45634 > 3: I0123 19:22:05.971737 15987 slave.cpp:1201] Detecting new master > 3: I0123 19:22:05.971755 15990 hierarchical.cpp:1517] Performed allocation > for 0 agents in 134021ns > 3: I0123 19:22:05.972729 15999 slave.cpp:6360] Current disk usage 16.56%. Max > allowed age: 5.140805523372986days > 3: I0123 19:22:05.972985 15988 master.cpp:1878] Skipping periodic registry > garbage collection: no agents qualify for removal > 3: I0123 19:22:05.974480 16001 slave.cpp:1228] Authenticating with master > master@172.17.0.2:45634 > 3: I0123 19:22:05.974581 16001 slave.cpp:1237] Using default CRAM-MD5 > authenticatee > 3: I0123 19:22:05.975023 16002 authenticatee.cpp:121] Creating new client > SASL connection > 3: I0123 19:22:05.975343 15998 master.cpp:8958] Authenticating > slave(443)@172.17.0.2:45634 > 3: I0123 19:22:05.975476 16000 authenticator.cpp:414] Starting authentication > session for crammd5-authenticatee(871)@172.17.0.2:45634 > 3: I0123 19:22:05.975735 15991 authenticator.cpp:98] Creating new server SASL > connection > 3: I0123 19:22:05.976027 15995 authenticatee.cpp:213] Received SASL > authentication mechanisms: CRAM-MD5 > 3: I0123 19:22:05.976143 15995 authenticatee.cpp:239] Attempting to > authenticate with mechanism 'CRAM-MD5' > 3: I0123 19:22:05.976356 15989 authenticator.cpp:204] Received SASL > authentication start > 3: I0123 19:22:05.976420 15989 authenticator.cpp:326] Authentication requires > more steps > 3: I0123 19:22:05.976552 15990 authenticatee.cpp:259] Received SASL > authentication step > 3: I0123 19:22:05.976698 15987 authenticator.cpp:232] Received SASL > authentication step > 3: I0123 19:22:05.976750 15987 auxprop.cpp:109] Request to lookup properties > for user: 'test-principal' realm: '455912973e2c' server FQDN: '455912973e2c' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: false > 3: I0123 19:22:05.976773 15987 auxprop.cpp:181] Looking up auxiliary property > '*userPassword' > 3: I0123 19:22:05.976821 15987 auxprop.cpp:181] Looking up auxiliary property > '*cmusaslsecretCRAM-MD5' > 3: I0123 19:22:05.976898 15987 auxprop.cpp:109] Request to lookup properties > for user: 'test-principal' realm: '455912973e2c' server FQDN: '455912973e2c' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: true > 3: I0123 19:22:05.976924 15987 auxprop.cpp:131] Skipping auxiliary property > '*userPassword' since SASL_AUXPROP_AUTHZID == true > 3: I0123 19:22:05.976935 15987 auxprop.cpp:131] Skipping auxiliary property > '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true > 3: I0123 19:22:05.976953 15987 authenticator.cpp:318] Authentication success > 3: I0123 19:22:05.977094 15996 authenticatee.cpp:299] Authentication success > 3: I0123 19:22:05.977233 15994 master.cpp:8988] Successfully authenticated > principal 'test-principal' at slave(443)@172.17.0.2:45634 > 3: I0123 19:22:05.977321 15987 authenticator.cpp:432] Authentication session > cleanup for crammd5-authenticatee(871)@172.17.0.2:45634 > 3: I0123 19:22:05.977475 15996 slave.cpp:1320] Successfully authenticated > with master master@172.17.0.2:45634 > 3: I0123 19:22:05.977953 15996 slave.cpp:1764] Will retry registration in > 6.841446ms if necessary > 3: I0123 19:22:05.978238 15992 master.cpp:6061] Received register agent > message from slave(443)@172.17.0.2:45634 (455912973e2c) > 3: I0123 19:22:05.978591 15992 master.cpp:3867] Authorizing agent with > principal 'test-principal' > 3: I0123 19:22:05.979161 16000 master.cpp:6123] Authorized registration of > agent at slave(443)@172.17.0.2:45634 (455912973e2c) > 3: I0123 19:22:05.979320 16000 master.cpp:6234] Registering agent at > slave(443)@172.17.0.2:45634 (455912973e2c) with id > eef8ea11-9247-44f3-84cf-340b24df3a52-S1 > 3: I0123 19:22:05.980505 15991 registrar.cpp:495] Applied 1 operations in > 455955ns; attempting to update the registry > 3: I0123 19:22:05.981642 15991 registrar.cpp:552] Successfully updated the > registry in 0ns > 3: I0123 19:22:05.981912 15988 master.cpp:6282] Admitted agent > eef8ea11-9247-44f3-84cf-340b24df3a52-S1 at slave(443)@172.17.0.2:45634 > (455912973e2c) > 3: I0123 19:22:05.982857 15988 master.cpp:6331] Registered agent > eef8ea11-9247-44f3-84cf-340b24df3a52-S1 at slave(443)@172.17.0.2:45634 > (455912973e2c) with cpus:2; mem:1024; disk:1024; ports:[31000-32000] > 3: I0123 19:22:05.982964 16001 slave.cpp:1366] Registered with master > master@172.17.0.2:45634; given agent ID > eef8ea11-9247-44f3-84cf-340b24df3a52-S1 > 3: I0123 19:22:05.983130 15996 task_status_update_manager.cpp:188] Resuming > sending task status updates > 3: I0123 19:22:05.983392 16001 slave.cpp:1386] Checkpointing SlaveInfo to > '/tmp/MasterTest_RegistryGcByCount_FyzIlU/meta/slaves/eef8ea11-9247-44f3-84cf-340b24df3a52-S1/slave.info' > 3: I0123 19:22:05.983423 15994 hierarchical.cpp:574] Added agent > eef8ea11-9247-44f3-84cf-340b24df3a52-S1 (455912973e2c) with cpus:2; mem:1024; > disk:1024; ports:[31000-32000] (allocated: {}) > 3: I0123 19:22:05.983815 15994 hierarchical.cpp:1517] Performed allocation > for 1 agents in 171516ns > 3: I0123 19:22:05.984135 16001 slave.cpp:1433] Forwarding agent update > \{"operations":{},"resource_version_uuid":\{"value":"1HNo1ICkRY24eDUqFmb6+Q=="},"slave_id":\{"value":"eef8ea11-9247-44f3-84cf-340b24df3a52-S1"},"update_oversubscribed_resources":true} > 3: I0123 19:22:05.984762 15997 master.cpp:7265] Received update of agent > eef8ea11-9247-44f3-84cf-340b24df3a52-S1 at slave(443)@172.17.0.2:45634 > (455912973e2c) with total oversubscribed resources {} > 3: I0123 19:22:05.985123 15997 master.cpp:7359] Ignoring update on agent > eef8ea11-9247-44f3-84cf-340b24df3a52-S1 at slave(443)@172.17.0.2:45634 > (455912973e2c) as it reports no changes > 3: W0123 19:22:05.985782 15986 process.cpp:2756] Attempted to spawn already > running process version@172.17.0.2:45634 > 3: I0123 19:22:05.986744 15986 sched.cpp:232] Version: 1.5.0 > 3: I0123 19:22:05.987470 15990 sched.cpp:336] New master detected at > master@172.17.0.2:45634 > 3: I0123 19:22:05.987567 15990 sched.cpp:396] Authenticating with master > master@172.17.0.2:45634 > 3: I0123 19:22:05.987582 15990 sched.cpp:403] Using default CRAM-MD5 > authenticatee > 3: I0123 19:22:05.987869 15999 authenticatee.cpp:121] Creating new client > SASL connection > 3: I0123 19:22:05.988121 15991 master.cpp:8958] Authenticating > scheduler-be5d74bf-c4bf-4504-9e67-6a4f8df93425@172.17.0.2:45634 > 3: I0123 19:22:05.988296 15987 authenticator.cpp:414] Starting authentication > session for crammd5-authenticatee(872)@172.17.0.2:45634 > 3: I0123 19:22:05.988575 15988 authenticator.cpp:98] Creating new server SASL > connection > 3: I0123 19:22:05.988821 15996 authenticatee.cpp:213] Received SASL > authentication mechanisms: CRAM-MD5 > 3: I0123 19:22:05.988852 15996 authenticatee.cpp:239] Attempting to > authenticate with mechanism 'CRAM-MD5' > 3: I0123 19:22:05.988967 15994 authenticator.cpp:204] Received SASL > authentication start > 3: I0123 19:22:05.989023 15994 authenticator.cpp:326] Authentication requires > more steps > 3: I0123 19:22:05.989145 15993 authenticatee.cpp:259] Received SASL > authentication step > 3: I0123 19:22:05.989271 16001 authenticator.cpp:232] Received SASL > authentication step > 3: I0123 19:22:05.989316 16001 auxprop.cpp:109] Request to lookup properties > for user: 'test-principal' realm: '455912973e2c' server FQDN: '455912973e2c' > SASL_AUXPROP_VER: > IFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: > false > 3: I0123 19:22:05.989334 16001 auxprop.cpp:181] Looking up auxiliary property > '*userPassword' > 3: I0123 19:22:05.989377 16001 auxprop.cpp:181] Looking up auxiliary property > '*cmusaslsecretCRAM-MD5' > 3: I0123 19:22:05.989400 16001 auxprop.cpp:109] Request to lookup properties > for user: 'test-principal' realm: '455912973e2c' server FQDN: '455912973e2c' > SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false > SASL_AUXPROP_AUTHZID: true > 3: I0123 19:22:05.989415 16001 auxprop.cpp:131] Skipping auxiliary property > '*userPassword' since SASL_AUXPROP_AUTHZID == true > 3: I0123 19:22:05.989423 16001 auxprop.cpp:131] Skipping auxiliary property > '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true > 3: I0123 19:22:05.989441 16001 authenticator.cpp:318] Authentication success > 3: I0123 19:22:05.989531 15997 authenticatee.cpp:299] Authentication success > 3: I0123 19:22:05.989719 15992 master.cpp:8988] Successfully authenticated > principal 'test-principal' at > scheduler-be5d74bf-c4bf-4504-9e67-6a4f8df93425@172.17.0.2:45634 > 3: I0123 19:22:05.989751 16000 authenticator.cpp:432] Authentication session > cleanup for crammd5-authenticatee(872)@172.17.0.2:45634 > 3: I0123 19:22:05.989894 15998 sched.cpp:502] Successfully authenticated with > master master@172.17.0.2:45634 > 3: I0123 19:22:05.989914 15998 sched.cpp:824] Sending SUBSCRIBE call to > master@172.17.0.2:45634 > 3: I0123 19:22:05.990039 15998 sched.cpp:857] Will retry registration in > 1.379182754secs if necessary > 3: I0123 19:22:05.990229 15991 master.cpp:2958] Received SUBSCRIBE call for > framework 'default' at > scheduler-be5d74bf-c4bf-4504-9e67-6a4f8df93425@172.17.0.2:45634 > 3: I0123 19:22:05.990311 15991 master.cpp:2275] Authorizing framework > principal 'test-principal' to receive offers for roles '\{ * }' > 3: I0123 19:22:05.990876 15987 master.cpp:3038] Subscribing framework default > with checkpointing disabled and capabilities [ MULTI_ROLE, > RESERVATION_REFINEMENT, PARTITION_AWARE ] > 3: I0123 19:22:05.991102 15987 master.cpp:9179] Adding framework > eef8ea11-9247-44f3-84cf-340b24df3a52-0000 (default) at > scheduler-be5d74bf-c4bf-4504-9e67-6a4f8df93425@172.17.0.2:45634 with roles { > } suppressed > 3: I0123 19:22:05.991621 15994 sched.cpp:751] Framework registered with > eef8ea11-9247-44f3-84cf-340b24df3a52-0000 > 3: I0123 19:22:05.991731 15988 hierarchical.cpp:297] Added framework > eef8ea11-9247-44f3-84cf-340b24df3a52-0000 > 3: I0123 19:22:05.991816 15994 sched.cpp:765] Scheduler::registered took > 25842ns > 3: I0123 19:22:05.993170 15988 hierarchical.cpp:1517] Performed allocation > for 1 agents in 1.236264ms > 3: I0123 19:22:05.993611 15997 master.cpp:8788] Sending 1 offers to framework > eef8ea11-9247-44f3-84cf-340b24df3a52-0000 (default) at > scheduler-be5d74bf-c4bf-4504-9e67-6a4f8df93425@172.17.0.2:45634 > 3: > 3: GMOCK WARNING: > 3: Uninteresting mock function call - returning directly. > 3: Function call: resourceOffers(0x7ffcbfa4e140, @0x7f82fc814860 \{ > 160-byte object <10-22 C5-0C 83-7F 00-00 00-00 00-00 00-00 00-00 5F-00 00-00 > 00-00 00-00 00-00 00-00 00-00 00-00 04-00 00-00 04-00 00-00 80-C0 03-C8 82-7F > 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 00-00 ... 10-38 04-C8 82-7F > 00-00 E0-C4 03-C8 82-7F 00-00 10-B3 00-C8 82-7F 00-00 60-A7 03-C8 82-7F 00-00 > 10-C3 00-C8 82-7F 00-00 00-00 00-00 00-00 00-00 10-DA 00-C8 82-7F 00-00 00-00 > 00-00 00-00 00-00> }) > 3: 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. > 3: I0123 19:22:05.994109 16001 sched.cpp:921] Scheduler::resourceOffers took > 77564ns > 3: I0123 19:22:05.994665 15989 master.cpp:8425] Performing explicit task > state reconciliation for 2 tasks of framework > eef8ea11-9247-44f3-84cf-340b24df3a52-0000 (default) at > scheduler-be5d74bf-c4bf-4504-9e67-6a4f8df93425@172.17.0.2:45634 > 3: I0123 19:22:05.994779 15989 master.cpp:8573] Sending explicit > reconciliation state TASK_GONE_BY_OPERATOR for task > 7a4ff1bf-488b-4152-a7e4-cf0876008c4d of framework > eef8ea11-9247-44f3-84cf-340b24df3a52-0000 (default) at > scheduler-be5d74bf-c4bf-4504-9e67-6a4f8df93425@172.17.0.2:45634 > 3: I0123 19:22:05.994936 15989 master.cpp:8573] Sending explicit > reconciliation state TASK_GONE_BY_OPERATOR for task > 9d4e66ef-86c7-428a-b110-ba949c0c19b8 of framework > eef8ea11-9247-44f3-84cf-340b24df3a52-0000 (default) at > scheduler-be5d74bf-c4bf-4504-9e67-6a4f8df93425@172.17.0.2:45634 > 3: I0123 19:22:05.995215 15989 sched.cpp:1029] Scheduler::statusUpdate took > 36257ns > 3: I0123 19:22:05.995381 15989 sched.cpp:1029] Scheduler::statusUpdate took > 36862ns > 3: /mesos/src/tests/master_tests.cpp:8606: Failure > 3: Expected: TASK_UNKNOWN > 3: To be equal to: reconcileUpdate1->state() > 3: Which is: TASK_GONE_BY_OPERATOR > 3: I0123 19:22:05.995779 16000 master.cpp:1420] Framework > eef8ea11-9247-44f3-84cf-340b24df3a52-0000 (default) at > scheduler-be5d74bf-c4bf-4504-9e67-6a4f8df93425@172.17.0.2:45634 disconnected > 3: I0123 19:22:05.995802 16000 master.cpp:3328] Deactivating framework > eef8ea11-9247-44f3-84cf-340b24df3a52-0000 (default) at > scheduler-be5d74bf-c4bf-4504-9e67-6a4f8df93425@172.17.0.2:45634 > 3: I0123 19:22:05.996014 15991 hierarchical.cpp:405] Deactivated framework > eef8ea11-9247-44f3-84cf-340b24df3a52-0000 > 3: I0123 19:22:05.996299 15994 slave.cpp:931] Agent terminating > 3: I0123 19:22:05.996402 16000 master.cpp:10703] Removing offer > eef8ea11-9247-44f3-84cf-340b24df3a52-O0 > 3: I0123 19:22:05.996474 16000 master.cpp:3305] Disconnecting framework > eef8ea11-9247-44f3-84cf-340b24df3a52-0000 (default) at > scheduler-be5d74bf-c4bf-4504-9e67-6a4f8df93425@172.17.0.2:45634 > 3: I0123 19:22:05.996522 16000 master.cpp:1435] Giving framework > eef8ea11-9247-44f3-84cf-340b24df3a52-0000 (default) at > scheduler-be5d74bf-c4bf-4504-9e67-6a4f8df93425@172.17.0.2:45634 0ns to > failover > 3: I0123 19:22:05.996711 16000 master.cpp:1306] Agent > eef8ea11-9247-44f3-84cf-340b24df3a52-S1 at slave(443)@172.17.0.2:45634 > (455912973e2c) disconnected > 3: I0123 19:22:05.996732 16000 master.cpp:3365] Disconnecting agent > eef8ea11-9247-44f3-84cf-340b24df3a52-S1 at slave(443)@172.17.0.2:45634 > (455912973e2c) > 3: I0123 19:22:05.996789 16000 master.cpp:3384] Deactivating agent > eef8ea11-9247-44f3-84cf-340b24df3a52-S1 at slave(443)@172.17.0.2:45634 > (455912973e2c) > 3: I0123 19:22:05.997368 15991 hierarchical.cpp:1192] Recovered > cpus(allocated: *):2; mem(allocated: *):1024; disk(allocated: *):1024; > ports(allocated: *):[31000-32000] (total: cpus:2; mem:1024; disk:1024; > ports:[31000-32000], allocated: {}) on agent > eef8ea11-9247-44f3-84cf-340b24df3a52-S1 from framework > eef8ea11-9247-44f3-84cf-340b24df3a52-0000 > 3: I0123 19:22:05.997454 15991 hierarchical.cpp:766] Agent > eef8ea11-9247-44f3-84cf-340b24df3a52-S1 deactivated > 3: I0123 19:22:05.998085 15992 master.cpp:8603] Framework failover timeout, > removing framework eef8ea11-9247-44f3-84cf-340b24df3a52-0000 (default) at > scheduler-be5d74bf-c4bf-4504-9e67-6a4f8df93425@172.17.0.2:45634 > 3: I0123 19:22:05.998239 15992 master.cpp:9480] Removing framework > eef8ea11-9247-44f3-84cf-340b24df3a52-0000 (default) at > scheduler-be5d74bf-c4bf-4504-9e67-6a4f8df93425@172.17.0.2:45634 > 3: I0123 19:22:05.998915 15995 hierarchical.cpp:344] Removed framework > eef8ea11-9247-44f3-84cf-340b24df3a52-0000 > 3: I0123 19:22:06.013475 15986 master.cpp:1148] Master terminating > 3: I0123 19:22:06.014463 15994 hierarchical.cpp:609] Removed agent > eef8ea11-9247-44f3-84cf-340b24df3a52-S1 > 3: [ FAILED ] MasterTest.RegistryGcByCount (172 ms) > {code} -- This message was sent by Atlassian JIRA (v7.6.3#76005)