Skip to content

Commit

Permalink
feat: more clear logging using Apex-inspired logger
Browse files Browse the repository at this point in the history
  • Loading branch information
develar committed Jan 2, 2018
1 parent 63fdecb commit fd70412
Show file tree
Hide file tree
Showing 63 changed files with 565 additions and 433 deletions.
3 changes: 1 addition & 2 deletions package.json
Original file line number Diff line number Diff line change
Expand Up @@ -53,11 +53,10 @@
"lodash.isequal": "^4.5.0",
"mime": "^2.1.0",
"minimatch": "^3.0.4",
"node-emoji": "^1.8.1",
"normalize-package-data": "^2.4.0",
"parse-color": "^1.0.0",
"plist": "^2.1.0",
"read-config-file": "1.2.2",
"read-config-file": "2.0.1",
"sanitize-filename": "^1.6.1",
"sax": "^1.2.4",
"semver": "^5.4.1",
Expand Down
1 change: 0 additions & 1 deletion packages/builder-util/package.json
Original file line number Diff line number Diff line change
Expand Up @@ -18,7 +18,6 @@
"bluebird-lst": "^1.0.5",
"chalk": "^2.3.0",
"debug": "^3.1.0",
"node-emoji": "^1.8.1",
"builder-util-runtime": "^0.0.0-semantic-release",
"source-map-support": "^0.5.0",
"7zip-bin": "^2.3.4",
Expand Down
26 changes: 12 additions & 14 deletions packages/builder-util/src/binDownload.ts
Original file line number Diff line number Diff line change
@@ -1,16 +1,12 @@
import { path7za } from "7zip-bin"
import BluebirdPromise from "bluebird-lst"
import { CancellationToken, DownloadOptions } from "builder-util-runtime"
import _debug from "debug"
import { emptyDir, rename, unlink } from "fs-extra-p"
import * as path from "path"
import { getTempName } from "temp-file"
import { statOrNull } from "./fs"
import { log, warn } from "./log"
import { httpExecutor } from "./nodeHttpExecutor"
import { debug7zArgs, getCacheDirectory, spawn } from "./util"

const debug = _debug("electron-builder:binDownload")
import { debug7zArgs, getCacheDirectory, log, spawn } from "./util"

const versionToPromise = new Map<string, BluebirdPromise<string>>()

