chore: remove logs for secret and change invalid token query logic (#…

…6907)

## About the changes
What's going on is the following:
1. When a token is not found in the token's cache we try to find it in
the db
2. To prevent a denial of service attack using invalid tokens, we cache
the invalid tokens so we don't hit the db.
3. The issue is that we stored this token in the cache regardless we
found it or not. And if the token was valid the first time we'd add a
timestamp to avoid querying this token again the next time.
4. The next iteration the token should be in the cache:
https://github.com/Unleash/unleash/blob/54383a6578c221bdacdd1b9f14a108a1eb256e7c/src/lib/services/api-token-service.ts#L162
but for some reason it is not and therefore we have to make a query. But
this is where the query prevention mechanism kicks in because it finds
the token in the cache and kicks us out. This PR fixes this by only
storing in the cache for misses if not found:
https://github.com/Unleash/unleash/blob/54383a6578c221bdacdd1b9f14a108a1eb256e7c/src/lib/services/api-token-service.ts#L164-L165

The token was added to the cache because we were not checking if it had
expired. Now we added a check and we also have a log for expired tokens.
Some improvement opportunities:
- I don't think we display that a token has expired in the UI which
probably led to this issue
- When a token expired we don't display a specific error message or
error response saying that which is not very helpful for users

src/lib/middleware/api-token-middleware.ts

@@ -78,9 +78,7 @@ const apiAccessMiddleware = (
                     // If we're here, we know that api token middleware was enabled, otherwise we'd returned a no-op middleware
                     // We explicitly only protect client and proxy apis, since admin apis are protected by our permission checker
                     // Reject with 401
-                    logger.warn(
-                        `Client api request without valid token (${apiToken}), rejecting`,
-                    );
+                    logger.warn(`No user found for token, rejecting`);
                     res.status(401).send({
                         message: NO_TOKEN_WHERE_TOKEN_WAS_REQUIRED,
                     });

src/lib/services/api-token-service.test.ts

@@ -12,7 +12,7 @@ import {
     API_TOKEN_UPDATED,
     TEST_AUDIT_USER,
 } from '../types';
-import { addDays, minutesToMilliseconds } from 'date-fns';
+import { addDays, minutesToMilliseconds, subDays } from 'date-fns';
 import EventService from '../features/events/event-service';
 import FakeFeatureTagStore from '../../test/fixtures/fake-feature-tag-store';
 import { createFakeEventsService } from '../../lib/features';
@@ -261,4 +261,18 @@ describe('API token getTokenWithCache', () => {
         }
         expect(apiTokenStoreGet).toHaveBeenCalledTimes(2);
     });
+
+    test('should not return the token if it has expired and shoud perform only one db query', async () => {
+        const { apiTokenService, apiTokenStore } = setup();
+        const apiTokenStoreGet = jest.spyOn(apiTokenStore, 'get');
+
+        // valid token not present in cache but expired
+        apiTokenStore.insert({ ...token, expiresAt: subDays(new Date(), 1) });
+
+        for (let i = 0; i < 5; i++) {
+            const found = await apiTokenService.getTokenWithCache(token.secret);
+            expect(found).toBeUndefined();
+        }
+        expect(apiTokenStoreGet).toHaveBeenCalledTimes(1);
+    });
 });

src/lib/services/api-token-service.ts

@@ -145,36 +145,41 @@ export class ApiTokenService {
         }
 
         const nextAllowedQuery = this.queryAfter.get(secret) ?? 0;
-        this.logger.info(
-            `Token found in cache: ${Boolean(
-                token,
-            )}, next allowed query: ${nextAllowedQuery}`,
-        );
-        if (!token && isPast(nextAllowedQuery)) {
-            this.logger.info(
-                `Token not found in cache, querying database for token with secret: ${secret}`,
-            );
-            if (this.queryAfter.size > 1000) {
-                // establish a max limit for queryAfter size to prevent memory leak
+        if (!token) {
+            if (isPast(nextAllowedQuery)) {
+                this.logger.info(`Token not found in cache, querying database`);
+                if (this.queryAfter.size > 1000) {
+                    // establish a max limit for queryAfter size to prevent memory leak
+                    this.logger.info(
+                        'queryAfter size exceeded 1000, clearing cache',
+                    );
+                    this.queryAfter.clear();
+                }
+
+                const stopCacheTimer = this.timer('getTokenWithCache.query');
+                token = await this.store.get(secret);
+                if (token) {
+                    if (token?.expiresAt && isPast(token.expiresAt)) {
+                        this.logger.info('Token has expired');
+                        // prevent querying the same invalid secret multiple times. Expire after 5 minutes
+                        this.queryAfter.set(secret, addMinutes(new Date(), 5));
+                        token = undefined;
+                    } else {
+                        this.activeTokens.push(token);
+                    }
+                } else {
+                    // prevent querying the same invalid secret multiple times. Expire after 5 minutes
+                    this.queryAfter.set(secret, addMinutes(new Date(), 5));
+                }
+                stopCacheTimer();
+            } else {
                 this.logger.info(
-                    'queryAfter size exceeded 1000, clearing cache',
+                    `Not allowed to query this token until: ${this.queryAfter.get(
+                        secret,
+                    )}`,
                 );
-                this.queryAfter.clear();
-            }
-            // prevent querying the same invalid secret multiple times. Expire after 5 minutes
-            this.queryAfter.set(secret, addMinutes(new Date(), 5));
-            this.logger.info(
-                `Added ${secret} to queryAfter: ${this.queryAfter.get(secret)}`,
-            );
-
-            const stopCacheTimer = this.timer('getTokenWithCache.query');
-            token = await this.store.get(secret);
-            if (token) {
-                this.activeTokens.push(token);
             }
-            stopCacheTimer();
         }
-
         return token;
     }
 
@@ -213,7 +218,7 @@ export class ApiTokenService {
         secret: string,
     ): Promise<IApiUser | undefined> {
         const token = await this.getTokenWithCache(secret);
-        this.logger.info(`getUserForToken ${secret} found: ${token}`);
+        this.logger.info(`Found user? ${token ? 'yes' : 'no'}`);
         if (token) {
             this.lastSeenSecrets.add(token.secret);
             const apiUser: IApiUser = new ApiUser({