Let ObjFileIsUpToDate output verbose debug output

If -debug-level=20 is passed, whenever the cached file is not usable for
whatever reason, a message is displayed. This should help debug caching
problems.

The messages are hardcoded in the source and not put into `constants`,
since they are only debug messages.

Signed-off-by: Matthijs Kooijman <matthijs@stdin.nl>

Author: matthijskooijman

builder_utils/utils.go

@@ -227,6 +227,12 @@ func ObjFileIsUpToDate(ctx *types.Context, sourceFile, objectFile, dependencyFil
 	sourceFile = filepath.Clean(sourceFile)
 	objectFile = filepath.Clean(objectFile)
 	dependencyFile = filepath.Clean(dependencyFile)
+	logger := ctx.GetLogger()
+	debugLevel := ctx.DebugLevel
+
+	if debugLevel >= 20 {
+		logger.Fprintln(os.Stdout, constants.LOG_LEVEL_DEBUG, "Checking previous results for {0} (result = {1}, dep = {2})", sourceFile, objectFile, dependencyFile)
+	}
 
 	sourceFileStat, err := os.Stat(sourceFile)
 	if err != nil {
@@ -236,6 +242,9 @@ func ObjFileIsUpToDate(ctx *types.Context, sourceFile, objectFile, dependencyFil
 	objectFileStat, err := os.Stat(objectFile)
 	if err != nil {
 		if os.IsNotExist(err) {
+			if debugLevel >= 20 {
+				logger.Fprintln(os.Stdout, constants.LOG_LEVEL_DEBUG, "Not found: {0}", objectFile)
+			}
 			return false, nil
 		} else {
 			return false, i18n.WrapError(err)
@@ -245,16 +254,25 @@ func ObjFileIsUpToDate(ctx *types.Context, sourceFile, objectFile, dependencyFil
 	dependencyFileStat, err := os.Stat(dependencyFile)
 	if err != nil {
 		if os.IsNotExist(err) {
+			if debugLevel >= 20 {
+				logger.Fprintln(os.Stdout, constants.LOG_LEVEL_DEBUG, "Not found: {0}", dependencyFile)
+			}
 			return false, nil
 		} else {
 			return false, i18n.WrapError(err)
 		}
 	}
 
 	if sourceFileStat.ModTime().After(objectFileStat.ModTime()) {
+		if debugLevel >= 20 {
+			logger.Fprintln(os.Stdout, constants.LOG_LEVEL_DEBUG, "{0} newer than {1}", sourceFile, objectFile)
+		}
 		return false, nil
 	}
 	if sourceFileStat.ModTime().After(dependencyFileStat.ModTime()) {
+		if debugLevel >= 20 {
+			logger.Fprintln(os.Stdout, constants.LOG_LEVEL_DEBUG, "{0} newer than {1}", sourceFile, dependencyFile)
+		}
 		return false, nil
 	}
 
@@ -274,10 +292,16 @@ func ObjFileIsUpToDate(ctx *types.Context, sourceFile, objectFile, dependencyFil
 
 	firstRow := rows[0]
 	if !strings.HasSuffix(firstRow, ":") {
+		if debugLevel >= 20 {
+			logger.Fprintln(os.Stdout, constants.LOG_LEVEL_DEBUG, "No colon in first line of depfile")
+		}
 		return false, nil
 	}
 	objFileInDepFile := firstRow[:len(firstRow)-1]
 	if objFileInDepFile != objectFile {
+		if debugLevel >= 20 {
+			logger.Fprintln(os.Stdout, constants.LOG_LEVEL_DEBUG, "Depfile is about different file: {0}", objFileInDepFile)
+		}
 		return false, nil
 	}
 
@@ -287,12 +311,22 @@ func ObjFileIsUpToDate(ctx *types.Context, sourceFile, objectFile, dependencyFil
 		if err != nil && !os.IsNotExist(err) {
 			// There is probably a parsing error of the dep file
 			// Ignore the error and trigger a full rebuild anyway
+			if debugLevel >= 20 {
+				logger.Fprintln(os.Stdout, constants.LOG_LEVEL_DEBUG, "Failed to read: {0}", row)
+				logger.Fprintln(os.Stdout, constants.LOG_LEVEL_DEBUG, i18n.WrapError(err).Error())
+			}
 			return false, nil
 		}
 		if os.IsNotExist(err) {
+			if debugLevel >= 20 {
+				logger.Fprintln(os.Stdout, constants.LOG_LEVEL_DEBUG, "Not found: {0}", row)
+			}
 			return false, nil
 		}
 		if depStat.ModTime().After(objectFileStat.ModTime()) {
+			if debugLevel >= 20 {
+				logger.Fprintln(os.Stdout, constants.LOG_LEVEL_DEBUG, "{0} newer than {1}", row, objectFile)
+			}
 			return false, nil
 		}
 	}