cleanup and logging

services/clsi/app/coffee/OutputCacheManager.coffee

@@ -8,44 +8,101 @@ _ = require "underscore"
 OutputFileOptimiser = require "./OutputFileOptimiser"
 
 module.exports = OutputCacheManager =
-	CACHE_DIR: '.cache/clsi'
+	CACHE_SUBDIR: '.cache/clsi'
+	BUILD_REGEX: /^[0-9a-f]+$/  # build id is Date.now() converted to hex
+	CACHE_LIMIT: 32  # maximum of 32 cache directories
+	CACHE_AGE: 60*60*1000 # up to one hour old
 
-	saveOutputFiles: (outputFiles, target, callback) ->
+	path: (buildId) ->
-		# make a target/build_id directory and
+		# used by static server, given build id return '.cache/clsi/buildId'
+		return Path.join(OutputCacheManager.CACHE_SUBDIR, buildId)
+
+	saveOutputFiles: (outputFiles, compileDir, callback = (error) ->) ->
+		# make a compileDir/CACHE_SUBDIR/build_id directory and
 		# copy all the output files into it
-		# 
+		cacheRoot = Path.join(compileDir, OutputCacheManager.CACHE_SUBDIR)
-		# TODO: use Path module
+		# Put the files into a new cache subdirectory
-		buildId = Date.now()
+		buildId = Date.now().toString(16)
-		relDir = OutputCacheManager.CACHE_DIR + '/' + buildId
+		cacheDir = Path.join(compileDir, OutputCacheManager.CACHE_SUBDIR, buildId)
-		newDir = target + '/' + relDir
+		# let file expiry run in the background
-		OutputCacheManager.expireOutputFiles target
+		OutputCacheManager.expireOutputFiles cacheRoot, {keep: buildId}
-		fse.ensureDir newDir, (err) ->
+
+		checkFile = (src, callback) ->
+			# check if we have a valid file to copy into the cache
+			fs.stat src, (err, stats) ->
+				if err?
+					# some problem reading the file
+					logger.error err: err, file: src, "stat error for file in cache"
+					callback(err)
+				else if not stats.isFile()
+					# other filetype - reject it
+					logger.error err: err, src: src, dst: dst, stat: stats, "nonfile output - refusing to copy to cache"
+					callback(new Error("output file is not a file"), file)
+				else
+					# it's a plain file, ok to copy
+					callback(null)
+
+		copyFile = (src, dst, callback) ->
+			# copy output file into the cache
+			fse.copy src, dst, (err) ->
+				if err?
+					logger.error err: err, src: src, dst: dst, "copy error for file in cache"
+					callback(err)
+				else
+					# call the optimiser for the file too
+					OutputFileOptimiser.optimiseFile src, dst, callback
+
+		# make the new cache directory
+		fse.ensureDir cacheDir, (err) ->
 			if err?
+				logger.error err: err, directory: cacheDir, "error creating cache directory"
 				callback(err, outputFiles)
 			else
+				# copy all the output files into the new cache directory
 				async.mapSeries outputFiles, (file, cb) ->
 					newFile = _.clone(file)
-					src = target + '/' + file.path
+					[src, dst] = [Path.join(compileDir, file.path), Path.join(cacheDir, file.path)]
-					dst = target + '/' + relDir + '/' + file.path
+					checkFile src, (err) ->
-					fs.stat src, (err, stats) ->
+						copyFile src, dst, (err) ->
-						if err?
+							if not err?
-							cb(err)
+								newFile.build = buildId  # attach a build id if we cached the file
-						else if stats.isFile()
+							cb(err, newFile)
-							fse.copy src, dst, (err) ->
-								OutputFileOptimiser.optimiseFile src, dst, (err, result) ->
-									newFile.build = buildId
-									cb(err, newFile)
-						else
-							# other filetype - shouldn't happen
-							cb(new Error("output file is not a file"), file)
 				, (err, results) ->
 					if err?
-						callback err, outputFiles
+						# pass back the original files if we encountered *any* error
+						callback(err, outputFiles)
 					else
+						# pass back the list of new files in the cache
 						callback(err, results)
 
-	expireOutputFiles: (target, callback) ->
+	expireOutputFiles: (cacheRoot, options, callback = (error) ->) ->
-		# look in target for build dirs and delete if > N or age of mod time > T
+		# look in compileDir for build dirs and delete if > N or age of mod time > T
-		cacheDir = target + '/' + OutputCacheManager.CACHE_DIR
+		fs.readdir cacheRoot, (err, results) ->
-		fs.readdir cacheDir, (err, results) ->
+			if err?
-			callback(err) if callback?
+				logger.error err: err, project_id: cacheRoot, "error clearing cache"
+				return callback(err)
+
+			dirs =  results.sort().reverse()
+			currentTime = Date.now()
+
+			isExpired = (dir, index) ->
+				return false if options?.keep == dir
+				# remove any directories over the hard limit
+				return true if index > OutputCacheManager.CACHE_LIMIT
+				# we can get the build time from the directory name
+				dirTime = parseInt(dir, 16)
+				age = currentTime - dirTime
+				return age > OutputCacheManager.CACHE_AGE
+
+			toRemove = _.filter(dirs, isExpired)
+
+			removeDir = (dir, cb) ->
+				fse.remove Path.join(cacheRoot, dir), (err, result) ->
+					logger.log cache: cacheRoot, dir: dir, "removed expired cache dir"
+					if err?
+						logger.error err: err, dir: dir, "cache remove error"
+					cb(err, result)
+
+			async.eachSeries toRemove, (dir, cb) ->
+				removeDir dir, cb
+			, callback

services/clsi/app/coffee/OutputFileOptimiser.coffee

@@ -6,6 +6,8 @@ logger = require "logger-sharelatex"
 module.exports = OutputFileOptimiser =
 
 	optimiseFile: (src, dst, callback = (error) ->) ->
+		# check output file (src) and see if we can optimise it, storing
+		# the result in the build directory (dst)
 		if src.match(/\.pdf$/)
 			OutputFileOptimiser.optimisePDF src, dst, callback
 		else
@@ -19,12 +21,13 @@ module.exports = OutputFileOptimiser =
 		proc = spawn("qpdf", args)
 		stdout = ""
 		proc.stdout.on "data", (chunk) ->
-			stdout += chunk.toString()	
+			stdout += chunk.toString()
-		proc.on "error", callback	
+		proc.on "error", callback
 		proc.on "close", (code) ->
 			if code != 0
 				logger.warn {directory, code}, "qpdf returned error"
 				return callback null
 			fs.rename tmpOutput, dst, (err) ->
-				# could log an error here
+				if err?
-				callback null
+					logger.warn {tmpOutput, dst}, "failed to rename output of qpdf command"
+				callback err