Fix pre-existing problem with handling of end of windows

Due to a bug with the old version of the window package that audiobait
was depending on and a bug in audiobait, audiobait would spin in a
tight loop and emit a bunch of logs for the last minute of each day's
schedule.

The window package has now been upgraded and the audiobait's daily
playback logic has been fixed to stop trying to play combos which are
already done.

go.mod

@@ -5,9 +5,10 @@ go 1.12
 require (
 	github.com/TheCacophonyProject/go-api v0.0.0-20190913044515-638d1f88861e
 	github.com/TheCacophonyProject/modemd v0.0.0-20190708011609-1940f5b6677b
-	github.com/TheCacophonyProject/window v0.0.0-20180531024057-3a2d74f7fcf5
+	github.com/TheCacophonyProject/window v0.0.0-20190821235241-ab92c2ee24b6
 	github.com/alexflint/go-arg v1.0.0
 	github.com/godbus/dbus v4.1.0+incompatible
+	github.com/nathan-osman/go-sunrise v0.0.0-20171121204956-7c449e7c690b // indirect
 	github.com/stretchr/objx v0.2.0 // indirect
 	github.com/stretchr/testify v1.4.0
 	golang.org/x/crypto v0.0.0-20190911031432-227b76d455e7 // indirect

go.sum

@@ -6,6 +6,8 @@ github.com/TheCacophonyProject/modemd v0.0.0-20190708011609-1940f5b6677b h1:iJVZ
 github.com/TheCacophonyProject/modemd v0.0.0-20190708011609-1940f5b6677b/go.mod h1:txGgnRinv6H0/jB4n71MpuS+2qtu8tAlntIjY5udXDU=
 github.com/TheCacophonyProject/window v0.0.0-20180531024057-3a2d74f7fcf5 h1:ihqo17eciOVXn6tZDw0G8L/xJOJ2iaNR9selfF+0uo4=
 github.com/TheCacophonyProject/window v0.0.0-20180531024057-3a2d74f7fcf5/go.mod h1:Vww417iimOb0s46Ndsm8U/vYtwc0dZUet4uW8QzBo4M=
+github.com/TheCacophonyProject/window v0.0.0-20190821235241-ab92c2ee24b6 h1:aLER2Au+/pJe9FzTW7lmQJIOLO8bgio5i/Uzx/EGEmE=
+github.com/TheCacophonyProject/window v0.0.0-20190821235241-ab92c2ee24b6/go.mod h1:Vww417iimOb0s46Ndsm8U/vYtwc0dZUet4uW8QzBo4M=
 github.com/alexflint/go-arg v1.0.0 h1:VWNnY3DyBHiq5lcwY2FlCE5t5qyHNV0o5i1bkCIHprU=
 github.com/alexflint/go-arg v1.0.0/go.mod h1:Cto8k5VtkP4pp0EXiWD4ZJMFOOinZ38ggVcQ/6CGuRI=
 github.com/alexflint/go-scalar v1.0.0 h1:NGupf1XV/Xb04wXskDFzS0KWOLH632W/EO4fAFi+A70=
@@ -21,12 +23,15 @@ github.com/gofrs/flock v0.7.1/go.mod h1:F1TvTiK9OcQqauNUHlbJvyl9Qa1QvF/gOUDKA14j
 github.com/kr/pretty v0.1.0/go.mod h1:dAy3ld7l9f0ibDNOQOHHMYYIIbhfbHSm3C4ZsoJORNo=
 github.com/kr/pty v1.1.1/go.mod h1:pFQYn66WHrOpPYNljwOMqo10TkYh1fy3cYio2l3bCsQ=
 github.com/kr/text v0.1.0/go.mod h1:4Jbv+DJW3UT/LiOwJeYQe1efqtUx/iVham/4vfdArNI=
+github.com/nathan-osman/go-sunrise v0.0.0-20171121204956-7c449e7c690b h1:nWQAhkNZTyV8tfXIpwSGm97Pd0mM1y9tutJiyWoEhw0=
+github.com/nathan-osman/go-sunrise v0.0.0-20171121204956-7c449e7c690b/go.mod h1:kCE4+NvReDuwiJGk03l6QONGmYy805GQP3xGcCm8cBg=
 github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM=
 github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
 github.com/spf13/afero v1.2.2 h1:5jhuqJyZCZf2JRofRvN/nIFgIWNzPa3/Vz8mYylgbWc=
 github.com/spf13/afero v1.2.2/go.mod h1:9ZxEEn6pIJ8Rxe320qSDBk6AsU0r9pR7Q4OcevTdifk=
 github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=
 github.com/stretchr/objx v0.2.0/go.mod h1:qt09Ya8vawLte6SNmTgCsAVtYtaKzEcn8ATUoHMkEqE=
+github.com/stretchr/testify v1.2.1/go.mod h1:a8OnRcib4nhh0OaRAV+Yts87kKdq0PP7pXfy6kDkUVs=
 github.com/stretchr/testify v1.2.2 h1:bSDNvY7ZPG5RlJ8otE/7V6gMiyenm9RtJ7IUVIAoJ1w=
 github.com/stretchr/testify v1.2.2/go.mod h1:a8OnRcib4nhh0OaRAV+Yts87kKdq0PP7pXfy6kDkUVs=
 github.com/stretchr/testify v1.3.0 h1:TivCn/peBQ7UY8ooIcPgZFpTNSz0Q2U6UrFlUfqbe0Q=

main.go

@@ -90,14 +90,17 @@ func runMain() error {
 		log.Print("loading schedule from disk")
 		player, schedule, err := createPlayer(soundCard, conf.AudioDir)
 		if err != nil {
-			log.Printf("error creating player: %v", err)
+			log.Printf("error creating player: %v (will wait for schedule update)", err)
+			playTime = nil
+		} else if len(schedule.Combos) < 1 {
+			log.Print("No schedule defined - waiting for schedule update")
 			playTime = nil
 		} else {
-			playTime = time.After(player.TimeUntilNextCombo(*schedule))
+			playIn := player.TimeUntilNextCombo(*schedule)
+			log.Printf("waiting %s for schedule to start", playIn)
+			playTime = time.After(playIn)
 		}
 
-		log.Print("waiting")
-
 		select {
 		case <-dl.Updated():
 			log.Print("new schedule - reloading")

playlist/player.go

@@ -54,7 +54,6 @@ func (t *ActualClock) Now() time.Time {
 }
 
 func (t *ActualClock) Wait(duration time.Duration) {
-	log.Printf("Waiting for %v", duration)
 	time.Sleep(duration)
 }
 
@@ -166,23 +165,31 @@ func (sp SchedulePlayer) PlayTodaysSchedule(schedule Schedule) {
 
 // PlayTodaysCombos plays the given combos - doesn't not care whether it is a control day
 func (sp SchedulePlayer) playTodaysCombos(combos []Combo) {
-	tomorrowStart := sp.nextDayStart()
-	numberCombos := len(combos)
-	count := sp.findNextCombo(combos)
+	done := make(map[int]bool)
 
-	nextComboStart := sp.time.Now().Add(sp.createWindow(combos[count]).Until())
+	tomorrowStart := sp.nextDayStart()
+	i := sp.findNextCombo(combos)
 
-	for nextComboStart.Before(tomorrowStart) {
-		log.Println("Playing combo...")
-		sp.playCombo(combos[count])
-		count = (count + 1) % numberCombos
-		nextComboStart = sp.time.Now().Add(sp.createWindow(combos[count]).Until())
+	for len(done) < len(combos) {
+		if !done[i] {
+			nextCombo := combos[i]
+			win := sp.createWindow(nextCombo)
+			nextComboStart := sp.time.Now().Add(win.Until())
+			if nextComboStart.Before(tomorrowStart) {
+				log.Println("Playing combo...")
+				sp.playCombo(nextCombo)
+			} else {
+				done[i] = true
+			}
+		}
+		i = (i + 1) % len(combos)
 	}
 	log.Println("Completed playing combos for today")
 }
 
-// nextDayStart works out when the next playing day starts.   As the playing day starts around midday, this could actually be
-// later today.
+// nextDayStart works out when the next playing day starts. As the
+// playing day starts around midday, this could actually be later
+// today.
 func (sp SchedulePlayer) nextDayStart() time.Time {
 	return nextDayStart(sp.time.Now())
 }
@@ -217,15 +224,19 @@ func (sp SchedulePlayer) playCombo(combo Combo) {
 			sp.playSounds(combo, soundChooser)
 		} else {
 			log.Print("Played last burst, sleeping until near end of window")
-			sp.time.Wait(win.UntilEnd()) // Stop 3s early so we don't miss the start of the next interval
+			sp.time.Wait(win.UntilEnd())
 			return
 		}
 	}
 }
 
+const hourMinuteFormat = "15:04"
+
 // createWindow creates a window with the times specified in the combo definition
 func (sp SchedulePlayer) createWindow(combo Combo) *window.Window {
-	win := window.New(combo.From.Time, combo.Until.Time)
+	from := combo.From.Time.Format(hourMinuteFormat)
+	to := combo.Until.Time.Format(hourMinuteFormat)
+	win, _ := window.New(from, to, 0, 0)
 	win.Now = sp.time.Now
 	return win
 }

playlist/player_test.go

@@ -112,8 +112,10 @@ func TestPlayingComboStartBefore(t *testing.T) {
 }
 
 func TestPlayTodaysScheduleWithComboOverMiddayShouldPlayToEndOfComboThenStop(t *testing.T) {
-	combos := []Combo{createCombo("19:00", "19:25", 30, "roar"),
-		createCombo("11:12", "12:40", 60, "cry")}
+	combos := []Combo{
+		createCombo("19:00", "19:25", 30, "roar"),
+		createCombo("11:12", "12:40", 60, "cry"),
+	}
 
 	schedulePlayer, testRecorder := createPlayer("18:30")
 	schedulePlayer.playTodaysCombos(combos)
@@ -128,8 +130,10 @@ func TestPlayTodaysScheduleWithComboOverMiddayShouldPlayToEndOfComboThenStop(t *
 }
 
 func TestPlayTodaysScheduleShouldLoopBackToStartOfCombosIfRequired(t *testing.T) {
-	combos := []Combo{createCombo("03:00", "04:00", 45, "squeal"),
-		createCombo("21:12", "22:00", 60, "tweet")}
+	combos := []Combo{
+		createCombo("03:00", "04:00", 45, "squeal"),
+		createCombo("21:12", "22:00", 60, "tweet"),
+	}
 
 	schedulePlayer, testRecorder := createPlayer("18:30")
 	schedulePlayer.playTodaysCombos(combos)
@@ -144,10 +148,14 @@ func TestPlayTodaysScheduleShouldLoopBackToStartOfCombosIfRequired(t *testing.T)
 }
 
 func TestScheduleWithZeroControlNightsAlwaysPlays(t *testing.T) {
-	schedule := Schedule{ControlNights: 0, PlayNights: 0}
+	schedule := Schedule{
+		ControlNights: 0,
+		PlayNights:    0,
+		Combos:        []Combo{createCombo("21:12", "22:00", 60, "foo")},
+	}
 	schedulePlayer, _ := createPlayer("12:01")
 
-	assert.Equal(t, true, schedulePlayer.IsSoundPlayingDay(schedule))
+	assert.True(t, schedulePlayer.IsSoundPlayingDay(schedule))
 }
 
 func checkPlaysOn(day int, month time.Month, t *testing.T, schedule Schedule, schedulePlayer *SchedulePlayer, clock *TestClockAndAudioDevice) {
@@ -165,7 +173,12 @@ func checkSilentOn(day int, month time.Month, t *testing.T, schedule Schedule, s
 }
 
 func TestScheduleWithControlDaysOnlyPlaysOnPlayingDays(t *testing.T) {
-	schedule := Schedule{ControlNights: 5, PlayNights: 2, StartDay: 3}
+	schedule := Schedule{
+		ControlNights: 5,
+		PlayNights:    2,
+		StartDay:      3,
+		Combos:        []Combo{createCombo("12:01", "20:00", 60, "foo")},
+	}
 	schedulePlayer, clock := createPlayer("17:01")
 
 	checkSilentOn(1, time.April, t, schedule, schedulePlayer, clock)
@@ -179,7 +192,12 @@ func TestScheduleWithControlDaysOnlyPlaysOnPlayingDays(t *testing.T) {
 	checkPlaysOn(10, time.April, t, schedule, schedulePlayer, clock)
 	checkPlaysOn(17, time.April, t, schedule, schedulePlayer, clock)
 
-	schedule = Schedule{ControlNights: 3, PlayNights: 2, StartDay: 19}
+	schedule = Schedule{
+		ControlNights: 3,
+		PlayNights:    2,
+		StartDay:      19,
+		Combos:        []Combo{createCombo("12:01", "20:00", 60, "foo")},
+	}
 	schedulePlayer, clock = createPlayer("17:01")
 
 	checkSilentOn(18, time.April, t, schedule, schedulePlayer, clock)
@@ -190,7 +208,11 @@ func TestScheduleWithControlDaysOnlyPlaysOnPlayingDays(t *testing.T) {
 	checkPlaysOn(4, time.April, t, schedule, schedulePlayer, clock)
 
 	// check if StartDay not defined
-	schedule = Schedule{ControlNights: 3, PlayNights: 2}
+	schedule = Schedule{
+		ControlNights: 3,
+		PlayNights:    2,
+		Combos:        []Combo{createCombo("12:01", "20:00", 60, "foo")},
+	}
 	schedulePlayer, clock = createPlayer("17:01")
 
 	checkPlaysOn(1, time.April, t, schedule, schedulePlayer, clock)