server: add jwk-refresh-log as configurable log type

PR-URL: https://github.com/hasura/graphql-engine-mono/pull/6705
GitOrigin-RevId: 1f6f45ce555cefc24836a2fc5363660e351fa13b

.circleci/test-server.sh

@@ -847,6 +847,66 @@ query-logs)
 	unset HASURA_GRAPHQL_ENABLED_LOG_TYPES
 	kill_hge_servers
 
+	# configurable jwk-refresh-log test
+	unset HASURA_GRAPHQL_AUTH_HOOK
+	unset HASURA_GRAPHQL_AUTH_HOOK_MODE
+	unset HASURA_GRAPHQL_JWT_SECRET
+
+	echo -e "\n$(time_elapsed): <########## TEST GRAPHQL-ENGINE WITH JWK REFRESH LOG ########> \n"
+
+	export JWK_SERVER_URL='http://localhost:5001'
+
+	# Start the JWK server.
+	# There is a fixture to do this, but when running in this fashion, we need to
+	# start the JWK server first so the HGE server can communicate with it.
+	python3 jwk_server.py >"$OUTPUT_FOLDER/configurable_log.log" 2>&1 &
+	JWKS_PID=$!
+	wait_for_port 5001
+
+	echo "Test: jwk-refresh-log type logs present if it is enabled"
+	export HASURA_GRAPHQL_JWT_SECRET="{\"jwk_url\": \"${JWK_SERVER_URL}/jwk-cache-control?no-cache=true\"}"
+	export HASURA_GRAPHQL_ENABLED_LOG_TYPES=" startup,http-log,webhook-log,websocket-log,query-log, jwk-refresh-log"
+
+	#run_hge_with_args serve
+	# we are doing this instead of calling run_hge_with_args, because we want to save in a custom log file
+	set -x
+	export LOGGING_TEST_LOGFILE_PATH="$OUTPUT_FOLDER/graphql-engine-verbose-logging.log"
+	"$GRAPHQL_ENGINE" serve >"$LOGGING_TEST_LOGFILE_PATH" 2>&1 &
+	HGE_PIDS=("${HGE_PIDS[@]}" $!)
+	set +x
+
+	wait_for_port 8080
+
+	pytest "${PYTEST_COMMON_ARGS[@]}" \
+		--test-logging \
+		test_logging.py::TestConfiguragbleLogs
+
+	kill_hge_servers
+	unset HASURA_GRAPHQL_ENABLED_LOG_TYPES
+
+	echo "Test: no jwk-refresh-log type logs if it is not enabled"
+	export HASURA_GRAPHQL_ENABLED_LOG_TYPES=" startup,http-log,webhook-log,websocket-log,query-log"
+	#run_hge_with_args serve
+	# we are doing this instead of calling run_hge_with_args, because we want to save in a custom log file
+	set -x
+	export LOGGING_TEST_LOGFILE_PATH="$OUTPUT_FOLDER/graphql-engine-verbose-logging.log"
+	"$GRAPHQL_ENGINE" serve >"$LOGGING_TEST_LOGFILE_PATH" 2>&1 &
+	HGE_PIDS=("${HGE_PIDS[@]}" $!)
+	set +x
+
+	wait_for_port 8080
+
+	pytest "${PYTEST_COMMON_ARGS[@]}" \
+		--test-logging \
+		test_logging.py::TestConfiguragbleLogs
+
+	kill_hge_servers
+	unset HASURA_GRAPHQL_ENABLED_LOG_TYPES
+	unset HASURA_GRAPHQL_JWT_SECRET
+	unset JWK_SERVER_URL
+
+	kill $JWKS_PID
+
 	# end verbose logging tests
 	;;
 

docs/docs/deployment/logging.mdx

@@ -46,13 +46,14 @@ Default enabled log-types are: `startup, http-log, webhook-log, websocket-log`
 
 All the log-types that can be enabled/disabled are:
 
