Finetune caching mechanism.

Graphql typically return Http 200 even when there are errors (unless the query can't be parsed). We don't want to cache errors which might resolve themselves. We check for errors in the response body before passing it back.
opentargets · Jan 11, 2022 · e2219ba · e2219ba
1 parent b6b9f2c
commit e2219ba
Show file tree

Hide file tree

Showing 4 changed files with 53 additions and 35 deletions.
diff --git a/.travis.yml b/.travis.yml
@@ -21,7 +21,7 @@ before_cache:
   - find $HOME/.sbt        -name "*.lock"               -print -delete
 script:
   - sbt ++$TRAVIS_SCALA_VERSION clean compile
-  - if [ "$TRAVIS_PULL_REQUEST" = "true" ]; then sbt ++${TRAVIS_SCALA_VERSION} scalafmtCheck; fi
+  - if [ "${TRAVIS_PULL_REQUEST}" = "true" ]; then sbt ++${TRAVIS_SCALA_VERSION} scalafmtCheck; fi
   - sbt ++$TRAVIS_SCALA_VERSION coverage "testOnly * -- -l test_configuration.IntegrationTestTag" coverageReport
   - sbt ++$TRAVIS_SCALA_VERSION dist
 deploy:

diff --git a/app/controllers/api/v4/graphql/GraphQLController.scala b/app/controllers/api/v4/graphql/GraphQLController.scala
@@ -1,5 +1,6 @@
 package controllers.api.v4.graphql
 
+import akka.stream.{ActorMaterializer, Materializer}
 import controllers.api.v4.graphql.QueryMetadataHeaders.{GQL_OP_HEADER, GQL_VAR_HEADER}
 import models.entities.TooComplexQueryError
 import models.entities.TooComplexQueryError._
@@ -23,6 +24,7 @@ case class GqlQuery(query: String, variables: JsObject, operation: Option[String
 @Singleton
 class GraphQLController @Inject()(implicit
                                   ec: ExecutionContext,
+                                  mat: Materializer,
                                   dbTables: Backend,
                                   cache: AsyncCacheApi,
                                   cc: ControllerComponents,
@@ -31,6 +33,7 @@ class GraphQLController @Inject()(implicit
     with Logging {
 
   private val non200CacheDuration = Duration(10, "seconds")
+
   def options: Action[AnyContent] = Action {
     NoContent
   }
@@ -57,25 +60,52 @@ class GraphQLController @Inject()(implicit
     if (variables.trim == "" || variables.trim == "null") Json.obj()
     else Json.parse(variables).as[JsObject]
 
+  private def responseContainsErrors(response: Result): Future[Boolean] =
+    response.body.consumeData
+      .map(_.utf8String)
+      .map(Json.parse)
+      .map { json =>
+        (json \ "errors").isDefined
+      }
+
   private def cachedQuery(gqlQuery: GqlQuery): Future[Result] = {
-    val fromCache: Future[Option[Result]] = cache.get[Result](gqlQuery.toString)
-    val cacheResult: Future[Result] = fromCache.flatMap {
-      case Some(result) => Future.successful(result)
-      case None =>
-        logger.debug(s"Cache miss on $gqlQuery")
-        val queryResult = executeQuery(gqlQuery)
-        queryResult.andThen {
-          case Success(s) =>
-            if (s.header.status == HttpStatus.SC_OK) {
-              logger.info(s"Caching 200 response on $gqlQuery")
-              cache.set(gqlQuery.toString, s)
-            } else {
-              logger.debug(s"Temporarily caching non-200 response on $gqlQuery")
-              cache.set(gqlQuery.toString, s, non200CacheDuration)
-            }
-        }
+    def cacheable(op: Option[String]): Boolean = !op.contains("IntrospectionQuery")
+
+    if (cacheable(gqlQuery.operation)) {
+      val fromCache: Future[Option[Result]] = cache.get[Result](gqlQuery.toString)
+      val cacheResult: Future[Result] = fromCache.flatMap {
+        case Some(result) => Future.successful(result)
+        case None =>
+          logger.debug(s"Cache miss on ${gqlQuery.operation}: ${gqlQuery.variables}")
+          val queryResult = executeQuery(gqlQuery)
+          queryResult.andThen {
+            case Success(s) =>
+              if (s.header.status == HttpStatus.SC_OK) {
+                /*
+                All GraphQL responses which pass basic validation return status code 200. If something went wrong a field
+                returned called 'errors'. If there were no errors, this field isn't present.
+                 */
+                responseContainsErrors(s).onComplete {
+                  case Success(hasErrors) =>
+                    if (hasErrors) {
+                      logger.info(s"Temporarily caching 200 response with errors")
+                      cache.set(gqlQuery.toString, s, non200CacheDuration)
+                    } else {
+                      logger.info(
+                        s"Caching 200 response on ${gqlQuery.operation}: ${gqlQuery.query.filter(_ >= ' ')}"
+                      )
+                      cache.set(gqlQuery.toString, s)
+                    }
+                  case Failure(exception) => logger.error(exception.getMessage)
+                }
+              }
+          }
+      }
+      cacheResult
+    } else {
+      executeQuery(gqlQuery)
     }
-    cacheResult
+
   }
 
   private def executeQuery(

diff --git a/conf/logback.xml b/conf/logback.xml
@@ -8,22 +8,12 @@
         </encoder>
     </appender>
 
-
     <appender name="ASYNCSTDOUT" class="ch.qos.logback.classic.AsyncAppender">
-        <appender-ref ref="STDOUT" />
-    </appender>
-
-    <appender name="FILEOUT" class="ch.qos.logback.core.FileAppender">
-        <!--file>${user.home}/opentargets-api-beta.log</file-->
-        <file>logs/opentargets-api-beta.log</file>
-        <append>false</append>
-        <encoder>
-            <pattern>%-5relative %-5level %logger{35} - %msg%n</pattern>
-        </encoder>
+        <appender-ref ref="STDOUT"/>
     </appender>
 
-    <logger name="play" level="DEBUG"/>
-    <logger name="application" level="DEBUG"/>
+    <logger name="play" level="INFO"/>
+    <logger name="application" level="INFO"/>
     <logger name="org.apache" level="WARN"/>
     <logger name="httpclient" level="WARN"/>
     <logger name="models" level="INFO"/>
@@ -44,8 +34,6 @@
 
     <root level="INFO">
         <appender-ref ref="ASYNCSTDOUT" />
-        <appender-ref ref="FILEOUT" />
-        <appender-ref ref="STDOUT" />
     </root>
 
     <shutdownHook class="ch.qos.logback.core.hook.DelayingShutdownHook"/>

diff --git a/production.xml b/production.xml
@@ -16,7 +16,7 @@
     <logger name="application" level="WARN"/>
     <logger name="org.apache" level="WARN"/>
     <logger name="httpclient" level="WARN"/>
-    <logger name="models" level="DEBUG"/>
+    <logger name="models" level="INFO"/>
     <logger name="controllers" level="INFO"/>
 
     <!-- Off these ones as they are annoying, and anyway we manage configuration ourselves -->
@@ -29,7 +29,7 @@
     <logger name="com.sksamuel.elastic4s.http.ResponseHandler" level="OFF"/>
     <logger name="akka" level="ERROR"/>
 
-    <root level="WARN">
+    <root level="INFO">
         <appender-ref ref="ASYNCSTDOUT"/>
     </root>