change cache check so that debugging can see which file caused failure

Currently the cache tracks the most recent timestamp of parsed files
and then compares that to the cache timestamp. This unfortunately
prevents the parser from being able to know which files caused the
cache check failure.

Rework the cache check so that there is a debug option, and that
the cache file timestamp is set first so that we can output
a deug message for each file that causes a cache check failure.

Signed-off-by: John Johansen <john.johansen@canonical.com>
[tyhicks: Forward ported to trunk and minor cleanups]
Signed-off-by: Tyler Hicks <tyhicks@canonical.com>
Acked-by: Steve Beattie <steve@nxnw.org>

parser/parser.h

@@ -317,7 +317,7 @@ extern void pwarn(const char *fmt, ...) __attribute__((__format__(__printf__, 1,
 /* from parser_main (cannot be used in tst builds) */
 extern int force_complain;
 extern struct timespec mru_tstamp;
-extern void update_mru_tstamp(FILE *file);
+extern void update_mru_tstamp(FILE *file, const char *path);
 extern void display_version(void);
 
 /* provided by parser_lex.l (cannot be used in tst builds) */

parser/parser_lex.l

@@ -138,7 +138,7 @@ static int include_dir_cb(DIR *dir unused, const char *name, struct stat *st,
 		if (!(yyin = fopen(path,"r")))
 			yyerror(_("Could not open '%s' in '%s'"), path, d->filename);
 		PDEBUG("Opened include \"%s\" in \"%s\"\n", path, d->filename);
-		update_mru_tstamp(yyin);
+		update_mru_tstamp(yyin, path);
 		push_include_stack(path);
 		yypush_buffer_state(yy_create_buffer(yyin, YY_BUF_SIZE));
 	}
@@ -174,7 +174,7 @@ void include_filename(char *filename, int search)
 
         if (S_ISREG(my_stat.st_mode)) {
 		yyin = include_file;
-		update_mru_tstamp(include_file);
+		update_mru_tstamp(include_file, fullpath);
 		PDEBUG("Opened include \"%s\"\n", fullpath);
 		push_include_stack(fullpath);
 		yypush_buffer_state(yy_create_buffer( yyin, YY_BUF_SIZE ));

parser/parser_main.c

@@ -76,6 +76,8 @@ int preprocess_only = 0;
 int skip_mode_force = 0;
 int abort_on_error = 0;			/* stop processing profiles if error */
 int skip_bad_cache_rebuild = 0;
+int mru_skip_cache = 1;
+int debug_cache = 0;
 struct timespec mru_tstamp;
 
 #define FEATURES_STRING_SIZE 8192
@@ -128,6 +130,7 @@ struct option long_options[] = {
 	{"abort-on-error",	0, 0, 132},	/* no short option */
 	{"skip-bad-cache-rebuild",	0, 0, 133},	/* no short option */
 	{"warn",		1, 0, 134},	/* no short option */
+	{"debug-cache",		0, 0, 135},	/* no short option */
 	{NULL, 0, 0, 0},
 };
 
@@ -167,6 +170,7 @@ static void display_usage(const char *command)
 	       "    --skip-bad-cache	Don't clear cache if out of sync\n"
 	       "    --purge-cache	Clear cache regardless of its state\n"
 	       "    --create-cache-dir	Create the cache dir if missing\n"
+	       "    --debug-cache       Debug cache file checks\n"
 	       "-L, --cache-loc n	Set the location of the profile cache\n"
 	       "-q, --quiet		Don't emit warnings\n"
 	       "-v, --verbose		Show profile names as they load\n"
@@ -463,6 +467,9 @@ static int process_arg(int c, char *optarg)
 			exit(1);
 		}
 		break;
+	case 135:
+		debug_cache = 1;
+		break;
 	default:
 		display_usage(progname);
 		exit(1);
@@ -815,6 +822,7 @@ int process_binary(int option, const char *profilename)
 void reset_parser(const char *filename)
 {
 	memset(&mru_tstamp, 0, sizeof(mru_tstamp));
+	mru_skip_cache = 1;
 	free_aliases();
 	free_symtabs();
 	free_policies();
@@ -856,19 +864,28 @@ static bool valid_cached_file_version(const char *cachename)
 	}
 	size_t res = fread(buffer, 1, 16, f);
 	fclose(f);
-	if (res < 16)
+	if (res < 16) {
+		if (debug_cache)
+			pwarn("%s: cache file '%s' invalid size\n", progname, cachename);
 		return false;
+	}
 
 	/* 12 byte header that is always the same and then 4 byte version # */
-	if (memcmp(buffer, header_string, HEADER_STRING_SIZE) != 0)
+	if (memcmp(buffer, header_string, HEADER_STRING_SIZE) != 0) {
+		if (debug_cache)
+			pwarn("%s: cache file '%s' has wrong header\n", progname, cachename);
 		return false;
+	}
 
 	uint32_t version = cpu_to_le32(ENCODE_VERSION(force_complain,
 						      policy_version,
 						      parser_abi_version,
 						      kernel_abi_version));
-	if (memcmp(buffer + 12, &version, 4) != 0)
+	if (memcmp(buffer + 12, &version, 4) != 0) {
+		if (debug_cache)
+			pwarn("%s: cache file '%s' has wrong version\n", progname, cachename);
 		return false;
+	}
 
 	return true;
 }
@@ -878,13 +895,22 @@ static bool valid_cached_file_version(const char *cachename)
 (((a).tv_sec == (mru_tstamp).tv_sec) ? \
   (a).tv_nsec > (mru_tstamp).tv_nsec : (a).tv_sec > (mru_tstamp).tv_sec)
 
-void update_mru_tstamp(FILE *file)
+void set_mru_tstamp(struct timespec t)
+{
+	mru_skip_cache = 0;
+	mru_tstamp = t;
+}
+
+void update_mru_tstamp(FILE *file, const char *name)
 {
 	struct stat stat_file;
-	if (fstat(fileno(file), &stat_file))
+	if (fstat(fileno(file), &stat_file) || (mru_tstamp.tv_sec == 0 && mru_tstamp.tv_nsec == 0))
 		return;
-	if (mru_t_cmp(stat_file.st_mtim))
+	if (mru_t_cmp(stat_file.st_mtim)) {
-		mru_tstamp = stat_file.st_mtim;
+		if (debug_cache)
+			pwarn("%s: file '%s' is newer than cache file\n", progname, name);
+		mru_skip_cache = 1;
+       }
 }
 
 int process_profile(int option, const char *profilename)
@@ -904,11 +930,12 @@ int process_profile(int option, const char *profilename)
 			       profilename, strerror(errno));
 			return errno;
 		}