-| Log type        | Description                                                                                                                                                                                                                       | Log Level          |
+| Log type             | Description                                                                                                                                                                                                                       | Log Level          |
-| --------------- | --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | ------------------ |
+| -------------------- | --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- | ------------------ |
-| `startup`       | Information that is logged during startup                                                                                                                                                                                         | `info`             |
+| `startup`            | Information that is logged during startup                                                                                                                                                                                         | `info`             |
-| `query-log`     | Logs: the entire GraphQL query with variables, generated SQL statements (only for database queries, not for mutations/subscriptions or remote schema and action queries), the operation name (if provided in the GraphQL request) | `info`             |
+| `query-log`          | Logs: the entire GraphQL query with variables, generated SQL statements (only for database queries, not for mutations/subscriptions or remote schema and action queries), the operation name (if provided in the GraphQL request) | `info`             |
-| `http-log`      | Http access and error logs at the webserver layer (handling GraphQL and metadata requests)                                                                                                                                        | `info` and `error` |
+| `http-log`           | Http access and error logs at the webserver layer (handling GraphQL and metadata requests)                                                                                                                                        | `info` and `error` |
-| `websocket-log` | Websocket events and error logs at the websocket server layer (handling GraphQL requests)                                                                                                                                         | `info` and `error` |
+| `websocket-log`      | Websocket events and error logs at the websocket server layer (handling GraphQL requests)                                                                                                                                         | `info` and `error` |
-| `webhook-log`   | Logs responses and errors from the authorization webhook (if setup)                                                                                                                                                               | `info` and `error` |
+| `webhook-log`        | Logs responses and errors from the authorization webhook (if setup)                                                                                                                                                               | `info` and `error` |
+| `jwk-refresh-log`    | Logs information and errors about periodic refreshing of JWK                                                                                                                                                                      | `info` and `error` |
 
 Configurable log-types
 
@@ -62,7 +63,6 @@ Apart from the above, there are other internal log-types which cannot be configu
 |----------------------|-----------------------------------------------------------------------------------------------------|--------------------|
 | `pg-client`          | Logs from the postgres client library                                                               | `warn`             |
 | `metadata`           | Logs inconsistent metadata items                                                                    | `warn`             |
-| `jwk-refresh-log`    | Logs information and errors about periodic refreshing of JWK                                        | `info` and `error` |
 | `telemetry-log`      | Logs error (if any) while sending out telemetry data                                                | `info`             |
 | `event-trigger`      | Logs HTTP responses from the webhook, HTTP exceptions and internal errors                           | `info` and `error` |
 | `ws-server`          | Debug logs from the websocket server, mostly used internally for debugging                          | `debug`            |

server/src-lib/Hasura/Logging.hs

@@ -77,6 +77,7 @@ data instance EngineLogType Hasura
   | ELTLivequeryPollerLog
   | ELTActionHandler
   | ELTDataConnectorLog
+  | ELTJwkRefreshLog
   | -- internal log types
     ELTInternal !InternalLogTypes
   deriving (Show, Eq, Generic)
@@ -93,6 +94,7 @@ instance Witch.From (EngineLogType Hasura) Text where
     ELTLivequeryPollerLog -> "livequery-poller-log"
     ELTActionHandler -> "action-handler-log"
     ELTDataConnectorLog -> "data-connector-log"
+    ELTJwkRefreshLog -> "jwk-refresh-log"
     ELTInternal t -> Witch.from t
 
 instance J.ToJSON (EngineLogType Hasura) where
@@ -122,7 +124,6 @@ data InternalLogTypes
   | ILTPgClient
   | -- | log type for logging metadata related actions; currently used in logging inconsistent metadata
     ILTMetadata
-  | ILTJwkRefreshLog
   | ILTTelemetry
   | ILTSchemaSync
   | ILTSourceCatalogMigration
