feat: add database initialization retry logic and enhance auth logging

This commit is contained in:
2026-06-03 17:09:31 +02:00
parent 10815300aa
commit 18dbcd372b
8 changed files with 189 additions and 90 deletions
+16
View File
@@ -33,3 +33,19 @@ PGPORT=5432
PGUSER=postgres
PGPASSWORD=
PGDATABASE=collabtable
#################################################################
# Startup resilience and sync/auth tuning
#################################################################
# DB init retry interval in milliseconds (default: 5000)
DB_INIT_RETRY_INTERVAL_MS=5000
# Max DB init retry attempts. 0 means retry forever (default: 0)
DB_INIT_RETRY_MAX_ATTEMPTS=0
# Suppress repetitive auth warning logs for the same path/method (default: 30000)
AUTH_LOG_THROTTLE_MS=30000
# Allow at most this much client clock skew into sync timestamps (default: 0)
# Keep this at 0 to prevent future-dated rows from being re-sent in hot loops.
SYNC_MAX_FUTURE_SKEW_MS=0
+4
View File
@@ -230,6 +230,10 @@ docker-compose up -d --build
- `DB_PATH` - Path to SQLite database file (default: ./data/collabtable.db for local, /data/collabtable.db in Docker)
- `DATABASE_URL` - PostgreSQL connection URL (optional alternative to PG* variables)
- `PGHOST`, `PGPORT`, `PGUSER`, `PGPASSWORD`, `PGDATABASE` - PostgreSQL connection parameters
- `DB_INIT_RETRY_INTERVAL_MS` - Delay between DB init retries in ms (default: `5000`)
- `DB_INIT_RETRY_MAX_ATTEMPTS` - Max DB init retries; `0` retries forever (default: `0`)
- `AUTH_LOG_THROTTLE_MS` - Minimum interval before repeating the same auth warning log (default: `30000`)
- `SYNC_MAX_FUTURE_SKEW_MS` - Allowed future timestamp skew from clients during sync (default: `0`)
## Data Persistence
Binary file not shown.
+5
View File
@@ -14,6 +14,11 @@ services:
- DB_CLIENT=sqlite
# SQLite path (used when DB_CLIENT=sqlite)
- DB_PATH=/data/collabtable.db
# Retry DB initialization instead of crashing immediately on startup races
- DB_INIT_RETRY_INTERVAL_MS=5000
- DB_INIT_RETRY_MAX_ATTEMPTS=0
# Clamp future client timestamps during sync to avoid resend loops
- SYNC_MAX_FUTURE_SKEW_MS=0
# PostgreSQL (used when DB_CLIENT=postgres) - choose either DATABASE_URL or the PG* vars
# - DATABASE_URL=postgres://user:password@postgres:5432/collabtable
# - PGHOST=postgres
+1 -34
View File
@@ -18,8 +18,7 @@
"eslint-config-prettier": "^9.1.0",
"express": "^4.18.2",
"pg": "^8.11.3",
"prettier": "^3.3.3",
"ws": "^8.16.0"
"prettier": "^3.3.3"
},
"devDependencies": {
"@types/better-sqlite3": "^7.6.11",
@@ -27,7 +26,6 @@
"@types/express": "^4.17.21",
"@types/node": "^20.10.6",
"@types/pg": "^8.10.2",
"@types/ws": "^8.5.10",
"ts-node-dev": "^2.0.0",
"typescript": "^5.3.3"
}
@@ -452,16 +450,6 @@
"dev": true,
"license": "MIT"
},
"node_modules/@types/ws": {
"version": "8.18.1",
"resolved": "https://registry.npmjs.org/@types/ws/-/ws-8.18.1.tgz",
"integrity": "sha512-ThVF6DCVhA8kUGy+aazFQ4kXQ7E1Ty7A3ypFOe0IcJV8O/M511G99AW24irKrW56Wt44yG9+ij8FaqoBGkuBXg==",
"dev": true,
"license": "MIT",
"dependencies": {
"@types/node": "*"
}
},
"node_modules/@typescript-eslint/eslint-plugin": {
"version": "7.18.0",
"resolved": "https://registry.npmjs.org/@typescript-eslint/eslint-plugin/-/eslint-plugin-7.18.0.tgz",
@@ -3717,27 +3705,6 @@
"integrity": "sha512-l4Sp/DRseor9wL6EvV2+TuQn63dMkPjZ/sp9XkghTEbV9KlPS1xUsZ3u7/IQO4wxtcFB4bgpQPRcR3QCvezPcQ==",
"license": "ISC"
},
"node_modules/ws": {
"version": "8.18.3",
"resolved": "https://registry.npmjs.org/ws/-/ws-8.18.3.tgz",
"integrity": "sha512-PEIGCY5tSlUt50cqyMXfCzX+oOPqN0vuGqWzbcJ2xvnkzkq46oOpz7dQaTDBdfICb4N14+GARUDw2XV2N4tvzg==",
"license": "MIT",
"engines": {
"node": ">=10.0.0"
},
"peerDependencies": {
"bufferutil": "^4.0.1",
"utf-8-validate": ">=5.0.2"
},
"peerDependenciesMeta": {
"bufferutil": {
"optional": true
},
"utf-8-validate": {
"optional": true
}
}
},
"node_modules/xtend": {
"version": "4.0.2",
"resolved": "https://registry.npmjs.org/xtend/-/xtend-4.0.2.tgz",
+34 -1
View File
@@ -16,6 +16,39 @@ dotenv.config();
const app = express();
const PORT = process.env.PORT || 3000;
const DB_INIT_RETRY_INTERVAL_MS = Math.max(250, Number(process.env.DB_INIT_RETRY_INTERVAL_MS || 5000));
const DB_INIT_RETRY_MAX_ATTEMPTS = Math.max(0, Number(process.env.DB_INIT_RETRY_MAX_ATTEMPTS || 0));
function sleep(ms: number) {
return new Promise(resolve => setTimeout(resolve, ms));
}
async function initializeDatabaseWithRetry() {
let attempt = 0;
while (true) {
attempt += 1;
try {
await initializeDatabase();
if (attempt > 1) {
console.log(`[DB] Connected after ${attempt} attempt(s)`);
}
return;
} catch (error) {
const reachedLimit = DB_INIT_RETRY_MAX_ATTEMPTS > 0 && attempt >= DB_INIT_RETRY_MAX_ATTEMPTS;
console.error(`[DB] Initialization attempt ${attempt} failed`, error);
if (reachedLimit) {
throw error;
}
console.log(`[DB] Retrying in ${DB_INIT_RETRY_INTERVAL_MS}ms...`);
await sleep(DB_INIT_RETRY_INTERVAL_MS);
}
}
}
// Middleware
app.use(cors());
@@ -44,7 +77,7 @@ app.use('/', webRoutes);
// Initialize database and start server
(async () => {
try {
await initializeDatabase();
await initializeDatabaseWithRetry();
console.log('Database synchronized successfully');
console.log('Database models loaded:');
console.log('- Lists');
+52 -20
View File
@@ -1,6 +1,33 @@
import { Request, Response, NextFunction } from 'express';
let warningLogged = false;
const AUTH_LOG_THROTTLE_MS = Math.max(1000, Number(process.env.AUTH_LOG_THROTTLE_MS || 30000));
const lastAuthLogAt = new Map<string, number>();
const commonProbePathPatterns = [
/^\/\./,
/client_secret\.json$/i,
/phpinfo/i,
/\.git/i,
/wp-admin/i,
/wp-login/i,
/id_rsa/i,
/config(\.|$)/i
];
function isCommonProbePath(pathname: string) {
return commonProbePathPatterns.some(pattern => pattern.test(pathname));
}
function shouldLogAuthWarning(kind: string, req: Request) {
const key = `${kind}:${req.method}:${req.path}`;
const now = Date.now();
const lastSeen = lastAuthLogAt.get(key) || 0;
if (now - lastSeen < AUTH_LOG_THROTTLE_MS) {
return false;
}
lastAuthLogAt.set(key, now);
return true;
}
export const authenticatePassword = (req: Request, res: Response, next: NextFunction) => {
const serverPassword = process.env.SERVER_PASSWORD;
@@ -18,12 +45,13 @@ export const authenticatePassword = (req: Request, res: Response, next: NextFunc
const authHeader = req.headers.authorization;
if (!authHeader) {
// Log diagnostic info to help trace intermittent 401s
console.warn('[AUTH] Missing Authorization header', {
path: req.path,
method: req.method,
ip: req.ip,
});
if (!isCommonProbePath(req.path) && shouldLogAuthWarning('missingHeader', req)) {
console.warn('[AUTH] Missing Authorization header', {
path: req.path,
method: req.method,
ip: req.ip,
});
}
return res.status(401).json({
error: 'Unauthorized',
message: 'No authorization header provided'
@@ -33,13 +61,15 @@ export const authenticatePassword = (req: Request, res: Response, next: NextFunc
// Parse the authorization header
const parts = authHeader.split(' ');
if (parts.length !== 2 || parts[0] !== 'Bearer') {
console.warn('[AUTH] Invalid authorization header format', {
path: req.path,
method: req.method,
ip: req.ip,
// Do not log full header to avoid leaking secrets; include prefix only
headerPreview: authHeader.substring(0, Math.min(authHeader.length, 20)) + '...'
});
if (shouldLogAuthWarning('invalidHeaderFormat', req)) {
console.warn('[AUTH] Invalid authorization header format', {
path: req.path,
method: req.method,
ip: req.ip,
// Do not log full header to avoid leaking secrets; include prefix only
headerPreview: authHeader.substring(0, Math.min(authHeader.length, 20)) + '...'
});
}
return res.status(401).json({
error: 'Unauthorized',
message: 'Invalid authorization header format. Expected: Bearer <password>'
@@ -51,13 +81,15 @@ export const authenticatePassword = (req: Request, res: Response, next: NextFunc
// Validate password
if (providedPassword !== serverPassword) {
// Avoid logging the full password; log only length and a small preview
const safePreview = providedPassword ? `${providedPassword.substring(0, 2)}…(${providedPassword.length})` : 'null';
console.warn('[AUTH] Invalid password', {
path: req.path,
method: req.method,
ip: req.ip,
providedPreview: safePreview,
});
if (shouldLogAuthWarning('invalidPassword', req)) {
const safePreview = providedPassword ? `${providedPassword.substring(0, 2)}..(${providedPassword.length})` : 'null';
console.warn('[AUTH] Invalid password', {
path: req.path,
method: req.method,
ip: req.ip,
providedPreview: safePreview,
});
}
return res.status(401).json({
error: 'Unauthorized',
message: 'Invalid password'
+77 -35
View File
@@ -12,6 +12,36 @@ interface SyncRequest {
itemValues: any[];
}
const SYNC_MAX_FUTURE_SKEW_MS = Math.max(0, Number(process.env.SYNC_MAX_FUTURE_SKEW_MS || 0));
function normalizeTimestamp(raw: any, fallback: number, nowMs: number) {
const numeric = Number(raw);
if (!Number.isFinite(numeric) || numeric <= 0) {
return fallback;
}
let ts = Math.trunc(numeric);
if (ts < 1e12) {
ts *= 1000;
}
const maxAllowed = nowMs + SYNC_MAX_FUTURE_SKEW_MS;
if (ts > maxAllowed) {
return maxAllowed;
}
return ts;
}
function normalizeEntityTimestamps(createdAtRaw: any, updatedAtRaw: any, nowMs: number) {
const createdAt = normalizeTimestamp(createdAtRaw, nowMs, nowMs);
const updatedAt = normalizeTimestamp(updatedAtRaw, createdAt, nowMs);
return {
createdAt,
updatedAt: Math.max(createdAt, updatedAt)
};
}
// Stats tracking
let syncStats = {
totalSyncs: 0,
@@ -55,7 +85,7 @@ setInterval(() => {
lastReset: Date.now()
};
}
}, 60000); // Changed from 30s to 60s
}, 60000).unref?.(); // Changed from 30s to 60s
// Helper function to get prepared statements (lazy initialization)
// We'll perform upserts with positional params for cross-DB portability
@@ -66,15 +96,23 @@ const UPSERT_ITEM_VALUE = 'INSERT INTO item_values (id, itemId, fieldId, value,
router.post('/sync', async (req: Request, res: Response) => {
try {
const { lastSyncTimestamp, lists, fields, items, itemValues }: SyncRequest = req.body;
const {
lastSyncTimestamp,
lists = [],
fields = [],
items = [],
itemValues = []
}: Partial<SyncRequest> = req.body || {};
const deviceId = (req as any).deviceId as string | undefined;
const nowMs = Date.now();
const safeLastSyncTimestamp = normalizeTimestamp(lastSyncTimestamp, 0, nowMs);
// Track stats
syncStats.totalSyncs++;
const incomingLists = lists?.length || 0;
const incomingFields = fields?.length || 0;
const incomingItems = items?.length || 0;
const incomingValues = itemValues?.length || 0;
const incomingLists = lists.length;
const incomingFields = fields.length;
const incomingItems = items.length;
const incomingValues = itemValues.length;
syncStats.listsReceived += incomingLists;
syncStats.fieldsReceived += incomingFields;
@@ -83,7 +121,7 @@ router.post('/sync', async (req: Request, res: Response) => {
// Only log significant sync events (not empty syncs)
const hasIncomingData = incomingLists > 0 || incomingFields > 0 || incomingItems > 0 || incomingValues > 0;
const isInitialSync = lastSyncTimestamp === 0;
const isInitialSync = safeLastSyncTimestamp === 0;
if (hasIncomingData) {
const timestamp = new Date().toLocaleTimeString();
@@ -92,7 +130,7 @@ router.post('/sync', async (req: Request, res: Response) => {
if (incomingLists > 0) {
console.log(` [LISTS] ${incomingLists} list(s)`);
lists.forEach(list => {
const action = list.isDeleted ? 'Deleted' : (lastSyncTimestamp === 0 ? 'Created' : 'Updated');
const action = list.isDeleted ? 'Deleted' : (safeLastSyncTimestamp === 0 ? 'Created' : 'Updated');
console.log(` ${action}: "${list.name}"`);
});
}
@@ -117,25 +155,26 @@ router.post('/sync', async (req: Request, res: Response) => {
await dbAdapter.transaction(async (tx) => {
if (lists && lists.length > 0) {
for (const list of lists) {
const listTs = normalizeEntityTimestamps(list.createdAt, list.updatedAt, nowMs);
await tx.execute(UPSERT_LIST, [
list.id,
list.name,
list.createdAt,
list.updatedAt,
listTs.createdAt,
listTs.updatedAt,
list.isDeleted ? 1 : 0
]);
// enqueue list-level notifications
try {
const ev = list.isDeleted ? 'deleted' : (lastSyncTimestamp === 0 ? 'created' : 'updated');
await enqueueNotification(tx, deviceId, ev, 'list', list.id, list.id, list.updatedAt);
const ev = list.isDeleted ? 'deleted' : (safeLastSyncTimestamp === 0 ? 'created' : 'updated');
await enqueueNotification(tx, deviceId, ev, 'list', list.id, list.id, listTs.updatedAt);
} catch {}
// If a list was deleted, cascade the deletion to child records on server
// - mark fields and items as deleted (tombstones) so other clients learn about them
// - remove item_values belonging to items under this list (no tombstone support for values)
if (list.isDeleted) {
try {
await tx.execute('UPDATE fields SET isDeleted = 1, updatedAt = ? WHERE listId = ?', [list.updatedAt, list.id]);
await tx.execute('UPDATE items SET isDeleted = 1, updatedAt = ? WHERE listId = ?', [list.updatedAt, list.id]);
await tx.execute('UPDATE fields SET isDeleted = 1, updatedAt = ? WHERE listId = ?', [listTs.updatedAt, list.id]);
await tx.execute('UPDATE items SET isDeleted = 1, updatedAt = ? WHERE listId = ?', [listTs.updatedAt, list.id]);
await tx.execute('DELETE FROM item_values WHERE itemId IN (SELECT id FROM items WHERE listId = ?)', [list.id]);
} catch (err) {
console.warn('[SYNC] Cascade delete for list failed:', String(err));
@@ -146,6 +185,7 @@ router.post('/sync', async (req: Request, res: Response) => {
if (fields && fields.length > 0) {
for (const field of fields) {
const fieldTs = normalizeEntityTimestamps(field.createdAt, field.updatedAt, nowMs);
await tx.execute(UPSERT_FIELD, [
field.id,
field.name,
@@ -154,13 +194,13 @@ router.post('/sync', async (req: Request, res: Response) => {
(field.alignment ?? 'start'),
field.listId,
field.order,
field.createdAt,
field.updatedAt,
fieldTs.createdAt,
fieldTs.updatedAt,
field.isDeleted ? 1 : 0
]);
try {
const ev = field.isDeleted ? 'deleted' : (lastSyncTimestamp === 0 ? 'created' : 'updated');
await enqueueNotification(tx, deviceId, ev, 'field', field.id, field.listId, field.updatedAt);
const ev = field.isDeleted ? 'deleted' : (safeLastSyncTimestamp === 0 ? 'created' : 'updated');
await enqueueNotification(tx, deviceId, ev, 'field', field.id, field.listId, fieldTs.updatedAt);
} catch {}
if (field.isDeleted) {
// Remove item_values for this field
@@ -175,7 +215,7 @@ router.post('/sync', async (req: Request, res: Response) => {
const remainingCount = remaining ? (remaining.cnt ?? remaining.CNT ?? remaining.count ?? 0) : 0;
if (remainingCount === 0) {
// Soft delete items in this list and purge their values
await tx.execute('UPDATE items SET isDeleted = 1, updatedAt = ? WHERE listId = ?', [field.updatedAt, field.listId]);
await tx.execute('UPDATE items SET isDeleted = 1, updatedAt = ? WHERE listId = ?', [fieldTs.updatedAt, field.listId]);
await tx.execute('DELETE FROM item_values WHERE itemId IN (SELECT id FROM items WHERE listId = ?)', [field.listId]);
console.log('[SYNC] Last field deleted; cascaded item+value cleanup for list', field.listId);
}
@@ -188,16 +228,17 @@ router.post('/sync', async (req: Request, res: Response) => {
if (items && items.length > 0) {
for (const item of items) {
const itemTs = normalizeEntityTimestamps(item.createdAt, item.updatedAt, nowMs);
await tx.execute(UPSERT_ITEM, [
item.id,
item.listId,
item.createdAt,
item.updatedAt,
itemTs.createdAt,
itemTs.updatedAt,
item.isDeleted ? 1 : 0
]);
try {
const ev = item.isDeleted ? 'deleted' : (lastSyncTimestamp === 0 ? 'created' : 'updated');
await enqueueNotification(tx, deviceId, ev, 'item', item.id, item.listId, item.updatedAt);
const ev = item.isDeleted ? 'deleted' : (safeLastSyncTimestamp === 0 ? 'created' : 'updated');
await enqueueNotification(tx, deviceId, ev, 'item', item.id, item.listId, itemTs.updatedAt);
} catch {}
// If an item was deleted, remove its values (no tombstone support for values)
if (item.isDeleted) {
@@ -220,9 +261,9 @@ router.post('/sync', async (req: Request, res: Response) => {
// Helper to build IN clause placeholders (?,?,?) matching adapter's ? substitution
const makeIn = (arr: string[]) => arr.map(() => '?').join(', ');
let existingItemIds = new Set<string>();
let existingFieldIds = new Set<string>();
const fieldToList: Record<string, string> = {};
let existingItemIds = new Set<string>();
let existingFieldIds = new Set<string>();
const fieldToList: Record<string, string> = {};
try {
if (distinctItemIds.length > 0) {
const rows = await tx.queryAll(`SELECT id FROM items WHERE id IN (${makeIn(distinctItemIds)})`, distinctItemIds);
@@ -238,6 +279,7 @@ router.post('/sync', async (req: Request, res: Response) => {
}
for (const value of itemValues) {
const valueUpdatedAt = normalizeTimestamp(value.updatedAt, nowMs, nowMs);
const hasItem = existingItemIds.has(value.itemId);
const hasField = existingFieldIds.has(value.fieldId);
if (!hasField) {
@@ -252,7 +294,7 @@ router.post('/sync', async (req: Request, res: Response) => {
orphanValues.push({ id: value.id, itemId: value.itemId, fieldId: value.fieldId, reason: 'missingItemNoList' });
continue;
}
const ts = value.updatedAt ?? Date.now();
const ts = valueUpdatedAt;
try {
await tx.execute(UPSERT_ITEM, [
value.itemId,
@@ -274,13 +316,13 @@ router.post('/sync', async (req: Request, res: Response) => {
value.itemId,
value.fieldId,
value.value,
value.updatedAt
valueUpdatedAt
]);
// Coarse list content update notification
try {
const lId = fieldToList[value.fieldId];
if (lId) {
await enqueueNotification(tx, deviceId, 'listContentUpdated', 'value', value.id, lId, value.updatedAt);
await enqueueNotification(tx, deviceId, 'listContentUpdated', 'value', value.id, lId, valueUpdatedAt);
}
} catch {}
} catch (err: any) {
@@ -309,17 +351,17 @@ router.post('/sync', async (req: Request, res: Response) => {
// IMPORTANT: Include deleted items so clients can sync deletions
let serverLists, serverFields, serverItems, serverItemValues;
if (lastSyncTimestamp === 0) {
if (safeLastSyncTimestamp === 0) {
// Include deleted rows on initial sync to propagate tombstones
serverLists = await dbAdapter.queryAll('SELECT * FROM lists');
serverFields = await dbAdapter.queryAll('SELECT * FROM fields');
serverItems = await dbAdapter.queryAll('SELECT * FROM items');
serverItemValues = await dbAdapter.queryAll('SELECT * FROM item_values');
} else {
serverLists = await dbAdapter.queryAll('SELECT * FROM lists WHERE updatedAt >= ?', [lastSyncTimestamp]);
serverFields = await dbAdapter.queryAll('SELECT * FROM fields WHERE updatedAt >= ?', [lastSyncTimestamp]);
serverItems = await dbAdapter.queryAll('SELECT * FROM items WHERE updatedAt >= ?', [lastSyncTimestamp]);
serverItemValues = await dbAdapter.queryAll('SELECT * FROM item_values WHERE updatedAt >= ?', [lastSyncTimestamp]);
serverLists = await dbAdapter.queryAll('SELECT * FROM lists WHERE updatedAt >= ?', [safeLastSyncTimestamp]);
serverFields = await dbAdapter.queryAll('SELECT * FROM fields WHERE updatedAt >= ?', [safeLastSyncTimestamp]);
serverItems = await dbAdapter.queryAll('SELECT * FROM items WHERE updatedAt >= ?', [safeLastSyncTimestamp]);
serverItemValues = await dbAdapter.queryAll('SELECT * FROM item_values WHERE updatedAt >= ?', [safeLastSyncTimestamp]);
}
// Normalize output for clients (camelCase keys, ms timestamps, boolean isDeleted)
@@ -383,7 +425,7 @@ router.post('/sync', async (req: Request, res: Response) => {
// Only log when sending significant data back
const hasOutgoingData = (serverLists as any[]).length > 0 || (serverFields as any[]).length > 0 || (serverItems as any[]).length > 0 || (serverItemValues as any[]).length > 0;
if (hasOutgoingData && !isInitialSync) {
if (hasOutgoingData && !isInitialSync && hasIncomingData) {
console.log(` [OUT] Sending back: ${(serverLists as any[]).length} lists, ${(serverFields as any[]).length} fields, ${(serverItems as any[]).length} items, ${(serverItemValues as any[]).length} values`);
} else if (isInitialSync && hasOutgoingData) {
console.log(` [OUT] Sending initial data: ${(serverLists as any[]).length} lists, ${(serverFields as any[]).length} fields, ${(serverItems as any[]).length} items, ${(serverItemValues as any[]).length} values`);