Напишите middleware для логирования запросов Express

Решение

Базовая реализация

import { Request, Response, NextFunction } from 'express';

function requestLogger() {
  return (req: Request, res: Response, next: NextFunction) => {
    const startTime = Date.now();

    // Отслеживаем момент отправки ответа
    res.on('finish', () => {
      const duration = Date.now() - startTime;
      console.log(`${req.method} ${req.url} - ${duration}ms`);
    });

    next();
  };
}

Как это работает

Принцип работы middleware:

1. Фиксируем время начала — startTime = Date.now()
2. Слушаем событие 'finish' — это событие срабатывает когда ответ полностью отправлен
3. Вычисляем время — duration = Date.now() - startTime
4. Логируем информацию — выводим метод, URL и время
5. Передаём управление — next() вызывает следующий middleware

Порядок выполнения:

Запрос GET /api/users
├─ requestLogger middleware
│  ├─ startTime = 1000
│  └─ next() → следующий middleware
├─ app.get('/api/users') handler
│  └─ res.send(...) → отправка ответа
└─ res.on('finish') → логирование
   ├─ duration = 1005 - 1000 = 5ms
   └─ console.log('GET /api/users - 5ms')

Пример использования

import express from 'express';
const app = express();

app.use(requestLogger());

app.get('/', (req, res) => {
  res.send('Hello');
});

app.listen(3000, () => {
  console.log('Server running on port 3000');
});

// При запросе GET /:
// GET / - 5ms

Расширенная версия с цветным выводом

interface ColorMap {
  [key: string]: string;
}

function requestLogger() {
  const colors: ColorMap = {
    GET: '\x1b[36m',     // Cyan
    POST: '\x1b[32m',    // Green
    PUT: '\x1b[33m',     // Yellow
    DELETE: '\x1b[31m',  // Red
    PATCH: '\x1b[35m',   // Magenta
    reset: '\x1b[0m'     // Reset
  };

  return (req: Request, res: Response, next: NextFunction) => {
    const startTime = Date.now();
    const method = req.method;
    const color = colors[method] || colors.reset;

    res.on('finish', () => {
      const duration = Date.now() - startTime;
      const statusColor = res.statusCode >= 400 ? '\x1b[31m' : '\x1b[32m';
      const status = res.statusCode;

      console.log(
        `${color}${method}${colors.reset} ${req.url} - ${statusColor}${status}${colors.reset} ${duration}ms`
      );
    });

    next();
  };
}

Версия с дополнительной информацией

function requestLogger() {
  return (req: Request, res: Response, next: NextFunction) => {
    const startTime = performance.now();
    const { ip, method, url, hostname } = req;

    res.on('finish', () => {
      const duration = (performance.now() - startTime).toFixed(2);
      const { statusCode } = res;
      const contentLength = res.get('content-length') || 0;

      const log = {
        timestamp: new Date().toISOString(),
        method,
        url,
        statusCode,
        duration: `${duration}ms`,
        contentLength,
        ip,
        hostname,
        userAgent: req.get('user-agent')
      };

      console.log(JSON.stringify(log, null, 2));
    });

    next();
  };
}

Версия с error handling

function requestLogger() {
  return (req: Request, res: Response, next: NextFunction) => {
    const startTime = Date.now();

    // Слушаем и 'finish' и 'close' события
    const onResponse = () => {
      const duration = Date.now() - startTime;
      console.log(`${req.method} ${req.url} - ${duration}ms`);
      cleanup();
    };

    const cleanup = () => {
      res.removeListener('finish', onResponse);
      res.removeListener('close', onResponse);
    };

    res.on('finish', onResponse);
    res.on('close', onResponse); // Если соединение закроется раньше

    next();
  };
}

Версия с разными уровнями логирования

enum LogLevel {
  INFO = 'INFO',
  WARN = 'WARN',
  ERROR = 'ERROR'
}

function requestLogger(level: LogLevel = LogLevel.INFO) {
  return (req: Request, res: Response, next: NextFunction) => {
    const startTime = Date.now();

    res.on('finish', () => {
      const duration = Date.now() - startTime;
      const log = `[${level}] ${req.method} ${req.url} - ${duration}ms (${res.statusCode})`;

      if (level === LogLevel.ERROR && res.statusCode >= 500) {
        console.error(log);
      } else if (level === LogLevel.WARN && res.statusCode >= 400) {
        console.warn(log);
      } else {
        console.log(log);
      }
    });

    next();
  };
}

Полный пример с несколькими middleware

import express, { Request, Response } from 'express';

const app = express();

function requestLogger() {
  return (req: Request, res: Response, next: NextFunction) => {
    const startTime = Date.now();
    const method = req.method;
    const url = req.url;

    res.on('finish', () => {
      const duration = Date.now() - startTime;
      console.log(`${method} ${url} - ${duration}ms`);
    });

    next();
  };
}

// Middleware цепь
app.use(requestLogger());
app.use(express.json());
app.use(express.static('public'));

app.get('/api/users', (req: Request, res: Response) => {
  res.json({ users: [] });
});

app.post('/api/users', (req: Request, res: Response) => {
  res.status(201).json({ id: 1 });
});

app.listen(3000, () => {
  console.log('Server running');
});

// Вывод:
// GET /api/users - 2ms
// POST /api/users - 3ms

Тестирование

import { describe, it, expect, vi } from 'vitest';
import express, { Request, Response } from 'express';

describe('requestLogger middleware', () => {
  it('должен логировать запросы', (done) => {
    const app = express();
    const consoleSpy = vi.spyOn(console, 'log');

    app.use(requestLogger());
    app.get('/test', (req, res) => {
      res.send('ok');
    });

    const req = new RequestMock();
    const res = new ResponseMock();

    middleware(req, res, () => {
      res.emit('finish');
      expect(consoleSpy).toHaveBeenCalled();
      const log = consoleSpy.mock.calls[0][0];
      expect(log).toMatch(/GET \/test - \d+ms/);
      done();
    });
  });

  it('должен измерять время выполнения', (done) => {
    const consoleSpy = vi.spyOn(console, 'log');
    const middleware = requestLogger();

    const req = { method: 'GET', url: '/api' } as Request;
    const res = {
      on: vi.fn((event: string, callback: () => void) => {
        if (event === 'finish') {
          setTimeout(callback, 10);
        }
      })
    } as any;
    const next = vi.fn();

    middleware(req, res, next);

    setTimeout(() => {
      expect(consoleSpy).toHaveBeenCalled();
      const log = consoleSpy.mock.calls[0][0];
      expect(log).toMatch(/\d+ms/);
      done();
    }, 20);
  });
});

Важные замечания

1. Event 'finish' vs 'close':

• 'finish' — ответ полностью отправлен клиенту
• 'close' — соединение закрыто (может произойти раньше finish)

res.on('finish', () => {
  // Ответ отправлен
});

res.on('close', () => {
  // Соединение закрыто
});

2. Date.now() vs performance.now():

• Date.now() — абсолютное время, подходит для логирования
• performance.now() — высокая точность, подходит для профилирования

3. Порядок middleware:

Между requestLogger и обработчиком маршрута может быть много middleware.

4. Cleanup в обработчиках:

Важно удалять слушатели событий, чтобы избежать утечек памяти.