Server: Add transaction info to debug deadlock issues

packages/server/src/models/BaseModel.ts

@@ -7,6 +7,9 @@ import { Models } from './factory';
 import * as EventEmitter from 'events';
 import { Config } from '../utils/types';
 import personalizedUserContentBaseUrl from '@joplin/lib/services/joplinServer/personalizedUserContentBaseUrl';
+import Logger from '@joplin/lib/Logger';
+
+const logger = Logger.create('BaseModel');
 
 export interface SaveOptions {
 	isNew?: boolean;
@@ -163,33 +166,39 @@ export default abstract class BaseModel<T> {
 	//
 	// The `name` argument is only for debugging, so that any stuck transaction
 	// can be more easily identified.
-	protected async withTransaction<T>(fn: Function, name: string = null): Promise<T> {
-		const debugTransaction = false;
+	protected async withTransaction<T>(fn: Function, name: string): Promise<T> {
+		const debugSteps = false;
+		const debugTimeout = true;
+		const timeoutMs = 10000;
 
-		const debugTimerId = debugTransaction ? setTimeout(() => {
-			console.info('Transaction did not complete:', name, txIndex);
-		}, 5000) : null;
+		let txIndex = 0;
 
-		const txIndex = await this.transactionHandler_.start();
+		const debugTimerId = debugTimeout ? setTimeout(() => {
+			logger.error('Transaction did not complete:', name, txIndex);
+			logger.error('Transaction stack:');
+			logger.error(this.transactionHandler_.stackInfo);
+		}, timeoutMs) : null;
 
-		if (debugTransaction) console.info('START', name, txIndex);
+		txIndex = await this.transactionHandler_.start(name);
+
+		if (debugSteps) console.info('START', name, txIndex);
 
 		let output: T = null;
 
 		try {
 			output = await fn();
 		} catch (error) {
-			await this.transactionHandler_.rollback(txIndex);
-
-			if (debugTransaction) {
+			if (debugSteps) {
 				console.info('ROLLBACK', name, txIndex);
 				clearTimeout(debugTimerId);
 			}
 
+			await this.transactionHandler_.rollback(txIndex);
+
 			throw error;
 		}
 
-		if (debugTransaction) {
+		if (debugSteps) {
 			console.info('COMMIT', name, txIndex);
 			clearTimeout(debugTimerId);
 		}

packages/server/src/models/ItemResourceModel.ts

@@ -34,7 +34,7 @@ export default class ItemResourceModel extends BaseModel<ItemResource> {
 					resource_id: resourceId,
 				});
 			}
-		});
+		}, 'ItemResourceModel::addResourceIds');
 	}
 
 	public async byItemId(itemId: Uuid): Promise<string[]> {

packages/server/src/models/KeyValueModel.ts

@@ -48,7 +48,7 @@ export default class NotificationModel extends BaseModel<KeyValue> {
 				value: this.serializeValue(value),
 				type,
 			});
-		});
+		}, 'KeyValueModel::setValue');
 	}
 
 	public async value<T>(key: string, defaultValue: Value = null): Promise<T> {

packages/server/src/models/ShareModel.ts

@@ -315,7 +315,7 @@ export default class ShareModel extends BaseModel<Share> {
 			for (const item of items) {
 				await this.models().userItem().add(userId, item.id);
 			}
-		});
+		}, 'ShareModel::createSharedFolderUserItems');
 	}
 
 	public async shareFolder(owner: User, folderId: string): Promise<Share> {

packages/server/src/models/ShareUserModel.ts

@@ -126,7 +126,7 @@ export default class ShareUserModel extends BaseModel<ShareUser> {
 			}
 
 			return this.save({ ...shareUser, status });
-		});
+		}, 'ShareUserModel::setStatus');
 	}
 
 	public async deleteByShare(share: Share): Promise<void> {

packages/server/src/models/SubscriptionModel.ts

@@ -91,7 +91,7 @@ export default class SubscriptionModel extends BaseModel<Subscription> {
 					last_payment_time: now,
 					last_payment_failed_time: 0,
 				});
-			});
+			}, 'SubscriptionModel::handlePayment');
 		} else {
 			// We only update the payment failed time if it's not already set
 			// since the only thing that matter is the first time the payment
@@ -145,7 +145,7 @@ export default class SubscriptionModel extends BaseModel<Subscription> {
 			});
 
 			return { user, subscription };
