dcrouter/test/suite/error-handling/test.error-logging.ts

import * as plugins from '@git.zone/tstest/tapbundle';
import { expect, tap } from '@git.zone/tstest/tapbundle';
import * as net from 'net';
import { startTestServer, stopTestServer } from '../server.loader.js';

const TEST_PORT = 2525;

tap.test('prepare server', async () => {
  await startTestServer();
  await new Promise(resolve => setTimeout(resolve, 100));
});

tap.test('ERR-08: Error logging - Command errors', async (tools) => {
  const done = tools.defer();
  const socket = net.createConnection({
    host: 'localhost',
    port: TEST_PORT,
    timeout: 30000
  });

  socket.on('connect', async () => {
    try {
      // Read greeting
      await new Promise<void>((resolve) => {
        socket.once('data', () => resolve());
      });

      // Send EHLO
      socket.write('EHLO testhost\r\n');
      
      await new Promise<void>((resolve) => {
        let data = '';
        const handleData = (chunk: Buffer) => {
          data += chunk.toString();
          if (data.includes('250 ') && data.includes('\r\n')) {
            socket.removeListener('data', handleData);
            resolve();
          }
        };
        socket.on('data', handleData);
      });

      // Test various error conditions that should be logged
      const errorTests = [
        { command: 'INVALID_COMMAND', expectedCode: '500', description: 'Invalid command' },
        { command: 'MAIL FROM:<invalid@@email>', expectedCode: '501', description: 'Invalid email syntax' },
        { command: 'RCPT TO:<invalid@@recipient>', expectedCode: '501', description: 'Invalid recipient syntax' },
        { command: 'VRFY nonexistent@domain.com', expectedCode: '550', description: 'User verification failed' },
        { command: 'EXPN invalidlist', expectedCode: '550', description: 'List expansion failed' }
      ];

      let errorsDetected = 0;
      let totalTests = errorTests.length;

      for (const test of errorTests) {
        try {
          socket.write(test.command + '\r\n');
          
          const response = await new Promise<string>((resolve) => {
            const timeout = setTimeout(() => {
              resolve('TIMEOUT');
            }, 5000);

            socket.once('data', (chunk) => {
              clearTimeout(timeout);
              resolve(chunk.toString());
            });
          });

          console.log(`${test.description}: ${test.command} -> ${response.substring(0, 50)}`);

          // Check if appropriate error code was returned
          if (response.includes(test.expectedCode) ||
              response.includes('500') ||  // General error
              response.includes('501') ||  // Syntax error
              response.includes('502') ||  // Not implemented
              response.includes('550')) {  // Action not taken
            errorsDetected++;
          }

          // Small delay between commands
          await new Promise(resolve => setTimeout(resolve, 100));

        } catch (err) {
          console.log('Error during test:', test.description, err);
          // Connection errors also count as detected errors
          errorsDetected++;
        }
      }

      const detectionRate = errorsDetected / totalTests;
      console.log(`Error detection rate: ${errorsDetected}/${totalTests} (${Math.round(detectionRate * 100)}%)`);

      // Expect at least 80% of errors to be properly detected and responded to
      expect(detectionRate).toBeGreaterThanOrEqual(0.8);

      socket.write('QUIT\r\n');
      socket.end();
      done.resolve();
    } catch (error) {
      socket.end();
      done.reject(error);
    }
  });

  socket.on('error', (error) => {
    done.reject(error);
  });
});

