fix: don't fail immediately if cache dir is not accessible

This also changes all the log messages about not being able to create
initial directories and files to `log.verbose` since we know run those
commands on init. There are a lot of valid reasons why those might fail,
and we don't want to show a warning for them every time.

Fixes: #4769
Fixes: #4838
Fixes: #4996

Author: lukekarrys

lib/npm.js

@@ -241,16 +241,18 @@ class Npm extends EventEmitter {
     await this.time('npm:load:configload', () => this.config.load())
 
     // mkdir this separately since the logs dir can be set to
-    // a different location. an error here should be surfaced
-    // right away since it will error in cacache later
+    // a different location. if this fails, then we don't have
+    // a cache dir, but we don't want to fail immediately since
+    // the command might not need a cache dir (like `npm --version`)
     await this.time('npm:load:mkdirpcache', () =>
-      fs.mkdir(this.cache, { recursive: true, owner: 'inherit' }))
+      fs.mkdir(this.cache, { recursive: true, owner: 'inherit' })
+        .catch((e) => log.verbose('cache', `could not create cache: ${e}`)))
 
     // its ok if this fails. user might have specified an invalid dir
     // which we will tell them about at the end
     await this.time('npm:load:mkdirplogs', () =>
       fs.mkdir(this.logsDir, { recursive: true, owner: 'inherit' })
-        .catch((e) => log.warn('logfile', `could not create logs-dir: ${e}`)))
+        .catch((e) => log.verbose('logfile', `could not create logs-dir: ${e}`)))
 
     // note: this MUST be shorter than the actual argv length, because it
     // uses the same memory, so node will truncate it if it's too long.

lib/utils/log-file.js

@@ -204,7 +204,9 @@ class LogFiles {
       this.#files.push(logStream.path)
       return logStream
     } catch (e) {
-      log.warn('logfile', `could not be created: ${e}`)
+      // If the user has a readonly logdir then we don't want to
+      // warn this on every command so it should be verbose
+      log.verbose('logfile', `could not be created: ${e}`)
     }
   }
 
@@ -226,7 +228,7 @@ class LogFiles {
       )
 
       // Always ignore the currently written files