-		});
+		}, 'SubscriptionModel::saveUserAndSubscription');
 	}
 
 	public async toggleSoftDelete(id: number, isDeleted: boolean) {

packages/server/src/models/UserFlagModel.ts

@@ -70,7 +70,7 @@ export default class UserFlagModels extends BaseModel<UserFlag> {
 				await this.add(userId, flagType, { updateUser: false });
 			}
 			await this.updateUserFromFlags(userId);
-		});
+		}, 'UserFlagModels::addMulti');
 	}
 
 	public async removeMulti(userId: Uuid, flagTypes: UserFlagType[]) {
@@ -79,7 +79,7 @@ export default class UserFlagModels extends BaseModel<UserFlag> {
 				await this.remove(userId, flagType, { updateUser: false });
 			}
 			await this.updateUserFromFlags(userId);
-		});
+		}, 'UserFlagModels::removeMulti');
 	}
 
 	// As a general rule the `enabled` and  `can_upload` properties should not

packages/server/src/models/UserItemModel.ts

@@ -141,7 +141,7 @@ export default class UserItemModel extends BaseModel<UserItem> {
 			}
 
 			return super.save(userItem, options);
-		});
+		}, 'UserItemModel::save');
 	}
 
 	public async delete(_id: string | string[], _options: DeleteOptions = {}): Promise<void> {

packages/server/src/models/UserModel.ts

@@ -369,7 +369,7 @@ export default class UserModel extends BaseModel<User> {
 					key: `payment_failed_upload_disabled_${sub.last_payment_failed_time}`,
 				});
 			}
-		});
+		}, 'UserModel::handleFailedPaymentSubscriptions');
 	}
 
 	public async handleOversizedAccounts() {
@@ -430,7 +430,7 @@ export default class UserModel extends BaseModel<User> {
 					});
 				}
 			}
-		});
+		}, 'UserModel::handleOversizedAccounts');
 	}
 
 	private formatValues(user: User): User {
@@ -466,7 +466,7 @@ export default class UserModel extends BaseModel<User> {
 			if (isNew) UserModel.eventEmitter.emit('created');
 
 			return savedUser;
-		});
+		}, 'UserModel::save');
 	}
 
 }

packages/server/src/utils/TransactionHandler.ts

@@ -1,6 +1,12 @@
 import { Knex } from 'knex';
 import { DbConnection } from '../db';
 
+interface TransactionInfo {
+	name: string;
+	index: number;
+	timestamp: Date;
+}
+
 // This transaction handler allows abstracting away the complexity of managing nested transactions
 // within models.
 // Any method in a model can start a transaction and, if one is already started, it
@@ -9,7 +15,7 @@ import { DbConnection } from '../db';
 // Set logEnabled_ to `true` to see what happens with nested transactions.
 export default class TransactionHandler {
 
-	private transactionStack_: number[] = [];
+	private transactionStack_: TransactionInfo[] = [];
 	private activeTransaction_: Knex.Transaction = null;
 	private transactionIndex_: number = 0;
 	private logEnabled_: boolean = false;
@@ -36,7 +42,15 @@ export default class TransactionHandler {
 		return this.activeTransaction_;
 	}
 
-	public async start(): Promise<number> {
+	public get stackInfo(): string {
+		const output: string[] = [];
+		for (const t of this.transactionStack_) {
+			output.push(`#${t.index}: ${t.name}: ${t.timestamp.toUTCString()}`);
+		}
+		return output.join('\n');
+	}
+
+	public async start(name: string): Promise<number> {
 		const txIndex = ++this.transactionIndex_;
 		this.log(`Starting transaction: ${txIndex}`);
 
@@ -47,14 +61,19 @@ export default class TransactionHandler {
 			this.log(`Got transaction: ${txIndex}`);
 		}
 
-		this.transactionStack_.push(txIndex);
+		this.transactionStack_.push({
+			name,
+			index: txIndex,
+			timestamp: new Date(),
+		});
+
 		return txIndex;
 	}
 
 	private finishTransaction(txIndex: number): boolean {
 		if (!this.transactionStack_.length) throw new Error('Committing but no transaction was started');
-		const lastTxIndex = this.transactionStack_.pop();
-		if (lastTxIndex !== txIndex) throw new Error(`Committing a transaction but was not last to start one: ${txIndex}. Expected: ${lastTxIndex}`);
+		const lastTx = this.transactionStack_.pop();
+		if (lastTx.index !== txIndex) throw new Error(`Committing a transaction but was not last to start one: ${txIndex}. Expected: ${lastTx.index}`);
 		return !this.transactionStack_.length;
 	}