tap.test('ERR-08: Error logging - Protocol violations', async (tools) => {
  const done = tools.defer();
  const socket = net.createConnection({
    host: 'localhost',
    port: TEST_PORT,
    timeout: 30000
  });

  socket.on('connect', async () => {
    try {
      // Read greeting
      await new Promise<void>((resolve) => {
        socket.once('data', () => resolve());
      });

      // Test protocol violations that should trigger error logging
      const violations = [
        { 
          sequence: ['RCPT TO:<test@example.com>'],  // RCPT before MAIL
          description: 'RCPT before MAIL FROM'
        },
        {
          sequence: ['MAIL FROM:<sender@example.com>', 'DATA'],  // DATA before RCPT
          description: 'DATA before RCPT TO'
        },
        {
          sequence: ['EHLO testhost', 'EHLO testhost', 'MAIL FROM:<test@example.com>', 'MAIL FROM:<test2@example.com>'],  // Double MAIL FROM
          description: 'Multiple MAIL FROM commands'
        }
      ];

      let violationsDetected = 0;

      for (const violation of violations) {
        // Reset connection state
        socket.write('RSET\r\n');
        await new Promise<void>((resolve) => {
          socket.once('data', () => resolve());
        });

        console.log(`Testing: ${violation.description}`);

        for (const cmd of violation.sequence) {
          socket.write(cmd + '\r\n');
          
          const response = await new Promise<string>((resolve) => {
            const timeout = setTimeout(() => {
              resolve('TIMEOUT');
            }, 5000);

            socket.once('data', (chunk) => {
              clearTimeout(timeout);
              resolve(chunk.toString());
            });
          });

          // Check for error responses
          if (response.includes('503') ||  // Bad sequence
              response.includes('501') ||  // Syntax error
              response.includes('500')) {  // Error
            violationsDetected++;
            console.log(`  Violation detected: ${response.substring(0, 50)}`);
            break;  // Move to next violation test
          }
        }

        await new Promise(resolve => setTimeout(resolve, 100));
      }

      console.log(`Protocol violations detected: ${violationsDetected}/${violations.length}`);

      // Expect all protocol violations to be detected
      expect(violationsDetected).toBeGreaterThan(0);

      socket.write('QUIT\r\n');
      socket.end();
      done.resolve();
    } catch (error) {
      socket.end();
      done.reject(error);
    }
  });

  socket.on('error', (error) => {
    done.reject(error);
  });
});

tap.test('ERR-08: Error logging - Data transmission errors', async (tools) => {
  const done = tools.defer();
  const socket = net.createConnection({
    host: 'localhost',
    port: TEST_PORT,
    timeout: 30000
  });

  socket.on('connect', async () => {
    try {
      // Read greeting
      await new Promise<void>((resolve) => {
        socket.once('data', () => resolve());
      });

      // Send EHLO
      socket.write('EHLO testhost\r\n');
      
      await new Promise<void>((resolve) => {
        let data = '';
        const handleData = (chunk: Buffer) => {
          data += chunk.toString();
          if (data.includes('250 ') && data.includes('\r\n')) {
            socket.removeListener('data', handleData);
            resolve();
          }
        };
        socket.on('data', handleData);
      });

      // Set up valid email transaction
      socket.write('MAIL FROM:<sender@example.com>\r\n');
      
      await new Promise<void>((resolve) => {
        socket.once('data', (chunk) => {
          const response = chunk.toString();
          expect(response).toInclude('250');
          resolve();
        });
      });

      socket.write('RCPT TO:<recipient@example.com>\r\n');
      
      await new Promise<void>((resolve) => {
        socket.once('data', (chunk) => {
          const response = chunk.toString();
          expect(response).toInclude('250');
          resolve();
        });
      });

      socket.write('DATA\r\n');
      
      const dataResponse = await new Promise<string>((resolve) => {
        socket.once('data', (chunk) => {
          resolve(chunk.toString());
        });
      });

      expect(dataResponse).toInclude('354');

      // Test various data transmission errors
      const dataErrors = [
        {
          data: 'From: sender@example.com\r\n.\r\n',  // Premature termination
          description: 'Premature dot termination'
        },
        {
          data: 'Subject: Test\r\n\r\n' + '\x00\x01\x02\x03',  // Binary data
          description: 'Binary data in message'
        },
        {
          data: 'X-Long-Line: ' + 'A'.repeat(2000) + '\r\n',  // Excessively long line
          description: 'Excessively long header line'
        }
      ];

      for (const errorData of dataErrors) {
        console.log(`Testing: ${errorData.description}`);
        socket.write(errorData.data);
      }

      // Terminate the data
      socket.write('\r\n.\r\n');

      const finalResponse = await new Promise<string>((resolve) => {
        const timeout = setTimeout(() => {
          resolve('TIMEOUT');
        }, 10000);

        socket.once('data', (chunk) => {
          clearTimeout(timeout);
          resolve(chunk.toString());
        });
      });

      console.log('Data transmission response:', finalResponse.substring(0, 100));

      // Server should either accept (250) or reject (5xx) but must respond
      const hasResponse = finalResponse !== 'TIMEOUT' && 
                         (finalResponse.includes('250') || 
                          finalResponse.includes('5'));

      expect(hasResponse).toBeTrue();

      socket.write('QUIT\r\n');
      socket.end();
      done.resolve();
    } catch (error) {
      socket.end();
      done.reject(error);
    }
  });

  socket.on('error', (error) => {
    done.reject(error);
  });
});

tap.test('cleanup server', async () => {
  await stopTestServer();
});

tap.start();