feat(pipeline-tasks): debug log.

package-lock.json

@@ -23,6 +23,7 @@
         "bull": "^3.20.1",
         "class-transformer": "^0.3.2",
         "class-validator": "^0.13.1",
+        "debug": "^4.3.1",
         "graphql": "^15.5.0",
         "graphql-tools": "^7.0.2",
         "js-yaml": "^4.0.0",
@@ -40,6 +41,7 @@
         "@nestjs/cli": "^7.5.1",
         "@nestjs/schematics": "^7.1.3",
         "@nestjs/testing": "^7.5.1",
+        "@types/debug": "^4.1.5",
         "@types/express": "^4.17.8",
         "@types/jest": "^26.0.15",
         "@types/js-yaml": "^4.0.0",
@@ -2827,6 +2829,12 @@
         "@types/express": "*"
       }
     },
+    "node_modules/@types/debug": {
+      "version": "4.1.5",
+      "resolved": "https://registry.npmjs.org/@types/debug/-/debug-4.1.5.tgz",
+      "integrity": "sha512-Q1y515GcOdTHgagaVFhHnIFQ38ygs/kmxdNpvpou+raI9UO3YZcHDngBSYKQklcKlvA7iuQlmIKbzvmxcOE9CQ==",
+      "dev": true
+    },
     "node_modules/@types/eslint": {
       "version": "7.2.6",
       "resolved": "https://registry.npmjs.org/@types/eslint/-/eslint-7.2.6.tgz",
@@ -5174,6 +5182,14 @@
         "node": ">= 0.8"
       }
     },
+    "node_modules/body-parser/node_modules/debug": {
+      "version": "2.6.9",
+      "resolved": "https://registry.npmjs.org/debug/-/debug-2.6.9.tgz",
+      "integrity": "sha512-bC7ElrdJaJnPbAP+1EotYvqZsb3ecl5wi6Bfi6BJTUcNowp6cvspg0jXznRTKDjm/E7AdgFBVeAPVMNcKGsHMA==",
+      "dependencies": {
+        "ms": "2.0.0"
+      }
+    },
     "node_modules/brace-expansion": {
       "version": "1.1.11",
       "resolved": "https://registry.npmjs.org/brace-expansion/-/brace-expansion-1.1.11.tgz",
@@ -6163,13 +6179,21 @@
       "integrity": "sha512-YzhyDAwA4TaQIhM5go+vCLmU0UikghC/t9DTQYZR2M/UvZ1MdOhPezSDZcjj9uqQJOMqjLcpWtyW2iNINdlatQ=="
     },
     "node_modules/debug": {
-      "version": "2.6.9",
+      "version": "4.3.1",
-      "resolved": "https://registry.npmjs.org/debug/-/debug-2.6.9.tgz",
+      "resolved": "https://registry.npmjs.org/debug/-/debug-4.3.1.tgz",
-      "integrity": "sha512-bC7ElrdJaJnPbAP+1EotYvqZsb3ecl5wi6Bfi6BJTUcNowp6cvspg0jXznRTKDjm/E7AdgFBVeAPVMNcKGsHMA==",
+      "integrity": "sha512-doEwdvm4PCeK4K3RQN2ZC2BYUBaxwLARCqZmMjtF8a51J2Rb0xpVloFRnCODwqjpwnAoao4pelN8l3RJdv3gRQ==",
       "dependencies": {
-        "ms": "2.0.0"
+        "ms": "2.1.2"
+      },
+      "engines": {
+        "node": ">=6.0"
       }
     },
+    "node_modules/debug/node_modules/ms": {
+      "version": "2.1.2",
+      "resolved": "https://registry.npmjs.org/ms/-/ms-2.1.2.tgz",
+      "integrity": "sha512-sGkPx+VjMtmA6MX27oA4FBFELFCZZ4S4XqeGOXCv68tT+jb3vk/RyaKWP0PTKyWtmLSM0b+adUTEvbs1PEaH2w=="
+    },
     "node_modules/debuglog": {
       "version": "1.0.1",
       "resolved": "https://registry.npmjs.org/debuglog/-/debuglog-1.0.1.tgz",
@@ -7129,6 +7153,15 @@
         "node": ">=0.10.0"
       }
     },
