From dcffb83e628662f439a615b07c0f3503286f77b0 Mon Sep 17 00:00:00 2001
From: Ajay <dev@ajay.app>
Date: Fri, 27 May 2022 01:24:34 -0400
Subject: [PATCH] Logs for submiting

---
 src/routes/getSkipSegments.ts  |  1 +
 src/routes/postSkipSegments.ts | 46 ++++++++++++++++++++++++++++++++++
 2 files changed, 47 insertions(+)

diff --git a/src/routes/getSkipSegments.ts b/src/routes/getSkipSegments.ts
index 1d10fa5..c1428e6 100644
--- a/src/routes/getSkipSegments.ts
+++ b/src/routes/getSkipSegments.ts
@@ -149,6 +149,7 @@ async function getSegmentsByHash(req: Request, hashedVideoIDPrefix: VideoIDHash,
         if (categories.length === 0) return null;
 
         if (logData.extraLogging) {
+            Logger.warn(`IP: ${getIP(req)}, request con ip: ${req.socket?.remoteAddress}`);
             Logger.error(`About to fetch: ${Date.now() - logData.lastTime}, ${Date.now() - logData.startTime}`);
             logData.lastTime = Date.now();
         }
diff --git a/src/routes/postSkipSegments.ts b/src/routes/postSkipSegments.ts
index 8ccee51..5536b76 100644
--- a/src/routes/postSkipSegments.ts
+++ b/src/routes/postSkipSegments.ts
@@ -475,6 +475,12 @@ export async function postSkipSegments(req: Request, res: Response): Promise<Res
         proxySubmission(req);
     }
 
+    const logData = {
+        extraLogging: req.query.extraLogging,
+        startTime: Date.now(),
+        lastTime: Date.now()
+    };
+
     // eslint-disable-next-line prefer-const
     let { videoID, userID: paramUserID, service, videoDuration, videoDurationParam, segments, userAgent } = preprocessInput(req);
 
@@ -513,6 +519,11 @@ export async function postSkipSegments(req: Request, res: Response): Promise<Res
         }
     }
 
+    if (logData.extraLogging) {
+        Logger.error(`Checks done: ${Date.now() - logData.lastTime}, ${Date.now() - logData.startTime}`);
+        logData.lastTime = Date.now();
+    }
+
     // Will be filled when submitting
     const UUIDs = [];
     const newSegments = [];
@@ -520,6 +531,11 @@ export async function postSkipSegments(req: Request, res: Response): Promise<Res
     //hash the ip 5000 times so no one can get it from the database
     const hashedIP = await getHashCache(rawIP + config.globalSalt);
 
+    if (logData.extraLogging) {
+        Logger.error(`IP hash done: ${Date.now() - logData.lastTime}, ${Date.now() - logData.startTime}`);
+        logData.lastTime = Date.now();
+    }
+
     try {
         //get current time
         const timeSubmitted = Date.now();
@@ -534,6 +550,11 @@ export async function postSkipSegments(req: Request, res: Response): Promise<Res
         const startingVotes = 0;
         const reputation = await getReputation(userID);
 
+        if (logData.extraLogging) {
+            Logger.error(`Ban check complete: ${Date.now() - logData.lastTime}, ${Date.now() - logData.startTime}`);
+            logData.lastTime = Date.now();
+        }
+
         for (const segmentInfo of segments) {
             // Full segments are always rejected since there can only be one, so shadow hide wouldn't work
             if (segmentInfo.ignoreSegment
@@ -547,6 +568,11 @@ export async function postSkipSegments(req: Request, res: Response): Promise<Res
             const UUID = getSubmissionUUID(videoID, segmentInfo.category, segmentInfo.actionType, userID, parseFloat(segmentInfo.segment[0]), parseFloat(segmentInfo.segment[1]), service);
             const hashedVideoID = getHash(videoID, 1);
 
+            if (logData.extraLogging) {
+                Logger.error(`Submission prep done: ${Date.now() - logData.lastTime}, ${Date.now() - logData.startTime}`);
+                logData.lastTime = Date.now();
+            }
+
             const startingLocked = isVIP ? 1 : 0;
             try {
                 await db.prepare("run", `INSERT INTO "sponsorTimes" 
@@ -557,14 +583,29 @@ export async function postSkipSegments(req: Request, res: Response): Promise<Res
                 ],
                 );
 
+                if (logData.extraLogging) {
+                    Logger.error(`Normal DB done: ${Date.now() - logData.lastTime}, ${Date.now() - logData.startTime}`);
+                    logData.lastTime = Date.now();
+                }
+
                 //add to private db as well
                 await privateDB.prepare("run", `INSERT INTO "sponsorTimes" VALUES(?, ?, ?, ?)`, [videoID, hashedIP, timeSubmitted, service]);
 
+                if (logData.extraLogging) {
+                    Logger.error(`Private db: ${Date.now() - logData.lastTime}, ${Date.now() - logData.startTime}`);
+                    logData.lastTime = Date.now();
+                }
+
                 await db.prepare("run", `INSERT INTO "videoInfo" ("videoID", "channelID", "title", "published", "genreUrl") 
                     SELECT ?, ?, ?, ?, ?
                     WHERE NOT EXISTS (SELECT 1 FROM "videoInfo" WHERE "videoID" = ?)`, [
                     videoID, apiVideoInfo?.data?.authorId || "", apiVideoInfo?.data?.title || "", apiVideoInfo?.data?.published || 0, apiVideoInfo?.data?.genreUrl || "", videoID]);
 
+                if (logData.extraLogging) {
+                    Logger.error(`Video info: ${Date.now() - logData.lastTime}, ${Date.now() - logData.startTime}`);
+                    logData.lastTime = Date.now();
+                }
+
                 // Clear redis cache for this video
                 QueryCacher.clearSegmentCache({
                     videoID,
@@ -590,6 +631,11 @@ export async function postSkipSegments(req: Request, res: Response): Promise<Res
         return res.sendStatus(500);
     }
 
+    if (logData.extraLogging) {
+        Logger.error(`Sending webhooks: ${Date.now() - logData.lastTime}, ${Date.now() - logData.startTime}`);
+        logData.lastTime = Date.now();
+    }
+
     for (let i = 0; i < segments.length; i++) {
         sendWebhooks(apiVideoInfo, userID, videoID, UUIDs[i], segments[i], service);
     }