Add more logging for debugging

src/routes/getSkipSegments.ts

@@ -13,7 +13,7 @@ import { getReputation } from "../utils/reputation";
 import { getService } from "../utils/getService";
 
 
-async function prepareCategorySegments(req: Request, videoID: VideoID, service: Service, segments: DBSegment[], cache: SegmentCache = { shadowHiddenSegmentIPs: {} }, useCache: boolean): Promise<Segment[]> {
+async function prepareCategorySegments(req: Request, videoID: VideoID, service: Service, segments: DBSegment[], cache: SegmentCache = { shadowHiddenSegmentIPs: {} }, useCache: boolean, logData: any): Promise<Segment[]> {
     const shouldFilter: boolean[] = await Promise.all(segments.map(async (segment) => {
         if (segment.votes < -1 && !segment.required) {
             return false; //too untrustworthy, just ignore it
@@ -47,9 +47,19 @@ async function prepareCategorySegments(req: Request, videoID: VideoID, service:
         return shouldShadowHide;
     }));
 
+    if (logData.extraLogging) {
+        Logger.error(`Preparing segments: ${Date.now() - logData.lastTime}, ${Date.now() - logData.startTime}`);
+        logData.lastTime = Date.now();
+    }
+
     const filteredSegments = segments.filter((_, index) => shouldFilter[index]);
 
-    return (await chooseSegments(videoID, service, filteredSegments, useCache)).map((chosenSegment) => ({
+    if (logData.extraLogging) {
+        Logger.error(`Filter complete: ${Date.now() - logData.lastTime}, ${Date.now() - logData.startTime}`);
+        logData.lastTime = Date.now();
+    }
+
+    return (await chooseSegments(videoID, service, filteredSegments, useCache, logData)).map((chosenSegment) => ({
         category: chosenSegment.category,
         actionType: chosenSegment.actionType,
         segment: [chosenSegment.startTime, chosenSegment.endTime],
@@ -83,7 +93,7 @@ async function getSegmentsByVideoID(req: Request, videoID: VideoID, categories:
             }, {});
 
         const canUseCache = requiredSegments.length === 0;
-        let processedSegments: Segment[] = (await prepareCategorySegments(req, videoID, service, segments, cache, canUseCache))
+        let processedSegments: Segment[] = (await prepareCategorySegments(req, videoID, service, segments, cache, canUseCache, {}))
             .filter((segment: Segment) => categories.includes(segment?.category) && (actionTypes.includes(segment?.actionType)));
 
         if (forcePoiAsSkip) {
@@ -113,12 +123,23 @@ async function getSegmentsByHash(req: Request, hashedVideoIDPrefix: VideoIDHash,
         actionTypes.push(ActionType.Poi);
     }
 
+    const logData = {
+        extraLogging: req.params.extraLogging,
+        startTime: Date.now(),
+        lastTime: Date.now()
+    };
+
     try {
         type SegmentWithHashPerVideoID = SBRecord<VideoID, { hash: VideoIDHash, segments: DBSegment[] }>;
 
         categories = categories.filter((category) => !(/[^a-z|_|-]/.test(category)));
         if (categories.length === 0) return null;
 
+        if (logData.extraLogging) {
+            Logger.error(`About to fetch: ${Date.now() - logData.lastTime}, ${Date.now() - logData.startTime}`);
+            logData.lastTime = Date.now();
+        }
+
         const segmentPerVideoID: SegmentWithHashPerVideoID = (await getSegmentsFromDBByHash(hashedVideoIDPrefix, service))
             .reduce((acc: SegmentWithHashPerVideoID, segment: DBSegment) => {
                 acc[segment.videoID] = acc[segment.videoID] || {
@@ -133,6 +154,11 @@ async function getSegmentsByHash(req: Request, hashedVideoIDPrefix: VideoIDHash,
                 return acc;
             }, {});
 
+        if (logData.extraLogging) {
+            Logger.error(`Fetch complete: ${Date.now() - logData.lastTime}, ${Date.now() - logData.startTime}`);
+            logData.lastTime = Date.now();
+        }
+
         for (const [videoID, videoData] of Object.entries(segmentPerVideoID)) {
             const data: VideoData = {
                 hash: videoData.hash,
@@ -140,7 +166,7 @@ async function getSegmentsByHash(req: Request, hashedVideoIDPrefix: VideoIDHash,
             };
 
             const canUseCache = requiredSegments.length === 0;
-            data.segments = (await prepareCategorySegments(req, videoID as VideoID, service, videoData.segments, cache, canUseCache))
+            data.segments = (await prepareCategorySegments(req, videoID as VideoID, service, videoData.segments, cache, canUseCache, logData))
                 .filter((segment: Segment) => categories.includes(segment?.category) && actionTypes.includes(segment?.actionType));
 
             if (forcePoiAsSkip) {
@@ -153,6 +179,11 @@ async function getSegmentsByHash(req: Request, hashedVideoIDPrefix: VideoIDHash,
             if (data.segments.length > 0) {
                 segments[videoID] = data;
             }
+
+            if (logData.extraLogging) {
+                Logger.error(`Done one video: ${Date.now() - logData.lastTime}, ${Date.now() - logData.startTime}`);
+                logData.lastTime = Date.now();
+            }
         }
 
         return segments;
@@ -255,13 +286,18 @@ function getWeightedRandomChoice<T extends VotableObject>(choices: T[], amountOf
     return chosen;
 }
 
-async function chooseSegments(videoID: VideoID, service: Service, segments: DBSegment[], useCache: boolean): Promise<DBSegment[]> {
+async function chooseSegments(videoID: VideoID, service: Service, segments: DBSegment[], useCache: boolean, logData: any): Promise<DBSegment[]> {
     const fetchData = async () => await buildSegmentGroups(segments);
 
     const groups = useCache
         ? await QueryCacher.get(fetchData, skipSegmentGroupsKey(videoID, service))
         : await fetchData();
 
+        if (logData.extraLogging) {
+            Logger.error(`Built groups: ${Date.now() - logData.lastTime}, ${Date.now() - logData.startTime}`);
+            logData.lastTime = Date.now();
+        }
+
     // Filter for only 1 item for POI categories and Full video
     let chosenGroups = getWeightedRandomChoice(groups, 1, true, (choice) => choice.segments[0].actionType === ActionType.Full);
     chosenGroups = getWeightedRandomChoice(chosenGroups, 1, true, (choice) => choice.segments[0].actionType === ActionType.Poi);

src/routes/voteOnSponsorTime.ts

@@ -310,7 +310,18 @@ export async function voteOnSponsorTime(req: Request, res: Response): Promise<Re
     const category = req.query.category as Category;
     const ip = getIP(req);
 
-    const result = await vote(ip, UUID, paramUserID, type, category);
+    const logData = {
+        extraLogging: req.params.extraLogging,
+        startTime: Date.now(),
+        lastTime: Date.now()
+    };
+
+    const result = await vote(ip, UUID, paramUserID, type, category, logData);
+
+    if (logData.extraLogging) {
+        Logger.error(`Done vote: ${Date.now() - logData.lastTime}, ${Date.now() - logData.startTime}`);
+        logData.lastTime = Date.now();
+    }
 
     const response = res.status(result.status);
     if (result.message) {
@@ -322,7 +333,7 @@ export async function voteOnSponsorTime(req: Request, res: Response): Promise<Re
     }
 }
 
-export async function vote(ip: IPAddress, UUID: SegmentUUID, paramUserID: UserID, type: number, category?: Category): Promise<{ status: number, message?: string, json?: unknown }> {
+export async function vote(ip: IPAddress, UUID: SegmentUUID, paramUserID: UserID, type: number, category?: Category, logData = {} as any): Promise<{ status: number, message?: string, json?: unknown }> {
     // missing key parameters
     if (!UUID || !paramUserID || !(type !== undefined || category)) {
         return { status: 400 };
@@ -354,6 +365,11 @@ export async function vote(ip: IPAddress, UUID: SegmentUUID, paramUserID: UserID
         return { status: 404 };
     }
 
+    if (logData.extraLogging) {
+        Logger.error(`Got segment info: ${Date.now() - logData.lastTime}, ${Date.now() - logData.startTime}`);
+        logData.lastTime = Date.now();
+    }
+
     const isTempVIP = await isUserTempVIP(nonAnonUserID, segmentInfo.videoID);
     const isVIP = await isUserVIP(nonAnonUserID);
 
@@ -415,10 +431,20 @@ export async function vote(ip: IPAddress, UUID: SegmentUUID, paramUserID: UserID
         checkVideoDuration(UUID);
     }
 
+    if (logData.extraLogging) {
+        Logger.error(`Main prep done: ${Date.now() - logData.lastTime}, ${Date.now() - logData.startTime}`);
+        logData.lastTime = Date.now();
+    }
+
     try {
         // check if vote has already happened
         const votesRow = await privateDB.prepare("get", `SELECT "type" FROM "votes" WHERE "userID" = ? AND "UUID" = ?`, [userID, UUID]);
 
+        if (logData.extraLogging) {
+            Logger.error(`Got previous vote info: ${Date.now() - logData.lastTime}, ${Date.now() - logData.startTime}`);
+            logData.lastTime = Date.now();
+        }
+
         // -1 for downvote, 1 for upvote. Maybe more depending on reputation in the future
         // oldIncrementAmount will be zero if row is null
         let incrementAmount = 0;
@@ -480,6 +506,11 @@ export async function vote(ip: IPAddress, UUID: SegmentUUID, paramUserID: UserID
 
         const ableToVote = isVIP || isTempVIP || userAbleToVote;
 
+        if (logData.extraLogging) {
+            Logger.error(`About to run vote code ${ableToVote}: ${Date.now() - logData.lastTime}, ${Date.now() - logData.startTime}`);
+            logData.lastTime = Date.now();
+        }
+
         if (ableToVote) {
             //update the votes table
             if (votesRow) {
@@ -507,8 +538,19 @@ export async function vote(ip: IPAddress, UUID: SegmentUUID, paramUserID: UserID
                 await db.prepare("run", 'UPDATE "sponsorTimes" SET "locked" = 0 WHERE "UUID" = ?', [UUID]);
             }
 
+            if (logData.extraLogging) {
+                Logger.error(`Did vote stuff: ${Date.now() - logData.lastTime}, ${Date.now() - logData.startTime}`);
+                logData.lastTime = Date.now();
+            }
+
             QueryCacher.clearSegmentCache(segmentInfo);
         }
+
+        if (logData.extraLogging) {
+            Logger.error(`Ready to send webhook ${incrementAmount - oldIncrementAmount !== 0}: ${Date.now() - logData.lastTime}, ${Date.now() - logData.startTime}`);
+            logData.lastTime = Date.now();
+        }
+
         if (incrementAmount - oldIncrementAmount !== 0) {
             sendWebhooks({
                 UUID,