log touchups

Author: thehabes

cache/__tests__/cache-metrics-worst-case.sh

@@ -1068,7 +1068,7 @@ test_create_endpoint_empty() {
         echo "{\"type\":\"CreatePerfTest\",\"timestamp\":$(date +%s%3N),\"random\":$RANDOM}"
     }
 
-    log_info "Testing create with empty cache (100 operations - 50 for each delete test)..."
+    log_info "Testing create with empty cache (100 operations)..."
 
     # Call function directly (not in subshell) so CREATED_IDS changes persist
     run_write_performance_test "create" "create" "POST" "generate_create_body" 100
@@ -1142,7 +1142,7 @@ test_update_endpoint_empty() {
         return
     fi
 
-    log_info "Testing update with empty cache ($NUM_ITERATIONS iterations on same object)..."
+    log_info "Testing update with empty cache ($NUM_ITERATIONS iterations)..."
 
     declare -a empty_times=()
     local empty_total=0
@@ -1216,7 +1216,7 @@ test_update_endpoint_full() {
         return
     fi
 
-    log_info "Testing update with full cache (${CACHE_FILL_SIZE} entries, $NUM_ITERATIONS iterations on same object)..."
+    log_info "Testing update with full cache (${CACHE_FILL_SIZE} entries, $NUM_ITERATIONS iterations)..."
     echo "[INFO] Using unique type 'WORST_CASE_WRITE_UNIQUE_99999' to force full cache scan with no invalidations..."
 
     declare -a full_times=()

cache/__tests__/cache-metrics.sh

@@ -1094,7 +1094,7 @@ test_create_endpoint_empty() {
         echo "{\"type\":\"CreatePerfTest\",\"timestamp\":$(date +%s%3N),\"random\":$RANDOM}"
     }
 
-    log_info "Testing create with empty cache (100 operations - 50 for each delete test)..."
+    log_info "Testing create with empty cache (100 operations)..."
 
     # Call function directly (not in subshell) so CREATED_IDS changes persist
     run_write_performance_test "create" "create" "POST" "generate_create_body" 100
@@ -1167,7 +1167,7 @@ test_update_endpoint_empty() {
         return
     fi
 
-    log_info "Testing update with empty cache ($NUM_ITERATIONS iterations on same object)..."
+    log_info "Testing update with empty cache ($NUM_ITERATIONS iterations)..."
 
     declare -a empty_times=()
     local empty_total=0
@@ -1241,7 +1241,7 @@ test_update_endpoint_full() {
         return
     fi
 
-    log_info "Testing update with full cache (${CACHE_FILL_SIZE} entries, $NUM_ITERATIONS iterations on same object)..."
+    log_info "Testing update with full cache (${CACHE_FILL_SIZE} entries, $NUM_ITERATIONS iterations)..."
 
     declare -a full_times=()
     local full_total=0

cache/docs/CACHE_METRICS_REPORT.md

@@ -1,21 +1,21 @@
 # RERUM Cache Metrics & Functionality Report
 
-**Generated**: Fri Oct 24 20:39:26 UTC 2025  
+**Generated**: Fri Oct 24 16:26:17 CDT 2025  
 **Test Duration**: Full integration and performance suite  
 **Server**: http://localhost:3001
 
 ---
 
 ## Executive Summary
 
-**Overall Test Results**: 37 passed, 0 failed, 0 skipped (37 total)
+**Overall Test Results**: 32 passed, 0 failed, 0 skipped (32 total)
 
 ### Cache Performance Summary
 
 | Metric | Value |
 |--------|-------|
 | Cache Hits | 3 |
-| Cache Misses | 1010 |
+| Cache Misses | 1007 |
 | Hit Rate | 0.30% |
 | Cache Size | 999 entries |
 | Invalidations | 7 |
@@ -33,7 +33,7 @@
 | `/history` | ✅ Functional | Get object version history |
 | `/since` | ✅ Functional | Get objects modified since timestamp |
 | `/create` | ✅ Functional | Create new objects |
-| `/update` | ✅ Functional | Update existing objects |
+| `/update` | ⚠️  Partial Failures (2/50) | Update existing objects |
 | `/patch` | ✅ Functional | Patch existing object properties |
 | `/set` | ✅ Functional | Add new properties to objects |
 | `/unset` | ✅ Functional | Remove properties from objects |
@@ -48,12 +48,12 @@
 
 | Endpoint | Cold Cache (DB) | Warm Cache (Memory) | Speedup | Benefit |
 |----------|-----------------|---------------------|---------|---------|
-| `/query` | 526 | N/A | N/A | N/A |
-| `/search` | 110 | N/A | N/A | N/A |
-| `/searchPhrase` | 34 | N/A | N/A | N/A |
-| `/id` | 416 | N/A | N/A | N/A |
-| `/history` | 734 | N/A | N/A | N/A |
-| `/since` | 724 | N/A | N/A | N/A |
+| `/query` | 444 | N/A | N/A | N/A |
+| `/search` | 516 | N/A | N/A | N/A |
+| `/searchPhrase` | 64 | N/A | N/A | N/A |
+| `/id` | 495 | N/A | N/A | N/A |
+| `/history` | 862 | N/A | N/A | N/A |
+| `/since` | 866 | N/A | N/A | N/A |
 
 **Interpretation**:
 - **Cold Cache**: First request hits database (cache miss)
@@ -69,13 +69,13 @@
 
 | Endpoint | Empty Cache | Full Cache (1000 entries) | Overhead | Impact |
 |----------|-------------|---------------------------|----------|--------|
-| `/create` | 22ms | 24ms | +2ms | ✅ Negligible |
-| `/update` | 424ms | 428ms | +4ms | ✅ Negligible |
-| `/patch` | 426ms | 425ms | -1ms | ✅ None |
-| `/set` | 447ms | 442ms | -5ms | ✅ None |
-| `/unset` | 427ms | 426ms | -1ms | ✅ None |
-| `/delete` | 445ms | 428ms | -17ms | ✅ None |
-| `/overwrite` | 438ms | 425ms | -13ms | ✅ None |
+| `/create` | 57ms | 56ms | -1ms | ✅ None |
+| `/update` | 470ms | N/A | N/A | ✅ Write-only |
+| `/patch` | 1078ms | 475ms | -603ms | ✅ None |
+| `/set` | 476ms | 475ms | -1ms | ✅ None |
+| `/unset` | 485ms | 899ms | +414ms | ⚠️  Moderate |
+| `/delete` | 517ms | 680ms | +163ms | ⚠️  Moderate |
+| `/overwrite` | 475ms | 477ms | +2ms | ✅ Negligible |
 
 **Interpretation**:
 - **Empty Cache**: Write with no cache to invalidate
@@ -98,7 +98,7 @@
 
 **Cache Costs (Writes)**:
 - Average overhead per write: ~-4ms
-- Overhead percentage: ~-1%
+- Overhead percentage: ~0%
 - Net cost on 1000 writes: ~-4000ms
 - Tested endpoints: create, update, patch, set, unset, delete, overwrite
 
@@ -111,17 +111,17 @@ For a workload with:
 
 ```
 Without Cache:
-  800 reads × 526ms = 420800ms
-  200 writes × 22ms = 4400ms
-  Total: 425200ms
+  800 reads × 444ms = 355200ms
+  200 writes × 57ms = 11400ms
+  Total: 366600ms
 
 With Cache:
   560 cached reads × 5ms = 2800ms
-  240 uncached reads × 526ms = 126240ms
-  200 writes × 24ms = 4800ms
-  Total: 133840ms
+  240 uncached reads × 444ms = 106560ms
+  200 writes × 56ms = 11200ms
+  Total: 120560ms
 
-Net Improvement: 291360ms faster (~69% improvement)
+Net Improvement: 246040ms faster (~68% improvement)
 ```
 
 ---
@@ -132,8 +132,8 @@ Net Improvement: 291360ms faster (~69% improvement)
 
 The cache layer provides:
 1. **Significant read performance improvements** (0ms average speedup)
-2. **Minimal write overhead** (-4ms average, ~-1% of write time)
-3. **All endpoints functioning correctly** (37 passed tests)
+2. **Minimal write overhead** (-4ms average, ~0% of write time)
+3. **All endpoints functioning correctly** (32 passed tests)
 
 ### 📊 Monitoring Recommendations
 
@@ -164,7 +164,7 @@ Consider tuning based on:
 - Server: http://localhost:3001
 - Test Framework: Bash + curl
 - Metrics Collection: Millisecond-precision timing
-- Test Objects Created: 202
+- Test Objects Created: 198
 - All test objects cleaned up: ✅
 
 **Test Coverage**:
@@ -176,6 +176,6 @@ Consider tuning based on:
 
 ---
 
-**Report Generated**: Fri Oct 24 20:39:26 UTC 2025  
+**Report Generated**: Fri Oct 24 16:26:17 CDT 2025  
 **Format Version**: 1.0  
 **Test Suite**: cache-metrics.sh

controllers/crud.js

@@ -41,7 +41,6 @@ const create = async function (req, res, next) {
     delete provided["@context"]
 
     let newObject = Object.assign(context, { "@id": process.env.RERUM_ID_PREFIX + id }, provided, rerumProp, { "_id": id })
-    console.log("CREATE")
     try {
         let result = await db.insertOne(newObject)
         res.set(utils.configureWebAnnoHeadersFor(newObject))
@@ -63,7 +62,6 @@ const create = async function (req, res, next) {
  * The return is always an array, even if 0 or 1 objects in the return.
  * */
 const query = async function (req, res, next) {
-    console.log("QUERY TO MONGODB")
     res.set("Content-Type", "application/json; charset=utf-8")
     let props = req.body
     const limit = parseInt(req.query.limit ?? 100)
@@ -93,7 +91,6 @@ const query = async function (req, res, next) {
  * Note /v1/id/{blank} does not route here.  It routes to the generic 404
  * */
 const id = async function (req, res, next) {
-    console.log("_id TO MONGODB")
     res.set("Content-Type", "application/json; charset=utf-8")
     let id = req.params["_id"]
     try {

controllers/delete.js

@@ -86,10 +86,9 @@ const deleteObj = async function(req, res, next) {
                 next(createExpressError(err))
                 return
             }
-            //204 to say it is deleted and there is nothing in the body
-            console.log("Object deleted: " + preserveID)
             // Store the deleted object for cache invalidation middleware to use for smart invalidation
             res.locals.deletedObject = safe_original
+            //204 to say it is deleted and there is nothing in the body
             res.sendStatus(204)
             return
         }

controllers/overwrite.js

@@ -23,7 +23,6 @@ const overwrite = async function (req, res, next) {
     let agentRequestingOverwrite = getAgentClaim(req, next)
     const receivedID = objectReceived["@id"] ?? objectReceived.id
     if (receivedID) {
-        console.log("OVERWRITE")
         let id = parseDocumentID(receivedID)
         let originalObject
         try {

controllers/patchUnset.js

@@ -91,7 +91,6 @@ const patchUnset = async function (req, res, next) {
             if(_contextid(patchedObject["@context"])) delete patchedObject.id
             delete patchedObject["@context"]
             let newObject = Object.assign(context, { "@id": process.env.RERUM_ID_PREFIX + id }, patchedObject, rerumProp, { "_id": id })
-            console.log("PATCH UNSET")
             try {
                 let result = await db.insertOne(newObject)
                 if (alterHistoryNext(originalObject, newObject["@id"])) {

controllers/patchUpdate.js

@@ -90,7 +90,6 @@ const patchUpdate = async function (req, res, next) {
             if(_contextid(patchedObject["@context"])) delete patchedObject.id
             delete patchedObject["@context"]
             let newObject = Object.assign(context, { "@id": process.env.RERUM_ID_PREFIX + id }, patchedObject, rerumProp, { "_id": id })
-            console.log("PATCH UPDATE")
             try {
                 let result = await db.insertOne(newObject)
                 if (alterHistoryNext(originalObject, newObject["@id"])) {

controllers/putUpdate.js

@@ -63,7 +63,6 @@ const putUpdate = async function (req, res, next) {
             delete objectReceived["@context"]
 
             let newObject = Object.assign(context, { "@id": process.env.RERUM_ID_PREFIX + id }, objectReceived, rerumProp, { "_id": id })
-            console.log("UPDATE")
             try {
                 let result = await db.insertOne(newObject)
                 if (alterHistoryNext(originalObject, newObject["@id"])) {
@@ -122,7 +121,6 @@ async function _import(req, res, next) {
     delete objectReceived["@context"]
 
     let newObject = Object.assign(context, { "@id": process.env.RERUM_ID_PREFIX + id }, objectReceived, rerumProp, { "_id": id })
-    console.log("IMPORT")
     try {
         let result = await db.insertOne(newObject)
         res.set(utils.configureWebAnnoHeadersFor(newObject))

controllers/release.js

@@ -71,7 +71,6 @@ const release = async function (req, res, next) {
             next(createExpressError(err))
             return
         }
-        console.log("RELEASE")
         if (null !== originalObject){
             safe_original["__rerum"].isReleased = new Date(Date.now()).toISOString().replace("Z", "")
             safe_original["__rerum"].releases.replaces = previousReleasedID
@@ -108,7 +107,6 @@ const release = async function (req, res, next) {
                     //result didn't error out, the action was not performed.  Sometimes, this is a neutral thing.  Sometimes it is indicative of an error.
                 }
                 res.set(utils.configureWebAnnoHeadersFor(releasedObject))
-                console.log(releasedObject._id+" has been released")
                 releasedObject = idNegotiation(releasedObject)
                 releasedObject.new_obj_state = JSON.parse(JSON.stringify(releasedObject))
                 res.location(releasedObject[_contextid(releasedObject["@context"]) ? "id":"@id"])