[web] Add tests to `collect_paypal_past_due_invoice.js` + update logging (#18310)

* Fix: Invoices collected array length comparison

Update the code with the correct condition to respect the intent of the previous implementation ("exit with non zero code when no invoicess were processed").
See https://github.com/overleaf/internal/commit/5476f39984f9cbb6edaeec3bef35e9e5207c5823

However, I'm not sure if erroring when no invoices are collected is actually what we want to do.

* Wrap `collect_paypal_past_due_invoice` script and export the function

* Fixup typo `accoutns`

* Log invoices collection data before throwing

* Add note: `handleAPIError` is silencing the errors

* Create a test on `collect_paypal_past_due_invoice`

* Replace `console.log` by `@overleaf/logger` (bunyan)

Our `console.warn` show up as Errors (in red) in GCP. For example the following is an error in GCP:
```
Errors in attemptInvoiceCollection with id=2693634 OError: Recurly API returned with status code: 400
```
https://github.com/overleaf/internal/blob/5476f39/services/web/scripts/recurly/collect_paypal_past_due_invoice.js#L9

---

Does it correctly set the levels as warnings if we use `@overleaf/logger`

GitOrigin-RevId: 37c8bdf4afd8cef4706700aafb44480ec8966a74

services/web/app/src/Features/Subscription/RecurlyWrapper.js

@@ -583,7 +583,7 @@ const RecurlyWrapper = {
         }
         return RecurlyWrapper._parseXml(body, function (err, data) {
           if (err) {
-            logger.warn({ err }, 'could not get accoutns')
+            logger.warn({ err }, 'could not get accounts')
             return callback(err)
           }
           const items = data[resource]

services/web/scripts/recurly/collect_paypal_past_due_invoice.js

@@ -1,102 +1,136 @@
 const RecurlyWrapper = require('../../app/src/Features/Subscription/RecurlyWrapper')
 const async = require('async')
 const minimist = require('minimist')
+const logger = require('@overleaf/logger')
 
-const slowCallback = (callback, error, data) =>
-  setTimeout(() => callback(error, data), 80)
+const slowCallback =
+  require.main === module
+    ? (callback, error, data) => setTimeout(() => callback(error, data), 80)
+    : (callback, error, data) => callback(error, data)
 
+// NOTE: Errors are not propagated to the caller
 const handleAPIError = (source, id, error, callback) => {
-  console.warn(`Errors in ${source} with id=${id}`, error)
+  logger.warn(`Errors in ${source} with id=${id}`, error)
   if (typeof error === 'string' && error.match(/429$/)) {
     return setTimeout(callback, 1000 * 60 * 5)
   }
   slowCallback(callback)
 }
 
-const attemptInvoiceCollection = (invoice, callback) => {
-  isAccountUsingPaypal(invoice, (error, isPaypal) => {
-    if (error || !isPaypal) {
-      return callback(error)
-    }
+/**
+ * @returns {Promise<{
+ *   INVOICES_COLLECTED: string[],
+ *   INVOICES_COLLECTED_SUCCESS: string[],
+ *   USERS_COLLECTED: string[],
+ * }>}
+ */
+const main = async () => {
+  const attemptInvoiceCollection = (invoice, callback) => {
+    isAccountUsingPaypal(invoice, (error, isPaypal) => {
+      if (error || !isPaypal) {
+        return callback(error)
+      }
+      const accountId = invoice.account.url.match(/accounts\/(.*)/)[1]
+      if (USERS_COLLECTED.indexOf(accountId) > -1) {
+        logger.warn(`Skipping duplicate user ${accountId}`)
+        return callback()
+      }
+      INVOICES_COLLECTED.push(invoice.invoice_number)
+      USERS_COLLECTED.push(accountId)
+      if (DRY_RUN) {
+        return callback()
+      }
+      RecurlyWrapper.attemptInvoiceCollection(
+        invoice.invoice_number,
+        (error, response) => {
+          if (error) {
+            return handleAPIError(
+              'attemptInvoiceCollection',
+              invoice.invoice_number,
+              error,
+              callback
+            )
+          }
+          INVOICES_COLLECTED_SUCCESS.push(invoice.invoice_number)
+          slowCallback(callback, null)
+        }
+      )
+    })
+  }
+
+  const isAccountUsingPaypal = (invoice, callback) => {
     const accountId = invoice.account.url.match(/accounts\/(.*)/)[1]
-    if (USERS_COLLECTED.indexOf(accountId) > -1) {
-      console.warn(`Skipping duplicate user ${accountId}`)
-      return callback()
-    }
-    INVOICES_COLLECTED.push(invoice.invoice_number)
-    USERS_COLLECTED.push(accountId)
-    if (DRY_RUN) {
-      return callback()
-    }
-    RecurlyWrapper.attemptInvoiceCollection(
-      invoice.invoice_number,
-      (error, response) => {
+    RecurlyWrapper.getBillingInfo(accountId, (error, response) => {
+      if (error) {
+        return handleAPIError('billing info', accountId, error, callback)
+      }
+      if (response.billing_info.paypal_billing_agreement_id) {
+        return slowCallback(callback, null, true)
+      }
+      slowCallback(callback, null, false)
+    })
+  }
+
+  const attemptInvoicesCollection = callback => {
+    RecurlyWrapper.getPaginatedEndpoint(
+      'invoices',
+      { state: 'past_due' },
+      (error, invoices) => {
+        logger.info('invoices', invoices.length)
         if (error) {
-          return handleAPIError(
-            'attemptInvoiceCollection',
-            invoice.invoice_number,
-            error,
-            callback
-          )
+          return callback(error)
         }
-        INVOICES_COLLECTED_SUCCESS.push(invoice.invoice_number)
-        slowCallback(callback, null)
+        async.eachSeries(invoices, attemptInvoiceCollection, callback)
       }
     )
-  })
-}
+  }
+  const argv = minimist(process.argv.slice(2))
+  const DRY_RUN = argv.n !== undefined
+  const INVOICES_COLLECTED = []
+  const INVOICES_COLLECTED_SUCCESS = []
+  const USERS_COLLECTED = []
 
-const isAccountUsingPaypal = (invoice, callback) => {
-  const accountId = invoice.account.url.match(/accounts\/(.*)/)[1]
-  RecurlyWrapper.getBillingInfo(accountId, (error, response) => {
-    if (error) {
-      return handleAPIError('billing info', accountId, error, callback)
-    }
-    if (response.billing_info.paypal_billing_agreement_id) {
-      return slowCallback(callback, null, true)
-    }
-    slowCallback(callback, null, false)
-  })
-}
+  return new Promise(resolve => {
+    attemptInvoicesCollection(error => {
+      logger.info(
+        `DONE (DRY_RUN=${DRY_RUN}). ${INVOICES_COLLECTED.length} invoices collection attempts for ${USERS_COLLECTED.length} users. ${INVOICES_COLLECTED_SUCCESS.length} successful collections`
+      )
+      console.dir(
+        {
+          INVOICES_COLLECTED,
+          INVOICES_COLLECTED_SUCCESS,
+          USERS_COLLECTED,
+        },
+        { maxArrayLength: null }
+      )
 
-const attemptInvoicesCollection = callback => {
-  RecurlyWrapper.getPaginatedEndpoint(
-    'invoices',
-    { state: 'past_due' },
-    (error, invoices) => {
-      console.log('invoices', invoices.length)
       if (error) {
-        return callback(error)
+        throw error
+      }
+
+      if (INVOICES_COLLECTED_SUCCESS.length === 0) {
+        throw new Error('No invoices collected')
       }
-      async.eachSeries(invoices, attemptInvoiceCollection, callback)
-    }
-  )
+
+      resolve({
+        INVOICES_COLLECTED,
+        INVOICES_COLLECTED_SUCCESS,
+        USERS_COLLECTED,
+      })
+    })
+  })
 }
 
-const argv = minimist(process.argv.slice(2))
-const DRY_RUN = argv.n !== undefined
-const INVOICES_COLLECTED = []
-const INVOICES_COLLECTED_SUCCESS = []
-const USERS_COLLECTED = []
-attemptInvoicesCollection(error => {
-  if (error) {
-    throw error
-  }
-  console.log(
-    `DONE (DRY_RUN=${DRY_RUN}). ${INVOICES_COLLECTED.length} invoices collection attempts for ${USERS_COLLECTED.length} users. ${INVOICES_COLLECTED_SUCCESS.length} successful collections`
-  )
-  console.dir(
-    {
-      INVOICES_COLLECTED,
-      INVOICES_COLLECTED_SUCCESS,
-      USERS_COLLECTED,
-    },
-    { maxArrayLength: null }
-  )
+if (require.main === module) {
+  main()
+    .then(() => {
+      logger.error('Done.')
+      process.exit(0)
+    })
+    .catch(err => {
+      logger.error('Error', err)
+      process.exit(1)
+    })
+}
 
-  if (INVOICES_COLLECTED_SUCCESS === 0) {
-    process.exit(1)
-  } else {
-    process.exit()
-  }
-})
+module.exports = { main }

services/web/test/acceptance/src/CollectPayPalPastDueInvoiceTest.js

@@ -0,0 +1,235 @@
+const sinon = require('sinon')
+const chai = require('chai')
+const { expect } = require('chai')
+
+chai.use(require('chai-as-promised'))
+chai.use(require('sinon-chai'))
+
+const {
+  main,
+} = require('../../../scripts/recurly/collect_paypal_past_due_invoice')
+
+const RecurlyWrapper = require('../../../app/src/Features/Subscription/RecurlyWrapper')
+const OError = require('@overleaf/o-error')
+
+// from https://recurly.com/developers/api-v2/v2.21/#operation/listInvoices
+const invoicesXml = invoiceIds => `
+<invoices type="array">
+  ${invoiceIds
+    .map(
+      invoiceId => `
+  <invoice href="https://your-subdomain.recurly.com/v2/invoices/${invoiceId}">
+    <account href="https://your-subdomain.recurly.com/v2/accounts/${invoiceId}"/>
+    <subscriptions href="https://your-subdomain.recurly.com/v2/invoices/${invoiceId}/subscriptions"/>
+    <address>
+      <address1></address1>
+      <address2></address2>
+      <city></city>
+      <state></state>
+      <zip></zip>
+      <country></country>
+      <phone></phone>
+    </address>
+    <shipping_address>
+      <name>Lon Doner</name>
+      <address1>221B Baker St.</address1>
+      <address2></address2>
+      <city>London</city>
+      <state></state>
+      <zip>W1K 6AH</zip>
+      <country>GB</country>
+      <phone></phone>
+    </shipping_address>
+    <uuid>421f7b7d414e4c6792938e7c49d552e9</uuid>
+    <state>paid</state>
+    <invoice_number_prefix></invoice_number_prefix> <!-- Only populated for VAT Country Invoice Sequencing. Shows a country code. -->
+    <invoice_number type="integer">${invoiceId}</invoice_number>
+    <po_number nil="nil"></po_number>
+    <vat_number nil="nil"></vat_number>
+    <subtotal_in_cents type="integer">2000</subtotal_in_cents>
+    <discount_in_cents type="integer">0</discount_in_cents>
+    <due_on type="datetime">2018-01-30T21:11:50Z</due_on>
+    <balance_in_cents type="integer">0</balance_in_cents>
+    <type>charge</type>
+    <origin>purchase</origin>
+    <credit_invoices href="https://your-subdomain.recurly.com/v2/invoices/1325/credit_invoices"/>
+    <refundable_total_in_cents type="integer">2000</refundable_total_in_cents>
+    <credit_payments type="array">
+    </credit_payments>
+    <tax_in_cents type="integer">0</tax_in_cents>
+    <total_in_cents type="integer">1200</total_in_cents>
+    <currency>USD</currency>
+    <created_at type="datetime">2016-06-25T12:00:00Z</created_at>
+    <closed_at nil="nil"></closed_at>
+    <terms_and_conditions></terms_and_conditions>
+    <customer_notes></customer_notes>
+    <vat_reverse_charge_notes></vat_reverse_charge_notes>
+    <tax_type>usst</tax_type>
+    <tax_region>CA</tax_region>
+    <tax_rate type="float">0</tax_rate>
+    <net_terms type="integer">0</net_terms>
+    <collection_method>automatic</collection_method>
+    <redemptions href="https://your-subdomain.recurly.com/v2/invoices/e3f0a9e084a2468480d00ee61b090d4d/redemptions"/>
+    <line_items type="array">
+      <adjustment href="https://your-subdomain.recurly.com/v2/adjustments/05a4bbdeda2a47348185270021e6087b">
+      </adjustment>
+    </line_items>
+    <transactions type="array">
+    </transactions>
+  </invoice>`
+    )
+    .join('')}
+</invoices>
+`
+
+// from https://recurly.com/developers/api-v2/v2.21/#operation/lookupAccountsBillingInfo
+const billingInfoXml = `
+<billing_info href="https://your-subdomain.recurly.com/v2/accounts/1/billing_info" type="credit_card">
+  <paypal_billing_agreement_id>PAYPAL_BILLING_AGREEMENT_ID</paypal_billing_agreement_id>
+  <account href="https://your-subdomain.recurly.com/v2/accounts/1"/>
+  <first_name>Verena</first_name>
+  <last_name>Example</last_name>
+  <company nil="nil"/>
+  <address1>123 Main St.</address1>
+  <address2 nil="nil"/>
+  <city>San Francisco</city>
+  <state>CA</state>
+  <zip>94105</zip>
+  <country>US</country>
+  <phone nil="nil"/>
+  <vat_number nil="nil"/>
+  <ip_address>127.0.0.1</ip_address>
+  <ip_address_country nil="nil"/>
+  <card_type>Visa</card_type>
+  <year type="integer">2019</year>
+  <month type="integer">11</month>
+  <first_six>411111</first_six>
+  <last_four>1111</last_four>
+  <updated_at type="datetime">2017-02-17T15:38:53Z</updated_at>
+</billing_info>
+`
+
+// from https://recurly.com/developers/api-v2/v2.21/#operation/collectAnInvoice
+const invoiceCollectXml = `
+<invoice href="https://your-subdomain.recurly.com/v2/invoices/1000">
+  <account href="https://your-subdomain.recurly.com/v2/accounts/1"/>
+  <subscriptions href="https://your-subdomain.recurly.com/v2/invoices/1000/subscriptions"/>
+  <address>
+    <address1>123 Main St.</address1>
+    <address2 nil="nil"/>
+    <city>San Francisco</city>
+    <state>CA</state>
+    <zip>94105</zip>
+    <country>US</country>
+    <phone nil="nil"/>
+  </address>
+  <uuid>374a37924f83c733b9c9814e9580496a</uuid>
+  <state>pending</state>
+  <invoice_number_prefix/>
+  <invoice_number type="integer">1000</invoice_number>
+  <po_number nil="nil"/>
+  <vat_number nil="nil"/>
+  <subtotal_in_cents type="integer">5000</subtotal_in_cents>
+  <tax_in_cents type="integer">438</tax_in_cents>
+  <total_in_cents type="integer">5438</total_in_cents>
+  <currency>USD</currency>
+  <created_at type="datetime">2016-07-11T19:25:57Z</created_at>
+  <updated_at type="datetime">2016-07-11T19:25:57Z</updated_at>
+  <closed_at nil="nil"/>
+  <terms_and_conditions nil="nil"/>
+  <customer_notes nil="nil"/>
+  <tax_type>usst</tax_type>
+  <tax_region>CA</tax_region>
+  <tax_rate type="float">0.0875</tax_rate>
+  <net_terms type="integer">0</net_terms>
+  <collection_method>automatic</collection_method>
+  <line_items type="array">
+    <adjustment href="https://your-subdomain.recurly.com/v2/adjustments/374a2729397882fafbc82041a0a4dd0d" type="charge">
+      <!-- Detail. -->
+    </adjustment>
+  </line_items>
+  <transactions type="array">
+  </transactions>
+  <a name="mark_successful" href="https://your-subdomain.recurly.com/v2/invoices/1000/mark_successful" method="put"/>
+  <a name="mark_failed" href="https://your-subdomain.recurly.com/v2/invoices/1000/mark_failed" method="put"/>
+</invoice>
+`
+
+// from our logs
+const invoiceCollectErrXml2 = `
+<?xml version="1.0" encoding="UTF-8"?>
+<error>
+  <symbol>not_found</symbol>
+  <description lang="en-US">Couldn't find BillingInfo with account_code = abcdef87654321</description>
+</error>
+`
+
+describe('CollectPayPalPastDueInvoice', function () {
+  let apiRequestStub
+  const fakeApiRequests = invoiceIdsAndReturnCode => {
+    apiRequestStub = sinon.stub(RecurlyWrapper, 'apiRequest')
+    apiRequestStub.callsFake((options, callback) => {
+      switch (options.url) {
+        case 'invoices':
+          callback(
+            null,
+            { statusCode: 200, headers: {} },
+            invoicesXml(invoiceIdsAndReturnCode)
+          )
+          return
+        case 'accounts/200/billing_info':
+        case 'accounts/404/billing_info':
+          callback(null, { statusCode: 200, headers: {} }, billingInfoXml)
+          return
+        case 'invoices/200/collect':
+          callback(null, { statusCode: 200, headers: {} }, invoiceCollectXml)
+          return
+        case 'invoices/404/collect':
+          callback(
+            new OError(`Recurly API returned with status code: 404`, {
+              statusCode: 404,
+            }),
+            { statusCode: 404, headers: {} },
+            invoiceCollectErrXml2
+          )
+          return
+        default:
+          throw new Error(`Unexpected URL: ${options.url}`)
+      }
+    })
+  }
+
+  afterEach(function () {
+    apiRequestStub?.restore()
+  })
+
+  it('collects one valid invoice', async function () {
+    fakeApiRequests([200])
+    const r = await main()
+    await expect(r).to.eql({
+      INVOICES_COLLECTED: [200],
+      INVOICES_COLLECTED_SUCCESS: [200],
+      USERS_COLLECTED: ['200'],
+    })
+  })
+
+  it('rejects with no invoices are processed because of errors', async function () {
+    fakeApiRequests([404])
+    await expect(main()).to.be.rejectedWith('No invoices collected')
+  })
+
+  it('rejects when there are no invoices', async function () {
+    fakeApiRequests([])
+    await expect(main()).to.be.rejectedWith('No invoices collected')
+  })
+
+  it('resolves when some invoices are partially successful', async function () {
+    fakeApiRequests([200, 404])
+    const r = await main()
+    await expect(r).to.eql({
+      INVOICES_COLLECTED: [200, 404],
+      INVOICES_COLLECTED_SUCCESS: [200],
+      USERS_COLLECTED: ['200', '404'],
+    })
+  })
+})