Debug flapping test

.travis.yml

@@ -3,6 +3,7 @@ sudo: false
 go:
 - 1.8.x
 - 1.9.x
+- 1.10.x
 install:
 - go get -t ./...
 - go get github.com/nats-io/gnatsd
@@ -26,3 +27,5 @@ script:
 - if [[ "$TRAVIS_GO_VERSION" == 1.9.* ]]; then ./scripts/cov.sh TRAVIS; else go test $EXCLUDE_VENDOR; fi
 after_success:
 - if [[ "$TRAVIS_GO_VERSION" == 1.9.* ]] && [ "$TRAVIS_TAG" != "" ]; then ./scripts/cross_compile.sh $TRAVIS_TAG; ghr --owner nats-io --token $GITHUB_TOKEN --draft --replace $TRAVIS_TAG pkg/; fi
+notifications:
+ email: false

stores/common_msg_test.go

@@ -307,44 +307,60 @@ func dumpFSState(t *testing.T, s Store, format string, args ...interface{}) {
 		stackFatalf(t, format, args...)
 		return
 	}
-	fs.RLock()
-	channels := fs.channels
-	fs.RUnlock()
-	for name, c := range channels {
-		fmt.Printf("== Channel %q ==\n", name)
-		ms := c.Msgs.(*FileMsgStore)
-		ms.RLock()
-		nextExp := ms.expiration
-		totalCount := ms.totalCount
-		first := ms.first
-		last := ms.last
-		lenWakeChan := len(ms.bkgTasksWake)
-		timeTick := atomic.LoadInt64(&ms.timeTick)
-		ms.RUnlock()
-		fmt.Printf(" Now             : %v\n", time.Now())
-		fmt.Printf(" TimeTick        : %v\n", time.Unix(0, timeTick))
-		fmt.Printf(" Next Expiration : %v\n", time.Unix(0, nextExp))
-		fmt.Printf(" Sleep interval  : %v\n", bkgTasksSleepDuration)
-		fmt.Printf(" Total Count     : %v\n", totalCount)
-		fmt.Printf(" First           : %v\n", first)
-		fmt.Printf(" Last            : %v\n", last)
-		fmt.Printf(" Len wakeup chan : %v\n", lenWakeChan)
-		fmt.Printf(" -- Messages --\n")
-		for idx := first; idx <= last; idx++ {
-			m, err := ms.Lookup(idx)
-			if err != nil {
-				fmt.Printf("   Msg %2d : Error during lookup: %v\n", idx, err)
-			} else if m == nil {
-				fmt.Printf("   Msg %2d : Lookup returned nil\n", idx)
-			} else {
-				fmt.Printf("   Msg %2d : %v\n", idx, time.Unix(0, m.Timestamp))
+	f := func(notify bool) {
+		fs.RLock()
+		channels := fs.channels
+		fs.RUnlock()
+		for name, c := range channels {
+			fmt.Printf("== Channel %q ==\n", name)
+			ms := c.Msgs.(*FileMsgStore)
+			if notify {
+				ms.Lock()
+				ms.expiration = 1
+				ms.Unlock()
+				select {
+				case ms.bkgTasksWake <- true:
+				default:
+					fmt.Printf("@@IK: Unable to notify background tasks\n")
+				}
+			}
+			ms.RLock()
+			nextExp := ms.expiration
+			totalCount := ms.totalCount
+			first := ms.first
+			last := ms.last
+			lenWakeChan := len(ms.bkgTasksWake)
+			timeTick := atomic.LoadInt64(&ms.timeTick)
+			ms.RUnlock()
+			fmt.Printf(" Now             : %v\n", time.Now())
+			fmt.Printf(" TimeTick        : %v\n", time.Unix(0, timeTick))
+			fmt.Printf(" Next Expiration : %v\n", time.Unix(0, nextExp))
+			fmt.Printf(" Sleep interval  : %v\n", bkgTasksSleepDuration)
+			fmt.Printf(" Total Count     : %v\n", totalCount)
+			fmt.Printf(" First           : %v\n", first)
+			fmt.Printf(" Last            : %v\n", last)
+			fmt.Printf(" Len wakeup chan : %v\n", lenWakeChan)
+			fmt.Printf(" -- Messages --\n")
+			for idx := first; idx <= last; idx++ {
+				m, err := ms.Lookup(idx)
+				if err != nil {
+					fmt.Printf("   Msg %2d : Error during lookup: %v\n", idx, err)
+				} else if m == nil {
+					fmt.Printf("   Msg %2d : Lookup returned nil\n", idx)
+				} else {
+					fmt.Printf("   Msg %2d : %v\n", idx, time.Unix(0, m.Timestamp))
+				}
 			}
+			fmt.Printf(" --------------\n")
 		}
-		fmt.Printf(" --------------\n")
 	}
-	buf := make([]byte, 1024*1024)
-	n := runtime.Stack(buf, true)
-	fmt.Printf("Go-routines:\n%s\n", string(buf[:n]))
+	f(false)
+	fmt.Printf("@@IK: Waiting a bit more...\n")
+	time.Sleep(time.Second)
+	fmt.Printf("@@IK: new state:\n")
+	f(false)
+	fmt.Printf("@@IK: notify channels\n")
+	f(true)
 	stackFatalf(t, format, args...)
 }
 

stores/filestore.go

@@ -2554,11 +2554,18 @@ func (ms *FileMsgStore) expireMsgs(now, maxAge int64) int64 {
 						slice = nil
 						break
 					}
+				} else {
+					fmt.Printf("@@IK: exireMsgs slice nil for: %v\n", ms.first)
 				}
 			}
 			if slice != nil {
 				m = ms.getMsgIndex(slice, ms.first)
+				if m == nil {
+					fmt.Printf("@@IK: expireMsgs could not find: %v\n", ms.first)
+				}
 			}
+		} else {
+			fmt.Printf("@@IK: expireMsgs first=%v last=%v\n", ms.first, ms.last)
 		}
 		if m == nil {
 			ms.expiration = 0