Fixed CT HTTP 403 issue, fixed cache lifetime, bumped version to 3.1.1

CHANGELOG.md

@@ -1,5 +1,10 @@
 # Changelog
 
+### 3.1.1
+- Introduced CookieJar pools as workaround for ChurchTools HTTP 403 bugs
+- Fixed default cache lifetime in `Dockerfile`
+- Fixed some debug output
+
 ### 3.1.0
 - Migrated to `ldapjs` 3.0.4
 - Added case-insensitive EqualityFilter.matches() implementation

Dockerfile

@@ -27,6 +27,6 @@ ENV LDAP_IP 0.0.0.0
 ENV LDAP_PORT 1389
 ENV CT_URI https://mysite.church.tools/
 ENV API_TOKEN ""
-ENV CACHE_LIFETIME_MS 10000
+ENV CACHE_LIFETIME_MS 300000
 
 CMD ["node", "ctldap.js"]

README.md

@@ -1,4 +1,4 @@
-# ctldap 3.1.0 - LDAP Wrapper for ChurchTools
+# ctldap 3.1.1 - LDAP Wrapper for ChurchTools
 
 This software acts as an LDAP server for ChurchTools 3
 

docker-compose.yml → compose.yml

@@ -1,4 +1,3 @@
-version: "3"
 services:
 
   ldap:

ctldap-site.js

@@ -9,7 +9,7 @@ import bcrypt from "bcrypt";
 import argon2 from "argon2";
 import { CtldapConfig } from "./ctldap-config.js"
 import { CookieJar } from "tough-cookie";