@@ -138,7 +139,6 @@ instance Witch.From InternalLogTypes Text where
     ILTWsServer -> "ws-server"
     ILTPgClient -> "pg-client"
     ILTMetadata -> "metadata"
-    ILTJwkRefreshLog -> "jwk-refresh-log"
     ILTTelemetry -> "telemetry-log"
     ILTSchemaSync -> "schema-sync"
     ILTSourceCatalogMigration -> "source-catalog-migration"
@@ -176,7 +176,8 @@ userAllowedLogTypes =
     ELTQueryLog,
     ELTLivequeryPollerLog,
     ELTActionHandler,
-    ELTDataConnectorLog
+    ELTDataConnectorLog,
+    ELTJwkRefreshLog
   ]
 
 data LogLevel

server/src-lib/Hasura/Server/Auth/JWT/Logging.hs

@@ -10,7 +10,6 @@ import Hasura.HTTP
 import Hasura.Logging
   ( EngineLogType (..),
     Hasura,
-    InternalLogTypes (..),
     LogLevel (..),
     ToEngineLog (..),
   )
@@ -62,4 +61,4 @@ instance ToJSON JwkRefreshLog where
 
 instance ToEngineLog JwkRefreshLog Hasura where
   toEngineLog jwkRefreshLog =
-    (jrlLogLevel jwkRefreshLog, ELTInternal ILTJwkRefreshLog, toJSON jwkRefreshLog)
+    (jrlLogLevel jwkRefreshLog, ELTJwkRefreshLog, toJSON jwkRefreshLog)

server/tests-py/test_logging.py

@@ -205,8 +205,7 @@ class TestLogging():
         # By default, 'raw_query' field is ignored for metadata queries. To allow
         # logging this field use the flag HASURA_GRAPHQL_ENABLE_METADATA_QUERY_LOGGING
         assert http_logs[0]['detail']['operation'].get('raw_query') is None
-
+    
-
 class TestWebsocketLogging():
     """
     Test logs emitted on websocket transport
@@ -278,3 +277,45 @@ class TestWebsocketLogging():
         onelog = ws_logs[0]['detail']
         assert 'operation_id' in onelog['metadata']
         assert 'operation_name' in onelog['metadata']
+
+class TestConfiguragbleLogs():
+    dir = 'queries/logging'
+    success_query = {'query': 'query { hello {code name} }'}
+
+    def _teardown(self, hge_ctx):
+        hge_ctx.v1q_f(self.dir + '/teardown.yaml')
+
+    @pytest.fixture(autouse=True)
+    def transact(self, hge_ctx):
+        # setup some tables
+        hge_ctx.v1q_f(self.dir + '/setup.yaml')
+
+        try:
+            # make a successful query
+            q = self.success_query
+            headers = {'x-request-id': 'successful-query-log-test'}
+            if hge_ctx.hge_key:
+                headers['x-hasura-admin-secret'] = hge_ctx.hge_key
+            resp = hge_ctx.http.post(hge_ctx.hge_url + '/v1/graphql', json=q,
+                                     headers=headers)
+            assert resp.status_code == 200 and 'data' in resp.json()
+
+            # gather and parse the logs now
+            self.logs = parse_logs()
+            # sometimes the log might take time to buffer
+            time.sleep(2)
+            yield
+        finally:
+            self._teardown(hge_ctx)
+
+    @pytest.mark.jwk_path('/jwk-cache-control?no-cache=true')
+    def test_jwk_refresh_log(self, hge_ctx):
+        def _get_jwk_refresh_log(x):
+            return x['type'] == 'jwk-refresh-log'
+        jwk_refresh_logs = list(filter(_get_jwk_refresh_log, self.logs))
+        env_var = os.getenv('HASURA_GRAPHQL_ENABLED_LOG_TYPES')
+        if env_var:
+            if "jwk-refresh-log" in env_var:
+                assert len(jwk_refresh_logs) > 0
+            else:
+                assert len(jwk_refresh_logs) == 0