Uploaded image for project: 'Mesos'
  1. Mesos
  2. MESOS-3733

ContentType/SchedulerTest.Suppress/0 is flaky

Attach filesAttach ScreenshotVotersWatch issueWatchersLinkCloneUpdate Comment AuthorReplace String in CommentUpdate Comment VisibilityDelete Comments
    XMLWordPrintableJSON

Details

    • Bug
    • Status: Resolved
    • Major
    • Resolution: Fixed
    • None
    • 0.26.0
    • HTTP API

    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

        Activity

          This comment will be Viewable by All Users Viewable by All Users
          Cancel

          People

            gyliu Guangya Liu
            anandmazumdar Anand Mazumdar
            Vinod Kone Vinod Kone
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved:

              Slack

                Issue deployment