fix: time log

src/cli-loading.ts

@@ -1,6 +1,6 @@
 import Spinners from 'cli-spinners'
 import logFigures from 'figures'
-import { Is } from './utils'
+import { formatDuration, Is } from './utils'
 import chalk from 'chalk'
 import { DepsTree, TaskState } from './task-manager'
 import wcwidth from 'wcwidth'
@@ -53,7 +53,7 @@ export class CliLoading {
  : f => f
  let skipped = depsTree.state === TaskState.skipped
  output.push(
- `${indent}${symbol} ${color(depsTree.task.name)}${skipped ? chalk.gray(` [skipped]`) : ''}${depsTree.priority ? chalk.gray(` [priority: ${depsTree.priority}]`) : ''}`,
+ `${indent}${symbol} ${color(depsTree.task.name)}${skipped ? chalk.gray(` [skipped]`) : ''}${depsTree.priority ? chalk.gray(` [priority: ${depsTree.priority}]`) : ''}${(depsTree.duration>=0) ? chalk.gray(` [duration: ${formatDuration(depsTree.duration)}]`) : ''}`,
  )
  let childDeps = ([] as DepsTree[])
  .concat(...depsTree.asyncDeps)
@@ -97,6 +97,7 @@ export class CliLoading {
  if (i > 0) {
  this.props.stream.moveCursor(0, -1)
  }
+ // @ts-ignore
  this.props.stream.clearLine && (this.props.stream as any).clearLine()
  this.props.stream.cursorTo(0)
  }

src/cli.ts

@@ -24,18 +24,12 @@ taskManager.getTasks().forEach(t => {
  let { globalOptions } = taskManager
  globalOptions.rawArgs = taskCli.rawArgs
  globalOptions.options = options
- let startTime = Date.now()
  await taskManager.run(t.name, {
  options,
  rawArgs: taskCli.rawArgs.slice(3),
  }).catch(err => {
  logger.error(err)
  throw err
- }).finally(() => {
- if (taskManager.globalOptions.showTaskDuration) {
- let duration = (Date.now() - startTime)/1000
- logger.info(`Done in ${duration.toFixed(2)}s`)
- }
  })
  })
 })

src/task-manager.ts

@@ -1,14 +1,13 @@
 import { CliLoading } from './cli-loading'
 import { Task } from './task'
 import chalk from 'chalk'
-import { hashAny, defaults, Is, DefaultLogFile } from './utils'
+import { hashAny, defaults, Is, DefaultLogFile, formatDuration } from './utils'
 import { Writable, Stream } from 'stream'
 import { fs } from './fs'
 import { ShellContext } from './exec'
 import { logger, ILogInfo, ILoggerProps, LogLevels, Logger } from './logger'
 import figures from 'figures'
 
