log-file.js 7.7 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247
  1. const os = require('node:os')
  2. const { join, dirname, basename } = require('node:path')
  3. const fsMiniPass = require('fs-minipass')
  4. const fs = require('node:fs/promises')
  5. const { log } = require('proc-log')
  6. const { formatWithOptions } = require('./format')
  7. const padZero = (n, length) => n.toString().padStart(length.toString().length, '0')
  8. class LogFiles {
  9. // Default to an array so we can buffer
  10. // initial writes before we know the cache location
  11. #logStream = []
  12. // We cap log files at a certain number of log events per file.
  13. // Note that each log event can write more than one line to the file.
  14. // Then we rotate log files once this number of events is reached
  15. #MAX_LOGS_PER_FILE = null
  16. // Now that we write logs continuously we need to have a backstop here for infinite loops that still log.
  17. // This is also partially handled by the config.get('max-files') option, but this is a failsafe to prevent runaway log file creation
  18. #MAX_FILES_PER_PROCESS = null
  19. #fileLogCount = 0
  20. #totalLogCount = 0
  21. #path = null
  22. #logsMax = null
  23. #files = []
  24. #timing = false
  25. constructor ({
  26. maxLogsPerFile = 50_000,
  27. maxFilesPerProcess = 5,
  28. } = {}) {
  29. this.#MAX_LOGS_PER_FILE = maxLogsPerFile
  30. this.#MAX_FILES_PER_PROCESS = maxFilesPerProcess
  31. this.on()
  32. }
  33. on () {
  34. process.on('log', this.#logHandler)
  35. }
  36. off () {
  37. process.off('log', this.#logHandler)
  38. this.#endStream()
  39. }
  40. load ({ command, path, logsMax = Infinity, timing } = {}) {
  41. if (['completion'].includes(command)) {
  42. return
  43. }
  44. // dir is user configurable and is required to exist so this can error if the dir is missing or not configured correctly
  45. this.#path = path
  46. this.#logsMax = logsMax
  47. this.#timing = timing
  48. // Log stream has already ended
  49. if (!this.#logStream) {
  50. return
  51. }
  52. log.verbose('logfile', `logs-max:${logsMax} dir:${this.#path}`)
  53. // Write the contents of our array buffer to our new file stream and set that as the new log logstream for future writes
  54. // if logs max is 0 then the user does not want a log file
  55. if (this.#logsMax > 0) {
  56. const initialFile = this.#openLogFile()
  57. if (initialFile) {
  58. for (const item of this.#logStream) {
  59. const formatted = this.#formatLogItem(...item)
  60. if (formatted !== null) {
  61. initialFile.write(formatted)
  62. }
  63. }
  64. this.#logStream = initialFile
  65. }
  66. }
  67. log.verbose('logfile', this.files[0] || 'no logfile created')
  68. // Kickoff cleaning process, even if we aren't writing a logfile.
  69. // This is async but it will always ignore the current logfile
  70. // Return the result so it can be awaited in tests
  71. return this.#cleanLogs()
  72. }
  73. get files () {
  74. return this.#files
  75. }
  76. get #isBuffered () {
  77. return Array.isArray(this.#logStream)
  78. }
  79. #endStream (output) {
  80. if (this.#logStream && !this.#isBuffered) {
  81. this.#logStream.end(output)
  82. this.#logStream = null
  83. }
  84. }
  85. #logHandler = (level, ...args) => {
  86. // Ignore pause and resume events since we write everything to the log file
  87. if (level === 'pause' || level === 'resume') {
  88. return
  89. }
  90. // If the stream is ended then do nothing
  91. if (!this.#logStream) {
  92. return
  93. }
  94. if (this.#isBuffered) {
  95. // Cant do anything but buffer the output if we don't have a file stream yet
  96. this.#logStream.push([level, ...args])
  97. return
  98. }
  99. const logOutput = this.#formatLogItem(level, ...args)
  100. if (logOutput === null) {
  101. return
  102. }
  103. // Open a new log file if we've written too many logs to this one
  104. if (this.#fileLogCount >= this.#MAX_LOGS_PER_FILE) {
  105. // Write last chunk to the file and close it
  106. this.#endStream(logOutput)
  107. if (this.#files.length >= this.#MAX_FILES_PER_PROCESS) {
  108. // but if its way too many then we just stop listening
  109. this.off()
  110. } else {
  111. // otherwise we are ready for a new file for the next event
  112. this.#logStream = this.#openLogFile()
  113. }
  114. } else {
  115. this.#logStream.write(logOutput)
  116. }
  117. }
  118. #formatLogItem (level, title, ...args) {
  119. // Only right timing logs to logfile if explicitly requests
  120. if (level === log.KEYS.timing && !this.#timing) {
  121. return null
  122. }
  123. this.#fileLogCount += 1
  124. const prefix = [this.#totalLogCount++, level, title || null]
  125. return formatWithOptions({ prefix, eol: os.EOL, colors: false }, ...args)
  126. }
  127. #getLogFilePath (count = '') {
  128. return `${this.#path}debug-${count}.log`
  129. }
  130. #openLogFile () {
  131. // Count in filename will be 0 indexed
  132. const count = this.#files.length
  133. try {
  134. // Pad with zeros so that our log files are always sorted properly
  135. // We never want to write files ending in `-9.log` and `-10.log` because log file cleaning is done by deleting the oldest.
  136. // So in this example `-10.log` would be deleted next.
  137. const f = this.#getLogFilePath(padZero(count, this.#MAX_FILES_PER_PROCESS))
  138. // Some effort was made to make the async, but we need to write logs during process.on('exit') which has to be synchronous.
  139. // So in order to never drop log messages, it is easiest to make it sync all the time and this was measured to be about 1.5% slower for 40k lines of output
  140. const logStream = new fsMiniPass.WriteStreamSync(f, { flags: 'a' })
  141. if (count > 0) {
  142. // Reset file log count if we are opening after our first file
  143. this.#fileLogCount = 0
  144. }
  145. this.#files.push(logStream.path)
  146. return logStream
  147. } catch (e) {
  148. // If the user has a readonly logdir then we don't want to warn this on every command so it should be verbose
  149. log.verbose('logfile', `could not be created: ${e}`)
  150. }
  151. }
  152. async #cleanLogs () {
  153. // module to clean out the old log files this is a best-effort attempt.
  154. // if a rm fails, we just log a message about it and move on.
  155. // We do return a Promise that succeeds when we've tried to delete everything, just for the benefit of testing this function properly.
  156. try {
  157. const logPath = this.#getLogFilePath()
  158. const patternFileName = basename(logPath)
  159. // tell glob to only match digits
  160. .replace(/\d/g, 'd')
  161. // Handle the old (prior to 8.2.0) log file names which did not have a counter suffix
  162. .replace('-.log', '')
  163. let files = await fs.readdir(
  164. dirname(logPath), {
  165. withFileTypes: true,
  166. encoding: 'utf-8',
  167. })
  168. files = files.sort((a, b) => basename(a.name).localeCompare(basename(b.name), 'en'))
  169. const logFiles = []
  170. for (const file of files) {
  171. if (!file.isFile()) {
  172. continue
  173. }
  174. const genericFileName = file.name.replace(/\d/g, 'd')
  175. const filePath = join(dirname(logPath), basename(file.name))
  176. // Always ignore the currently written files
  177. if (
  178. genericFileName.includes(patternFileName)
  179. && genericFileName.endsWith('.log')
  180. && !this.#files.includes(filePath)
  181. ) {
  182. logFiles.push(filePath)
  183. }
  184. }
  185. const toDelete = logFiles.length - this.#logsMax
  186. if (toDelete <= 0) {
  187. return
  188. }
  189. log.silly('logfile', `start cleaning logs, removing ${toDelete} files`)
  190. for (const file of logFiles.slice(0, toDelete)) {
  191. try {
  192. await fs.rm(file, { force: true })
  193. } catch (e) {
  194. log.silly('logfile', 'error removing log file', file, e)
  195. }
  196. }
  197. } catch (e) {
  198. // Disable cleanup failure warnings when log writing is disabled
  199. if (this.#logsMax > 0) {
  200. log.verbose('logfile', 'error cleaning log files', e)
  201. }
  202. } finally {
  203. log.silly('logfile', 'done cleaning log files')
  204. }
  205. }
  206. }
  207. module.exports = LogFiles