-      const files = await glob(globify(logGlob), { ignore: this.#files.map(globify) })
+      const files = await glob(globify(logGlob), { ignore: this.#files.map(globify), silent: true })
       const toDelete = files.length - this.#logsMax
 
       if (toDelete <= 0) {

test/fixtures/mock-npm.js

@@ -108,25 +108,29 @@ const LoadMockNpm = async (t, {
     cache: cacheDir,
     global: globalPrefixDir,
   })
-  const prefix = path.join(dir, 'prefix')
-  const cache = path.join(dir, 'cache')
-  const globalPrefix = path.join(dir, 'global')
-  const home = path.join(dir, 'home')
+  const dirs = {
+    testdir: dir,
+    prefix: path.join(dir, 'prefix'),
+    cache: path.join(dir, 'cache'),
+    globalPrefix: path.join(dir, 'global'),
+    home: path.join(dir, 'home'),
+  }
 
   // Set cache to testdir via env var so it is available when load is run
   // XXX: remove this for a solution where cache argv is passed in
   mockGlobals(t, {
-    'process.env.HOME': home,
-    'process.env.npm_config_cache': cache,
-    ...(globals ? result(globals, { prefix, cache, home }) : {}),
+    'process.env.HOME': dirs.home,
+    'process.env.npm_config_cache': dirs.cache,
+    ...(globals ? result(globals, { ...dirs }) : {}),
     // Some configs don't work because they can't be set via npm.config.set until
     // config is loaded. But some config items are needed before that. So this is
     // an explicit set of configs that must be loaded as env vars.
     // XXX(npm9): make this possible by passing in argv directly to npm/config
     ...Object.entries(config)
       .filter(([k]) => envConfigKeys.includes(k))
       .reduce((acc, [k, v]) => {
-        acc[`process.env.npm_config_${k.replace(/-/g, '_')}`] = v.toString()
+        acc[`process.env.npm_config_${k.replace(/-/g, '_')}`] =
+          result(v, { ...dirs }).toString()
         return acc
       }, {}),
   })
@@ -138,7 +142,7 @@ const LoadMockNpm = async (t, {
 
   if (load) {
     await npm.load()
-    for (const [k, v] of Object.entries(result(config, { npm, prefix, cache }))) {
+    for (const [k, v] of Object.entries(result(config, { npm, ...dirs }))) {
       if (typeof v === 'object' && v.value && v.where) {
         npm.config.set(k, v.value, v.where)
       } else {
@@ -148,20 +152,16 @@ const LoadMockNpm = async (t, {
     // Set global loglevel *again* since it possibly got reset during load
     // XXX: remove with npmlog
     setLoglevel(t, config.loglevel, false)
-    npm.prefix = prefix
-    npm.cache = cache
-    npm.globalPrefix = globalPrefix
+    npm.prefix = dirs.prefix
+    npm.cache = dirs.cache
+    npm.globalPrefix = dirs.globalPrefix
   }
 
   return {
     ...rest,
+    ...dirs,
     Npm,
     npm,
-    home,
-    prefix,
-    globalPrefix,
-    testdir: dir,
-    cache,
     debugFile: async () => {
       const readFiles = npm.logFiles.map(f => fs.readFile(f))
       const logFiles = await Promise.all(readFiles)
@@ -171,7 +171,7 @@ const LoadMockNpm = async (t, {
         .join('\n')
     },
     timingFile: async () => {
-      const data = await fs.readFile(path.resolve(cache, '_timing.json'), 'utf8')
+      const data = await fs.readFile(path.resolve(dirs.cache, '_timing.json'), 'utf8')
       return JSON.parse(data) // XXX: this fails if multiple timings are written
     },
   }

test/lib/npm.js

@@ -3,6 +3,7 @@ const { resolve, dirname, join } = require('path')
 
 const { load: loadMockNpm } = require('../fixtures/mock-npm.js')
 const mockGlobals = require('../fixtures/mock-globals')
+const fs = require('@npmcli/fs')
 
 // delete this so that we don't have configs from the fact that it
 // is being run by 'npm test'
@@ -435,23 +436,42 @@ t.test('debug log', async t => {
     t.match(debug, log2.join(' '), 'after load log appears')
   })
 
-  t.test('with bad dir', async t => {
-    const { npm } = await loadMockNpm(t, {
+  t.test('can load with bad dir', async t => {
+    const { npm, testdir } = await loadMockNpm(t, {
+      load: false,
       config: {
-        'logs-dir': 'LOGS_DIR',
-      },
-      mocks: {
-        '@npmcli/fs': {
-          mkdir: async (dir) => {
-            if (dir.includes('LOGS_DIR')) {
-              throw new Error('err')
-            }
-          },
-        },
+        'logs-dir': (c) => join(c.testdir, 'my_logs_dir'),
       },
     })
+    const logsDir = join(testdir, 'my_logs_dir')
+
+    // make logs dir a file before load so it files
+    await fs.writeFile(logsDir, 'A_TEXT_FILE')
+    await t.resolves(npm.load(), 'loads with invalid logs dir')
+
+    t.equal(npm.logFiles.length, 0, 'no log files array')
+    t.strictSame(fs.readFileSync(logsDir, 'utf-8'), 'A_TEXT_FILE')
+  })
+})
+
+t.test('cache dir', async t => {
+  t.test('creates a cache dir', async t => {
+    const { npm } = await loadMockNpm(t)
+
+    t.ok(fs.existsSync(npm.cache), 'cache dir exists')
+  })
+
+  t.test('can load with a bad cache dir', async t => {
+    const { npm, cache } = await loadMockNpm(t, {
+      load: false,
+      // The easiest way to make mkdir(cache) fail is to make it a file.
+      // This will have the same effect as if its read only or inaccessible.
+      cacheDir: 'A_TEXT_FILE',
+    })
+
+    await t.resolves(npm.load(), 'loads with cache dir as a file')
 
-    t.equal(npm.logFiles.length, 0, 'no log file')
+    t.equal(fs.readFileSync(cache, 'utf-8'), 'A_TEXT_FILE')
   })
 })