-
 export interface GlobalOptions {
  /**
  * @default true
@@ -60,16 +59,27 @@ export interface DepsTree {
  state: TaskState
  depth: number
  priority: number
+ duration: number
 }
 
 export class TaskContext<O = any> extends ShellContext {
  fs = fs
  protected _logger: Logger
- get debug(){return this._logger.debug}
- get info(){return this._logger.info}
- get log(){return this._logger.log}
- get warn(){return this._logger.warn}
- get error(){return this._logger.error}
+ get debug() {
+ return this._logger.debug
+ }
+ get info() {
+ return this._logger.info
+ }
+ get log() {
+ return this._logger.log
+ }
+ get warn() {
+ return this._logger.warn
+ }
+ get error() {
+ return this._logger.error
+ }
  constructor(public task: Task<O>, public global: GlobalOptions) {
  super()
  this.logCommand = defaults(task.logger && task.logCommand, global.logCommand, true)
@@ -96,7 +106,7 @@ export class TaskContext<O = any> extends ShellContext {
 }
 
 export type Callback = {
- fn: (args?: any) => void | Promise<void>,
+ fn: (args?: any) => void | Promise<void>
  namespaces: string[]
 }
 export type ListenerNames = 'before' | 'after' | 'onerror'
@@ -114,12 +124,11 @@ export class TaskManager {
  options: {},
  indent: 3,
  logCommand: true,
- logger: {
- },
+ logger: {},
  showTaskDuration: true,
  }
  getTasks() {
- return Object.keys(this._tasks).map(k => this._tasks[k])
+ return Object.keys(this._tasks).map((k) => this._tasks[k])
  }
  addTask(task: Task) {
  if (this._tasks[task.name]) {
@@ -133,12 +142,12 @@ export class TaskManager {
  resolveDependencyTree(t: Task, depth = 0): DepsTree {
  let asyncDeps: DepsTree[][] = []
  let syncDeps: DepsTree[] = []
- let asyncDepsMap: {[k: number]: DepsTree[]} = {}
+ let asyncDepsMap: { [k: number]: DepsTree[] } = {}
  if (t.async === true) {
  t.async = 0
  }
  if (t.dependencies) {
- t.dependencies.forEach(taskDep => {
+ t.dependencies.forEach((taskDep) => {
  let fullTask = this._tasks[taskDep.name]
  if (!fullTask) {
  throw new TypeError(`Cannot find task with name [${taskDep.name}]`)
@@ -152,32 +161,30 @@ export class TaskManager {
  },
  }
  let depTask = this.resolveDependencyTree(t, depth + 1)
- if (t.async === false || !Is.defed(t.async)) { // sync tasks
+ if (t.async === false || !Is.defed(t.async)) {
+ // sync tasks
  syncDeps.push(depTask)
  } else {
  let idx = t.async === true ? 0 : t.async
- let deps = asyncDepsMap[idx] = asyncDepsMap[idx] || []
+ let deps = (asyncDepsMap[idx] = asyncDepsMap[idx] || [])
  deps.push(depTask)
  }
  })
  asyncDeps = []
- Object.keys(asyncDepsMap)  // Sort async deps via priority, bigger is former
- .map(Number)
- .sort((a, b) => b - a)
- .map(k => (asyncDeps.push(asyncDepsMap[k])))
+ Object.keys(asyncDepsMap) // Sort async deps via priority, bigger is former
+  .map(Number)
+  .sort((a, b) => b - a)
+  .map((k) => asyncDeps.push(asyncDepsMap[k]))
  }
  return {
- uid:
- Date.now().toString(36) +
- Math.random()
- .toString(36)
- .slice(2),
+ uid: Date.now().toString(36) + Math.random().toString(36).slice(2),
  task: t,
  asyncDeps,
  syncDeps,
  state: TaskState.waiting,
  depth,
  priority: Is.num(t.async) ? t.async : 0,
+ duration: -1,
  }
  }
 
@@ -188,6 +195,7 @@ export class TaskManager {
  let t = depsTree.task
  let taskHash = hashAny(t)
  let loading = this.isLoading(t, props)
+ let startTime = Date.now()
 
  let didResolved = null as ((value?: any) => void) | null
  if (this._didMap.has(taskHash) && !t.force) {
@@ -198,7 +206,7 @@ export class TaskManager {
  }
  return
  }
- this._didMap.set(taskHash, new Promise(res => (didResolved = res)))
+ this._didMap.set(taskHash, new Promise((res) => (didResolved = res)))
 
  t.rawArgs = props.rawArgs || []
  const ctx = new TaskContext(t, this.globalOptions)
@@ -218,9 +226,7 @@ export class TaskManager {
  })(),
  (async () => {
  for (const deps of depsTree.asyncDeps) {
- await Promise.all(
- deps.map(t => this.runDepsTree(t, { ...depProps, parentCtx: ctx })),
- )
+ await Promise.all(deps.map((t) => this.runDepsTree(t, { ...depProps, parentCtx: ctx })))
  }
  })(),
  ])
@@ -237,9 +243,6 @@ export class TaskManager {
 
  if (!loading) {
  console.log(chalk.yellow('Task: ') + t.name)
- let retPromise = t.fn && t.fn(ctx)
- didResolved && didResolved()
- return retPromise
  }
 
  try {
@@ -250,12 +253,21 @@ export class TaskManager {
  } catch (error) {
  depsTree.state = TaskState.failed
  throw error
+ } finally {
+ if (this.globalOptions.showTaskDuration) {
+ depsTree.duration = Date.now() - startTime
+ if (!loading) {
+ console.log(
+ chalk.yellow('Task: ') + t.name + ` done in ${formatDuration(depsTree.duration)}`,
+ )
+ }
+ }
  }
  }
  async runListner(name: ListenerNames, ns: string[], args: any[] = []) {
  const listeners = this.listeners[name].slice()
  if (name === 'before') {
- listeners.sort((a, b) => a.namespaces.length - b .namespaces.length)
+ listeners.sort((a, b) => a.namespaces.length - b.namespaces.length)
  } else {
  listeners.sort((a, b) => b.namespaces.length - a.namespaces.length)
  }
@@ -282,7 +294,8 @@ export class TaskManager {
  ...props,
  }
  this._tasks.all =
- this._tasks.all || (await import('./task').then(e => e.task('all', Object.keys(this._tasks))))
+ this._tasks.all ||
+ (await import('./task').then((e) => e.task('all', Object.keys(this._tasks))))
  this._tasks.default = this._tasks.default || this._tasks.all
 
  if (!this._tasks[Is.str(name) ? name : name.name]) {

src/test/fixtures/snaps/Foyfile1_ts_aa_-a

@@ -6,7 +6,7 @@ CACError: option `-a <val>` value is missing
  at Command.checkOptionValue (/home/z/Mine/foy/node_modules/cac/dist/index.js:404:17)
  at CAC.runMatchedCommand (/home/z/Mine/foy/node_modules/cac/dist/index.js:586:13)
  at CAC.parse (/home/z/Mine/foy/node_modules/cac/dist/index.js:526:12)
- at Object.<anonymous> (/home/z/Mine/foy/src/cli.ts:59:9)
+ at Object.<anonymous> (/home/z/Mine/foy/src/cli.ts:53:9)
  at Module._compile (internal/modules/cjs/loader.js:1085:14)
  at Module.m._compile (/home/z/Mine/foy/node_modules/ts-node/src/index.ts:1056:23)
  at Module._extensions..js (internal/modules/cjs/loader.js:1114:10)

src/test/fixtures/snaps/Foyfile1_ts_aa_-a_1_-b_1_-d

@@ -6,7 +6,7 @@ CACError: Unknown option `-b`
  at Command.checkUnknownOptions (/home/z/Mine/foy/node_modules/cac/dist/index.js:391:17)
  at CAC.runMatchedCommand (/home/z/Mine/foy/node_modules/cac/dist/index.js:585:13)
  at CAC.parse (/home/z/Mine/foy/node_modules/cac/dist/index.js:526:12)
- at Object.<anonymous> (/home/z/Mine/foy/src/cli.ts:59:9)
+ at Object.<anonymous> (/home/z/Mine/foy/src/cli.ts:53:9)
  at Module._compile (internal/modules/cjs/loader.js:1085:14)
  at Module.m._compile (/home/z/Mine/foy/node_modules/ts-node/src/index.ts:1056:23)
  at Module._extensions..js (internal/modules/cjs/loader.js:1114:10)

src/test/fixtures/snaps/Foyfile1_ts_aa_-a_bb

@@ -6,4 +6,4 @@ Task: aa
 [info] { '--': [], a: 'bb' }
 [warn] { '--': [], a: 'bb' }
 [error] { '--': [], a: 'bb' }
-[info] Done in 0.01s
+Task: aa done in 0s

src/test/fixtures/snaps/Foyfile1_ts_async

@@ -6,6 +6,8 @@ DependencyGraph for task [async]:
 Task: wait
 Task: wait
 wait 1
+Task: wait done in 0s
 wait 100
+Task: wait done in 0.1s
 Task: async
-[info] Done in 0.11s
+Task: async done in 0.1s

src/test/fixtures/snaps/Foyfile1_ts_async_priority

@@ -5,7 +5,9 @@ DependencyGraph for task [async:priority]:
 
 Task: wait
 wait 100
+Task: wait done in 0.1s
 Task: wait
 wait 1
+Task: wait done in 0s
 Task: async:priority
-[info] Done in 0.11s
+Task: async:priority done in 0.1s

src/test/fixtures/snaps/Foyfile1_ts_bb

@@ -7,6 +7,7 @@ Task: aa
 [info] {}
 [warn] {}
 [error] {}
+Task: aa done in 0s
 Task: bb
 [debug] { '--': [] } { '--': [] }
-[info] Done in 0.02s
+Task: bb done in 0.01s

src/test/fixtures/snaps/Foyfile1_ts_cc

@@ -9,9 +9,11 @@ Task: aa
 [info] {}
 [warn] {}
 [error] {}
+Task: aa done in 0s
 Task: bb
 [debug] { test: 123 } { '--': [], c: 123 }
+Task: bb done in 0.01s
 Skip task: aa
 Task: cc
 [debug] { '--': [], c: 123 }
-[info] Done in 0.01s
+Task: cc done in 0.01s

src/test/fixtures/snaps/Foyfile1_ts_dd

@@ -5,4 +5,4 @@ Task: dd
 [info] $ pwd
 [debug] p.stdout.trim() === ctx.cwd() true
 [debug] true
-[info] Done in 0.03s
+Task: dd done in 0.11s

src/test/fixtures/snaps/Foyfile1_ts_ee

@@ -6,4 +6,4 @@ Task: ee
 [info] $ echo bb
 aa
 bb
-[info] Done in 0.08s
+Task: ee done in 0.05s

src/test/fixtures/snaps/Foyfile1_ts_ff

@@ -8,10 +8,12 @@ Task: aa
 [info] { aa: 1 }
 [warn] { aa: 1 }
 [error] { aa: 1 }
+Task: aa done in 0s
 Task: aa
 [debug] { aa: 2 }
 [info] { aa: 2 }
 [warn] { aa: 2 }
 [error] { aa: 2 }
+Task: aa done in 0s
 Task: ff
-[info] Done in 0.01s
+Task: ff done in 0.01s

src/test/fixtures/snaps/Foyfile1_ts_force

@@ -8,10 +8,12 @@ Task: aa
 [info] { noop: [Function: noop] }
 [warn] { noop: [Function: noop] }
 [error] { noop: [Function: noop] }
+Task: aa done in 0s
 Task: aa
 [debug] { noop: [Function: noop] }
 [info] { noop: [Function: noop] }
 [warn] { noop: [Function: noop] }
 [error] { noop: [Function: noop] }
+Task: aa done in 0s
 Task: force
-[info] Done in 0.01s
+Task: force done in 0s

src/test/fixtures/snaps/Foyfile1_ts_notForce

@@ -8,6 +8,7 @@ Task: aa
 [info] { noop: [Function: noop] }
 [warn] { noop: [Function: noop] }
 [error] { noop: [Function: noop] }
+Task: aa done in 0s
 Skip task: aa
 Task: notForce
-[info] Done in 0.01s
+Task: notForce done in 0.01s

src/test/fixtures/snaps/Foyfile1_ts_pushpopd

@@ -9,4 +9,4 @@ Task: pushpopd
 [info] cd works true
 [info] popd works true
 [info] popd 2 works true
-[info] Done in 0.03s
+Task: pushpopd done in 0.03s

src/test/fixtures/snaps/Foyfile1_ts_resolveOptions

@@ -4,6 +4,7 @@ DependencyGraph for task [resolveOptions]:
 
 Task: logOptions
 [debug] logOptions { aa: 1, '--': [], c: 1, rawArgs: [] } { '--': [], c: 1 } []
+Task: logOptions done in 0s
 Task: resolveOptions
 rawArgs []
-[info] Done in 0.01s
+Task: resolveOptions done in 0s