Fix URI Decode Logging Errors

.github/workflows/integration.yml

@@ -10,10 +10,11 @@ jobs:
   integration:
 
     runs-on: ubuntu-latest
+    timeout-minutes: 30
 
     strategy:
       matrix:
-        node-version: [16.x]
+        node-version: [18.x]
 
     steps:
     - uses: actions/checkout@v2
@@ -22,5 +23,7 @@ jobs:
       with:
         node-version: ${{ matrix.node-version }}
     - run: npm install
-    - run: npm run functionaltest
+    - name: Run functional tests
+      run: npm run functionaltest
+      timeout-minutes: 25
       continue-on-error: true

AutoCollection/HttpRequestParser.ts

@@ -249,17 +249,19 @@ class HttpRequestParser extends RequestParser {
         var cookie = (this.rawHeaders && this.rawHeaders["cookie"] &&
             typeof this.rawHeaders["cookie"] === "string" && this.rawHeaders["cookie"]) || "";
 
-        if (name === HttpRequestCookieNames.AUTH_USER) {
+        var value = Util.getCookie(name, cookie);
+
+        if (name === HttpRequestCookieNames.AUTH_USER && value) {
             try {
-                cookie = decodeURI(cookie);
+                value = decodeURIComponent(value);
             } catch (error) {
                 // Failed to decode, ignore cookie
-                cookie = "";
                 Logging.warn("Could not decode the auth cookie with error: ", Util.dumpObj(error));
+                return null;
             }
         }
-        var value = HttpRequestParser.parseId(Util.getCookie(name, cookie));
-        return value;
+
+        return value ? HttpRequestParser.parseId(value) : null;
     }
 
     /**

Tests/AutoCollection/HttpRequestParser.tests.ts

@@ -5,6 +5,8 @@ import HttpRequestParser = require("../../AutoCollection/HttpRequestParser");
 import CorrelationIdManager = require("../../Library/CorrelationIdManager");
 import Util = require("../../Library/Util");
 import Traceparent = require("../../Library/Traceparent");
+import Logging = require("../../Library/Logging");
+import { HttpRequestCookieNames } from "../../Declarations/Constants";
 
 describe("AutoCollection/HttpRequestParser", () => {
     describe("#parseId()", () => {
@@ -269,4 +271,145 @@ describe("AutoCollection/HttpRequestParser", () => {
             assert.equal(newTags[(<any>HttpRequestParser).keys.userAuthUserId], 'userAuthName');
         });
     });
+
+    describe("Cookie Decoding", () => {
+        var origLogWarn: any;
+        var logWarnStub: sinon.SinonStub;
+
+        beforeEach(() => {
+            origLogWarn = Logging.warn;
+            logWarnStub = sinon.stub(Logging, "warn");
+        });
+
+        afterEach(() => {
+            Logging.warn = origLogWarn;
+        });
+
+        it("should decode valid AUTH_USER cookie", () => {
+            var request = {
+                method: "GET",
+                url: "/",
+                headers: {
+                    "cookie": "ai_authUser=user%40example.com; other=value"
+                }
+            };
+
+            var requestParser = new HttpRequestParser(<any>request);
+            var id = requestParser["_getId"](HttpRequestCookieNames.AUTH_USER);
+
+            assert.equal(id, "user@example.com");
+            assert.ok(!logWarnStub.called);
+        });
+
+        it("should handle malformed AUTH_USER cookie gracefully", () => {
+            var request = {
+                method: "GET",
+                url: "/",
+                headers: {
+                    "cookie": "ai_authUser=user%invalid%encoding; other=value"
+                }
+            };
+
+            var requestParser = new HttpRequestParser(<any>request);
+            var id = requestParser["_getId"](HttpRequestCookieNames.AUTH_USER);
+
+            assert.equal(id, null);
+            assert.ok(logWarnStub.called);
+            assert.ok(logWarnStub.calledWith("Could not decode the auth cookie with error: "));
+        });
+
+        it("should handle malformed cookies from other applications without affecting AUTH_USER", () => {
+            var request = {
+                method: "GET",
+                url: "/",
+                headers: {
+                    "cookie": "ai_authUser=user%40example.com; invalid%cookie%format=value%bad%encoding; other=normal"
+                }
+            };
+
+            var requestParser = new HttpRequestParser(<any>request);
+            var id = requestParser["_getId"](HttpRequestCookieNames.AUTH_USER);
+
+            assert.equal(id, "user@example.com");
+            assert.ok(!logWarnStub.called);
+        });
+
+        it("should return null when AUTH_USER cookie is not present", () => {
+            var request = {
+                method: "GET",
+                url: "/",
+                headers: {
+                    "cookie": "other=value; session=abc123"
+                }
+            };
+
+            var requestParser = new HttpRequestParser(<any>request);
+            var id = requestParser["_getId"](HttpRequestCookieNames.AUTH_USER);
+
+            assert.equal(id, null);
+            assert.ok(!logWarnStub.called);
+        });
+
+        it("should return null when no cookies are present", () => {
+            var request = {
+                method: "GET",
+                url: "/",
+                headers: {}
+            };
+
+            var requestParser = new HttpRequestParser(<any>request);
+            var id = requestParser["_getId"](HttpRequestCookieNames.AUTH_USER);
+
+            assert.equal(id, null);
+            assert.ok(!logWarnStub.called);
+        });
+
+        it("should return null when cookie header is empty", () => {
+            var request = {
+                method: "GET",
+                url: "/",
+                headers: {
+                    "cookie": ""
+                }
+            };
+
+            var requestParser = new HttpRequestParser(<any>request);
+            var id = requestParser["_getId"](HttpRequestCookieNames.AUTH_USER);
+
+            assert.equal(id, null);
+            assert.ok(!logWarnStub.called);
+        });
+
+        it("should decode AUTH_USER cookie with special characters", () => {
+            var request = {
+                method: "GET",
+                url: "/",
+                headers: {
+                    "cookie": "ai_authUser=user%40domain.com%2Btest; other=value"
+                }
+            };
+
+            var requestParser = new HttpRequestParser(<any>request);
+            var id = requestParser["_getId"](HttpRequestCookieNames.AUTH_USER);
+
+            assert.equal(id, "user@domain.com+test");
+            assert.ok(!logWarnStub.called);
+        });
+
+        it("should handle AUTH_USER cookie with no value", () => {
+            var request = {
+                method: "GET",
+                url: "/",
+                headers: {
+                    "cookie": "ai_authUser=; other=value"
+                }
+            };
+
+            var requestParser = new HttpRequestParser(<any>request);
+            var id = requestParser["_getId"](HttpRequestCookieNames.AUTH_USER);
+
+            assert.equal(id, null);
+            assert.ok(!logWarnStub.called);
+        });
+    });
 });

Tests/FunctionalTests/RunFunctionalTests.js

@@ -64,10 +64,10 @@ function runAsync(cmd, workingDir) {
 
 function startDocker() {
     const tasks =  [
-        run("docker run -d -p 27017:27017 --name ainjsmongo mongo"),
-        run("docker run -e MYSQL_ROOT_PASSWORD=dummypw -e MYSQL_DATABASE=testdb -d -p 33060:3306 --name ainjsmysql mysql:5"),
-        run("docker run -d -p 63790:6379 --name ainjsredis redis:alpine"),
-        run("docker run -e POSTGRES_PASSWORD=dummypw -d -p 54320:5432 --name ainjspostgres postgres:alpine")
+        run("docker run -d -p 27017:27017 --name ainjsmongo --health-cmd 'mongosh --eval \"db.stats()\" || mongo --eval \"db.stats()\"' --health-interval=10s --health-timeout=5s --health-retries=5 mongo:4.4"),
+        run("docker run -e MYSQL_ROOT_PASSWORD=dummypw -e MYSQL_DATABASE=testdb -d -p 33060:3306 --name ainjsmysql --health-cmd 'mysqladmin ping -h localhost -u root -pdummypw' --health-interval=10s --health-timeout=5s --health-retries=5 mysql:5.7"),
+        run("docker run -d -p 63790:6379 --name ainjsredis --health-cmd 'redis-cli ping' --health-interval=10s --health-timeout=5s --health-retries=5 redis:6-alpine"),
+        run("docker run -e POSTGRES_PASSWORD=dummypw -d -p 54320:5432 --name ainjspostgres --health-cmd 'pg_isready -U postgres -d postgres' --health-interval=10s --health-timeout=10s --health-retries=10 postgres:13-alpine")
     ];
 
     for(let i = 0; i < tasks.length; i++) {
@@ -77,9 +77,78 @@ function startDocker() {
             return false;
         }
     }
+
     return true;
 }
 
+function waitForContainers() {
+    console.log("Waiting for containers to initialize...");
+    return new Promise(resolve => {
+        setTimeout(() => {
+            console.log("Waiting for container health checks to pass...");
+
+            const maxRetries = 60; // 60 attempts, 2 seconds each = 120 seconds max
+            let retries = 0;
+
+            const checkHealth = () => {
+                const healthCheck = run("docker ps --filter 'name=ainjs' --format 'table {{.Names}}\\t{{.Status}}'");
+                if (healthCheck.code === 0) {
+                    console.log("Container status:");
+                    console.log(healthCheck.output);
+
+                    // Check if all containers are healthy (not just running)
+                    const output = healthCheck.output;
+                    const hasUnhealthy = output.includes("(health: starting)") || 
+                                       output.includes("(unhealthy)") || 
+                                       !output.includes("(healthy)");
+
+                    if (!hasUnhealthy) {
+                        console.log("All containers are healthy");
+                        resolve();
+                        return;
+                    } else if (retries >= maxRetries) {
+                        console.log("Max retries reached, checking individual containers...");
+                        // Try direct health checks as fallback
+                        const directChecks = [
+                            run("docker exec ainjspostgres pg_isready -U postgres -d postgres"),
+                            run("docker exec ainjsmysql mysqladmin ping -h localhost -u root -pdummypw"),
+                            run("docker exec ainjsredis redis-cli ping"),
+                            run("docker exec ainjsmongo mongosh --eval 'db.runCommand(\"ping\")' || docker exec ainjsmongo mongo --eval 'db.runCommand(\"ping\")'")
+                        ];
+
+                        let allHealthy = true;
+                        directChecks.forEach((check, index) => {
+                            if (check.code !== 0) {
+                                console.log(`Direct health check failed for container ${index}`);
+                                allHealthy = false;
+                            }
+                        });
+
+                        if (allHealthy) {
+                            console.log("Direct health checks passed");
+                        } else {
+                            console.log("Some direct health checks failed, but proceeding anyway");
+                        }
+                        resolve();
+                        return;
+                    }
+                }
+
+                retries++;
+                if (retries < maxRetries) {
+                    console.log(`Health check attempt ${retries}/${maxRetries}...`);
+                    setTimeout(checkHealth, 2000);
+                } else {
+                    console.log("Max retries reached, proceeding anyway");
+                    resolve();
+                }
+            };
+
+            checkHealth();
+        }, 5000); // Initial 5 second wait
+    });
+}
+
 function cleanUpDocker() {
     run("docker stop ainjsmongo");
     run("docker stop ainjsmysql");
@@ -92,7 +161,7 @@ function cleanUpDocker() {
     run("docker rm ainjspostgres");
 }
 
-function main() {
+async function main() {
     // Find the SDK TGZ archive
     let path = null;
     if (process.argv.length > 2) {
@@ -127,6 +196,9 @@ function main() {
         console.error("Could not spin up containers!");
         return 1;
     }
+
+    // Wait for containers to be ready
+    await waitForContainers();
 
     // Prepare runner and testapp
     console.log("Installing Runner and TestApp dependencies...");
@@ -144,7 +216,23 @@ function main() {
     // Run tests
     console.log("Running functional tests...");
     console.log("=======================\n");
+
+    // Start TestApp with output visible for debugging
+    console.log("Starting TestApp...");
     const testApp = runAsync("node --use_strict Main.js", "./TestApp");
+
+    // Add event listeners to capture TestApp output
+    testApp.stdout.on('data', (data) => {
+        console.log('TestApp:', data.toString().trim());
+    });
+
+    testApp.stderr.on('data', (data) => {
+        console.error('TestApp Error:', data.toString().trim());
+    });
+
+    // Give TestApp time to start up
+    await new Promise(resolve => setTimeout(resolve, 5000));
+
     const runnerStatus = runLive("node --use_strict Main.js" + (perfMode ? " -perfmode": ""), "./Runner").code;
     console.log("\n=======================");
 
@@ -159,4 +247,9 @@ function main() {
 }
 
 
-process.exit(main());
+main().then(code => {
+    process.exit(code);
+}).catch(error => {
+    console.error("Error in main function:", error);
+    process.exit(1);
+});