[MESOS-3733] ContentType/SchedulerTest.Suppress/0 is flaky - ASF JIRA

XML

Word

Printable

JSON

Details

Type: Bug
Status: Resolved
Priority: Major
Resolution: Fixed
Affects Version/s: None
Fix Version/s: 0.26.0
Component/s: HTTP API
Labels:
- flaky-test

Epic Link:
Scheduler API v1 improvements

Description

Showed up on ASF CI:
https://builds.apache.org/job/Mesos/931/COMPILER=clang,CONFIGURATION=--verbose,OS=ubuntu:14.04,label_exp=docker%7C%7CHadoop/console

[ RUN      ] ContentType/SchedulerTest.Suppress/0
Using temporary directory '/tmp/ContentType_SchedulerTest_Suppress_0_qcnnQi'
I1014 17:34:11.225731 27650 leveldb.cpp:176] Opened db in 2.974504ms
I1014 17:34:11.226856 27650 leveldb.cpp:183] Compacted db in 980779ns
I1014 17:34:11.227028 27650 leveldb.cpp:198] Created db iterator in 37641ns
I1014 17:34:11.227159 27650 leveldb.cpp:204] Seeked to beginning of db in 14959ns
I1014 17:34:11.227283 27650 leveldb.cpp:273] Iterated through 0 keys in the db in 14672ns
I1014 17:34:11.227449 27650 replica.cpp:746] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I1014 17:34:11.228469 27680 recover.cpp:449] Starting replica recovery
I1014 17:34:11.229202 27673 recover.cpp:475] Replica is in EMPTY status
I1014 17:34:11.231384 27673 replica.cpp:642] Replica in EMPTY status received a broadcasted recover request from (10262)@172.17.2.194:37545
I1014 17:34:11.231745 27673 recover.cpp:195] Received a recover response from a replica in EMPTY status
I1014 17:34:11.234242 27680 master.cpp:376] Master 0cc41e7f-8d87-4c2f-9543-3f7198f9fdaf (23af00e0dbe0) started on 172.17.2.194:37545
I1014 17:34:11.234283 27680 master.cpp:378] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="false" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/ContentType_SchedulerTest_Suppress_0_qcnnQi/credentials" --framework_sorter="drf" --help="false" --hostname_lookup="true" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_slave_ping_timeouts="5" --quiet="false" --recovery_slave_removal_limit="100%" --registry="replicated_log" --registry_fetch_timeout="1mins" --registry_store_timeout="25secs" --registry_strict="true" --root_submissions="true" --slave_ping_timeout="15secs" --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false" --webui_dir="/mesos/mesos-0.26.0/_inst/share/mesos/webui" --work_dir="/tmp/ContentType_SchedulerTest_Suppress_0_qcnnQi/master" --zk_session_timeout="10secs"
I1014 17:34:11.234679 27680 master.cpp:425] Master allowing unauthenticated frameworks to register
I1014 17:34:11.234694 27680 master.cpp:428] Master only allowing authenticated slaves to register
I1014 17:34:11.234705 27680 credentials.hpp:37] Loading credentials for authentication from '/tmp/ContentType_SchedulerTest_Suppress_0_qcnnQi/credentials'
I1014 17:34:11.235251 27673 recover.cpp:566] Updating replica status to STARTING
I1014 17:34:11.235857 27680 master.cpp:467] Using default 'crammd5' authenticator
I1014 17:34:11.236006 27680 master.cpp:504] Authorization enabled
I1014 17:34:11.236187 27673 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 729504ns
I1014 17:34:11.236224 27673 replica.cpp:323] Persisted replica status to STARTING
I1014 17:34:11.236227 27678 whitelist_watcher.cpp:79] No whitelist given
I1014 17:34:11.236366 27676 hierarchical.cpp:140] Initialized hierarchical allocator process
I1014 17:34:11.236495 27677 recover.cpp:475] Replica is in STARTING status
I1014 17:34:11.237670 27678 replica.cpp:642] Replica in STARTING status received a broadcasted recover request from (10263)@172.17.2.194:37545
I1014 17:34:11.238782 27673 recover.cpp:195] Received a recover response from a replica in STARTING status
I1014 17:34:11.238916 27672 master.cpp:1609] The newly elected leader is master@172.17.2.194:37545 with id 0cc41e7f-8d87-4c2f-9543-3f7198f9fdaf
I1014 17:34:11.238993 27672 master.cpp:1622] Elected as the leading master!
I1014 17:34:11.239013 27672 master.cpp:1382] Recovering from registrar
I1014 17:34:11.239480 27672 recover.cpp:566] Updating replica status to VOTING
I1014 17:34:11.239630 27675 registrar.cpp:309] Recovering registrar
I1014 17:34:11.240074 27673 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 452562ns
I1014 17:34:11.240137 27673 replica.cpp:323] Persisted replica status to VOTING
I1014 17:34:11.240310 27676 recover.cpp:580] Successfully joined the Paxos group
I1014 17:34:11.240517 27676 recover.cpp:464] Recover process terminated
I1014 17:34:11.240991 27675 log.cpp:661] Attempting to start the writer
I1014 17:34:11.242359 27676 replica.cpp:478] Replica received implicit promise request from (10264)@172.17.2.194:37545 with proposal 1
I1014 17:34:11.242797 27676 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 409770ns
I1014 17:34:11.242822 27676 replica.cpp:345] Persisted promised to 1
I1014 17:34:11.243399 27677 coordinator.cpp:231] Coordinator attemping to fill missing position
I1014 17:34:11.244962 27668 replica.cpp:378] Replica received explicit promise request from (10265)@172.17.2.194:37545 for position 0 with proposal 2
I1014 17:34:11.245369 27668 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 373472ns
I1014 17:34:11.245398 27668 replica.cpp:681] Persisted action at 0
I1014 17:34:11.246665 27682 replica.cpp:512] Replica received write request for position 0 from (10266)@172.17.2.194:37545
I1014 17:34:11.246799 27682 leveldb.cpp:438] Reading position from leveldb took 47248ns
I1014 17:34:11.247285 27682 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 346641ns
I1014 17:34:11.247313 27682 replica.cpp:681] Persisted action at 0
I1014 17:34:11.247911 27677 replica.cpp:660] Replica received learned notice for position 0 from @0.0.0.0:0
I1014 17:34:11.248361 27677 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 374186ns
I1014 17:34:11.248392 27677 replica.cpp:681] Persisted action at 0
I1014 17:34:11.248425 27677 replica.cpp:666] Replica learned NOP action at position 0
I1014 17:34:11.248965 27668 log.cpp:677] Writer started with ending position 0
I1014 17:34:11.250398 27680 leveldb.cpp:438] Reading position from leveldb took 59955ns
I1014 17:34:11.251452 27678 registrar.cpp:342] Successfully fetched the registry (0B) in 11.641856ms
I1014 17:34:11.251591 27678 registrar.cpp:441] Applied 1 operations in 47847ns; attempting to update the 'registry'
I1014 17:34:11.252187 27671 log.cpp:685] Attempting to append 176 bytes to the log
I1014 17:34:11.252398 27678 coordinator.cpp:341] Coordinator attempting to write APPEND action at position 1
I1014 17:34:11.253121 27671 replica.cpp:512] Replica received write request for position 1 from (10267)@172.17.2.194:37545
I1014 17:34:11.253900 27671 leveldb.cpp:343] Persisting action (195 bytes) to leveldb took 620040ns
I1014 17:34:11.254027 27671 replica.cpp:681] Persisted action at 1
I1014 17:34:11.254781 27673 replica.cpp:660] Replica received learned notice for position 1 from @0.0.0.0:0
I1014 17:34:11.255285 27673 leveldb.cpp:343] Persisting action (197 bytes) to leveldb took 395796ns
I1014 17:34:11.255378 27673 replica.cpp:681] Persisted action at 1
I1014 17:34:11.255509 27673 replica.cpp:666] Replica learned APPEND action at position 1
I1014 17:34:11.256971 27677 registrar.cpp:486] Successfully updated the 'registry' in 5.293824ms
I1014 17:34:11.257071 27671 log.cpp:704] Attempting to truncate the log to 1
I1014 17:34:11.257113 27677 registrar.cpp:372] Successfully recovered registrar
I1014 17:34:11.257222 27669 coordinator.cpp:341] Coordinator attempting to write TRUNCATE action at position 2
I1014 17:34:11.257467 27673 master.cpp:1419] Recovered 0 slaves from the Registry (137B) ; allowing 10mins for slaves to re-register
I1014 17:34:11.258081 27669 replica.cpp:512] Replica received write request for position 2 from (10268)@172.17.2.194:37545
I1014 17:34:11.258520 27669 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 409663ns
I1014 17:34:11.258550 27669 replica.cpp:681] Persisted action at 2
I1014 17:34:11.259354 27669 replica.cpp:660] Replica received learned notice for position 2 from @0.0.0.0:0
I1014 17:34:11.259742 27669 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 357386ns
I1014 17:34:11.259805 27669 leveldb.cpp:401] Deleting ~1 keys from leveldb took 43662ns
I1014 17:34:11.259831 27669 replica.cpp:681] Persisted action at 2
I1014 17:34:11.259858 27669 replica.cpp:666] Replica learned TRUNCATE action at position 2
I1014 17:34:11.274111 27650 containerizer.cpp:143] Using isolation: posix/cpu,posix/mem,filesystem/posix
W1014 17:34:11.274689 27650 backend.cpp:50] Failed to create 'bind' backend: BindBackend requires root privileges
I1014 17:34:11.293387 27681 slave.cpp:191] Slave started on 353)@172.17.2.194:37545
I1014 17:34:11.293440 27681 slave.cpp:192] Flags at startup: --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5" --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/ContentType_SchedulerTest_Suppress_0_aMwzO7/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_local_archives_dir="/tmp/mesos/images/docker" --docker_puller="local" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/ContentType_SchedulerTest_Suppress_0_aMwzO7/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/mesos/mesos-0.26.0/_build/src" --logbufsecs="0" --logging_level="INFO" --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;mem:1024;disk:1024;ports:[31000-32000]" --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/ContentType_SchedulerTest_Suppress_0_aMwzO7"
I1014 17:34:11.293864 27681 credentials.hpp:85] Loading credential for authentication from '/tmp/ContentType_SchedulerTest_Suppress_0_aMwzO7/credential'
I1014 17:34:11.294132 27681 slave.cpp:322] Slave using credential for: test-principal
I1014 17:34:11.294801 27681 slave.cpp:392] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I1014 17:34:11.294878 27681 slave.cpp:400] Slave attributes: [  ]
I1014 17:34:11.294893 27681 slave.cpp:405] Slave hostname: 23af00e0dbe0
I1014 17:34:11.294901 27681 slave.cpp:410] Slave checkpoint: true
I1014 17:34:11.295868 27650 scheduler.cpp:157] Version: 0.26.0
I1014 17:34:11.296658 27682 state.cpp:54] Recovering state from '/tmp/ContentType_SchedulerTest_Suppress_0_aMwzO7/meta'
I1014 17:34:11.297065 27682 status_update_manager.cpp:202] Recovering status update manager
I1014 17:34:11.297297 27682 containerizer.cpp:385] Recovering containerizer
I1014 17:34:11.298284 27678 slave.cpp:4222] Finished recovery
I1014 17:34:11.298730 27669 scheduler.cpp:240] New master detected at master@172.17.2.194:37545
I1014 17:34:11.298903 27678 slave.cpp:4379] Querying resource estimator for oversubscribable resources
I1014 17:34:11.299192 27678 slave.cpp:726] New master detected at master@172.17.2.194:37545
I1014 17:34:11.299300 27668 status_update_manager.cpp:176] Pausing sending status updates
I1014 17:34:11.299401 27678 slave.cpp:789] Authenticating with master master@172.17.2.194:37545
I1014 17:34:11.299481 27678 slave.cpp:794] Using default CRAM-MD5 authenticatee
I1014 17:34:11.299731 27678 slave.cpp:762] Detecting new master
I1014 17:34:11.299808 27668 authenticatee.cpp:115] Creating new client SASL connection
I1014 17:34:11.299965 27678 slave.cpp:4393] Received oversubscribable resources  from the resource estimator
I1014 17:34:11.300192 27668 master.cpp:5144] Authenticating slave(353)@172.17.2.194:37545
I1014 17:34:11.300303 27679 authenticator.cpp:407] Starting authentication session for crammd5_authenticatee(769)@172.17.2.194:37545
I1014 17:34:11.300539 27675 authenticator.cpp:92] Creating new server SASL connection
I1014 17:34:11.300757 27675 authenticatee.cpp:206] Received SASL authentication mechanisms: CRAM-MD5
I1014 17:34:11.300791 27675 authenticatee.cpp:232] Attempting to authenticate with mechanism 'CRAM-MD5'
I1014 17:34:11.300890 27675 authenticator.cpp:197] Received SASL authentication start
I1014 17:34:11.300981 27675 authenticator.cpp:319] Authentication requires more steps
I1014 17:34:11.301070 27675 authenticatee.cpp:252] Received SASL authentication step
I1014 17:34:11.301164 27675 authenticator.cpp:225] Received SASL authentication step
I1014 17:34:11.301195 27675 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: '23af00e0dbe0' server FQDN: '23af00e0dbe0' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
I1014 17:34:11.301209 27675 auxprop.cpp:174] Looking up auxiliary property '*userPassword'
I1014 17:34:11.301264 27675 auxprop.cpp:174] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1014 17:34:11.301293 27675 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: '23af00e0dbe0' server FQDN: '23af00e0dbe0' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
I1014 17:34:11.301306 27675 auxprop.cpp:124] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1014 17:34:11.301314 27675 auxprop.cpp:124] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1014 17:34:11.301332 27675 authenticator.cpp:311] Authentication success
I1014 17:34:11.301553 27675 scheduler.cpp:302] Sending SUBSCRIBE call to master@172.17.2.194:37545
I1014 17:34:11.301865 27679 authenticatee.cpp:292] Authentication success
I1014 17:34:11.301973 27671 master.cpp:5174] Successfully authenticated principal 'test-principal' at slave(353)@172.17.2.194:37545
I1014 17:34:11.302222 27671 slave.cpp:857] Successfully authenticated with master master@172.17.2.194:37545
I1014 17:34:11.302371 27671 slave.cpp:1251] Will retry registration in 2.428485ms if necessary
I1014 17:34:11.302661 27671 master.cpp:3868] Registering slave at slave(353)@172.17.2.194:37545 (23af00e0dbe0) with id 0cc41e7f-8d87-4c2f-9543-3f7198f9fdaf-S0
I1014 17:34:11.303707 27671 registrar.cpp:441] Applied 1 operations in 87412ns; attempting to update the 'registry'
I1014 17:34:11.303856 27675 process.cpp:3078] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I1014 17:34:11.304033 27675 http.cpp:336] HTTP POST for /master/api/v1/scheduler from 172.17.2.194:44627
I1014 17:34:11.304214 27675 master.cpp:1871] Received subscription request for HTTP framework 'default'
I1014 17:34:11.304242 27675 master.cpp:1648] Authorizing framework principal 'test-principal' to receive offers for role '*'
I1014 17:34:11.304700 27678 master.cpp:1963] Subscribing framework 'default' with checkpointing disabled and capabilities [  ]
I1014 17:34:11.304977 27682 authenticator.cpp:425] Authentication session cleanup for crammd5_authenticatee(769)@172.17.2.194:37545
I1014 17:34:11.305321 27675 slave.cpp:1251] Will retry registration in 664899ns if necessary
I1014 17:34:11.305526 27675 hierarchical.cpp:185] Added framework 0cc41e7f-8d87-4c2f-9543-3f7198f9fdaf-0000
I1014 17:34:11.305533 27678 master.cpp:3856] Ignoring register slave message from slave(353)@172.17.2.194:37545 (23af00e0dbe0) as admission is already in progress
I1014 17:34:11.305577 27675 hierarchical.cpp:952] No resources available to allocate!
I1014 17:34:11.305608 27675 hierarchical.cpp:1045] No inverse offers to send out!
I1014 17:34:11.305629 27675 hierarchical.cpp:851] Performed allocation for 0 slaves in 89256ns
I1014 17:34:11.305822 27675 master.hpp:1436] Sending heartbeat to 0cc41e7f-8d87-4c2f-9543-3f7198f9fdaf-0000
I1014 17:34:11.306128 27675 log.cpp:685] Attempting to append 345 bytes to the log
I1014 17:34:11.306233 27668 coordinator.cpp:341] Coordinator attempting to write APPEND action at position 3
I1014 17:34:11.306396 27675 slave.cpp:1251] Will retry registration in 41.981124ms if necessary
I1014 17:34:11.306854 27668 master.cpp:3856] Ignoring register slave message from slave(353)@172.17.2.194:37545 (23af00e0dbe0) as admission is already in progress
I1014 17:34:11.307449 27678 scheduler.cpp:461] Enqueuing event SUBSCRIBED received from master@172.17.2.194:37545
I1014 17:34:11.308254 27676 replica.cpp:512] Replica received write request for position 3 from (10280)@172.17.2.194:37545
I1014 17:34:11.308490 27676 leveldb.cpp:343] Persisting action (364 bytes) to leveldb took 211419ns
I1014 17:34:11.308517 27676 replica.cpp:681] Persisted action at 3
I1014 17:34:11.309520 27676 replica.cpp:660] Replica received learned notice for position 3 from @0.0.0.0:0
I1014 17:34:11.309991 27671 scheduler.cpp:461] Enqueuing event HEARTBEAT received from master@172.17.2.194:37545
I1014 17:34:11.310329 27671 master_maintenance_tests.cpp:179] Ignoring HEARTBEAT event
I1014 17:34:11.310917 27676 leveldb.cpp:343] Persisting action (366 bytes) to leveldb took 1.390299ms
I1014 17:34:11.310958 27676 replica.cpp:681] Persisted action at 3
I1014 17:34:11.310981 27676 replica.cpp:666] Replica learned APPEND action at position 3
I1014 17:34:11.312510 27671 registrar.cpp:486] Successfully updated the 'registry' in 8.701952ms
I1014 17:34:11.312698 27676 log.cpp:704] Attempting to truncate the log to 3
I1014 17:34:11.312883 27670 coordinator.cpp:341] Coordinator attempting to write TRUNCATE action at position 4
I1014 17:34:11.313498 27672 slave.cpp:3212] Received ping from slave-observer(338)@172.17.2.194:37545
I1014 17:34:11.313563 27679 master.cpp:3936] Registered slave 0cc41e7f-8d87-4c2f-9543-3f7198f9fdaf-S0 at slave(353)@172.17.2.194:37545 (23af00e0dbe0) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I1014 17:34:11.313817 27678 hierarchical.cpp:335] Added slave 0cc41e7f-8d87-4c2f-9543-3f7198f9fdaf-S0 (23af00e0dbe0) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
I1014 17:34:11.313863 27672 slave.cpp:901] Registered with master master@172.17.2.194:37545; given slave ID 0cc41e7f-8d87-4c2f-9543-3f7198f9fdaf-S0
I1014 17:34:11.313889 27672 fetcher.cpp:77] Clearing fetcher cache
I1014 17:34:11.314031 27670 replica.cpp:512] Replica received write request for position 4 from (10282)@172.17.2.194:37545
I1014 17:34:11.314168 27668 status_update_manager.cpp:183] Resuming sending status updates
I1014 17:34:11.314539 27672 slave.cpp:924] Checkpointing SlaveInfo to '/tmp/ContentType_SchedulerTest_Suppress_0_aMwzO7/meta/slaves/0cc41e7f-8d87-4c2f-9543-3f7198f9fdaf-S0/slave.info'
I1014 17:34:11.314800 27678 hierarchical.cpp:1045] No inverse offers to send out!
I1014 17:34:11.314834 27678 hierarchical.cpp:867] Performed allocation for slave 0cc41e7f-8d87-4c2f-9543-3f7198f9fdaf-S0 in 981957ns
I1014 17:34:11.314975 27670 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 920860ns
I1014 17:34:11.315001 27670 replica.cpp:681] Persisted action at 4
I1014 17:34:11.315034 27672 slave.cpp:960] Forwarding total oversubscribed resources 
I1014 17:34:11.315377 27678 master.cpp:4973] Sending 1 offers to framework 0cc41e7f-8d87-4c2f-9543-3f7198f9fdaf-0000 (default)
I1014 17:34:11.315760 27668 replica.cpp:660] Replica received learned notice for position 4 from @0.0.0.0:0
I1014 17:34:11.315867 27678 master.cpp:4278] Received update of slave 0cc41e7f-8d87-4c2f-9543-3f7198f9fdaf-S0 at slave(353)@172.17.2.194:37545 (23af00e0dbe0) with total oversubscribed resources 
I1014 17:34:11.316174 27678 hierarchical.cpp:391] Slave 0cc41e7f-8d87-4c2f-9543-3f7198f9fdaf-S0 (23af00e0dbe0) updated with oversubscribed resources  (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000])
I1014 17:34:11.316457 27668 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 682497ns
I1014 17:34:11.316524 27668 leveldb.cpp:401] Deleting ~2 keys from leveldb took 52031ns
I1014 17:34:11.316546 27668 replica.cpp:681] Persisted action at 4
I1014 17:34:11.316566 27678 hierarchical.cpp:952] No resources available to allocate!
I1014 17:34:11.316611 27678 hierarchical.cpp:1045] No inverse offers to send out!
I1014 17:34:11.316628 27678 hierarchical.cpp:867] Performed allocation for slave 0cc41e7f-8d87-4c2f-9543-3f7198f9fdaf-S0 in 408038ns
I1014 17:34:11.316566 27668 replica.cpp:666] Replica learned TRUNCATE action at position 4
I1014 17:34:11.318416 27679 scheduler.cpp:461] Enqueuing event OFFERS received from master@172.17.2.194:37545
I1014 17:34:11.320318 27670 scheduler.cpp:302] Sending DECLINE call to master@172.17.2.194:37545
I1014 17:34:11.323171 27670 process.cpp:3078] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I1014 17:34:11.323374 27670 http.cpp:336] HTTP POST for /master/api/v1/scheduler from 172.17.2.194:44628
I1014 17:34:11.323690 27670 master.cpp:3306] Processing DECLINE call for offers: [ 0cc41e7f-8d87-4c2f-9543-3f7198f9fdaf-O0 ] for framework 0cc41e7f-8d87-4c2f-9543-3f7198f9fdaf-0000 (default)
I1014 17:34:11.324636 27668 hierarchical.cpp:739] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on slave 0cc41e7f-8d87-4c2f-9543-3f7198f9fdaf-S0 from framework 0cc41e7f-8d87-4c2f-9543-3f7198f9fdaf-0000
I1014 17:34:11.324704 27668 hierarchical.cpp:776] Framework 0cc41e7f-8d87-4c2f-9543-3f7198f9fdaf-0000 filtered slave 0cc41e7f-8d87-4c2f-9543-3f7198f9fdaf-S0 for 1hrs
I1014 17:34:11.325999 27677 scheduler.cpp:302] Sending SUPPRESS call to master@172.17.2.194:37545
I1014 17:34:11.327674 27679 hierarchical.cpp:1045] No inverse offers to send out!
I1014 17:34:11.327715 27679 hierarchical.cpp:851] Performed allocation for 1 slaves in 738917ns
I1014 17:34:11.328177 27675 slave.cpp:4379] Querying resource estimator for oversubscribable resources
I1014 17:34:11.328255 27679 master.cpp:4973] Sending 1 offers to framework 0cc41e7f-8d87-4c2f-9543-3f7198f9fdaf-0000 (default)
I1014 17:34:11.328433 27675 slave.cpp:3248] No pings from master received within 75secs
I1014 17:34:11.328589 27675 slave.cpp:4038] Current disk usage 6.45%. Max allowed age: 5.848702530562280days
I1014 17:34:11.328656 27679 master.hpp:1436] Sending heartbeat to 0cc41e7f-8d87-4c2f-9543-3f7198f9fdaf-0000
I1014 17:34:11.329265 27679 slave.cpp:3212] Received ping from slave-observer(338)@172.17.2.194:37545
I1014 17:34:11.329396 27679 slave.cpp:715] Re-detecting master
I1014 17:34:11.329417 27679 slave.cpp:762] Detecting new master
I1014 17:34:11.329653 27680 status_update_manager.cpp:176] Pausing sending status updates
I1014 17:34:11.330000 27682 slave.cpp:726] New master detected at master@172.17.2.194:37545
I1014 17:34:11.330071 27682 slave.cpp:789] Authenticating with master master@172.17.2.194:37545
I1014 17:34:11.330015 27669 status_update_manager.cpp:176] Pausing sending status updates
I1014 17:34:11.330145 27682 slave.cpp:794] Using default CRAM-MD5 authenticatee
I1014 17:34:11.330381 27682 slave.cpp:762] Detecting new master
I1014 17:34:11.330467 27669 authenticatee.cpp:115] Creating new client SASL connection
I1014 17:34:11.330770 27669 master.cpp:5144] Authenticating slave(353)@172.17.2.194:37545
I1014 17:34:11.330890 27668 authenticator.cpp:407] Starting authentication session for crammd5_authenticatee(770)@172.17.2.194:37545
I1014 17:34:11.331152 27668 process.cpp:3078] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I1014 17:34:11.331272 27669 authenticator.cpp:92] Creating new server SASL connection
I1014 17:34:11.331504 27669 authenticatee.cpp:206] Received SASL authentication mechanisms: CRAM-MD5
I1014 17:34:11.331537 27669 authenticatee.cpp:232] Attempting to authenticate with mechanism 'CRAM-MD5'
I1014 17:34:11.331621 27669 authenticator.cpp:197] Received SASL authentication start
I1014 17:34:11.331681 27669 authenticator.cpp:319] Authentication requires more steps
I1014 17:34:11.331779 27677 authenticatee.cpp:252] Received SASL authentication step
I1014 17:34:11.331893 27677 authenticator.cpp:225] Received SASL authentication step
I1014 17:34:11.331934 27677 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: '23af00e0dbe0' server FQDN: '23af00e0dbe0' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
I1014 17:34:11.331954 27677 auxprop.cpp:174] Looking up auxiliary property '*userPassword'
I1014 17:34:11.332003 27677 auxprop.cpp:174] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1014 17:34:11.332042 27677 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: '23af00e0dbe0' server FQDN: '23af00e0dbe0' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
I1014 17:34:11.332058 27677 auxprop.cpp:124] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1014 17:34:11.332067 27677 auxprop.cpp:124] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1014 17:34:11.332087 27677 authenticator.cpp:311] Authentication success
I1014 17:34:11.332262 27677 authenticatee.cpp:292] Authentication success
I1014 17:34:11.332358 27677 authenticator.cpp:425] Authentication session cleanup for crammd5_authenticatee(770)@172.17.2.194:37545
I1014 17:34:11.332571 27682 scheduler.cpp:461] Enqueuing event OFFERS received from master@172.17.2.194:37545
I1014 17:34:11.332603 27671 slave.cpp:857] Successfully authenticated with master master@172.17.2.194:37545
I1014 17:34:11.332741 27671 slave.cpp:1251] Will retry registration in 16.610351ms if necessary
I1014 17:34:11.333477 27682 scheduler.cpp:461] Enqueuing event HEARTBEAT received from master@172.17.2.194:37545
I1014 17:34:11.334038 27678 master_maintenance_tests.cpp:179] Ignoring HEARTBEAT event
I1014 17:34:11.334199 27681 slave.cpp:4393] Received oversubscribable resources  from the resource estimator
I1014 17:34:11.334462 27668 http.cpp:336] HTTP POST for /master/api/v1/scheduler from 172.17.2.194:44629
I1014 17:34:11.334588 27668 master.cpp:2638] Processing SUPPRESS call for framework 0cc41e7f-8d87-4c2f-9543-3f7198f9fdaf-0000 (default)
I1014 17:34:11.334728 27673 hierarchical.cpp:811] Suppressed offers for framework 0cc41e7f-8d87-4c2f-9543-3f7198f9fdaf-0000
I1014 17:34:11.334831 27668 master.cpp:5174] Successfully authenticated principal 'test-principal' at slave(353)@172.17.2.194:37545
I1014 17:34:11.335122 27668 master.cpp:4028] Re-registering slave 0cc41e7f-8d87-4c2f-9543-3f7198f9fdaf-S0 at slave(353)@172.17.2.194:37545 (23af00e0dbe0)
I1014 17:34:11.335297 27668 master.cpp:4216] Sending updated checkpointed resources  to slave 0cc41e7f-8d87-4c2f-9543-3f7198f9fdaf-S0 at slave(353)@172.17.2.194:37545 (23af00e0dbe0)
I1014 17:34:11.335350 27674 slave.cpp:1001] Re-registered with master master@172.17.2.194:37545
I1014 17:34:11.335451 27674 slave.cpp:1037] Forwarding total oversubscribed resources 
I1014 17:34:11.335825 27674 slave.cpp:2284] Updated checkpointed resources from  to 
I1014 17:34:11.335872 27674 status_update_manager.cpp:183] Resuming sending status updates
I1014 17:34:11.335973 27674 master.cpp:4278] Received update of slave 0cc41e7f-8d87-4c2f-9543-3f7198f9fdaf-S0 at slave(353)@172.17.2.194:37545 (23af00e0dbe0) with total oversubscribed resources 
I1014 17:34:11.336297 27674 hierarchical.cpp:391] Slave 0cc41e7f-8d87-4c2f-9543-3f7198f9fdaf-S0 (23af00e0dbe0) updated with oversubscribed resources  (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000])
I1014 17:34:11.336602 27674 hierarchical.cpp:952] No resources available to allocate!
I1014 17:34:11.336642 27674 hierarchical.cpp:1045] No inverse offers to send out!
I1014 17:34:11.336663 27674 hierarchical.cpp:867] Performed allocation for slave 0cc41e7f-8d87-4c2f-9543-3f7198f9fdaf-S0 in 319336ns
../../src/tests/scheduler_tests.cpp:1028: Failure
Value of: event.isPending()
  Actual: false