+    "node_modules/expand-brackets/node_modules/debug": {
+      "version": "2.6.9",
+      "resolved": "https://registry.npmjs.org/debug/-/debug-2.6.9.tgz",
+      "integrity": "sha512-bC7ElrdJaJnPbAP+1EotYvqZsb3ecl5wi6Bfi6BJTUcNowp6cvspg0jXznRTKDjm/E7AdgFBVeAPVMNcKGsHMA==",
+      "dev": true,
+      "dependencies": {
+        "ms": "2.0.0"
+      }
+    },
     "node_modules/expand-brackets/node_modules/define-property": {
       "version": "0.2.5",
       "resolved": "https://registry.npmjs.org/define-property/-/define-property-0.2.5.tgz",
@@ -7210,6 +7243,14 @@
         "node": ">= 0.10.0"
       }
     },
+    "node_modules/express/node_modules/debug": {
+      "version": "2.6.9",
+      "resolved": "https://registry.npmjs.org/debug/-/debug-2.6.9.tgz",
+      "integrity": "sha512-bC7ElrdJaJnPbAP+1EotYvqZsb3ecl5wi6Bfi6BJTUcNowp6cvspg0jXznRTKDjm/E7AdgFBVeAPVMNcKGsHMA==",
+      "dependencies": {
+        "ms": "2.0.0"
+      }
+    },
     "node_modules/express/node_modules/path-to-regexp": {
       "version": "0.1.7",
       "resolved": "https://registry.npmjs.org/path-to-regexp/-/path-to-regexp-0.1.7.tgz",
@@ -7510,6 +7551,14 @@
         "node": ">= 0.8"
       }
     },
+    "node_modules/finalhandler/node_modules/debug": {
+      "version": "2.6.9",
+      "resolved": "https://registry.npmjs.org/debug/-/debug-2.6.9.tgz",
+      "integrity": "sha512-bC7ElrdJaJnPbAP+1EotYvqZsb3ecl5wi6Bfi6BJTUcNowp6cvspg0jXznRTKDjm/E7AdgFBVeAPVMNcKGsHMA==",
+      "dependencies": {
+        "ms": "2.0.0"
+      }
+    },
     "node_modules/find-up": {
       "version": "4.1.0",
       "resolved": "https://registry.npmjs.org/find-up/-/find-up-4.1.0.tgz",
@@ -11310,10 +11359,7 @@
     "node_modules/observable-to-async-generator": {
       "version": "1.0.1-rc",
       "resolved": "https://registry.npmjs.org/observable-to-async-generator/-/observable-to-async-generator-1.0.1-rc.tgz",
-      "integrity": "sha512-fSV1h5D6fv1X3vfeOQF6u7Mq5VUrM1K5AxfgAIjVqLBhDHQFg/Jp9J3fOc2CR6EDr/JFjs7IxbRlvDigVh7Wgg==",
+      "integrity": "sha512-fSV1h5D6fv1X3vfeOQF6u7Mq5VUrM1K5AxfgAIjVqLBhDHQFg/Jp9J3fOc2CR6EDr/JFjs7IxbRlvDigVh7Wgg=="
-      "peerDependencies": {
-        "rxjs": "6.x.x"
-      }
     },
     "node_modules/on-finished": {
       "version": "2.3.0",
@@ -13094,6 +13140,19 @@
         "node": ">= 0.8.0"
       }
     },
+    "node_modules/send/node_modules/debug": {
+      "version": "2.6.9",
+      "resolved": "https://registry.npmjs.org/debug/-/debug-2.6.9.tgz",
+      "integrity": "sha512-bC7ElrdJaJnPbAP+1EotYvqZsb3ecl5wi6Bfi6BJTUcNowp6cvspg0jXznRTKDjm/E7AdgFBVeAPVMNcKGsHMA==",
+      "dependencies": {
+        "ms": "2.0.0"
+      }
+    },
+    "node_modules/send/node_modules/debug/node_modules/ms": {
+      "version": "2.0.0",
+      "resolved": "https://registry.npmjs.org/ms/-/ms-2.0.0.tgz",
+      "integrity": "sha1-VgiurfwAvmwpAd9fmGF4jeDVl8g="
+    },
     "node_modules/send/node_modules/ms": {
       "version": "2.1.1",
       "resolved": "https://registry.npmjs.org/ms/-/ms-2.1.1.tgz",
@@ -13402,6 +13461,15 @@
         "node": ">=0.10.0"
       }
     },
