zotregistry.dev/zot@v1.4.4-0.20240314164342-eec277e14d20/pkg/scheduler/scheduler_test.go (about)

     1  package scheduler_test
     2  
     3  import (
     4  	"context"
     5  	"errors"
     6  	"fmt"
     7  	"os"
     8  	"runtime"
     9  	"strings"
    10  	"testing"
    11  	"time"
    12  
    13  	. "github.com/smartystreets/goconvey/convey"
    14  
    15  	"zotregistry.dev/zot/pkg/api/config"
    16  	"zotregistry.dev/zot/pkg/extensions/monitoring"
    17  	"zotregistry.dev/zot/pkg/log"
    18  	"zotregistry.dev/zot/pkg/scheduler"
    19  )
    20  
    21  type task struct {
    22  	log   log.Logger
    23  	msg   string
    24  	err   bool
    25  	delay time.Duration
    26  }
    27  
    28  var errInternal = errors.New("task: internal error")
    29  
    30  func (t *task) DoWork(ctx context.Context) error {
    31  	if t.err {
    32  		return errInternal
    33  	}
    34  
    35  	for idx := 0; idx < 5; idx++ {
    36  		if ctx.Err() != nil {
    37  			return ctx.Err()
    38  		}
    39  
    40  		time.Sleep(t.delay)
    41  	}
    42  
    43  	t.log.Info().Msg(t.msg)
    44  
    45  	return nil
    46  }
    47  
    48  func (t *task) String() string {
    49  	return t.Name()
    50  }
    51  
    52  func (t *task) Name() string {
    53  	return "TestTask"
    54  }
    55  
    56  type generator struct {
    57  	log       log.Logger
    58  	priority  string
    59  	done      bool
    60  	index     int
    61  	step      int
    62  	limit     int
    63  	taskDelay time.Duration
    64  }
    65  
    66  func (g *generator) Name() string {
    67  	return "TestGenerator"
    68  }
    69  
    70  func (g *generator) Next() (scheduler.Task, error) {
    71  	if g.step > g.limit {
    72  		g.done = true
    73  	}
    74  	g.step++
    75  	g.index++
    76  
    77  	if g.step%11 == 0 {
    78  		return nil, nil
    79  	}
    80  
    81  	if g.step%13 == 0 {
    82  		return nil, errInternal
    83  	}
    84  
    85  	return &task{
    86  		log:   g.log,
    87  		msg:   fmt.Sprintf("executing %s task; index: %d", g.priority, g.index),
    88  		err:   false,
    89  		delay: g.taskDelay,
    90  	}, nil
    91  }
    92  
    93  func (g *generator) IsDone() bool {
    94  	return g.done
    95  }
    96  
    97  func (g *generator) IsReady() bool {
    98  	return true
    99  }
   100  
   101  func (g *generator) Reset() {
   102  	g.done = false
   103  	g.step = 0
   104  }
   105  
   106  type shortGenerator struct {
   107  	log      log.Logger
   108  	priority string
   109  	done     bool
   110  	index    int
   111  	step     int
   112  }
   113  
   114  func (g *shortGenerator) Name() string {
   115  	return "ShortTestGenerator"
   116  }
   117  
   118  func (g *shortGenerator) Next() (scheduler.Task, error) {
   119  	g.done = true
   120  
   121  	return &task{log: g.log, msg: fmt.Sprintf("executing %s task; index: %d", g.priority, g.index), err: false}, nil
   122  }
   123  
   124  func (g *shortGenerator) IsDone() bool {
   125  	return g.done
   126  }
   127  
   128  func (g *shortGenerator) IsReady() bool {
   129  	return true
   130  }
   131  
   132  func (g *shortGenerator) Reset() {
   133  	g.done = true
   134  	g.step = 0
   135  }
   136  
   137  func TestScheduler(t *testing.T) {
   138  	Convey("Test active to waiting periodic generator", t, func() {
   139  		logFile, err := os.CreateTemp("", "zot-log*.txt")
   140  		So(err, ShouldBeNil)
   141  
   142  		defer os.Remove(logFile.Name()) // clean up
   143  
   144  		logger := log.NewLogger("debug", logFile.Name())
   145  		metrics := monitoring.NewMetricsServer(true, logger)
   146  		sch := scheduler.NewScheduler(config.New(), metrics, logger)
   147  
   148  		genH := &shortGenerator{log: logger, priority: "high priority"}
   149  		// interval has to be higher than throttle value to simulate
   150  		sch.SubmitGenerator(genH, 1*time.Second, scheduler.HighPriority)
   151  
   152  		sch.RunScheduler()
   153  		time.Sleep(2 * time.Second)
   154  		sch.Shutdown()
   155  
   156  		data, err := os.ReadFile(logFile.Name())
   157  		So(err, ShouldBeNil)
   158  		So(string(data), ShouldContainSubstring, "waiting generator is ready, pushing to ready generators")
   159  	})
   160  
   161  	Convey("Test order of generators in queue", t, func() {
   162  		logFile, err := os.CreateTemp("", "zot-log*.txt")
   163  		So(err, ShouldBeNil)
   164  
   165  		defer os.Remove(logFile.Name()) // clean up
   166  
   167  		logger := log.NewLogger("debug", logFile.Name())
   168  		cfg := config.New()
   169  		cfg.Scheduler = &config.SchedulerConfig{NumWorkers: 3}
   170  		metrics := monitoring.NewMetricsServer(true, logger)
   171  		sch := scheduler.NewScheduler(cfg, metrics, logger)
   172  		sch.RateLimit = 5 * time.Second
   173  
   174  		genL := &generator{log: logger, priority: "low priority", limit: 100, taskDelay: 100 * time.Millisecond}
   175  		sch.SubmitGenerator(genL, time.Duration(0), scheduler.LowPriority)
   176  
   177  		genM := &generator{log: logger, priority: "medium priority", limit: 100, taskDelay: 100 * time.Millisecond}
   178  		sch.SubmitGenerator(genM, time.Duration(0), scheduler.MediumPriority)
   179  
   180  		genH := &generator{log: logger, priority: "high priority", limit: 100, taskDelay: 100 * time.Millisecond}
   181  		sch.SubmitGenerator(genH, time.Duration(0), scheduler.HighPriority)
   182  
   183  		sch.RunScheduler()
   184  		time.Sleep(4 * time.Second)
   185  		sch.Shutdown()
   186  
   187  		data, err := os.ReadFile(logFile.Name())
   188  		So(err, ShouldBeNil)
   189  
   190  		So(string(data), ShouldContainSubstring, "executing high priority task; index: 1")
   191  		So(string(data), ShouldContainSubstring, "executing high priority task; index: 2")
   192  		So(string(data), ShouldNotContainSubstring, "executing medium priority task; index: 1")
   193  		So(string(data), ShouldNotContainSubstring, "failed to execute task")
   194  	})
   195  
   196  	Convey("Test reordering of generators in queue", t, func() {
   197  		logFile, err := os.CreateTemp("", "zot-log*.txt")
   198  		So(err, ShouldBeNil)
   199  
   200  		defer os.Remove(logFile.Name()) // clean up
   201  
   202  		logger := log.NewLogger("debug", logFile.Name())
   203  		cfg := config.New()
   204  		cfg.Scheduler = &config.SchedulerConfig{NumWorkers: 3}
   205  		metrics := monitoring.NewMetricsServer(true, logger)
   206  		sch := scheduler.NewScheduler(cfg, metrics, logger)
   207  		sch.RateLimit = 1 * time.Nanosecond
   208  
   209  		// Testing repordering of generators using the same medium priority, as well as reordering with
   210  		// a low priority generator
   211  
   212  		genL := &generator{log: logger, priority: "low priority", limit: 110, taskDelay: time.Nanosecond}
   213  		sch.SubmitGenerator(genL, time.Duration(0), scheduler.LowPriority)
   214  
   215  		genM := &generator{log: logger, priority: "medium 1 priority", limit: 110, taskDelay: time.Nanosecond}
   216  		sch.SubmitGenerator(genM, time.Duration(0), scheduler.MediumPriority)
   217  
   218  		genH := &generator{log: logger, priority: "medium 2 priority", limit: 110, taskDelay: time.Nanosecond}
   219  		sch.SubmitGenerator(genH, time.Duration(0), scheduler.MediumPriority)
   220  
   221  		sch.RunScheduler()
   222  		time.Sleep(1 * time.Second)
   223  		sch.Shutdown()
   224  
   225  		data, err := os.ReadFile(logFile.Name())
   226  		So(err, ShouldBeNil)
   227  
   228  		// Check all tasks show up in the logs
   229  		for i := 1; i < 110; i++ {
   230  			if i%11 == 0 || i%13 == 0 {
   231  				continue
   232  			}
   233  
   234  			So(string(data), ShouldContainSubstring, fmt.Sprintf("executing medium 1 priority task; index: %d", i))
   235  			So(string(data), ShouldContainSubstring, fmt.Sprintf("executing medium 2 priority task; index: %d", i))
   236  			So(string(data), ShouldContainSubstring, fmt.Sprintf("executing low priority task; index: %d", i))
   237  		}
   238  
   239  		taskCounter := 0
   240  		priorityFlippedCounter := 0
   241  		samePriorityFlippedCounter := 0
   242  		lastPriority := "medium"
   243  		lastMediumGenerator := "1"
   244  
   245  		for _, line := range strings.Split(strings.TrimSuffix(string(data), "\n"), "\n") {
   246  			if !strings.Contains(line, "priority task; index: ") {
   247  				continue
   248  			}
   249  
   250  			taskCounter++
   251  
   252  			// low priority tasks start executing later
   253  			// medium priority generators are prioritized until the rank 100/9 (8 generated tasks)
   254  			// starting with 100/10, a low priority generator could potentially be prioritized instead
   255  			// there will be at least 8 * 2 medium priority tasks executed before low priority tasks are pushed
   256  			if taskCounter < 17 {
   257  				So(line, ShouldContainSubstring, "executing medium")
   258  			}
   259  
   260  			// medium priority 2*110 medium priority tasks should have been generated,
   261  			// medium priority generators should be done
   262  			// add around 10 low priority tasks to the counter
   263  			// and an additional margin of 5 to make sure the test is stable
   264  			if taskCounter > 225 {
   265  				So(line, ShouldContainSubstring, "executing low priority")
   266  			}
   267  
   268  			if strings.Contains(line, "executing medium") {
   269  				if !strings.Contains(line, fmt.Sprintf("executing medium %s", lastMediumGenerator)) {
   270  					samePriorityFlippedCounter++
   271  					if lastMediumGenerator == "1" {
   272  						lastMediumGenerator = "2"
   273  					} else {
   274  						lastMediumGenerator = "1"
   275  					}
   276  				}
   277  			}
   278  
   279  			if !strings.Contains(line, fmt.Sprintf("executing %s", lastPriority)) {
   280  				priorityFlippedCounter++
   281  				if lastPriority == "low" {
   282  					lastPriority = "medium"
   283  				} else {
   284  					lastPriority = "low"
   285  				}
   286  			}
   287  		}
   288  
   289  		// fairness: make sure none of the medium priority generators is favored by the algorithm
   290  		So(samePriorityFlippedCounter, ShouldBeGreaterThanOrEqualTo, 60)
   291  		t.Logf("Switched between medium priority generators %d times", samePriorityFlippedCounter)
   292  		// fairness: make sure the algorithm alternates between generator priorities
   293  		So(priorityFlippedCounter, ShouldBeGreaterThanOrEqualTo, 10)
   294  		t.Logf("Switched between generator priorities %d times", priorityFlippedCounter)
   295  	})
   296  
   297  	Convey("Test task returning an error", t, func() {
   298  		logFile, err := os.CreateTemp("", "zot-log*.txt")
   299  		So(err, ShouldBeNil)
   300  
   301  		defer os.Remove(logFile.Name()) // clean up
   302  
   303  		logger := log.NewLogger("debug", logFile.Name())
   304  		metrics := monitoring.NewMetricsServer(true, logger)
   305  		sch := scheduler.NewScheduler(config.New(), metrics, logger)
   306  
   307  		t := &task{log: logger, msg: "", err: true}
   308  		sch.SubmitTask(t, scheduler.MediumPriority)
   309  
   310  		sch.RunScheduler()
   311  		time.Sleep(500 * time.Millisecond)
   312  		sch.Shutdown()
   313  
   314  		data, err := os.ReadFile(logFile.Name())
   315  		So(err, ShouldBeNil)
   316  		So(string(data), ShouldContainSubstring, "adding a new task")
   317  		So(string(data), ShouldContainSubstring, "failed to execute task")
   318  	})
   319  
   320  	Convey("Test resubmit generator", t, func() {
   321  		logFile, err := os.CreateTemp("", "zot-log*.txt")
   322  		So(err, ShouldBeNil)
   323  
   324  		defer os.Remove(logFile.Name()) // clean up
   325  
   326  		logger := log.NewLogger("debug", logFile.Name())
   327  		metrics := monitoring.NewMetricsServer(true, logger)
   328  		sch := scheduler.NewScheduler(config.New(), metrics, logger)
   329  
   330  		genL := &generator{log: logger, priority: "low priority", limit: 100, taskDelay: 100 * time.Millisecond}
   331  		sch.SubmitGenerator(genL, 20*time.Millisecond, scheduler.LowPriority)
   332  
   333  		sch.RunScheduler()
   334  		time.Sleep(1 * time.Second)
   335  		sch.Shutdown()
   336  
   337  		data, err := os.ReadFile(logFile.Name())
   338  		So(err, ShouldBeNil)
   339  		So(string(data), ShouldContainSubstring, "executing low priority task; index: 1")
   340  		So(string(data), ShouldContainSubstring, "executing low priority task; index: 2")
   341  	})
   342  
   343  	Convey("Try to add a task with wrong priority", t, func() {
   344  		logFile, err := os.CreateTemp("", "zot-log*.txt")
   345  		So(err, ShouldBeNil)
   346  
   347  		defer os.Remove(logFile.Name()) // clean up
   348  
   349  		logger := log.NewLogger("debug", logFile.Name())
   350  		metrics := monitoring.NewMetricsServer(true, logger)
   351  		sch := scheduler.NewScheduler(config.New(), metrics, logger)
   352  
   353  		t := &task{log: logger, msg: "", err: false}
   354  		sch.SubmitTask(t, -1)
   355  
   356  		data, err := os.ReadFile(logFile.Name())
   357  		So(err, ShouldBeNil)
   358  		So(string(data), ShouldNotContainSubstring, "adding a new task")
   359  	})
   360  
   361  	Convey("Test adding a new task when context is done", t, func() {
   362  		logFile, err := os.CreateTemp("", "zot-log*.txt")
   363  		So(err, ShouldBeNil)
   364  
   365  		defer os.Remove(logFile.Name()) // clean up
   366  
   367  		logger := log.NewLogger("debug", logFile.Name())
   368  		metrics := monitoring.NewMetricsServer(true, logger)
   369  		sch := scheduler.NewScheduler(config.New(), metrics, logger)
   370  
   371  		sch.RunScheduler()
   372  		sch.Shutdown()
   373  		time.Sleep(500 * time.Millisecond)
   374  
   375  		t := &task{log: logger, msg: "", err: false}
   376  		sch.SubmitTask(t, scheduler.LowPriority)
   377  
   378  		data, err := os.ReadFile(logFile.Name())
   379  		So(err, ShouldBeNil)
   380  		So(string(data), ShouldNotContainSubstring, "adding a new task")
   381  	})
   382  
   383  	Convey("Test stopping scheduler by calling Shutdown()", t, func() {
   384  		logFile, err := os.CreateTemp("", "zot-log*.txt")
   385  		So(err, ShouldBeNil)
   386  
   387  		defer os.Remove(logFile.Name()) // clean up
   388  
   389  		logger := log.NewLogger("debug", logFile.Name())
   390  		metrics := monitoring.NewMetricsServer(true, logger)
   391  		sch := scheduler.NewScheduler(config.New(), metrics, logger)
   392  
   393  		genL := &generator{log: logger, priority: "medium priority", limit: 100, taskDelay: 100 * time.Millisecond}
   394  		sch.SubmitGenerator(genL, 20*time.Millisecond, scheduler.MediumPriority)
   395  
   396  		sch.RunScheduler()
   397  		time.Sleep(1 * time.Second)
   398  		sch.Shutdown()
   399  
   400  		data, err := os.ReadFile(logFile.Name())
   401  		So(err, ShouldBeNil)
   402  		So(string(data), ShouldContainSubstring, "executing medium priority task; index: 1")
   403  		So(string(data), ShouldContainSubstring, "executing medium priority task; index: 2")
   404  		So(string(data), ShouldContainSubstring, "received stop signal, gracefully shutting down...")
   405  	})
   406  
   407  	Convey("Test scheduler Priority.String() method", t, func() {
   408  		var p scheduler.Priority //nolint: varnamelen
   409  		// test invalid priority
   410  		p = 6238734
   411  		So(p.String(), ShouldEqual, "invalid")
   412  		p = scheduler.LowPriority
   413  		So(p.String(), ShouldEqual, "low")
   414  		p = scheduler.MediumPriority
   415  		So(p.String(), ShouldEqual, "medium")
   416  		p = scheduler.HighPriority
   417  		So(p.String(), ShouldEqual, "high")
   418  	})
   419  
   420  	Convey("Test scheduler State.String() method", t, func() {
   421  		var s scheduler.State //nolint: varnamelen
   422  		// test invalid state
   423  		s = -67
   424  		So(s.String(), ShouldEqual, "invalid")
   425  		s = scheduler.Ready
   426  		So(s.String(), ShouldEqual, "ready")
   427  		s = scheduler.Waiting
   428  		So(s.String(), ShouldEqual, "waiting")
   429  		s = scheduler.Done
   430  		So(s.String(), ShouldEqual, "done")
   431  	})
   432  }
   433  
   434  func TestGetNumWorkers(t *testing.T) {
   435  	Convey("Test setting the number of workers - default value", t, func() {
   436  		logger := log.NewLogger("debug", "logFile")
   437  		metrics := monitoring.NewMetricsServer(true, logger)
   438  		sch := scheduler.NewScheduler(config.New(), metrics, logger)
   439  		defer os.Remove("logFile")
   440  		So(sch.NumWorkers, ShouldEqual, runtime.NumCPU()*4)
   441  	})
   442  
   443  	Convey("Test setting the number of workers - getting the value from config", t, func() {
   444  		cfg := config.New()
   445  		cfg.Scheduler = &config.SchedulerConfig{NumWorkers: 3}
   446  		logger := log.NewLogger("debug", "logFile")
   447  		metrics := monitoring.NewMetricsServer(true, logger)
   448  		sch := scheduler.NewScheduler(cfg, metrics, logger)
   449  		defer os.Remove("logFile")
   450  		So(sch.NumWorkers, ShouldEqual, 3)
   451  	})
   452  }