Add extensive logging to scss cacherdebug/scss-cache-locking

Signed-off-by: Julius Härtl <jus@bitgrid.net>

1 files changed, 20 insertions, 7 deletions

diff --git a/lib/private/Template/SCSSCacher.php b/lib/private/Template/SCSSCacher.php
index 64d3caf9b6b..dca700ac9dc 100644
--- a/lib/private/Template/SCSSCacher.php
+++ b/lib/private/Template/SCSSCacher.php
@@ -166,18 +166,20 @@ class SCSSCacher {
 			while ($retry < 10) {
 				if (!$this->variablesChanged() && $this->isCached($fileNameCSS, $app)) {
 					// Inject icons vars css if any
+					// Maybe this causes the locking cache to be removed to early when another process is still holding the lock?
 					$this->lockingCache->remove($lockKey);
-					$this->logger->debug('SCSSCacher: ' .$lockKey.' is now available after '.$retry.'s. Moving on...', ['app' => 'core']);
+					$this->logger->debug('SCSSCacher: ' .$lockKey.' is now available after '.$retry.'s. Moving on...', ['app' => 'scss_debug']);
 					return $this->injectCssVariablesIfAny();
 				}
-				$this->logger->debug('SCSSCacher: scss cache file locked for '.$lockKey, ['app' => 'core']);
+				$this->logger->debug('SCSSCacher: scss cache file locked for '.$lockKey, ['app' => 'scss_debug']);
 				sleep(1);
 				$retry++;
 			}
-			$this->logger->debug('SCSSCacher: Giving up scss caching for '.$lockKey, ['app' => 'core']);
+			$this->logger->debug('SCSSCacher: Giving up scss caching for '.$lockKey, ['app' => 'scss_debug']);
 			return false;
 		}
 
+		$this->logger->debug('SCSSCacher: Lock acquired for '.$lockKey, ['app' => 'scss_debug']);
 		try {
 			$cached = $this->cache($path, $fileNameCSS, $fileNameSCSS, $folder, $webDir);
 		} catch (\Exception $e) {
@@ -187,6 +189,7 @@ class SCSSCacher {
 
 		// Cleaning lock
 		$this->lockingCache->remove($lockKey);
+		$this->logger->debug('SCSSCacher: Lock removed for '.$lockKey, ['app' => 'scss_debug']);
 
 		// Inject icons vars css if any
 		if ($this->iconsCacher->getCachedCSS() && $this->iconsCacher->getCachedCSS()->getSize() > 0) {
@@ -224,6 +227,7 @@ class SCSSCacher {
 				return true;
 			}
 		}
+		$this->logger->error("SCSSCacher::isCached isCachedCache is expired or unset", ['app' => 'scss_debug']);
 
 		// Creating file cache if none for further checks
 		try {
@@ -249,16 +253,19 @@ class SCSSCacher {
 
 				foreach ((array) $deps as $file => $mtime) {
 					if (!file_exists($file) || filemtime($file) > $mtime) {
+						$this->logger->error("SCSSCacher::isCached $fileNameCSS is not considered as cached due to deps file $file", ['app' => 'scss_debug']);
 						return false;
 					}
 				}
 
+				// It would probably make sense to adjust this timeout to something higher and see if that has some effect then
 				$this->isCachedCache->set($key, $this->timeFactory->getTime() + 5 * 60);
 				return true;
 			}
-
+			$this->logger->error("SCSSCacher::isCached $fileNameCSS is not considered as cached cacheValue: $cacheValue", ['app' => 'scss_debug']);
 			return false;
 		} catch (NotFoundException $e) {
+			$this->logger->logException($e, ['app' => 'scss_debug']);
 			return false;
 		}
 	}
@@ -270,6 +277,7 @@ class SCSSCacher {
 	private function variablesChanged(): bool {
 		$injectedVariables = $this->getInjectedVariables();
 		if ($this->config->getAppValue('core', 'theming.variables') !== md5($injectedVariables)) {
+			$this->logger->error('SCSSCacher::variablesChanged storedVariables: ' . json_encode($this->config->getAppValue('core', 'theming.variables')) . ' currentInjectedVariables: ' . json_encode($injectedVariables), ['app' => 'scss_debug']);
 			$this->config->setAppValue('core', 'theming.variables', md5($injectedVariables));
 			$this->resetCache();
 			return true;
@@ -328,7 +336,7 @@ class SCSSCacher {
 				'@import "functions.scss";' .
 				'@import "' . $fileNameSCSS . '";');
 		} catch (ParserException $e) {
-			$this->logger->logException($e, ['app' => 'core']);
+			$this->logger->logException($e, ['app' => 'scss_debug']);
 
 			return false;
 		}
@@ -350,7 +358,7 @@ class SCSSCacher {
 			$depFile->putContent($deps);
 			$this->depsCache->set($folder->getName() . '-' . $depFileName, $deps);
 			$gzipFile->putContent(gzencode($data, 9));
-			$this->logger->debug('SCSSCacher: ' . $webDir . '/' . $fileNameSCSS . ' compiled and successfully cached', ['app' => 'core']);
+			$this->logger->debug('SCSSCacher: ' . $webDir . '/' . $fileNameSCSS . ' compiled and successfully cached', ['app' => 'scss_debug']);
 
 			return true;
 		} catch (NotPermittedException $e) {
@@ -365,9 +373,12 @@ class SCSSCacher {
 	 * We need to regenerate all files when variables change
 	 */
 	public function resetCache() {
+		$this->logger->error('SCSSCacher::resetCache', ['app' => 'scss_debug']);
 		if (!$this->lockingCache->add('resetCache', 'locked!', 120)) {
+			$this->logger->error('SCSSCacher::resetCache Locked', ['app' => 'scss_debug']);
 			return;
 		}
+		$this->logger->error('SCSSCacher::resetCache Lock acquired', ['app' => 'scss_debug']);
 		$this->injectedVariables = null;
 
 		// do not clear locks
@@ -386,6 +397,8 @@ class SCSSCacher {
 		}
 		$this->logger->debug('SCSSCacher: css cache cleared!');
 		$this->lockingCache->remove('resetCache');
+		$this->logger->error('SCSSCacher::resetCache Locking removed', ['app' => 'scss_debug']);
+
 	}
 
 	/**
@@ -406,7 +419,7 @@ class SCSSCacher {
 			$scss->compile($variables);
 			$this->injectedVariables = $variables;
 		} catch (ParserException $e) {
-			$this->logger->logException($e, ['app' => 'core']);
+			$this->logger->logException($e, ['app' => 'scss_debug']);
 		}
 
 		return $variables;