-import { logWarn } from "./ctldap.js"
+import { logTrace, logWarn } from "./ctldap.js"
 
 export class CtldapSite {
 
@@ -30,24 +30,51 @@ export class CtldapSite {
         this.name = name;
         this.fnUserDn = (cn) => ldapEscape.dn`cn=${cn},ou=users,o=${name}`;
         this.fnGroupDn = (cn) => ldapEscape.dn`cn=${cn},ou=groups,o=${name}`;
+        // Let us keep cookies, which may improve CT API performance.
+        // We have to use a pool of CookieJars in order to avoid ChurchTools HTTP 403 bugs.
+        const cookieJars = []
         this.api = got.extend({
             headers: {"Authorization": `Login ${site.apiToken}`},
             prefixUrl: `${site.ctUri.replace(/\/$/g, '')}/api`,
-            // Let us keep cookies, which may improve CT API performance.
-            // "undefined" is fine as "store" parameter here, it results in memory storage.
-            cookieJar: new CookieJar(undefined),
             retry: {
                 statusCodes: [403, 408, 413, 429, 500, 502, 503, 504, 521, 522, 524]
             },
             hooks: {
+                beforeRequest: [
+                    options => {
+                        let cookieJar = cookieJars.pop()
+                        if (!cookieJar) {
+                            // "undefined" is fine as "store" parameter here, it results in memory storage.
+                            cookieJar = new CookieJar(undefined);
+                            logTrace(site, "Assign new CookieJar.")
+                        } else {
+                            logTrace(site, () => `Reusing CookieJar: ${JSON.stringify(cookieJar)}`)
+                        }
+                        options.cookieJar = cookieJar
+                    }
+                ],
                 beforeRetry: [
-                    (error, _retryCount) => {
+                    (error, retryCount) => {
                         if (error.response.statusCode === 403) {
-                            logWarn(this, "CT API responded with HTTP 403, clearing cookies before retry...");
+                            logWarn(
+                                this,
+                                `CT API responded with HTTP 403, clearing cookies before retry ${retryCount}...`
+                            );
                             error.options.cookieJar.removeAllCookiesSync();
                         }
                     }
-                ]
+                ],
+                afterResponse: [
+                    (response, _retryWithMergedOptions) => {
+                        // Return CookieJar to pool
+                        if (response.statusCode === 200) {
+                            const cookieJar = response.request.options.cookieJar
+                            logTrace(site, () => `Return CookieJar: ${JSON.stringify(cookieJar)}`)
+                            cookieJars.push(cookieJar)
+                        }
+                        return response;
+                    }
+                ],
             },
             responseType: 'json',
             resolveBodyOnly: true,

ctldap.js

@@ -8,9 +8,9 @@
  */
 import fs from "fs";
 import ldapjs from "ldapjs";
-const { InsufficientAccessRightsError, InvalidCredentialsError, OtherError, parseDN } = ldapjs;
 import { CtldapConfig } from "./ctldap-config.js";
 import { patchLdapjsFilters } from "./ldapjs-filter-overrides.js";
+const { InsufficientAccessRightsError, InvalidCredentialsError, OtherError, parseDN } = ldapjs;
 
 // Make some ldapjs filters case-insensitive
 patchLdapjsFilters();
@@ -31,12 +31,20 @@ function getIsoDate() {
 
 export const logTrace = (site, msg)  => {
   if (config.trace) {
+    // For lazy evaluation
+    if (typeof msg === "function") {
+      msg = msg()
+    }
     console.log(`${getIsoDate()} [TRACE] ${site.name} - ${msg}`);
   }
 }
 
 export const logDebug = (site, msg) => {
   if (config.debug) {
+    // For lazy evaluation
+    if (typeof msg === "function") {
+      msg = msg()
+    }
     console.log(`${getIsoDate()} [DEBUG] ${site.name} - ${msg}`);
   }
 }
@@ -131,15 +139,15 @@ async function fetchAllPaginated(site, apiPath, searchParams= {}) {
   // Check first result for completeness, and fix up results and pagination cache if necessary
   const nPages = firstResult['meta']['pagination']['lastPage'];
   if (nPages !== assumedPages) {
-    logDebug(site, `Assumed ${assumedPages} page(s) of data for /api/${apiPath}, but had to load ${nPages}.`);
+    logDebug(site, () => `Assumed ${assumedPages} page(s) of data for /api/${apiPath}, but had to load ${nPages}.`);
     // Update meta cache
     pCache[site] = nPages;
     // Fetch remaining pages, if any
     if (nPages > assumedPages) {
       promises.push(...range(assumedPages + 1, nPages + 1).map(fetchPage));
     }
   } else {
-    logDebug(site, `Assumed ${assumedPages} page(s) of data for /api/${apiPath}, which was correct.`);
+    logDebug(site, () => `Assumed ${assumedPages} page(s) of data for /api/${apiPath}, which was correct.`);
   }
   // Await all results
   const results = await Promise.all(promises);
@@ -304,8 +312,7 @@ function requestUsers(req, _res, next) {
         }
       });
     }
-    const size = newCache.length;
-    logDebug(site, "Updated users: " + size);
+    logDebug(site, () => `Updated users: ${newCache.length}`);
     return newCache;
   });
   return next();
@@ -340,8 +347,7 @@ function requestGroups(req, _res, next) {
         }
       };
     });
-    const size = newCache.length;
-    logDebug(site, "Updated groups: " + size);
+    logDebug(site, () => `Updated groups: ${newCache.length}`);
     return newCache;
   });
   return next();