Expand Down Expand Up @@ -44,19 +40,20 @@ async function doGetBin(name: string, dirName: string, url: string, checksum: st
const cachePath = path.join(getCacheDirectory(), name)
const dirPath = path.join(cachePath, dirName)

const logFlags = {path: dirPath}

const dirStat = await statOrNull(dirPath)
//noinspection ES6MissingAwait
if (dirStat != null && dirStat.isDirectory()) {
debug(`Found existing ${name} ${dirPath}`)
log.debug(logFlags, `found existing`)
return dirPath
}

log(`Downloading ${dirName}, please wait`)
log.info({...logFlags, url}, `downloading`)

// 7z cannot be extracted from the input stream, temp file is required
const tempUnpackDir = path.join(cachePath, getTempName())
const archiveName = `${tempUnpackDir}.7z`
debug(`Download ${name} from ${url} to ${archiveName}`)
// 7z doesn't create out dir, so, we don't create dir in parallel to download - dir creation will create parent dirs for archive file also
await emptyDir(tempUnpackDir)
const options: DownloadOptions = {
Expand All @@ -80,9 +77,12 @@ async function doGetBin(name: string, dirName: string, url: string, checksum: st
throw e
}

warn(`Cannot download ${name}, attempt #${attemptNumber}: ${e}`)
log.warn({...logFlags, attempt: attemptNumber}, `cannot download: ${e}`)
await new BluebirdPromise((resolve, reject) => {
setTimeout(() => httpExecutor.download(url, archiveName, options).then(resolve).catch(reject), 1000 * attemptNumber)
setTimeout(() =>
httpExecutor
.download(url, archiveName, options)
.then(resolve).catch(reject), 1000 * attemptNumber)
})
}
}
Expand All @@ -93,12 +93,10 @@ async function doGetBin(name: string, dirName: string, url: string, checksum: st

await BluebirdPromise.all([
rename(tempUnpackDir, dirPath)
.catch(e => {
console.warn(`Cannot move downloaded ${name} into final location (another process downloaded faster?): ${e}`)
}),
.catch(e => log.debug({...logFlags, tempUnpackDir, e}, `cannot move downloaded into final location (another process downloaded faster?)`)),
unlink(archiveName),
])

debug(`${name}} downloaded to ${dirPath}`)
log.debug(logFlags, `downloaded`)
return dirPath
}
16 changes: 8 additions & 8 deletions packages/builder-util/src/fs.ts
Original file line number Diff line number Diff line change
Expand Up @@ -3,8 +3,8 @@ import { access, chmod, copyFile as _nodeCopyFile, createReadStream, createWrite
import isCi from "is-ci"
import * as path from "path"
import Mode from "stat-mode"
import { log } from "./log"
import { orNullIfFileNotExist } from "./promise"
import { debug } from "./util"

export const MAX_FILE_REQUESTS = 8
export const CONCURRENCY = {concurrency: MAX_FILE_REQUESTS}
Expand Down Expand Up @@ -150,17 +150,17 @@ export function copyOrLinkFile(src: string, dest: string, stats?: Stats | null,
mode.others.read = true

if (originalModeNumber !== stats.mode) {
if (debug.enabled) {
if (log.isDebugEnabled) {
const oldMode = new Mode({mode: originalModeNumber})
debug(`${dest} permissions fixed from ${oldMode.toOctal()} (${oldMode.toString()}) to ${mode.toOctal()} (${mode.toString()})`)
log.debug({file: dest, oldMode, mode}, "permissions fixed from")
}

// https://helgeklein.com/blog/2009/05/hard-links-and-permissions-acls/
// Permissions on all hard links to the same data on disk are always identical. The same applies to attributes.
// That means if you change the permissions/owner/attributes on one hard link, you will immediately see the changes on all other hard links.
if (isUseHardLink) {
isUseHardLink = false
debug(`${dest} will be copied, but not linked, because file permissions need to be fixed`)
log.debug({dest}, "copied, but not linked, because file permissions need to be fixed")
}
}
}
Expand All @@ -170,8 +170,8 @@ export function copyOrLinkFile(src: string, dest: string, stats?: Stats | null,
.catch(e => {
if (e.code === "EXDEV") {
const isLog = exDevErrorHandler == null ? true : exDevErrorHandler()
if (isLog && debug.enabled) {
debug(`Cannot copy using hard link: ${e.message}`)
if (isLog && log.isDebugEnabled) {
log.debug({error: e.message}, "cannot copy using hard link")
}
return doCopyFile(src, dest, stats)
}
Expand Down Expand Up @@ -260,8 +260,8 @@ export interface CopyDirOptions {
export function copyDir(src: string, destination: string, options: CopyDirOptions = {}): Promise<any> {
const fileCopier = new FileCopier(options.isUseHardLink, options.transformer)

if (debug.enabled) {
debug(`Copying ${src} to ${destination}${fileCopier.isUseHardLink ? " using hard links" : ""}`)
if (log.isDebugEnabled) {
log.debug({src, destination}, `copying${fileCopier.isUseHardLink ? " using hard links" : ""}`)
}

const createdSourceDirs = new Set<string>()
Expand Down
114 changes: 83 additions & 31 deletions packages/builder-util/src/log.ts
Original file line number Diff line number Diff line change
@@ -1,58 +1,110 @@
import BluebirdPromise from "bluebird-lst"
import chalk from "chalk"
import { get as getEmoji } from "node-emoji"
import chalk, { Chalk } from "chalk"
import _debug from "debug"
import WritableStream = NodeJS.WritableStream

let printer: ((message: string) => void) | null = null

export const debug = _debug("electron-builder")

export interface Fields {
[index: string]: any
}

export function setPrinter(value: ((message: string) => void) | null) {
printer = value
}

class Logger {
export type LogLevel = "info" | "warn" | "debug" | "notice" | "error"

export const PADDING = 3

export class Logger {
constructor(protected readonly stream: WritableStream) {
}

warn(message: string): void {
this.log(chalk.yellow(`Warning: ${message}`))
messageTransformer: ((message: string, level: LogLevel) => string) = it => it

filePath(file: string) {
const cwd = process.cwd()
return file.startsWith(cwd) ? file.substring(cwd.length + 1) : file
}

log(message: string): void {
if (printer == null) {
this.stream.write(`${message}\n`)
// noinspection JSMethodCanBeStatic
get isDebugEnabled() {
return debug.enabled
}

info(messageOrFields: Fields | null | string, message?: string) {
this.doLog(message, messageOrFields, "info")
}

notice(messageOrFields: Fields | null | string, message?: string): void {
this.doLog(message, messageOrFields, "notice")
}

warn(messageOrFields: Fields | null | string, message?: string): void {
this.doLog(message, messageOrFields, "warn")
}

debug(fields: Fields | null, message: string) {
if (debug.enabled) {
this._doLog(message, fields, "debug")
}
}

private doLog(message: string | undefined, messageOrFields: Fields | null | string, level: LogLevel) {
if (message === undefined) {
this._doLog(messageOrFields as string, null, level)
}
else {
printer(message)
this._doLog(message, messageOrFields as Fields | null, level)
}
}

task(title: string, _promise: BluebirdPromise<any> | Promise<any>): BluebirdPromise<any> {
const promise = _promise as BluebirdPromise<any>
this.log(title)
return promise
private _doLog(message: string, fields: Fields | null, level: LogLevel) {
const levelIndicator = "•"
const color = LEVEL_TO_COLOR[level]
this.stream.write(`${" ".repeat(PADDING)}${color(levelIndicator)} `)
this.stream.write(Logger.createMessage(this.messageTransformer(message, level), fields, level, color))
this.stream.write("\n")
}
}

class TtyLogger extends Logger {
constructor(stream: WritableStream) {
super(stream)
}
static createMessage(message: string, fields: Fields | null, level: LogLevel, color: (it: string) => string): string {
let text = message

warn(message: string): void {
this.log(`${getEmoji("warning")} ${chalk.yellow(message)}`)
}
}
const fieldPadding = " ".repeat(Math.max(0, 16 - message.length))
text += fieldPadding

if (fields != null) {
for (const name of Object.keys(fields)) {
let fieldValue = fields[name]
if (fieldValue != null && typeof fieldValue === "string" && fieldValue.includes("\n")) {
fieldValue = ("\n" + fieldValue)
.replace(/\n/g, `\n${" ".repeat(PADDING)}${fieldPadding}`)
}

text += ` ${color(name)}=${Array.isArray(fieldValue) ? JSON.stringify(fieldValue) : fieldValue}`
}
}

const logger = (process.stdout as any).isTTY ? new TtyLogger(process.stdout) : new Logger(process.stdout)
return text
}

export function warn(message: string) {
logger.warn(message)
log(message: string): void {
if (printer == null) {
this.stream.write(`${message}\n`)
}
else {
printer(message)
}
}
}

export function log(message: string) {
logger.log(message)
const LEVEL_TO_COLOR: { [index: string]: Chalk } = {
info: chalk.blue,
notice: chalk.yellow,
warn: chalk.yellow,
debug: chalk.gray,
}

export function task(title: string, promise: BluebirdPromise<any> | Promise<any>): BluebirdPromise<any> {
return logger.task(title, promise)
}
export const log = new Logger(process.stdout)
4 changes: 2 additions & 2 deletions packages/builder-util/src/macosVersion.ts
Original file line number Diff line number Diff line change
@@ -1,15 +1,15 @@
import { readFile } from "fs-extra-p"
import { Lazy } from "lazy-val"
import * as semver from "semver"
import { debug } from "./util"
import { log } from "./util"

const macOsVersion = new Lazy<string>(async () => {
const file = await readFile("/System/Library/CoreServices/SystemVersion.plist", "utf8")
const matches = /<key>ProductVersion<\/key>[\s\S]*<string>([\d.]+)<\/string>/.exec(file)
if (!matches) {
throw new Error("Couldn't find the macOS version")
}
debug(`macOS version: ${matches[1]}`)
log.debug({version: matches[1]}, "macOS version")
return clean(matches[1])
})

Expand Down
14 changes: 7 additions & 7 deletions packages/builder-util/src/util.ts
Original file line number Diff line number Diff line change
Expand Up @@ -8,10 +8,11 @@ import { safeDump } from "js-yaml"
import { homedir, tmpdir } from "os"
import * as path from "path"
import "source-map-support/register"
import { debug, log } from "./log"

export { safeStringifyJson } from "builder-util-runtime"
export { TmpDir } from "temp-file"
export { log, warn, task } from "./log"
export { log, debug } from "./log"
export { isMacOsSierra, isCanSignDmg } from "./macosVersion"
export { execWine, prepareWindowsExecutableArgs } from "./wine"
export { Arch, toLinuxArchString, getArchSuffix, ArchType, archFromString } from "./arch"
Expand All @@ -22,7 +23,6 @@ export { hashFile } from "./hash"
export { copyFile } from "./fs"
export { asArray } from "builder-util-runtime"

export const debug = _debug("electron-builder")
export const debug7z = _debug("electron-builder:7z")

export function serializeToYaml(object: object) {
Expand Down Expand Up @@ -59,7 +59,7 @@ function getProcessEnv(env: { [key: string]: string | undefined } | undefined |

export function exec(file: string, args?: Array<string> | null, options?: ExecFileOptions, isLogOutIfDebug = true): Promise<string> {
if (debug.enabled) {
debug(`Executing ${file} ${args == null ? "" : removePassword(args.join(" "))}`)
log.debug({file, args: args == null ? "" : removePassword(args.join(" "))}, "executing")
if (options != null && options.env != null) {
const diffEnv = {...options.env}
for (const name of Object.keys(process.env)) {
Expand All @@ -70,7 +70,7 @@ export function exec(file: string, args?: Array<string> | null, options?: ExecFi
debug(`env: ${safeStringifyJson(diffEnv)}`)
}
if (options != null && options.cwd != null) {
debug(`cwd: ${options.cwd}`)
log.debug(null, `cwd: ${options.cwd}`)
}
}

Expand Down Expand Up @@ -141,9 +141,9 @@ export function doSpawn(command: string, args: Array<string>, options?: SpawnOpt
// use general debug.enabled to log spawn, because it doesn't produce a lot of output (the only line), but important in any case
if (debug.enabled) {
const argsString = args.join(" ")
debug(`Spawning ${command} ${command === "docker" ? argsString : removePassword(argsString)}`)
log.debug({command, args: command === "docker" ? argsString : removePassword(argsString)}, "spawning")
if (options != null && options.cwd != null) {
debug(`cwd: ${options.cwd}`)
debug({cwd: options.cwd}, "")
}
}

Expand Down Expand Up @@ -204,7 +204,7 @@ export function handleProcess(event: string, childProcess: ChildProcess, command

childProcess.once(event, (code: number) => {
if (code === 0 && debug.enabled) {
debug(`${path.basename(command)} (${childProcess.pid}) exited with exit code 0`)
log.debug({command: path.basename(command), pid: childProcess.pid}, "exited with exit code 0")
}

if (code === 0) {
Expand Down
10 changes: 5 additions & 5 deletions packages/builder-util/src/wine.ts
Original file line number Diff line number Diff line change
@@ -1,18 +1,18 @@
import { path7za } from "7zip-bin"
import { ExecFileOptions } from "child_process"
import { Lazy } from "lazy-val"
import * as os from "os"
import * as path from "path"
import * as semver from "semver"
import { getBinFromGithub } from "./binDownload"
import { computeEnv, EXEC_TIMEOUT, ToolInfo } from "./bundledTool"
import { getMacOsVersion } from "./macosVersion"
import { debug, debug7zArgs, exec, isEnvTrue } from "./util"
import { ExecFileOptions } from "child_process"
import { path7za } from "7zip-bin"
import * as os from "os"
import { debug7zArgs, exec, isEnvTrue, log } from "./util"

const wineExecutable = new Lazy<ToolInfo>(async () => {
const isUseSystemWine = isEnvTrue(process.env.USE_SYSTEM_WINE)
if (isUseSystemWine) {
debug("Using system wine is forced")
log.debug(null, "using system wine is forced")
}
else if (process.platform === "darwin") {
// assume that on travis latest version is used
Expand Down
Loading

0 comments on commit fd70412

Please sign in to comment.