diff --git a/CHANGELOG.md b/CHANGELOG.md index d94b04d3c..de2ea645c 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -2,6 +2,14 @@ All changes that impact users of this module are documented in this file, in the [Common Changelog](https://common-changelog.org) format with some additional specifications defined in the CONTRIBUTING file. This codebase adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html). +## Unreleased [minor] + +> Development of this release was supported by [Reset Tech](https://www.reset.tech). + +### Changed + +- Make SMTP port configurable and switch from implicit SSL to STARTTLS, enabling use of alternative ports (like 2525) on servers where standard SMTP ports are blocked + ## 10.3.3 - 2026-01-16 > Development of this release was supported by [Reset Tech](https://www.reset.tech). diff --git a/config/default.json b/config/default.json index 95dab61cd..e7531bf6c 100644 --- a/config/default.json +++ b/config/default.json @@ -43,7 +43,8 @@ }, "logger": { "smtp": { - "host": "smtp-relay.sendinblue.com", + "host": "smtp-relay.brevo.com", + "port": 587, "username": "admin@opentermsarchive.org" }, "sendMailOnError": false, diff --git a/src/collection-api/logger.js b/src/collection-api/logger.js index ce5ebb126..db309e3e7 100644 --- a/src/collection-api/logger.js +++ b/src/collection-api/logger.js @@ -3,7 +3,8 @@ import os from 'os'; import config from 'config'; import dotenv from 'dotenv'; import winston from 'winston'; -import 'winston-mail'; + +import MailTransportWithRetry from '../logger/mail-transport-with-retry.js'; dotenv.config({ quiet: true }); @@ -12,14 +13,15 @@ const { combine, timestamp, printf, colorize } = winston.format; const transports = [new winston.transports.Console()]; if (config.get('@opentermsarchive/engine.logger.sendMailOnError')) { - transports.push(new winston.transports.Mail({ + transports.push(new MailTransportWithRetry({ to: config.get('@opentermsarchive/engine.logger.sendMailOnError.to'), from: config.get('@opentermsarchive/engine.logger.sendMailOnError.from'), host: config.get('@opentermsarchive/engine.logger.smtp.host'), + port: config.get('@opentermsarchive/engine.logger.smtp.port'), username: config.get('@opentermsarchive/engine.logger.smtp.username'), password: process.env.OTA_ENGINE_SMTP_PASSWORD, - ssl: true, - timeout: 30 * 1000, + tls: true, + timeout: 60 * 1000, formatter: args => args[Object.getOwnPropertySymbols(args)[1]], // Returns the full error message, the same visible in the console. It is referenced in the argument object with a Symbol of which we do not have the reference but we know it is the second one. exitOnError: true, level: 'error', diff --git a/src/logger/index.js b/src/logger/index.js index 82c3a5813..38b326abe 100644 --- a/src/logger/index.js +++ b/src/logger/index.js @@ -2,10 +2,10 @@ import os from 'os'; import config from 'config'; import winston from 'winston'; -import 'winston-mail'; import { getCollection } from '../archivist/collection/index.js'; +import MailTransportWithRetry from './mail-transport-with-retry.js'; import { formatDuration } from './utils.js'; const { combine, timestamp, printf, colorize } = winston.format; @@ -57,10 +57,11 @@ if (config.get('@opentermsarchive/engine.logger.sendMailOnError')) { to: config.get('@opentermsarchive/engine.logger.sendMailOnError.to'), from: config.get('@opentermsarchive/engine.logger.sendMailOnError.from'), host: config.get('@opentermsarchive/engine.logger.smtp.host'), + port: config.get('@opentermsarchive/engine.logger.smtp.port'), username: config.get('@opentermsarchive/engine.logger.smtp.username'), password: process.env.OTA_ENGINE_SMTP_PASSWORD, - ssl: true, - timeout: 30 * 1000, + tls: true, + timeout: 60 * 1000, html: false, formatter({ message, level }) { const isError = level.includes('error'); @@ -141,14 +142,14 @@ if (config.get('@opentermsarchive/engine.logger.sendMailOnError')) { }, }; - transports.push(new winston.transports.Mail({ + transports.push(new MailTransportWithRetry({ ...mailerOptions, level: 'error', subject: `Server error on ${collection.id} collection`, })); if (config.get('@opentermsarchive/engine.logger.sendMailOnError.sendWarnings')) { - transports.push(new winston.transports.Mail({ + transports.push(new MailTransportWithRetry({ ...mailerOptions, level: 'warn', subject: `Inaccessible content on ${collection.id} collection`, diff --git a/src/logger/mail-transport-with-retry.js b/src/logger/mail-transport-with-retry.js new file mode 100644 index 000000000..4ec525e5c --- /dev/null +++ b/src/logger/mail-transport-with-retry.js @@ -0,0 +1,46 @@ +import { once } from 'node:events'; + +import async from 'async'; +import winston from 'winston'; + +import 'winston-mail'; + +export const RETRY_DELAYS = [ 5000, 20000, 60000 ]; + +const RETRY_OPTIONS = { + times: RETRY_DELAYS.length + 1, + interval: retryCount => RETRY_DELAYS[retryCount - 1] || RETRY_DELAYS.at(-1), + errorFilter: error => { + console.warn(`SMTP mail sending failed: ${error.message}; retrying…`); + + return true; + }, +}; + +class MailTransportWithRetry extends winston.Transport { + constructor(options) { + super(options); + this.mailTransport = new winston.transports.Mail(options); + } + + async log(info, callback) { + try { + await async.retry(RETRY_OPTIONS, async () => { + const result = Promise.race([ + once(this.mailTransport, 'logged'), + once(this.mailTransport, 'error').then(([err]) => { throw err; }), + ]); + + this.mailTransport.log(info, () => {}); + + return result; + }); + } catch (error) { + console.warn(`SMTP mail sending failed after ${RETRY_OPTIONS.times} attempts: ${error.message}`); + this.emit('error', error); + } + callback(); + } +} + +export default MailTransportWithRetry; diff --git a/src/logger/mail-transport-with-retry.test.js b/src/logger/mail-transport-with-retry.test.js new file mode 100644 index 000000000..9612ab66d --- /dev/null +++ b/src/logger/mail-transport-with-retry.test.js @@ -0,0 +1,192 @@ +import { EventEmitter } from 'node:events'; + +import { expect } from 'chai'; +import sinon from 'sinon'; +import winston from 'winston'; + +import MailTransportWithRetry, { RETRY_DELAYS } from './mail-transport-with-retry.js'; + +class MockMailTransport extends EventEmitter { + log() {} // eslint-disable-line +} + +describe('MailTransportWithRetry', () => { + let clock; + let mockMailTransport; + let transport; + let consoleWarnStub; + + beforeEach(() => { + clock = sinon.useFakeTimers(); + mockMailTransport = new MockMailTransport(); + sinon.stub(winston.transports, 'Mail').returns(mockMailTransport); + consoleWarnStub = sinon.stub(console, 'warn'); + transport = new MailTransportWithRetry({ to: 'test@example.com' }); + }); + + afterEach(() => { + sinon.restore(); + clock.restore(); + }); + + describe('#log', () => { + context('when email is sent successfully on first attempt', () => { + it('calls callback without error', async () => { + const callback = sinon.spy(); + const logPromise = transport.log({ message: 'test' }, callback); + + mockMailTransport.emit('logged'); + await logPromise; + + expect(callback).to.have.been.calledOnce; + }); + + it('does not emit error event', async () => { + const errorHandler = sinon.spy(); + + transport.on('error', errorHandler); + + const logPromise = transport.log({ message: 'test' }, () => {}); + + mockMailTransport.emit('logged'); + await logPromise; + + expect(errorHandler).not.to.have.been.called; + }); + + it('does not log any warning', async () => { + const logPromise = transport.log({ message: 'test' }, () => {}); + + mockMailTransport.emit('logged'); + await logPromise; + + expect(consoleWarnStub).not.to.have.been.called; + }); + }); + + context('when email fails then succeeds on retry', () => { + it('retries and eventually succeeds', async () => { + const callback = sinon.spy(); + const logSpy = sinon.spy(mockMailTransport, 'log'); + const logPromise = transport.log({ message: 'test' }, callback); + + mockMailTransport.emit('error', new Error('SMTP timeout')); + + await clock.tickAsync(RETRY_DELAYS[0]); + + mockMailTransport.emit('logged'); + await logPromise; + + expect(logSpy).to.have.been.calledTwice; + expect(callback).to.have.been.calledOnce; + }); + + it('logs warning for failed attempt', async () => { + const logPromise = transport.log({ message: 'test' }, () => {}); + + mockMailTransport.emit('error', new Error('SMTP timeout')); + + await clock.tickAsync(RETRY_DELAYS[0]); + + mockMailTransport.emit('logged'); + await logPromise; + + expect(consoleWarnStub).to.have.been.calledOnce; + expect(consoleWarnStub.firstCall.args[0]).to.include('SMTP mail sending failed'); + expect(consoleWarnStub.firstCall.args[0]).to.include('SMTP timeout'); + }); + }); + + context('when email fails after all retry attempts', () => { + it('emits error event after all retries are exhausted', async () => { + const errorHandler = sinon.spy(); + + transport.on('error', errorHandler); + + const logPromise = transport.log({ message: 'test' }, () => {}); + + mockMailTransport.emit('error', new Error('SMTP timeout')); + await clock.tickAsync(RETRY_DELAYS[0]); + + mockMailTransport.emit('error', new Error('SMTP timeout')); + await clock.tickAsync(RETRY_DELAYS[1]); + + mockMailTransport.emit('error', new Error('SMTP timeout')); + await clock.tickAsync(RETRY_DELAYS[2]); + + mockMailTransport.emit('error', new Error('SMTP timeout')); + await logPromise; + + expect(errorHandler).to.have.been.calledOnce; + expect(errorHandler.firstCall.args[0].message).to.equal('SMTP timeout'); + }); + + it('calls callback even after failure', async () => { + const callback = sinon.spy(); + + transport.on('error', () => {}); // Prevent unhandled error + + const logPromise = transport.log({ message: 'test' }, callback); + + mockMailTransport.emit('error', new Error('SMTP timeout')); + await clock.tickAsync(RETRY_DELAYS[0]); + + mockMailTransport.emit('error', new Error('SMTP timeout')); + await clock.tickAsync(RETRY_DELAYS[1]); + + mockMailTransport.emit('error', new Error('SMTP timeout')); + await clock.tickAsync(RETRY_DELAYS[2]); + + mockMailTransport.emit('error', new Error('SMTP timeout')); + await logPromise; + + expect(callback).to.have.been.calledOnce; + }); + + it('logs final failure warning', async () => { + transport.on('error', () => {}); // Prevent unhandled error + + const logPromise = transport.log({ message: 'test' }, () => {}); + + mockMailTransport.emit('error', new Error('SMTP timeout')); + await clock.tickAsync(RETRY_DELAYS[0]); + + mockMailTransport.emit('error', new Error('SMTP timeout')); + await clock.tickAsync(RETRY_DELAYS[1]); + + mockMailTransport.emit('error', new Error('SMTP timeout')); + await clock.tickAsync(RETRY_DELAYS[2]); + + mockMailTransport.emit('error', new Error('SMTP timeout')); + await logPromise; + + expect(consoleWarnStub.lastCall.args[0]).to.include(`failed after ${RETRY_DELAYS.length + 1} attempts`); + }); + }); + + context('when email succeeds after multiple failures', () => { + it('succeeds on third attempt', async () => { + const callback = sinon.spy(); + const errorHandler = sinon.spy(); + const logSpy = sinon.spy(mockMailTransport, 'log'); + + transport.on('error', errorHandler); + + const logPromise = transport.log({ message: 'test' }, callback); + + mockMailTransport.emit('error', new Error('SMTP timeout')); + await clock.tickAsync(RETRY_DELAYS[0]); + + mockMailTransport.emit('error', new Error('Connection refused')); + await clock.tickAsync(RETRY_DELAYS[1]); + + mockMailTransport.emit('logged'); + await logPromise; + + expect(logSpy).to.have.been.calledThrice; + expect(callback).to.have.been.calledOnce; + expect(errorHandler).not.to.have.been.called; + }); + }); + }); +});