@@ -368,8 +374,8 @@ function authorize(req, _res, next) {
  * @param {function} next - Next handler function of filter chain
  */
 function searchLogging(req, _res, next) {
-  logDebug(req.site, "SEARCH base object: " + req.dn.toString() + " scope: " + req.scopeName);
-  logDebug(req.site, "Filter: " + req.filter.toString());
+  logDebug(req.site, () => `SEARCH base object: ${req.dn.toString()} scope: ${req.scopeName}`);
+  logDebug(req.site, () => `Filter: ${req.filter.toString()}`);
   return next();
 }
 
@@ -383,7 +389,7 @@ function sendUsers(req, res, next) {
   req.usersPromise.then((users) => {
     users.forEach((u) => {
       if ((req.checkAll || req.dn.equals(u.dn)) && req.filter.matches(u.attributes, false)) {
-        logTrace(req.site, "MatchUser: " + u.dn.toString());
+        logTrace(req.site, () => `MatchUser: ${u.dn.toString()}`);
         res.send(u);
       }
     });
@@ -404,7 +410,7 @@ function sendGroups(req, res, next) {
   req.groupsPromise.then((groups) => {
     groups.forEach((g) => {
       if ((req.checkAll || req.dn.equals(g.dn)) && req.filter.matches(g.attributes, false)) {
-        logTrace(req.site, "MatchGroup: " + g.dn);
+        logTrace(req.site, () => `MatchGroup: ${g.dn}`);
         res.send(g);
       }
     });
@@ -435,22 +441,22 @@ function endSuccess(_req, res, next) {
 async function authenticate(req, _res, next) {
   const site = req.site;
   if (req.dn === site.adminDn) {
-    logDebug(site, "Admin bind DN: " + req.dn);
+    logDebug(site, () => `Admin bind with DN "${req.dn}"`);
     // If ldapPassword is undefined, try a default ChurchTools authentication with this user
-    if (site.ldapPassword !== undefined) {
+    if (site.ldapPassword) {
       try {
         await site.authenticateAdmin(req.credentials);
         logDebug(site, "Admin bind successful");
         return next();
       } catch (error) {
-        logError(site, `Invalid password for admin bind or auth error: `, error);
+        logError(site, "Invalid password for admin bind or auth error: ", error);
         return next(new InvalidCredentialsError());
       }
     } else {
       logDebug("ldapPassword is undefined, trying ChurchTools authentication...")
     }
   } else {
-    logDebug(site, "Bind user DN: %s", req.dn);
+    logDebug(site, () => `Bind user with DN "${req.dn}"`);
   }
   const username = parseDN(req.dn).rdnAt(0).getValue("cn");
   try {
@@ -460,14 +466,14 @@ async function authenticate(req, _res, next) {
         "password": req.credentials
       }
     });
-    logDebug(site, "Authentication successful for " + req.dn);
+    logDebug(site, `Authentication successful for "${username}"`);
     return next();
   } catch (error) {
     if (error.response?.statusCode === 400) {
-      logWarn(site, `Authentication error (CT API HTTP 400) occurred for ${username} (probably wrong password): ${error}`);
+      logWarn(site, `Authentication error (CT API HTTP 400) occurred for "${username}" (probably wrong password): ${error}`);
       return next(new InvalidCredentialsError());
     } else {
-      logError(site, `Authentication error for ${username}: ${error}`);
+      logError(site, `Authentication error for "${username}": ${error}`);
       return next(new OtherError());
     }
   }
@@ -520,7 +526,7 @@ server.search('', (req, res) => {
     "attributes": {
       "objectClass": ["top", "OpenLDAProotDSE"],
       "subschemaSubentry": ["cn=subschema"],
-      "namingContexts": "o=" + req.dn.o,
+      "namingContexts": `o=${req.dn.o}`,
     },
     "dn": "",
   };

package.json

@@ -2,7 +2,7 @@
   "name": "ctldap",
   "license": "GPL-3.0",
   "description": "LDAP Wrapper for ChurchTools",
-  "version": "3.1.0",
+  "version": "3.1.1",
   "private": true,
   "type": "module",
   "dependencies": {

yarn.lock

@@ -281,7 +281,7 @@ __metadata:
   languageName: node
   linkType: hard
 
-"argon2@npm:0.30.3":
+"argon2@npm:^0.30.3":
   version: 0.30.3
   resolution: "argon2@npm:0.30.3"
   dependencies:
@@ -473,7 +473,7 @@ __metadata:
     "@ldapjs/filter": ^2.1.0
     "@ldapjs/messages": ^1.2.0
     "@ldapjs/protocol": ^1.2.1
-    argon2: 0.30.3
+    argon2: ^0.30.3
     bcrypt: ^5.1.0
     got: ^13.0.0
     ldap-escape: ^2.0.6