From 428b0ee3823d7825c189fd6ab52ff31f6adb4a97 Mon Sep 17 00:00:00 2001 From: Eleazar Resendez Date: Thu, 12 Dec 2024 10:32:24 -0600 Subject: [PATCH 1/5] Enhance ETag middleware to log dynamic endpoint detection - Introduced logging for highly dynamic endpoints by tracking ETag history for each endpoint. - Implemented a mechanism to limit the number of tracked ETags and log when all tracked ETags are unique. - Updated documentation to reflect the new logging feature and its implications for performance optimization. --- .../Http/Middleware/Etag/HandleEtag.php | 47 +++++++++++++++++++ docs/etag-caching.md | 19 ++++++++ 2 files changed, 66 insertions(+) diff --git a/ProcessMaker/Http/Middleware/Etag/HandleEtag.php b/ProcessMaker/Http/Middleware/Etag/HandleEtag.php index fe51c6d35e..bbfa8a2e69 100644 --- a/ProcessMaker/Http/Middleware/Etag/HandleEtag.php +++ b/ProcessMaker/Http/Middleware/Etag/HandleEtag.php @@ -4,6 +4,8 @@ use Closure; use Illuminate\Http\Request; +use Illuminate\Support\Facades\Cache; +use Illuminate\Support\Facades\Log; use ProcessMaker\Http\Resources\Caching\EtagManager; use Symfony\Component\HttpFoundation\Response; @@ -11,6 +13,10 @@ class HandleEtag { public string $middleware = 'etag'; + private const ETAG_HISTORY_LIMIT = 10; // Limit of ETags to track per endpoint. + + private const CACHE_EXPIRATION_MINUTES = 30; // Cache expiration time in minutes. + /** * Handle an incoming request. */ @@ -48,6 +54,9 @@ public function handle(Request $request, Closure $next): Response } } + // Detect if the ETag changes frequently for dynamic responses. + $this->logEtagChanges($request, $etag); + return $response; } @@ -113,4 +122,42 @@ private function stripWeakTags(string $etag): string { return str_replace('W/', '', $etag); } + + /** + * Log ETag changes to detect highly dynamic responses. + */ + private function logEtagChanges(Request $request, ?string $etag): void + { + if (!$etag) { + return; + } + + // Retrieve the history of ETags for this endpoint. + $url = $request->fullUrl(); + $cacheKey = 'etag_history:' . md5($url); + $etagHistory = Cache::get($cacheKey, []); + + // If the ETag is already in the history, it is not considered dynamic. + if (in_array($etag, $etagHistory, true)) { + return; + } + + // Add the new ETag to the history. + $etagHistory[] = $etag; + + // Keep the history limited to the last n ETags. + if (count($etagHistory) > self::ETAG_HISTORY_LIMIT) { + array_shift($etagHistory); // Remove the oldest ETag. + } + + // Save the updated history in the cache, valid for 30 minutes. + Cache::put($cacheKey, $etagHistory, now()->addMinutes(self::CACHE_EXPIRATION_MINUTES)); + + // If the history is full and all ETags are unique, log this as a highly dynamic endpoint. + if (count(array_unique($etagHistory)) === self::ETAG_HISTORY_LIMIT) { + Log::info('ETag Dynamic endpoint detected', [ + 'url' => $url, + ]); + } + } } diff --git a/docs/etag-caching.md b/docs/etag-caching.md index a3aaa5498d..3d352864d6 100644 --- a/docs/etag-caching.md +++ b/docs/etag-caching.md @@ -100,6 +100,25 @@ In this example: - Middleware generates the ETag based on the last update of the `processes` table. - If the client has the corresponding ETag, the server responds with `304 Not Modified` and does not execute the controller logic. +## Logs + +This middleware detects **highly dynamic endpoints** by tracking the history of ETags generated for each endpoint. It helps identify endpoints where ETags are consistently different, indicating dynamic responses that may require further optimization. + +1. Tracks the last **N ETags** (default: 10) for each endpoint using Laravel's cache. +2. Logs endpoints as "highly dynamic" if all tracked ETags are unique. +3. Efficient caching and memory usage to minimize performance overhead. + +### Example Logs + +When an endpoint is identified as highly dynamic, the following log is generated: + +``` +ETag Dynamic endpoint detected: +{ + "url": "https://example.com/api/resource", +} +``` + ## Testing ### Unit Tests From f28fcb54ff40835b94ff37c568227afa9874dd6b Mon Sep 17 00:00:00 2001 From: Eleazar Resendez Date: Mon, 16 Dec 2024 11:10:16 -0600 Subject: [PATCH 2/5] Add configuration support for ETag logging and caching - Integrated `config/etag.php` for dynamic configuration of ETag functionality. - Added `enabled` and `log_dynamic_endpoints` flags to control feature behavior. This update improves flexibility and allows disabling ETag processing entirely when `enabled` is set to false. --- .../Http/Middleware/Etag/HandleEtag.php | 20 +++++--- config/etag.php | 47 +++++++++++++++++++ docs/etag-caching.md | 14 ++++-- 3 files changed, 71 insertions(+), 10 deletions(-) create mode 100644 config/etag.php diff --git a/ProcessMaker/Http/Middleware/Etag/HandleEtag.php b/ProcessMaker/Http/Middleware/Etag/HandleEtag.php index bbfa8a2e69..5425e0e6da 100644 --- a/ProcessMaker/Http/Middleware/Etag/HandleEtag.php +++ b/ProcessMaker/Http/Middleware/Etag/HandleEtag.php @@ -13,15 +13,15 @@ class HandleEtag { public string $middleware = 'etag'; - private const ETAG_HISTORY_LIMIT = 10; // Limit of ETags to track per endpoint. - - private const CACHE_EXPIRATION_MINUTES = 30; // Cache expiration time in minutes. - /** * Handle an incoming request. */ public function handle(Request $request, Closure $next): Response { + if (!config('etag.enabled')) { + return $next($request); + } + // Process only GET and HEAD methods. if (!$request->isMethod('GET') && !$request->isMethod('HEAD')) { return $next($request); @@ -128,6 +128,10 @@ private function stripWeakTags(string $etag): string */ private function logEtagChanges(Request $request, ?string $etag): void { + if (!config('etag.enabled') || !config('etag.log_dynamic_endpoints')) { + return; + } + if (!$etag) { return; } @@ -146,15 +150,17 @@ private function logEtagChanges(Request $request, ?string $etag): void $etagHistory[] = $etag; // Keep the history limited to the last n ETags. - if (count($etagHistory) > self::ETAG_HISTORY_LIMIT) { + $etagHistoryLimit = config('etag.history_limit', 10); + if (count($etagHistory) > $etagHistoryLimit) { array_shift($etagHistory); // Remove the oldest ETag. } // Save the updated history in the cache, valid for 30 minutes. - Cache::put($cacheKey, $etagHistory, now()->addMinutes(self::CACHE_EXPIRATION_MINUTES)); + $cacheExpirationMinute = config('etag.history_cache_expiration'); + Cache::put($cacheKey, $etagHistory, now()->addMinutes($cacheExpirationMinute)); // If the history is full and all ETags are unique, log this as a highly dynamic endpoint. - if (count(array_unique($etagHistory)) === self::ETAG_HISTORY_LIMIT) { + if (count(array_unique($etagHistory)) === $etagHistoryLimit) { Log::info('ETag Dynamic endpoint detected', [ 'url' => $url, ]); diff --git a/config/etag.php b/config/etag.php new file mode 100644 index 0000000000..b4e016f8db --- /dev/null +++ b/config/etag.php @@ -0,0 +1,47 @@ + env('ETAG_ENABLED', true), + + /* + |-------------------------------------------------------------------------- + | Log Dynamic Endpoints + |-------------------------------------------------------------------------- + | + | Enable or disable logging when an endpoint is detected as dynamic. + | If set to false, no logs will be recorded for dynamic endpoints. + | + */ + 'log_dynamic_endpoints' => env('ETAG_LOG_DYNAMIC_ENDPOINTS', false), + + /* + |-------------------------------------------------------------------------- + | ETag History Limit + |-------------------------------------------------------------------------- + | + | The maximum number of ETags to track per endpoint. If the number of + | unique ETags exceeds this limit, the oldest ETag will be removed. + | + */ + 'history_limit' => env('ETAG_HISTORY_LIMIT', 10), + + /* + |-------------------------------------------------------------------------- + | History Cache Expiration Time + |-------------------------------------------------------------------------- + | + | The duration (in minutes) for which the ETag history should be stored + | in the cache. Adjust this based on your caching strategy. + | + */ + 'history_cache_expiration' => env('ETAG_HISTORY_CACHE_EXPIRATION_MINUTES', 30), +]; diff --git a/docs/etag-caching.md b/docs/etag-caching.md index 3d352864d6..4ee52a2549 100644 --- a/docs/etag-caching.md +++ b/docs/etag-caching.md @@ -100,6 +100,16 @@ In this example: - Middleware generates the ETag based on the last update of the `processes` table. - If the client has the corresponding ETag, the server responds with `304 Not Modified` and does not execute the controller logic. +## Config file + +The ETag functionality is managed through the `config/etag.php` file, which centralizes all related settings. This configuration file allows you to enable or disable ETag logging and caching, as well as customize key parameters such as history limits and cache expiration times. + +### Key Options +- **`enabled`**: Determines whether the ETag functionality is active. If set to `false`, all ETag-related processing is skipped. +- **`log_dynamic_endpoints`**: Controls whether dynamic endpoints are logged. When disabled, no cache processing occurs. +- **`history_limit`**: Specifies the maximum number of ETags to track per endpoint. +- **`cache_expiration`**: Sets the duration (in minutes) for which the ETag history is cached. + ## Logs This middleware detects **highly dynamic endpoints** by tracking the history of ETags generated for each endpoint. It helps identify endpoints where ETags are consistently different, indicating dynamic responses that may require further optimization. @@ -154,9 +164,7 @@ This implementation leverages ETags to optimize `GET` requests in the API, reduc 1. **ETag Versioning with Cache**: - Store ETag versions in cache to avoid database queries. - Enable manual invalidation via model events. -2. **Configuration File**: - - Add a `config/etag.php` for global middleware control. -3. **Metrics Collection**: +2. **Metrics Collection**: - Monitor request duration, `304` response percentage and bandwidth savings. This solution is well-suited for global optimizations and specific dynamic routes. From 4e7afdc75c7501c004da89e3608398d4ad29acc3 Mon Sep 17 00:00:00 2001 From: Eleazar Resendez Date: Tue, 17 Dec 2024 08:25:57 -0600 Subject: [PATCH 3/5] Add ETag response time comparison for 200 vs 304 - Added custom Trend metrics to measure and compare durations of 200 OK and 304 Not Modified responses - Validates that 304 responses are faster using If-None-Match header - Improved test clarity by focusing on ETag performance under load --- tests/k6/etag/performance-test.js | 48 +++++++++++++++++++++++++++++++ 1 file changed, 48 insertions(+) create mode 100644 tests/k6/etag/performance-test.js diff --git a/tests/k6/etag/performance-test.js b/tests/k6/etag/performance-test.js new file mode 100644 index 0000000000..21f40cac4a --- /dev/null +++ b/tests/k6/etag/performance-test.js @@ -0,0 +1,48 @@ +import http from 'k6/http'; +import { check, sleep, group } from 'k6'; +import { Trend } from 'k6/metrics'; + +// Custom metrics to track request durations. +let duration200 = new Trend('duration_200'); +let duration304 = new Trend('duration_304'); + +export let options = { + stages: [ + { duration: '10s', target: 10 }, + { duration: '20s', target: 50 }, + { duration: '10s', target: 0 }, + ], +}; + +export default function () { + const baseUrl = 'https://processmaker.test/api/1.0/start_processes?page=1&per_page=15&filter=&order_by=category.name%2Cname&order_direction=asc%2Casc&include=events%2Ccategories&without_event_definitions=true'; + const token = 'fake-jwt'; // Replace with your actual token + const headers = { Authorization: `Bearer ${token}` }; + + group('ETag Performance', () => { + // Add the duration of the 200 response to the custom metric. + let res = http.get(baseUrl, { headers }); + duration200.add(res.timings.duration); + check(res, { + 'status is 200': (r) => r.status === 200, + }); + + // Use ETag with If-None-Match header to validate 304 response. + const etag = res.headers.Etag; + if (etag) { + const conditionalHeaders = { + ...headers, + 'If-None-Match': etag, + }; + + // Add the duration of the 304 response to the custom metric + let conditionalRes = http.get(baseUrl, { headers: conditionalHeaders }); + duration304.add(conditionalRes.timings.duration); + check(conditionalRes, { + 'status is 304': (r) => r.status === 304, + }); + } + + sleep(1); + }); +} \ No newline at end of file From d590373592d4096bb8dcc2e18555cb753b2e9ad1 Mon Sep 17 00:00:00 2001 From: Eleazar Resendez Date: Tue, 17 Dec 2024 08:33:43 -0600 Subject: [PATCH 4/5] Add ETag history tracking to detect dynamic endpoints - Implemented tracking of ETag values for specified endpoints - Added logic to identify dynamic endpoints when ETag history shows diff values --- tests/k6/etag/detect-dynamic-endpoints.js | 61 +++++++++++++++++++++++ 1 file changed, 61 insertions(+) create mode 100644 tests/k6/etag/detect-dynamic-endpoints.js diff --git a/tests/k6/etag/detect-dynamic-endpoints.js b/tests/k6/etag/detect-dynamic-endpoints.js new file mode 100644 index 0000000000..1b48ff5191 --- /dev/null +++ b/tests/k6/etag/detect-dynamic-endpoints.js @@ -0,0 +1,61 @@ +import http from 'k6/http'; + +export let options = { + vus: 1, + iterations: 5, // n iterations per URL. +}; + +const token = 'fake-jwt'; +const endpoints = [ + 'https://processmaker.test/api/1.0/requests?page=1&per_page=15&include=process%2Cparticipants%2CactiveTasks%2Cdata&pmql=%28requester%20%3D%20%22admin%22%29&filter=&order_by=id&order_direction=DESC&advanced_filter=%5B%7B%22subject%22%3A%7B%22type%22%3A%22Status%22%7D%2C%22operator%22%3A%22%3D%22%2C%22value%22%3A%22In%20Progress%22%7D%5D' +]; + +// Object to track ETag history for each endpoint. +const etagHistory = {}; + +// Limit to determine when an endpoint is considered dynamic. +const ETAG_HISTORY_LIMIT = 5; + +export default function () { + const headers = { + Authorization: `Bearer ${token}`, + }; + + endpoints.forEach((url) => { + const res1 = http.get(url, { headers }); + const etag = res1.headers['Etag']; + + // If no ETag is present, log a warning and skip further processing. + if (!etag) { + console.log(`No ETag found for ${url}`); + return; + } + + // Log the ETag value for debugging. + console.log(`ETag: ${etag}`); + + // Initialize the ETag history for this endpoint if not already present. + if (!etagHistory[url]) { + etagHistory[url] = []; + } + + // Add the ETag to the history if it is unique. + if (!etagHistory[url].includes(etag)) { + etagHistory[url].push(etag); + } + + // Keep the history limited to the last N ETags. + if (etagHistory[url].length > ETAG_HISTORY_LIMIT) { + etagHistory[url].shift(); // Remove the oldest ETag + } + + // Check if the endpoint is dynamic. + // If the history is full and all ETags are unique, the endpoint is considered dynamic. + if ( + etagHistory[url].length === ETAG_HISTORY_LIMIT && + new Set(etagHistory[url]).size === ETAG_HISTORY_LIMIT + ) { + console.log(`Dynamic endpoint detected: ${url}`); + } + }); +} \ No newline at end of file From 8086a78951f8e76d761364328d5d680853c4017d Mon Sep 17 00:00:00 2001 From: Eleazar Resendez Date: Tue, 17 Dec 2024 09:37:44 -0600 Subject: [PATCH 5/5] Add long-duration test to validate ETag stability under sustained load --- tests/k6/etag/config.js | 11 ++++++ tests/k6/etag/detect-dynamic-endpoints.js | 8 ++--- tests/k6/etag/long-duration-test.js | 43 +++++++++++++++++++++++ tests/k6/etag/performance-test.js | 8 ++--- 4 files changed, 59 insertions(+), 11 deletions(-) create mode 100644 tests/k6/etag/config.js create mode 100644 tests/k6/etag/long-duration-test.js diff --git a/tests/k6/etag/config.js b/tests/k6/etag/config.js new file mode 100644 index 0000000000..843d73bcc4 --- /dev/null +++ b/tests/k6/etag/config.js @@ -0,0 +1,11 @@ +export const config = { + token: 'FAKE_JWT', // Replace with a valid token. + endpoints: { + startProcesses: 'https://processmaker.test/api/1.0/start_processes?page=1&per_page=15&filter=&order_by=category.name%2Cname&order_direction=asc%2Casc&include=events%2Ccategories&without_event_definitions=true', + }, +}; + +export const headers = { + 'Content-Type': 'application/json', + Authorization: `Bearer ${config.token}`, +}; \ No newline at end of file diff --git a/tests/k6/etag/detect-dynamic-endpoints.js b/tests/k6/etag/detect-dynamic-endpoints.js index 1b48ff5191..091a3722a1 100644 --- a/tests/k6/etag/detect-dynamic-endpoints.js +++ b/tests/k6/etag/detect-dynamic-endpoints.js @@ -1,13 +1,13 @@ import http from 'k6/http'; +import { config, headers } from './config.js'; export let options = { vus: 1, iterations: 5, // n iterations per URL. }; -const token = 'fake-jwt'; const endpoints = [ - 'https://processmaker.test/api/1.0/requests?page=1&per_page=15&include=process%2Cparticipants%2CactiveTasks%2Cdata&pmql=%28requester%20%3D%20%22admin%22%29&filter=&order_by=id&order_direction=DESC&advanced_filter=%5B%7B%22subject%22%3A%7B%22type%22%3A%22Status%22%7D%2C%22operator%22%3A%22%3D%22%2C%22value%22%3A%22In%20Progress%22%7D%5D' + config.endpoints.startProcesses, ]; // Object to track ETag history for each endpoint. @@ -17,10 +17,6 @@ const etagHistory = {}; const ETAG_HISTORY_LIMIT = 5; export default function () { - const headers = { - Authorization: `Bearer ${token}`, - }; - endpoints.forEach((url) => { const res1 = http.get(url, { headers }); const etag = res1.headers['Etag']; diff --git a/tests/k6/etag/long-duration-test.js b/tests/k6/etag/long-duration-test.js new file mode 100644 index 0000000000..5ed1651568 --- /dev/null +++ b/tests/k6/etag/long-duration-test.js @@ -0,0 +1,43 @@ +import http from 'k6/http'; +import { check, sleep } from 'k6'; +import { Trend } from 'k6/metrics'; +import { config, headers } from './config.js'; + +// Metrics to track response durations. +let duration200 = new Trend('duration_200'); +let duration304 = new Trend('duration_304'); + +export let options = { + stages: [ + { duration: '5m', target: 50 }, // Hold 50 VUs for 5 minutes. + ], + thresholds: { + http_req_duration: ['p(95)<1000'], // 95% of requests should respond in < 1s. + duration_200: ['avg<800'], // Ensure 200 OK average duration is < 800ms. + duration_304: ['avg<400'], // Ensure 304 Not Modified avg duration is < 400ms. + }, +}; + +export default function () { + const url = config.endpoints.startProcesses; + let res = http.get(url, { headers }); + duration200.add(res.timings.duration); + check(res, { + 'status is 200': (r) => r.status === 200, + 'ETag exists': (r) => !!r.headers.Etag, + }); + + const etag = res.headers.Etag; + if (etag) { + const conditionalHeaders = { ...headers, 'If-None-Match': etag }; + + let conditionalRes = http.get(url, { headers: conditionalHeaders }); + duration304.add(conditionalRes.timings.duration); + + check(conditionalRes, { + 'status is 304': (r) => r.status === 304, + }); + } + + sleep(1); +} \ No newline at end of file diff --git a/tests/k6/etag/performance-test.js b/tests/k6/etag/performance-test.js index 21f40cac4a..0805d98ceb 100644 --- a/tests/k6/etag/performance-test.js +++ b/tests/k6/etag/performance-test.js @@ -1,6 +1,7 @@ import http from 'k6/http'; import { check, sleep, group } from 'k6'; import { Trend } from 'k6/metrics'; +import { config, headers } from './config.js'; // Custom metrics to track request durations. let duration200 = new Trend('duration_200'); @@ -15,10 +16,7 @@ export let options = { }; export default function () { - const baseUrl = 'https://processmaker.test/api/1.0/start_processes?page=1&per_page=15&filter=&order_by=category.name%2Cname&order_direction=asc%2Casc&include=events%2Ccategories&without_event_definitions=true'; - const token = 'fake-jwt'; // Replace with your actual token - const headers = { Authorization: `Bearer ${token}` }; - + const baseUrl = config.endpoints.startProcesses; group('ETag Performance', () => { // Add the duration of the 200 response to the custom metric. let res = http.get(baseUrl, { headers }); @@ -42,7 +40,7 @@ export default function () { 'status is 304': (r) => r.status === 304, }); } - + sleep(1); }); } \ No newline at end of file