+    "node_modules/snapdragon/node_modules/debug": {
+      "version": "2.6.9",
+      "resolved": "https://registry.npmjs.org/debug/-/debug-2.6.9.tgz",
+      "integrity": "sha512-bC7ElrdJaJnPbAP+1EotYvqZsb3ecl5wi6Bfi6BJTUcNowp6cvspg0jXznRTKDjm/E7AdgFBVeAPVMNcKGsHMA==",
+      "dev": true,
+      "dependencies": {
+        "ms": "2.0.0"
+      }
+    },
     "node_modules/snapdragon/node_modules/define-property": {
       "version": "0.2.5",
       "resolved": "https://registry.npmjs.org/define-property/-/define-property-0.2.5.tgz",
@@ -18247,6 +18315,12 @@
         "@types/express": "*"
       }
     },
+    "@types/debug": {
+      "version": "4.1.5",
+      "resolved": "https://registry.npmjs.org/@types/debug/-/debug-4.1.5.tgz",
+      "integrity": "sha512-Q1y515GcOdTHgagaVFhHnIFQ38ygs/kmxdNpvpou+raI9UO3YZcHDngBSYKQklcKlvA7iuQlmIKbzvmxcOE9CQ==",
+      "dev": true
+    },
     "@types/eslint": {
       "version": "7.2.6",
       "resolved": "https://registry.npmjs.org/@types/eslint/-/eslint-7.2.6.tgz",
@@ -20356,6 +20430,16 @@
         "qs": "6.7.0",
         "raw-body": "2.4.0",
         "type-is": "~1.6.17"
+      },
+      "dependencies": {
+        "debug": {
+          "version": "2.6.9",
+          "resolved": "https://registry.npmjs.org/debug/-/debug-2.6.9.tgz",
+          "integrity": "sha512-bC7ElrdJaJnPbAP+1EotYvqZsb3ecl5wi6Bfi6BJTUcNowp6cvspg0jXznRTKDjm/E7AdgFBVeAPVMNcKGsHMA==",
+          "requires": {
+            "ms": "2.0.0"
+          }
+        }
       }
     },
     "brace-expansion": {
@@ -21170,11 +21254,18 @@
       "integrity": "sha512-YzhyDAwA4TaQIhM5go+vCLmU0UikghC/t9DTQYZR2M/UvZ1MdOhPezSDZcjj9uqQJOMqjLcpWtyW2iNINdlatQ=="
     },
     "debug": {
-      "version": "2.6.9",
+      "version": "4.3.1",
-      "resolved": "https://registry.npmjs.org/debug/-/debug-2.6.9.tgz",
+      "resolved": "https://registry.npmjs.org/debug/-/debug-4.3.1.tgz",
-      "integrity": "sha512-bC7ElrdJaJnPbAP+1EotYvqZsb3ecl5wi6Bfi6BJTUcNowp6cvspg0jXznRTKDjm/E7AdgFBVeAPVMNcKGsHMA==",
+      "integrity": "sha512-doEwdvm4PCeK4K3RQN2ZC2BYUBaxwLARCqZmMjtF8a51J2Rb0xpVloFRnCODwqjpwnAoao4pelN8l3RJdv3gRQ==",
       "requires": {
-        "ms": "2.0.0"
+        "ms": "2.1.2"
+      },
+      "dependencies": {
+        "ms": {
+          "version": "2.1.2",
+          "resolved": "https://registry.npmjs.org/ms/-/ms-2.1.2.tgz",
+          "integrity": "sha512-sGkPx+VjMtmA6MX27oA4FBFELFCZZ4S4XqeGOXCv68tT+jb3vk/RyaKWP0PTKyWtmLSM0b+adUTEvbs1PEaH2w=="
+        }
       }
     },
     "debuglog": {
@@ -21937,6 +22028,15 @@
         "to-regex": "^3.0.1"
       },
       "dependencies": {
+        "debug": {
+          "version": "2.6.9",
+          "resolved": "https://registry.npmjs.org/debug/-/debug-2.6.9.tgz",
+          "integrity": "sha512-bC7ElrdJaJnPbAP+1EotYvqZsb3ecl5wi6Bfi6BJTUcNowp6cvspg0jXznRTKDjm/E7AdgFBVeAPVMNcKGsHMA==",
+          "dev": true,
+          "requires": {
+            "ms": "2.0.0"
+          }
+        },
         "define-property": {
           "version": "0.2.5",
           "resolved": "https://registry.npmjs.org/define-property/-/define-property-0.2.5.tgz",
@@ -22008,6 +22108,14 @@
         "vary": "~1.1.2"
       },
       "dependencies": {
+        "debug": {
+          "version": "2.6.9",
+          "resolved": "https://registry.npmjs.org/debug/-/debug-2.6.9.tgz",
+          "integrity": "sha512-bC7ElrdJaJnPbAP+1EotYvqZsb3ecl5wi6Bfi6BJTUcNowp6cvspg0jXznRTKDjm/E7AdgFBVeAPVMNcKGsHMA==",
+          "requires": {
+            "ms": "2.0.0"
+          }
+        },
         "path-to-regexp": {
           "version": "0.1.7",
           "resolved": "https://registry.npmjs.org/path-to-regexp/-/path-to-regexp-0.1.7.tgz",
@@ -22263,6 +22371,16 @@
         "parseurl": "~1.3.3",
         "statuses": "~1.5.0",
         "unpipe": "~1.0.0"
+      },
+      "dependencies": {
+        "debug": {
+          "version": "2.6.9",
+          "resolved": "https://registry.npmjs.org/debug/-/debug-2.6.9.tgz",
+          "integrity": "sha512-bC7ElrdJaJnPbAP+1EotYvqZsb3ecl5wi6Bfi6BJTUcNowp6cvspg0jXznRTKDjm/E7AdgFBVeAPVMNcKGsHMA==",
+          "requires": {
+            "ms": "2.0.0"
+          }
+        }
       }
     },
     "find-up": {
@@ -25392,8 +25510,7 @@
     "observable-to-async-generator": {
       "version": "1.0.1-rc",
       "resolved": "https://registry.npmjs.org/observable-to-async-generator/-/observable-to-async-generator-1.0.1-rc.tgz",
-      "integrity": "sha512-fSV1h5D6fv1X3vfeOQF6u7Mq5VUrM1K5AxfgAIjVqLBhDHQFg/Jp9J3fOc2CR6EDr/JFjs7IxbRlvDigVh7Wgg==",
+      "integrity": "sha512-fSV1h5D6fv1X3vfeOQF6u7Mq5VUrM1K5AxfgAIjVqLBhDHQFg/Jp9J3fOc2CR6EDr/JFjs7IxbRlvDigVh7Wgg=="
-      "requires": {}
     },
     "on-finished": {
       "version": "2.3.0",
@@ -26838,6 +26955,21 @@
         "statuses": "~1.5.0"
       },
       "dependencies": {
+        "debug": {
+          "version": "2.6.9",
+          "resolved": "https://registry.npmjs.org/debug/-/debug-2.6.9.tgz",
+          "integrity": "sha512-bC7ElrdJaJnPbAP+1EotYvqZsb3ecl5wi6Bfi6BJTUcNowp6cvspg0jXznRTKDjm/E7AdgFBVeAPVMNcKGsHMA==",
+          "requires": {
+            "ms": "2.0.0"
+          },
+          "dependencies": {
+            "ms": {
+              "version": "2.0.0",
+              "resolved": "https://registry.npmjs.org/ms/-/ms-2.0.0.tgz",
+              "integrity": "sha1-VgiurfwAvmwpAd9fmGF4jeDVl8g="
+            }
+          }
+        },
         "ms": {
           "version": "2.1.1",
           "resolved": "https://registry.npmjs.org/ms/-/ms-2.1.1.tgz",
@@ -27024,6 +27156,15 @@
         "use": "^3.1.0"
       },
       "dependencies": {
+        "debug": {
+          "version": "2.6.9",
+          "resolved": "https://registry.npmjs.org/debug/-/debug-2.6.9.tgz",
+          "integrity": "sha512-bC7ElrdJaJnPbAP+1EotYvqZsb3ecl5wi6Bfi6BJTUcNowp6cvspg0jXznRTKDjm/E7AdgFBVeAPVMNcKGsHMA==",
+          "dev": true,
+          "requires": {
+            "ms": "2.0.0"
+          }
+        },
         "define-property": {
           "version": "0.2.5",
           "resolved": "https://registry.npmjs.org/define-property/-/define-property-0.2.5.tgz",

package.json

@@ -10,7 +10,7 @@
     "build": "nest build",
     "format": "prettier --write \"src/**/*.ts\" \"test/**/*.ts\"",
     "start": "nest start",
-    "start:dev": "nest start --watch",
+    "start:dev": "DEBUG=fennec:*,simple-git:* nest start --watch",
     "start:debug": "DEBUG=simple-git,simple-git:* nest start --debug --watch",
     "start:prod": "node dist/main",
     "lint": "eslint \"{src,apps,libs,test}/**/*.ts\" --fix",
@@ -36,6 +36,7 @@
     "bull": "^3.20.1",
     "class-transformer": "^0.3.2",
     "class-validator": "^0.13.1",
+    "debug": "^4.3.1",
     "graphql": "^15.5.0",
     "graphql-tools": "^7.0.2",
     "js-yaml": "^4.0.0",
@@ -53,6 +54,7 @@
     "@nestjs/cli": "^7.5.1",
     "@nestjs/schematics": "^7.1.3",
     "@nestjs/testing": "^7.5.1",
+    "@types/debug": "^4.1.5",
     "@types/express": "^4.17.8",
     "@types/jest": "^26.0.15",
     "@types/js-yaml": "^4.0.0",

src/app.module.ts

@@ -51,7 +51,7 @@ import { RedisModule } from 'nestjs-redis';
         host: configService.get<string>('db.redis.host', 'localhost'),
         port: configService.get<number>('db.redis.port', 6379),
         password: configService.get<string>('db.redis.password', ''),
-        keyPrefix: configService.get<string>('db.redis.prefix', 'fennec'),
+        keyPrefix: configService.get<string>('db.redis.prefix', 'fennec') + ':',
       }),
       inject: [ConfigService],
     }),

src/pipeline-tasks/pipeline-task.consumer.ts

@@ -16,6 +16,10 @@ import { PipelineUnits } from './enums/pipeline-units.enum';
 import { PipelineTaskLogMessage } from './models/pipeline-task-log-message.module';
 import { TaskStatuses } from './enums/task-statuses.enum';
 import { PipelineTaskLogsService } from './pipeline-task-logs.service';
+import debug from 'debug';
+
+const log = debug('fennec:pipeline-tasks:consumer');
+
 @Processor(PIPELINE_TASK_QUEUE)
 export class PipelineTaskConsumer {
   constructor(
@@ -35,6 +39,7 @@ export class PipelineTaskConsumer {
     task.startedAt = new Date();
     task.status = TaskStatuses.working;
     task = await this.service.updateTask(task);
+    log('start job');
     await job.update(task);
 
     const workspaceRoot = this.reposService.getWorkspaceRootByTask(task);
@@ -46,20 +51,26 @@ export class PipelineTaskConsumer {
         ) ?? { type: type, scripts: [] },
     );
 
+    log('task have [%o] units', units);
     try {
       for (const unit of units) {
         const unitLog = new PipelineTaskLogs();
         unitLog.unit = unit.type;
         unitLog.startedAt = new Date();
+        log('curr unit is %s', unit.type);
         try {
           // 检出代码前执行 git checkout
           if (unit.type === PipelineUnits.checkout) {
+            log('begin checkout');
             await this.reposService.checkout(task, workspaceRoot);
             unitLog.status = TaskStatuses.success;
+            log('end checkout');
           }
           for (const script of unit.scripts) {
             unitLog.logs += `[RUN SCRIPT] ${script}`;
+            log('begin runScript %s', script);
             await this.runScript(script, workspaceRoot, task, unit.type);
+            log('end runScript %s', script);
           }
           unitLog.status = TaskStatuses.success;
         } catch (err) {
@@ -82,7 +93,7 @@ export class PipelineTaskConsumer {
       task.status = TaskStatuses.success;
     } catch (err) {
       task.status = TaskStatuses.failed;
-      console.log(err);
+      log('task is failed', err);
     } finally {
       task.endedAt = new Date();
       task = await this.service.updateTask(task);
@@ -124,11 +135,13 @@ export class PipelineTaskConsumer {
 
   @OnQueueCompleted()
   onCompleted(job: Job<PipelineTask>) {
+    log('queue onCompleted');
     this.service.doNextTask(job.data.pipeline);
   }
 
   @OnQueueFailed()
   onFailed(job: Job<PipelineTask>) {
+    log('queue onFailed');
     this.service.doNextTask(job.data.pipeline);
   }
 }

src/pipeline-tasks/pipeline-tasks.service.ts

@@ -12,6 +12,9 @@ import { LockFailedException } from '../commons/exceptions/lock-failed.exception
 import { PubSub } from 'apollo-server-express';
 import { TaskStatuses } from './enums/task-statuses.enum';
 import { isNil } from 'ramda';
+import debug from 'debug';
+
+const log = debug('fennec:pipeline-tasks:service');
 
 @Injectable()
 export class PipelineTasksService {
@@ -30,23 +33,30 @@ export class PipelineTasksService {
       where: { id: dto.pipelineId },
       relations: ['project'],
     });
-    // const hasUnfinishedTask = await this.repository
+    const hasUnfinishedTask = await this.repository
-    //   .findOne({
+      .findOne({
-    //     pipelineId: pipeline.id,
+        pipelineId: dto.pipelineId,
-    //     status: In([TaskStatuses.pending, TaskStatuses.working]),
+        commit: dto.commit,
-    //   })
+        status: In([TaskStatuses.pending, TaskStatuses.working]),
-    //   .then((val) => !isNil(val));
+      })
-    // if (hasUnfinishedTask) {
+      .then((val) => !isNil(val));
-    //   throw new ConflictException(
+    if (hasUnfinishedTask) {
-    //     'there are still unfinished task in the current pipeline.',
+      throw new ConflictException(
-    //   );
+        'There are the same tasks among the unfinished tasks!',
-    // }
+      );
+    }
     const task = await this.repository.save(this.repository.create(dto));
     task.pipeline = pipeline;
 
     const tasksKey = this.getRedisTokens(pipeline)[1];
     const redis = this.redis.getClient();
     await redis.lpush(tasksKey, JSON.stringify(task));
+    log(
+      'add task %s:%s-%s',
+      task.id,
+      task.pipeline.branch,
+      task.commit.slice(0, 6),
+    );
     await this.doNextTask(pipeline);
     return task;
   }
@@ -63,6 +73,7 @@ export class PipelineTasksService {
     const [lckKey, tasksKey] = this.getRedisTokens(pipeline);
     const redis = this.redis.getClient();
 
+    log('doNextTask()');
     const unLck = await new Promise<() => Promise<void>>(
       async (resolve, reject) => {
         const lckValue = Date.now().toString();
@@ -90,7 +101,15 @@ export class PipelineTasksService {
       (await redis.rpop(tasksKey).finally(() => unLck())) ?? 'null',
     );
     if (task) {
+      log(
+        'add task (%s:%s-%s) to queue',
+        task.id,
+        task.pipeline.branch,
+        task.commit.slice(0, 6),
+      );
       await this.queue.add(task);
+    } else {
+      log('task is empty');
     }
   }