Expected: true
I1014 17:34:11.350008 27650 master.cpp:925] Master terminating
I1014 17:34:11.350783 27672 hierarchical.cpp:364] Removed slave 0cc41e7f-8d87-4c2f-9543-3f7198f9fdaf-S0
I1014 17:34:11.354817 27676 hierarchical.cpp:220] Removed framework 0cc41e7f-8d87-4c2f-9543-3f7198f9fdaf-0000
I1014 17:34:11.355031 27677 slave.cpp:3258] master@172.17.2.194:37545 exited
W1014 17:34:11.355795 27677 slave.cpp:3261] Master disconnected! Waiting for a new master to be elected
I1014 17:34:11.383412 27650 slave.cpp:606] Slave terminating
[  FAILED  ] ContentType/SchedulerTest.Suppress/0, where GetParam() = application/x-protobuf (166 ms)

Logs from a good run:

[ RUN      ] ContentType/SchedulerTest.Suppress/0
Using temporary directory '/tmp/ContentType_SchedulerTest_Suppress_0_LdvGud'
I1014 17:03:11.364305 27652 leveldb.cpp:176] Opened db in 3.076649ms
I1014 17:03:11.365097 27652 leveldb.cpp:183] Compacted db in 742760ns
I1014 17:03:11.365154 27652 leveldb.cpp:198] Created db iterator in 37891ns
I1014 17:03:11.365278 27652 leveldb.cpp:204] Seeked to beginning of db in 24443ns
I1014 17:03:11.365391 27652 leveldb.cpp:273] Iterated through 0 keys in the db in 15185ns
I1014 17:03:11.365561 27652 replica.cpp:746] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned
I1014 17:03:11.366643 27670 recover.cpp:449] Starting replica recovery
I1014 17:03:11.367421 27673 recover.cpp:475] Replica is in EMPTY status
I1014 17:03:11.369869 27673 replica.cpp:642] Replica in EMPTY status received a broadcasted recover request from (10246)@172.17.2.187:41367
I1014 17:03:11.370345 27680 master.cpp:376] Master 89a77d0d-a789-4878-9a21-2f610b238f73 (6b343c026fe3) started on 172.17.2.187:41367
I1014 17:03:11.370378 27680 master.cpp:378] Flags at startup: --acls="" --allocation_interval="1secs" --allocator="HierarchicalDRF" --authenticate="false" --authenticate_slaves="true" --authenticators="crammd5" --authorizers="local" --credentials="/tmp/ContentType_SchedulerTest_Suppress_0_LdvGud/credentials" --framework_sorter="drf" --help="false" --hostname_lookup="true" --initialize_driver_logging="true" --log_auto_initialize="true" --logbufsecs="0" --logging_level="INFO" --max_slave_ping_timeouts="5" --quiet="false" --recovery_slave_removal_limit="100%" --registry="replicated_log" --registry_fetch_timeout="1mins" --registry_store_timeout="25secs" --registry_strict="true" --root_submissions="true" --slave_ping_timeout="15secs" --slave_reregister_timeout="10mins" --user_sorter="drf" --version="false" --webui_dir="/mesos/mesos-0.26.0/_inst/share/mesos/webui" --work_dir="/tmp/ContentType_SchedulerTest_Suppress_0_LdvGud/master" --zk_session_timeout="10secs"
I1014 17:03:11.370731 27680 master.cpp:425] Master allowing unauthenticated frameworks to register
I1014 17:03:11.370745 27680 master.cpp:428] Master only allowing authenticated slaves to register
I1014 17:03:11.370754 27680 credentials.hpp:37] Loading credentials for authentication from '/tmp/ContentType_SchedulerTest_Suppress_0_LdvGud/credentials'
I1014 17:03:11.371085 27680 master.cpp:467] Using default 'crammd5' authenticator
I1014 17:03:11.371230 27680 master.cpp:504] Authorization enabled
I1014 17:03:11.371273 27674 recover.cpp:195] Received a recover response from a replica in EMPTY status
I1014 17:03:11.371551 27671 hierarchical.cpp:140] Initialized hierarchical allocator process
I1014 17:03:11.371723 27671 whitelist_watcher.cpp:79] No whitelist given
I1014 17:03:11.371788 27671 recover.cpp:566] Updating replica status to STARTING
I1014 17:03:11.372547 27675 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 644694ns
I1014 17:03:11.372580 27675 replica.cpp:323] Persisted replica status to STARTING
I1014 17:03:11.372818 27675 recover.cpp:475] Replica is in STARTING status
I1014 17:03:11.375089 27670 replica.cpp:642] Replica in STARTING status received a broadcasted recover request from (10247)@172.17.2.187:41367
I1014 17:03:11.375115 27680 master.cpp:1609] The newly elected leader is master@172.17.2.187:41367 with id 89a77d0d-a789-4878-9a21-2f610b238f73
I1014 17:03:11.375171 27680 master.cpp:1622] Elected as the leading master!
I1014 17:03:11.375186 27680 master.cpp:1382] Recovering from registrar
I1014 17:03:11.375422 27675 registrar.cpp:309] Recovering registrar
I1014 17:03:11.375470 27680 recover.cpp:195] Received a recover response from a replica in STARTING status
I1014 17:03:11.375955 27684 recover.cpp:566] Updating replica status to VOTING
I1014 17:03:11.376567 27673 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 524373ns
I1014 17:03:11.376596 27673 replica.cpp:323] Persisted replica status to VOTING
I1014 17:03:11.376724 27673 recover.cpp:580] Successfully joined the Paxos group
I1014 17:03:11.376914 27673 recover.cpp:464] Recover process terminated
I1014 17:03:11.377447 27682 log.cpp:661] Attempting to start the writer
I1014 17:03:11.378676 27675 replica.cpp:478] Replica received implicit promise request from (10248)@172.17.2.187:41367 with proposal 1
I1014 17:03:11.379227 27675 leveldb.cpp:306] Persisting metadata (8 bytes) to leveldb took 528053ns
I1014 17:03:11.379256 27675 replica.cpp:345] Persisted promised to 1
I1014 17:03:11.379874 27676 coordinator.cpp:231] Coordinator attemping to fill missing position
I1014 17:03:11.381230 27679 replica.cpp:378] Replica received explicit promise request from (10249)@172.17.2.187:41367 for position 0 with proposal 2
I1014 17:03:11.381744 27679 leveldb.cpp:343] Persisting action (8 bytes) to leveldb took 482856ns
I1014 17:03:11.381772 27679 replica.cpp:681] Persisted action at 0
I1014 17:03:11.382881 27670 replica.cpp:512] Replica received write request for position 0 from (10250)@172.17.2.187:41367
I1014 17:03:11.382984 27670 leveldb.cpp:438] Reading position from leveldb took 79194ns
I1014 17:03:11.383424 27670 leveldb.cpp:343] Persisting action (14 bytes) to leveldb took 400109ns
I1014 17:03:11.383451 27670 replica.cpp:681] Persisted action at 0
I1014 17:03:11.384080 27683 replica.cpp:660] Replica received learned notice for position 0 from @0.0.0.0:0
I1014 17:03:11.384512 27683 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 412977ns
I1014 17:03:11.384544 27683 replica.cpp:681] Persisted action at 0
I1014 17:03:11.384572 27683 replica.cpp:666] Replica learned NOP action at position 0
I1014 17:03:11.385211 27671 log.cpp:677] Writer started with ending position 0
I1014 17:03:11.386322 27680 leveldb.cpp:438] Reading position from leveldb took 61867ns
I1014 17:03:11.387409 27681 registrar.cpp:342] Successfully fetched the registry (0B) in 11.930112ms
I1014 17:03:11.387562 27681 registrar.cpp:441] Applied 1 operations in 51127ns; attempting to update the 'registry'
I1014 17:03:11.388289 27682 log.cpp:685] Attempting to append 176 bytes to the log
I1014 17:03:11.388444 27676 coordinator.cpp:341] Coordinator attempting to write APPEND action at position 1
I1014 17:03:11.389215 27674 replica.cpp:512] Replica received write request for position 1 from (10251)@172.17.2.187:41367
I1014 17:03:11.389758 27674 leveldb.cpp:343] Persisting action (195 bytes) to leveldb took 519056ns
I1014 17:03:11.389782 27674 replica.cpp:681] Persisted action at 1
I1014 17:03:11.390542 27685 replica.cpp:660] Replica received learned notice for position 1 from @0.0.0.0:0
I1014 17:03:11.391060 27685 leveldb.cpp:343] Persisting action (197 bytes) to leveldb took 500040ns
I1014 17:03:11.391083 27685 replica.cpp:681] Persisted action at 1
I1014 17:03:11.391099 27685 replica.cpp:666] Replica learned APPEND action at position 1
I1014 17:03:11.392037 27683 registrar.cpp:486] Successfully updated the 'registry' in 4.404992ms
I1014 17:03:11.392163 27683 registrar.cpp:372] Successfully recovered registrar
I1014 17:03:11.392194 27685 log.cpp:704] Attempting to truncate the log to 1
I1014 17:03:11.392305 27684 coordinator.cpp:341] Coordinator attempting to write TRUNCATE action at position 2
I1014 17:03:11.392843 27681 master.cpp:1419] Recovered 0 slaves from the Registry (137B) ; allowing 10mins for slaves to re-register
I1014 17:03:11.393597 27679 replica.cpp:512] Replica received write request for position 2 from (10252)@172.17.2.187:41367
I1014 17:03:11.393996 27679 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 367447ns
I1014 17:03:11.394021 27679 replica.cpp:681] Persisted action at 2
I1014 17:03:11.394567 27681 replica.cpp:660] Replica received learned notice for position 2 from @0.0.0.0:0
I1014 17:03:11.394965 27681 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 319737ns
I1014 17:03:11.395026 27681 leveldb.cpp:401] Deleting ~1 keys from leveldb took 61697ns
I1014 17:03:11.395068 27681 replica.cpp:681] Persisted action at 2
I1014 17:03:11.395088 27681 replica.cpp:666] Replica learned TRUNCATE action at position 2
I1014 17:03:11.405890 27652 containerizer.cpp:143] Using isolation: posix/cpu,posix/mem,filesystem/posix
W1014 17:03:11.406304 27652 backend.cpp:50] Failed to create 'bind' backend: BindBackend requires root privileges
I1014 17:03:11.408805 27679 slave.cpp:191] Slave started on 353)@172.17.2.187:41367
I1014 17:03:11.408848 27679 slave.cpp:192] Flags at startup: --appc_store_dir="/tmp/mesos/store/appc" --authenticatee="crammd5" --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/ContentType_SchedulerTest_Suppress_0_hg0j0r/credential" --default_role="*" --disk_watch_interval="1mins" --docker="docker" --docker_kill_orphans="true" --docker_local_archives_dir="/tmp/mesos/images/docker" --docker_puller="local" --docker_remove_delay="6hrs" --docker_socket="/var/run/docker.sock" --docker_stop_timeout="0ns" --docker_store_dir="/tmp/mesos/store/docker" --enforce_container_disk_quota="false" --executor_registration_timeout="1mins" --executor_shutdown_grace_period="5secs" --fetcher_cache_dir="/tmp/ContentType_SchedulerTest_Suppress_0_hg0j0r/fetch" --fetcher_cache_size="2GB" --frameworks_home="" --gc_delay="1weeks" --gc_disk_headroom="0.1" --hadoop_home="" --help="false" --hostname_lookup="true" --image_provisioner_backend="copy" --initialize_driver_logging="true" --isolation="posix/cpu,posix/mem" --launcher_dir="/mesos/mesos-0.26.0/_build/src" --logbufsecs="0" --logging_level="INFO" --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;mem:1024;disk:1024;ports:[31000-32000]" --revocable_cpu_low_priority="true" --sandbox_directory="/mnt/mesos/sandbox" --strict="true" --switch_user="true" --systemd_runtime_directory="/run/systemd/system" --version="false" --work_dir="/tmp/ContentType_SchedulerTest_Suppress_0_hg0j0r"
I1014 17:03:11.409215 27679 credentials.hpp:85] Loading credential for authentication from '/tmp/ContentType_SchedulerTest_Suppress_0_hg0j0r/credential'
I1014 17:03:11.409391 27679 slave.cpp:322] Slave using credential for: test-principal
I1014 17:03:11.409945 27679 slave.cpp:392] Slave resources: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I1014 17:03:11.410015 27679 slave.cpp:400] Slave attributes: [  ]
I1014 17:03:11.410027 27679 slave.cpp:405] Slave hostname: 6b343c026fe3
I1014 17:03:11.410032 27679 slave.cpp:410] Slave checkpoint: true
I1014 17:03:11.410245 27652 scheduler.cpp:157] Version: 0.26.0
I1014 17:03:11.410827 27683 scheduler.cpp:240] New master detected at master@172.17.2.187:41367
I1014 17:03:11.411283 27670 state.cpp:54] Recovering state from '/tmp/ContentType_SchedulerTest_Suppress_0_hg0j0r/meta'
I1014 17:03:11.411622 27672 status_update_manager.cpp:202] Recovering status update manager
I1014 17:03:11.411891 27672 containerizer.cpp:385] Recovering containerizer
I1014 17:03:11.412047 27683 scheduler.cpp:302] Sending SUBSCRIBE call to master@172.17.2.187:41367
I1014 17:03:11.413441 27677 slave.cpp:4222] Finished recovery
I1014 17:03:11.413974 27674 process.cpp:3078] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I1014 17:03:11.413981 27677 slave.cpp:4379] Querying resource estimator for oversubscribable resources
I1014 17:03:11.414353 27677 slave.cpp:726] New master detected at master@172.17.2.187:41367
I1014 17:03:11.414355 27674 http.cpp:336] HTTP POST for /master/api/v1/scheduler from 172.17.2.187:53170
I1014 17:03:11.414428 27677 slave.cpp:789] Authenticating with master master@172.17.2.187:41367
I1014 17:03:11.414443 27677 slave.cpp:794] Using default CRAM-MD5 authenticatee
I1014 17:03:11.414564 27677 slave.cpp:762] Detecting new master
I1014 17:03:11.414608 27674 master.cpp:1871] Received subscription request for HTTP framework 'default'
I1014 17:03:11.414652 27674 master.cpp:1648] Authorizing framework principal 'test-principal' to receive offers for role '*'
I1014 17:03:11.414659 27677 slave.cpp:4393] Received oversubscribable resources  from the resource estimator
I1014 17:03:11.414769 27677 status_update_manager.cpp:176] Pausing sending status updates
I1014 17:03:11.414973 27671 authenticatee.cpp:115] Creating new client SASL connection
I1014 17:03:11.415251 27683 master.cpp:1963] Subscribing framework 'default' with checkpointing disabled and capabilities [  ]
I1014 17:03:11.415618 27670 hierarchical.cpp:185] Added framework 89a77d0d-a789-4878-9a21-2f610b238f73-0000
I1014 17:03:11.415678 27670 hierarchical.cpp:952] No resources available to allocate!
I1014 17:03:11.415788 27683 master.cpp:5144] Authenticating slave(353)@172.17.2.187:41367
I1014 17:03:11.415812 27677 master.hpp:1436] Sending heartbeat to 89a77d0d-a789-4878-9a21-2f610b238f73-0000
I1014 17:03:11.415807 27670 hierarchical.cpp:1045] No inverse offers to send out!
I1014 17:03:11.416024 27670 hierarchical.cpp:851] Performed allocation for 0 slaves in 399209ns
I1014 17:03:11.416290 27674 authenticator.cpp:407] Starting authentication session for crammd5_authenticatee(769)@172.17.2.187:41367
I1014 17:03:11.416447 27673 scheduler.cpp:461] Enqueuing event SUBSCRIBED received from master@172.17.2.187:41367
I1014 17:03:11.416554 27682 authenticator.cpp:92] Creating new server SASL connection
I1014 17:03:11.416779 27670 authenticatee.cpp:206] Received SASL authentication mechanisms: CRAM-MD5
I1014 17:03:11.417119 27670 authenticatee.cpp:232] Attempting to authenticate with mechanism 'CRAM-MD5'
I1014 17:03:11.417292 27681 scheduler.cpp:461] Enqueuing event HEARTBEAT received from master@172.17.2.187:41367
I1014 17:03:11.417403 27682 authenticator.cpp:197] Received SASL authentication start
I1014 17:03:11.417631 27682 authenticator.cpp:319] Authentication requires more steps
I1014 17:03:11.417641 27681 master_maintenance_tests.cpp:179] Ignoring HEARTBEAT event
I1014 17:03:11.417780 27682 authenticatee.cpp:252] Received SASL authentication step
I1014 17:03:11.417990 27682 authenticator.cpp:225] Received SASL authentication step
I1014 17:03:11.418025 27682 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: '6b343c026fe3' server FQDN: '6b343c026fe3' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
I1014 17:03:11.418043 27682 auxprop.cpp:174] Looking up auxiliary property '*userPassword'
I1014 17:03:11.418099 27682 auxprop.cpp:174] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1014 17:03:11.418138 27682 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: '6b343c026fe3' server FQDN: '6b343c026fe3' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
I1014 17:03:11.418217 27682 auxprop.cpp:124] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1014 17:03:11.418233 27682 auxprop.cpp:124] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1014 17:03:11.418257 27682 authenticator.cpp:311] Authentication success
I1014 17:03:11.418349 27670 authenticatee.cpp:292] Authentication success
I1014 17:03:11.418401 27675 master.cpp:5174] Successfully authenticated principal 'test-principal' at slave(353)@172.17.2.187:41367
I1014 17:03:11.418448 27677 authenticator.cpp:425] Authentication session cleanup for crammd5_authenticatee(769)@172.17.2.187:41367
I1014 17:03:11.418675 27685 slave.cpp:857] Successfully authenticated with master master@172.17.2.187:41367
I1014 17:03:11.418825 27685 slave.cpp:1251] Will retry registration in 19.470135ms if necessary
I1014 17:03:11.419034 27678 master.cpp:3868] Registering slave at slave(353)@172.17.2.187:41367 (6b343c026fe3) with id 89a77d0d-a789-4878-9a21-2f610b238f73-S0
I1014 17:03:11.419417 27685 registrar.cpp:441] Applied 1 operations in 73476ns; attempting to update the 'registry'
I1014 17:03:11.420022 27674 log.cpp:685] Attempting to append 345 bytes to the log
I1014 17:03:11.420151 27670 coordinator.cpp:341] Coordinator attempting to write APPEND action at position 3
I1014 17:03:11.420897 27670 replica.cpp:512] Replica received write request for position 3 from (10265)@172.17.2.187:41367
I1014 17:03:11.421458 27670 leveldb.cpp:343] Persisting action (364 bytes) to leveldb took 518390ns
I1014 17:03:11.421486 27670 replica.cpp:681] Persisted action at 3
I1014 17:03:11.422088 27678 replica.cpp:660] Replica received learned notice for position 3 from @0.0.0.0:0
I1014 17:03:11.422430 27678 leveldb.cpp:343] Persisting action (366 bytes) to leveldb took 322654ns
I1014 17:03:11.422454 27678 replica.cpp:681] Persisted action at 3
I1014 17:03:11.422479 27678 replica.cpp:666] Replica learned APPEND action at position 3
I1014 17:03:11.423759 27674 registrar.cpp:486] Successfully updated the 'registry' in 4.271104ms
I1014 17:03:11.423974 27676 log.cpp:704] Attempting to truncate the log to 3
I1014 17:03:11.424101 27671 coordinator.cpp:341] Coordinator attempting to write TRUNCATE action at position 4
I1014 17:03:11.424832 27677 replica.cpp:512] Replica received write request for position 4 from (10266)@172.17.2.187:41367
I1014 17:03:11.425096 27672 slave.cpp:3212] Received ping from slave-observer(339)@172.17.2.187:41367
I1014 17:03:11.425233 27672 slave.cpp:901] Registered with master master@172.17.2.187:41367; given slave ID 89a77d0d-a789-4878-9a21-2f610b238f73-S0
I1014 17:03:11.425194 27675 master.cpp:3936] Registered slave 89a77d0d-a789-4878-9a21-2f610b238f73-S0 at slave(353)@172.17.2.187:41367 (6b343c026fe3) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000]
I1014 17:03:11.425535 27672 fetcher.cpp:77] Clearing fetcher cache
I1014 17:03:11.425494 27673 hierarchical.cpp:335] Added slave 89a77d0d-a789-4878-9a21-2f610b238f73-S0 (6b343c026fe3) with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (allocated: )
I1014 17:03:11.425287 27677 leveldb.cpp:343] Persisting action (16 bytes) to leveldb took 428853ns
I1014 17:03:11.425580 27677 replica.cpp:681] Persisted action at 4
I1014 17:03:11.426163 27677 replica.cpp:660] Replica received learned notice for position 4 from @0.0.0.0:0
I1014 17:03:11.426292 27673 hierarchical.cpp:1045] No inverse offers to send out!
I1014 17:03:11.426334 27673 hierarchical.cpp:867] Performed allocation for slave 89a77d0d-a789-4878-9a21-2f610b238f73-S0 in 789179ns
I1014 17:03:11.426530 27676 status_update_manager.cpp:183] Resuming sending status updates
I1014 17:03:11.426626 27677 leveldb.cpp:343] Persisting action (18 bytes) to leveldb took 461517ns
I1014 17:03:11.426758 27672 slave.cpp:924] Checkpointing SlaveInfo to '/tmp/ContentType_SchedulerTest_Suppress_0_hg0j0r/meta/slaves/89a77d0d-a789-4878-9a21-2f610b238f73-S0/slave.info'
I1014 17:03:11.426771 27674 master.cpp:4973] Sending 1 offers to framework 89a77d0d-a789-4878-9a21-2f610b238f73-0000 (default)
I1014 17:03:11.426882 27677 leveldb.cpp:401] Deleting ~2 keys from leveldb took 78018ns
I1014 17:03:11.426906 27677 replica.cpp:681] Persisted action at 4
I1014 17:03:11.426954 27677 replica.cpp:666] Replica learned TRUNCATE action at position 4
I1014 17:03:11.427263 27672 slave.cpp:960] Forwarding total oversubscribed resources 
I1014 17:03:11.427502 27674 master.cpp:4278] Received update of slave 89a77d0d-a789-4878-9a21-2f610b238f73-S0 at slave(353)@172.17.2.187:41367 (6b343c026fe3) with total oversubscribed resources 
I1014 17:03:11.427811 27679 hierarchical.cpp:391] Slave 89a77d0d-a789-4878-9a21-2f610b238f73-S0 (6b343c026fe3) updated with oversubscribed resources  (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000])
I1014 17:03:11.428234 27679 hierarchical.cpp:952] No resources available to allocate!
I1014 17:03:11.428340 27679 hierarchical.cpp:1045] No inverse offers to send out!
I1014 17:03:11.428367 27679 hierarchical.cpp:867] Performed allocation for slave 89a77d0d-a789-4878-9a21-2f610b238f73-S0 in 518440ns
I1014 17:03:11.429276 27683 scheduler.cpp:461] Enqueuing event OFFERS received from master@172.17.2.187:41367
I1014 17:03:11.430548 27683 scheduler.cpp:302] Sending DECLINE call to master@172.17.2.187:41367
I1014 17:03:11.431470 27684 slave.cpp:4379] Querying resource estimator for oversubscribable resources
I1014 17:03:11.431581 27672 master.hpp:1436] Sending heartbeat to 89a77d0d-a789-4878-9a21-2f610b238f73-0000
I1014 17:03:11.431821 27684 slave.cpp:3248] No pings from master received within 75secs
I1014 17:03:11.432174 27684 slave.cpp:3212] Received ping from slave-observer(339)@172.17.2.187:41367
I1014 17:03:11.432307 27684 slave.cpp:4038] Current disk usage 6.43%. Max allowed age: 5.849680426210520days
I1014 17:03:11.432430 27684 slave.cpp:4393] Received oversubscribable resources  from the resource estimator
I1014 17:03:11.432561 27684 slave.cpp:715] Re-detecting master
I1014 17:03:11.432585 27684 slave.cpp:762] Detecting new master
I1014 17:03:11.432579 27670 hierarchical.cpp:952] No resources available to allocate!
I1014 17:03:11.432652 27670 hierarchical.cpp:1045] No inverse offers to send out!
I1014 17:03:11.432694 27684 status_update_manager.cpp:176] Pausing sending status updates
I1014 17:03:11.432705 27670 hierarchical.cpp:851] Performed allocation for 1 slaves in 649078ns
I1014 17:03:11.433046 27670 slave.cpp:726] New master detected at master@172.17.2.187:41367
I1014 17:03:11.433059 27682 status_update_manager.cpp:176] Pausing sending status updates
I1014 17:03:11.433120 27670 slave.cpp:789] Authenticating with master master@172.17.2.187:41367
I1014 17:03:11.433148 27670 slave.cpp:794] Using default CRAM-MD5 authenticatee
I1014 17:03:11.433310 27670 slave.cpp:762] Detecting new master
I1014 17:03:11.433388 27676 authenticatee.cpp:115] Creating new client SASL connection
I1014 17:03:11.433735 27676 master.cpp:5144] Authenticating slave(353)@172.17.2.187:41367
I1014 17:03:11.433837 27677 authenticator.cpp:407] Starting authentication session for crammd5_authenticatee(770)@172.17.2.187:41367
I1014 17:03:11.433964 27670 scheduler.cpp:461] Enqueuing event HEARTBEAT received from master@172.17.2.187:41367
I1014 17:03:11.434542 27683 master_maintenance_tests.cpp:179] Ignoring HEARTBEAT event
I1014 17:03:11.434628 27679 authenticator.cpp:92] Creating new server SASL connection
I1014 17:03:11.434886 27683 authenticatee.cpp:206] Received SASL authentication mechanisms: CRAM-MD5
I1014 17:03:11.434988 27683 authenticatee.cpp:232] Attempting to authenticate with mechanism 'CRAM-MD5'
I1014 17:03:11.435096 27679 authenticator.cpp:197] Received SASL authentication start
I1014 17:03:11.435117 27678 process.cpp:3078] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I1014 17:03:11.435156 27679 authenticator.cpp:319] Authentication requires more steps
I1014 17:03:11.435231 27679 authenticatee.cpp:252] Received SASL authentication step
I1014 17:03:11.435410 27681 authenticator.cpp:225] Received SASL authentication step
I1014 17:03:11.435447 27681 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: '6b343c026fe3' server FQDN: '6b343c026fe3' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: false 
I1014 17:03:11.435468 27681 auxprop.cpp:174] Looking up auxiliary property '*userPassword'
I1014 17:03:11.435518 27681 auxprop.cpp:174] Looking up auxiliary property '*cmusaslsecretCRAM-MD5'
I1014 17:03:11.435570 27681 auxprop.cpp:102] Request to lookup properties for user: 'test-principal' realm: '6b343c026fe3' server FQDN: '6b343c026fe3' SASL_AUXPROP_VERIFY_AGAINST_HASH: false SASL_AUXPROP_OVERRIDE: false SASL_AUXPROP_AUTHZID: true 
I1014 17:03:11.435600 27681 auxprop.cpp:124] Skipping auxiliary property '*userPassword' since SASL_AUXPROP_AUTHZID == true
I1014 17:03:11.435601 27678 http.cpp:336] HTTP POST for /master/api/v1/scheduler from 172.17.2.187:53171
I1014 17:03:11.435612 27681 auxprop.cpp:124] Skipping auxiliary property '*cmusaslsecretCRAM-MD5' since SASL_AUXPROP_AUTHZID == true
I1014 17:03:11.435641 27681 authenticator.cpp:311] Authentication success
I1014 17:03:11.435742 27678 master.cpp:3306] Processing DECLINE call for offers: [ 89a77d0d-a789-4878-9a21-2f610b238f73-O0 ] for framework 89a77d0d-a789-4878-9a21-2f610b238f73-0000 (default)
I1014 17:03:11.436012 27681 authenticatee.cpp:292] Authentication success
I1014 17:03:11.436115 27681 authenticator.cpp:425] Authentication session cleanup for crammd5_authenticatee(770)@172.17.2.187:41367
I1014 17:03:11.436475 27685 slave.cpp:857] Successfully authenticated with master master@172.17.2.187:41367
I1014 17:03:11.436609 27682 hierarchical.cpp:739] Recovered cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: ) on slave 89a77d0d-a789-4878-9a21-2f610b238f73-S0 from framework 89a77d0d-a789-4878-9a21-2f610b238f73-0000
I1014 17:03:11.436641 27685 slave.cpp:1251] Will retry registration in 10.388009ms if necessary
I1014 17:03:11.436676 27682 hierarchical.cpp:776] Framework 89a77d0d-a789-4878-9a21-2f610b238f73-0000 filtered slave 89a77d0d-a789-4878-9a21-2f610b238f73-S0 for 1hrs
I1014 17:03:11.437121 27678 master.cpp:5174] Successfully authenticated principal 'test-principal' at slave(353)@172.17.2.187:41367
I1014 17:03:11.437444 27678 master.cpp:4028] Re-registering slave 89a77d0d-a789-4878-9a21-2f610b238f73-S0 at slave(353)@172.17.2.187:41367 (6b343c026fe3)
I1014 17:03:11.437765 27678 master.cpp:4216] Sending updated checkpointed resources  to slave 89a77d0d-a789-4878-9a21-2f610b238f73-S0 at slave(353)@172.17.2.187:41367 (6b343c026fe3)
I1014 17:03:11.437777 27683 slave.cpp:1001] Re-registered with master master@172.17.2.187:41367
I1014 17:03:11.437911 27672 status_update_manager.cpp:183] Resuming sending status updates
I1014 17:03:11.437923 27683 slave.cpp:1037] Forwarding total oversubscribed resources 
I1014 17:03:11.438442 27683 slave.cpp:2284] Updated checkpointed resources from  to 
I1014 17:03:11.438519 27685 master.cpp:4278] Received update of slave 89a77d0d-a789-4878-9a21-2f610b238f73-S0 at slave(353)@172.17.2.187:41367 (6b343c026fe3) with total oversubscribed resources 
I1014 17:03:11.438582 27683 scheduler.cpp:302] Sending SUPPRESS call to master@172.17.2.187:41367
I1014 17:03:11.439237 27685 hierarchical.cpp:391] Slave 89a77d0d-a789-4878-9a21-2f610b238f73-S0 (6b343c026fe3) updated with oversubscribed resources  (total: cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000], allocated: )
I1014 17:03:11.439790 27685 hierarchical.cpp:1139] Filtered offer with cpus(*):2; mem(*):1024; disk(*):1024; ports(*):[31000-32000] on slave 89a77d0d-a789-4878-9a21-2f610b238f73-S0 for framework 89a77d0d-a789-4878-9a21-2f610b238f73-0000
I1014 17:03:11.439844 27685 hierarchical.cpp:952] No resources available to allocate!
I1014 17:03:11.439893 27685 hierarchical.cpp:1045] No inverse offers to send out!
I1014 17:03:11.440057 27685 hierarchical.cpp:867] Performed allocation for slave 89a77d0d-a789-4878-9a21-2f610b238f73-S0 in 768887ns
I1014 17:03:11.440455 27673 process.cpp:3078] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I1014 17:03:11.440728 27673 http.cpp:336] HTTP POST for /master/api/v1/scheduler from 172.17.2.187:53172
I1014 17:03:11.440886 27673 master.cpp:2638] Processing SUPPRESS call for framework 89a77d0d-a789-4878-9a21-2f610b238f73-0000 (default)
I1014 17:03:11.441036 27677 hierarchical.cpp:811] Suppressed offers for framework 89a77d0d-a789-4878-9a21-2f610b238f73-0000
I1014 17:03:11.451550 27677 scheduler.cpp:302] Sending REVIVE call to master@172.17.2.187:41367
I1014 17:03:11.453866 27685 process.cpp:3078] Handling HTTP event for process 'master' with path: '/master/api/v1/scheduler'
I1014 17:03:11.454181 27685 http.cpp:336] HTTP POST for /master/api/v1/scheduler from 172.17.2.187:53173
I1014 17:03:11.454349 27685 master.cpp:3385] Processing REVIVE call for framework 89a77d0d-a789-4878-9a21-2f610b238f73-0000 (default)
I1014 17:03:11.454676 27677 hierarchical.cpp:831] Removed offer filters for framework 89a77d0d-a789-4878-9a21-2f610b238f73-0000
I1014 17:03:11.455766 27677 hierarchical.cpp:1045] No inverse offers to send out!
I1014 17:03:11.456523 27677 hierarchical.cpp:851] Performed allocation for 1 slaves in 1.832172ms
I1014 17:03:11.456339 27685 master.cpp:4973] Sending 1 offers to framework 89a77d0d-a789-4878-9a21-2f610b238f73-0000 (default)
I1014 17:03:11.458744 27677 scheduler.cpp:461] Enqueuing event OFFERS received from master@172.17.2.187:41367
I1014 17:03:11.462066 27675 master.cpp:925] Master terminating
I1014 17:03:11.463048 27675 hierarchical.cpp:364] Removed slave 89a77d0d-a789-4878-9a21-2f610b238f73-S0
I1014 17:03:11.463291 27675 hierarchical.cpp:220] Removed framework 89a77d0d-a789-4878-9a21-2f610b238f73-0000
I1014 17:03:11.463346 27683 slave.cpp:3258] master@172.17.2.187:41367 exited
W1014 17:03:11.463405 27683 slave.cpp:3261] Master disconnected! Waiting for a new master to be elected
E1014 17:03:11.463980 27671 scheduler.cpp:435] End-Of-File received from master. The master closed the event stream
I1014 17:03:11.489421 27652 slave.cpp:606] Slave terminating
[       OK ] ContentType/SchedulerTest.Suppress/0 (137 ms)

Attachments

Issue Links

is related to

MESOS-3789 ContentType/SchedulerTest.Suppress/1 is flalky

Resolved

Activity

People

Assignee:: Guangya Liu

Reporter:: Anand Mazumdar

Shepherd:: Vinod Kone

Votes:: 0 Vote for this issue

Watchers:: 2 Start watching this issue

Dates

Created:: 14/Oct/15 17:56

Updated:: 23/Oct/15 17:24

Resolved:: 23/Oct/15 17:24