ace.log locked

[laudrain]

Please provide the following details if possible or relevant:

• [1.1.1] the version of Ace impacted by the issue (as returned by the ace -v command).
• [10.16.0] the version of Node used to run Ace (as returned by the node -v command).
• [MacOS 10.14.6] your operating system and version.
• [] if the issue is a bug when running Ace: the error message as produced in the log file (you can enable debug logging with the --verbose option).
• [] if the issue is about the HTML report: the browser(s) and version(s) you used.
• [] if possible, let us know if you can share a sample input file to help us reproduce the issue.

After a crash of node.exe, the ace.log file in the folder ...\Daisy Ace\Log\ace.log is locked.
All future run of ace fails with permission error :
Throw er ; // Unhandled ‘error’ event
Error : EPERM : operation not pemitted, stat ‘C:\Users\VerifEpub\AppData\Local\Daisy Ace\Log\ace.log’

Would it be possible to give this ace.log a unique name per activation, so that next executions of ace are not locked ?

[rdeltour]

Thanks for the report. This is problematic indeed. We could either make try to figure out if the permission can be somehow reset, or else use a uniquely named log file as you suggest.

[danielweck]

Developer notes:

• The latest version v3.x of Winston ( https://github.com/winstonjs/winston ) is used in the "Ace App" (ace-gui) branch (https://github.com/daisy/ace/tree/feature/axe-runner-electron with PR WIP: an Electron Axe runner for Ace (side-by-side with the Puppeteer one) #236 ... and the corresponding deployment branch for AceApp: https://github.com/daisy/ace/tree/pr-merge/223+227 )
• I would suggest using a "log rotate" Winston transport in order to alleviate file-locking issues, such as https://github.com/winstonjs/winston-daily-rotate-file (this library automatically discards old log files, so that they do not grow indefinitely)
• We might need to adjust unit-tests that expect a single log file in a predictable location.

[danielweck]

Main code reference:

ace/packages/ace-logger/src/index.js

Lines 49 to 58 in 72047a2

	const logConfigFileName = options.fileName || logConfig.fileName;
	// OS-dependant path to log file
	const logfile = path.join(paths.log, logConfigFileName);
	// clear old log file
	if (!disableWinstonFileTransport && fs.existsSync(logfile)) {
	fs.removeSync(logfile);
	}
	const fileTransport = new winston.transports.File({ name: 'file', filename: logfile, silent: disableWinstonFileTransport });

Note that we would have to capture stream termination (final flush) using the private logStream member instead of _stream:

ace/packages/ace-logger/src/index.js

Lines 11 to 38 in 72047a2

	const closeTransportAndWaitForFinish = async (transport) => {
	if (!transport.close) {
	return Promise.resolve();
	}
	return new Promise((resolve, reject) => {
	transport._doneFinish = false;
	function done() {
	if (transport._doneFinish) {
	return;
	}
	transport._doneFinish = true;
	resolve();
	}
	setTimeout(() => {
	done();
	}, 5000);
	const finished = () => {
	done();
	};
	if (transport._stream) {
	transport._stream.once('finish', finished);
	transport._stream.end();
	} else {
	transport.once('finish', finished);
	transport.close();
	}
	});
	}

https://github.com/winstonjs/winston-daily-rotate-file/blob/6f60117cd3fd9e5cee1d8a4a8f494df3bd4e270a/daily-rotate-file.js#L80-L94
vs.:
https://github.com/winstonjs/winston/blob/ae2335b49f4fb3e49f79801f5fc6da1159ed3133/lib/winston/transports/file.js#L50

See the reason for this hack:
https://github.com/winstonjs/winston#awaiting-logs-to-be-written-in-winston
winstonjs/winston#1504 (comment)
winstonjs/winston#228 (comment)

[danielweck]

Problem with "log rotate" Winston transport plugin (winston-daily-rotate-file): attempting to delete a locked file is probably as problematic as trying to write into it. Perhaps an easier-to-maintain option would be to implement an ad-hoc log rotation routine, not based on time/size, but on launched instances (each Ace execution would create its own UUID unique logfile). There would need to be a LRU Least Recently Used logic to discard old log files, which would be unlikely to attempt access to locked / in-use files.

[danielweck]

Related (identical?) issue: #286 (comment)

[laudrain]

@danielweck this issue comes from wrong process killing when tentatively trying to stop the node.js freeze (see issue #286).