Add more logging during publishing (#913)

change/beachball-f146e707-ddd6-42bd-8918-391c07aaeabf.json

@@ -0,0 +1,7 @@
+{
+  "type": "patch",
+  "comment": "Add more logging during publishing",
+  "packageName": "beachball",
+  "email": "[email protected]",
+  "dependentChangeType": "patch"
+}

src/__functional__/packageManager/packagePublish.test.ts

@@ -13,12 +13,13 @@ import { npm, NpmResult } from '../../packageManager/npm';
 const testTag = 'testbeachballtag';
 const testName = 'testbeachballpackage';
 const testVersion = '0.6.0';
+const testSpec = `${testName}@${testVersion}`;
 const testPackage = { name: testName, version: testVersion };
 
-// Some of these tests use an actual local npm registry, so they're slower to run.
-// The rest mock npm calls for efficiency.
 //
-// (If there's ever a bug that could have been caught by testing against a real registry/npm,
+// Some of these tests use an actual local npm registry, so they're slower to run.
+// The rest mock npm calls for efficiency (but could potentially be updated to use real npm if
+// a bug is found that would have been caught that way).
 //
 describe('packagePublish', () => {
   let npmSpy: jest.SpiedFunction<typeof npm>;
@@ -86,7 +87,7 @@ describe('packagePublish', () => {
     expect(npmSpy).toHaveBeenCalledTimes(1);
 
     const allLogs = logs.getMockLines('all');
-    expect(allLogs).toMatch(`Publishing - ${testName}@${testVersion} with tag ${testTag}`);
+    expect(allLogs).toMatch(`Publishing - ${testSpec} with tag ${testTag}`);
     expect(allLogs).toMatch('publish command:');
     expect(allLogs).toMatch(`[log] Published!`);
 
@@ -113,7 +114,7 @@ describe('packagePublish', () => {
     expect(npmSpy).toHaveBeenCalledTimes(2);
 
     const logs2ndTry = logs.getMockLines('all');
-    expect(logs2ndTry).toMatch(`${testName}@${testVersion} already exists in the registry`);
+    expect(logs2ndTry).toMatch(`${testSpec} already exists in the registry`);
   });
 
   it('performs retries', async () => {
@@ -134,9 +135,9 @@ describe('packagePublish', () => {
     expect(npmSpy).toHaveBeenCalledTimes(3);
 
     const allLogs = logs.getMockLines('all');
-    expect(allLogs).toMatch(`[warn] Publishing ${testName} failed. Output:\n\nsome errors`);
+    expect(allLogs).toMatch(`[warn] Publishing ${testSpec} failed. Output:\n\nsome errors`);
     expect(allLogs).toMatch('Retrying... (1/3)');
-    expect(allLogs).toMatch(`[warn] Publishing ${testName} failed (timed out). Output:\n\nsloooow`);
+    expect(allLogs).toMatch(`[warn] Publishing ${testSpec} failed (timed out). Output:\n\nsloooow`);
     expect(allLogs).toMatch('Retrying... (2/3)');
     expect(allLogs).toMatch(`[log] Published!`);
   });
@@ -153,7 +154,7 @@ describe('packagePublish', () => {
     expect(allLogs).toMatch('Retrying... (1/3)');
     expect(allLogs).toMatch('Retrying... (2/3)');
     expect(allLogs).toMatch('Retrying... (3/3)');
-    expect(allLogs).toMatch(`[error] Publishing ${testName} failed. Output:\n\nsome errors`);
+    expect(allLogs).toMatch(`[error] Publishing ${testSpec} failed. Output:\n\nsome errors`);
   });
 
   it('does not retry on auth error', async () => {
@@ -166,7 +167,7 @@ describe('packagePublish', () => {
     expect(npmSpy).toHaveBeenCalledTimes(1);
 
     expect(logs.getMockLines('error')).toMatch(
-      `Publishing ${testName} failed due to an auth error. Output:\n\nERR! code ENEEDAUTH`
+      `Publishing ${testSpec} failed due to an auth error. Output:\n\nERR! code ENEEDAUTH`
     );
   });
 
@@ -180,6 +181,17 @@ describe('packagePublish', () => {
     expect(publishResult).toEqual(failedResult);
     expect(npmSpy).toHaveBeenCalledTimes(1);
 
-    expect(logs.getMockLines('error')).toMatch(`Publishing ${testName} returned E404`);
+    expect(logs.getMockLines('error')).toMatch(`Publishing ${testSpec} failed with E404`);
+  });
+
+  it('does not retry on E403', async () => {
+    const testPackageInfo = getTestPackageInfo();
+    npmSpy.mockImplementation(() => Promise.resolve({ success: false, all: 'ERR! code E403' } as NpmResult));
+
+    const publishResult = await packagePublish(testPackageInfo, { registry: 'fake', retries: 3 });
+    expect(publishResult).toEqual(failedResult);
+    expect(npmSpy).toHaveBeenCalledTimes(1);
+
+    expect(logs.getMockLines('error')).toMatch(`Publishing ${testSpec} failed due to a 403 error`);
   });
 });

src/packageManager/npmArgs.ts

@@ -12,7 +12,7 @@ export function getNpmPublishArgs(packageInfo: PackageInfo, options: NpmOptions)
     '--tag',
     pkgCombinedOptions.tag || pkgCombinedOptions.defaultNpmTag || 'latest',
     '--loglevel',
-    'warn',
+    options.verbose ? 'notice' : 'warn',
     ...getNpmAuthArgs(registry, token, authType),
   ];
 

src/packageManager/packagePublish.ts

@@ -15,11 +15,13 @@ export async function packagePublish(
 ): Promise<NpmResult> {
   const publishArgs = getNpmPublishArgs(packageInfo, options);
 
+  const packageRoot = path.dirname(packageInfo.packageJsonPath);
   const publishTag = publishArgs[publishArgs.indexOf('--tag') + 1];
-  const pkg = packageInfo.name;
-  console.log(`\nPublishing - ${pkg}@${packageInfo.version} with tag ${publishTag}`);
+  const packageSpec = `${packageInfo.name}@${packageInfo.version}`;
+  console.log(`\nPublishing - ${packageSpec} with tag ${publishTag}`);
 
   console.log(`  publish command: ${publishArgs.join(' ')}`);
+  console.log(`  (cwd: ${packageRoot})`);
 
   let result: NpmResult;
 
@@ -32,7 +34,7 @@ export async function packagePublish(
 
     result = await npm(publishArgs, {
       // Run npm publish in the package directory
-      cwd: path.dirname(packageInfo.packageJsonPath),
+      cwd: packageRoot,
       timeout: options.timeout,
       all: true,
     });
@@ -42,24 +44,38 @@ export async function packagePublish(
       return result;
     }
 
+    console.log();
     const output = `Output:\n\n${result.all}\n`;
 
-    // First check for specific cases where retries are unlikely to help
+    // First check the output for specific cases where retries are unlikely to help.
+    // NOTE: much of npm's output is localized, so it's best to only check for error codes.
     if (result.all!.includes('EPUBLISHCONFLICT')) {
-      console.error(`${pkg}@${packageInfo.version} already exists in the registry. ${output}`);
+      console.error(`${packageSpec} already exists in the registry. ${output}`);
+      break;
+    }
+    if (result.all!.includes('code E403')) {
+      // This is apparently a less common variant of trying to publish over an existing version
+      // (not sure when this error is used vs. EPUBLISHCONFLICT). Keep the message generic since
+      // there may be other possible causes for 403 errors.
+      //   npm ERR! code E403
+      //   npm ERR! 403 403 Forbidden - PUT https://registry.npmjs.org/pkg-name - You cannot publish over the previously published versions: 0.1.6.
+      //   npm ERR! 403 In most cases, you or one of your dependencies are requesting
+      //   npm ERR! 403 a package version that is forbidden by your security policy, or
+      //   npm ERR! 403 on a server you do not have access to.
+      console.error(`Publishing ${packageSpec} failed due to a 403 error. ${output}`);
       break;
     }
     if (result.all!.includes('ENEEDAUTH')) {
       // ENEEDAUTH only happens if no auth was attempted (no token/password provided).
-      console.error(`Publishing ${pkg} failed due to an auth error. ${output}`);
+      console.error(`Publishing ${packageSpec} failed due to an auth error. ${output}`);
       break;
     }
     if (result.all!.includes('code E404')) {
       // All types of invalid credentials appear to cause E404.
       // validate() already checks for the most common ways invalid variable names might show up,
       // so log a slightly more generic message instead of details about the token.
       console.error(
-        `Publishing ${pkg} returned E404. Contrary to the output, this usually indicates an issue ` +
+        `Publishing ${packageSpec} failed with E404. Contrary to the output, this usually indicates an issue ` +
           'with an auth token (expired, improper scopes, or incorrect variable name).'
       );
       // demote the output on this one due to the misleading message
@@ -69,7 +85,7 @@ export async function packagePublish(
 
     const timedOutMessage = result.timedOut ? ' (timed out)' : '';
     const log = retries < options.retries ? console.warn : console.error;
-    log(`Publishing ${pkg} failed${timedOutMessage}. ${output}`);
+    log(`Publishing ${packageSpec} failed${timedOutMessage}. ${output}`);
   }
 
   return result!;

src/types/NpmOptions.ts

@@ -1,4 +1,4 @@
 import { BeachballOptions } from './BeachballOptions';
 
 export type NpmOptions = Required<Pick<BeachballOptions, 'registry'>> &
-  Partial<Pick<BeachballOptions, 'token' | 'authType' | 'access' | 'timeout'>>;
+  Partial<Pick<BeachballOptions, 'token' | 'authType' | 'access' | 'timeout' | 'verbose'>>;