-	}
+	} else {
-	else {
 		pwarn("%s: cannot use or update cache, disable, or force-complain via stdin\n", progname);
 	}
 
+	reset_parser(profilename);
+
 	if (profilename && option != OPTION_REMOVE) {
 		/* make decisions about disabled or complain-mode profiles */
 		basename = strrchr(profilename, '/');
@@ -928,17 +955,27 @@ int process_profile(int option, const char *profilename)
  			force_complain = 1;
  		}
 
-		/* TODO: add primary cache check.
+		/* setup cachename and tstamp */
-		 * If .file for cached binary exists get the list of profile
+		if (!force_complain && !skip_cache) {
-		 * names and check their time stamps.
+			if (asprintf(&cachename, "%s/%s", cacheloc, basename)<0) {
-		 */
+				PERROR(_("Memory allocation error."));
-		/* TODO: primary cache miss/hit messages */
+				exit(1);
+			}
+			if (!skip_read_cache) {
+				if (stat(cachename, &stat_bin) == 0 &&
+				    stat_bin.st_size > 0) {
+					if (valid_cached_file_version(cachename))
+						set_mru_tstamp(stat_bin.st_ctim);
+				} else if (debug_cache)
+					pwarn("%s: Invalid or missing cache file '%s'\n", progname, cachename);
+			}
+		}
+
 	}
 
-	reset_parser(profilename);
 	if (yyin) {
 		yyrestart(yyin);
-		update_mru_tstamp(yyin);
+		update_mru_tstamp(yyin, profilename ? profilename : "stdin");
 	}
 
 	retval = yyparse();
@@ -960,17 +997,9 @@ int process_profile(int option, const char *profilename)
 	 * Parsing the profile is slower that doing primary cache check
 	 * its still faster than doing full compilation
 	 */
-	if ((profilename && option != OPTION_REMOVE) && !force_complain &&
+	if (cachename) {
-	    !skip_cache) {
-		if (asprintf(&cachename, "%s/%s", cacheloc, basename)<0) {
-			PERROR(_("Memory allocation error."));
-			return ENOMEM;
-		}
 		/* Load a binary cache if it exists and is newest */
-		if (!skip_read_cache &&
+		if (!mru_skip_cache) {
-		    stat(cachename, &stat_bin) == 0 &&
-		    stat_bin.st_size > 0 && (mru_t_cmp(stat_bin.st_mtim)) &&
-		    valid_cached_file_version(cachename)) {
 			if (show_cache)
 				PERROR("Cache hit: %s\n", cachename);
 			retval = process_binary(option, cachename);