test(e2e): add verbose logging verification for CLI commands (#323)

Adds comprehensive E2E test coverage verifying that emulator verbose logging correctly captures Modbus operations during CLI read/write commands.

## E2E Test Coverage (4 new tests)
- Read single data point with verbose logging
- Read multiple data points with verbose logging  
- Write operation with verbose logging
- Write with verification (logs both WRITE and READ)

Each test verifies:
- Correct operation type ([VERBOSE] READ or [VERBOSE] WRITE)
- Slave ID, function code, register address, count
- Specific hex values for data being read/written

## Documentation Improvements
- Inline comments explain hex value conversions (e.g., 2300 = 0x08FC = 230.0V)
- Register address explanations (e.g., 0x002B = device_address config parameter)
- Driver behavior notes (e.g., "EX9EM reads all 11 registers in one operation")
- Comments explain why specific function codes are used (0x03 vs 0x10)

## Test Infrastructure
Enhanced helpers.bash with:
- Verbose flag support for emulator startup
- Improved log file handling (temp log + symlink approach)
- New assert_emulator_log_contains helper for log verification
- Comprehensive cleanup of all temporary artifacts

## Technical Details
Tests verify VerboseLogger output format:
[VERBOSE] {READ|WRITE} slave={id} func=0x{code} addr=0x{addr} count={n} values=[0x{val1}, ...]

Known limitation: Discover command verbose logging test omitted due to emulator restart issue (tracked for follow-up).

Builds on PR #322.

Author: groupsky

tests/e2e/tests/04-cli.bats

@@ -411,3 +411,104 @@ teardown() {
   assert_failure
   assert_output_contains "port"
 }
+
+@test "read command logs verbose READ operation to emulator" {
+  # Start emulator with verbose logging enabled
+  run start_test_emulator "fixtures/emulators/port1-single-device.json" "--verbose"
+  assert_success
+  EMULATOR_PID="$output"
+
+  # Read voltage data point from EX9EM device
+  run node "$CLI_BIN" read \
+    --port /tmp/ttyV1 \
+    --slave-id 1 \
+    --driver @ya-modbus/driver-ex9em \
+    --data-point voltage
+
+  assert_success
+
+  # Verify emulator logged the READ operation
+  # EX9EM driver reads all 11 data registers in one operation starting at addr 0x0000
+  assert_emulator_log_contains "$EMULATOR_PID" "\[VERBOSE\] READ"
+  assert_emulator_log_contains "$EMULATOR_PID" "slave=1"
+  assert_emulator_log_contains "$EMULATOR_PID" "func=0x03"
+  assert_emulator_log_contains "$EMULATOR_PID" "addr=0x0000"
+  assert_emulator_log_contains "$EMULATOR_PID" "count=11"
+  # Verify voltage value is present (2300 decimal = 0x08FC hex = 230.0V when scaled /10)
+  assert_emulator_log_contains "$EMULATOR_PID" "0x08FC"
+}
+
+@test "read multiple data points logs READ with multiple values" {
+  run start_test_emulator "fixtures/emulators/port1-single-device.json" "--verbose"
+  assert_success
+  EMULATOR_PID="$output"
+
+  # Read voltage and current from EX9EM device
+  run node "$CLI_BIN" read \
+    --port /tmp/ttyV1 \
+    --slave-id 1 \
+    --driver @ya-modbus/driver-ex9em \
+    --data-point voltage current
+
+  assert_success
+
+  # Verify READ operation logged with both values
+  assert_emulator_log_contains "$EMULATOR_PID" "\[VERBOSE\] READ"
+  assert_emulator_log_contains "$EMULATOR_PID" "addr=0x0000"
+  # Verify voltage (register 0: 2300 = 0x08FC = 230.0V) and current (register 1: 520 = 0x0208 = 52.0A)
+  assert_emulator_log_contains "$EMULATOR_PID" "0x08FC"
+  assert_emulator_log_contains "$EMULATOR_PID" "0x0208"
+}
+
+@test "write command logs verbose WRITE operation to emulator" {
+  run start_test_emulator "fixtures/emulators/port1-single-device.json" "--verbose"
+  assert_success
+  EMULATOR_PID="$output"
+
+  # Write device_address configuration parameter (register 43 = 0x002B)
+  run node "$CLI_BIN" write \
+    --port /tmp/ttyV1 \
+    --slave-id 1 \
+    --driver @ya-modbus/driver-ex9em \
+    --data-point device_address \
+    --value 5 \
+    --yes
+
+  assert_success
+
+  # Verify emulator logged the WRITE operation
+  # Transport layer uses func 0x10 (Write Multiple Registers) even for single register writes
+  assert_emulator_log_contains "$EMULATOR_PID" "\[VERBOSE\] WRITE"
+  assert_emulator_log_contains "$EMULATOR_PID" "slave=1"
+  assert_emulator_log_contains "$EMULATOR_PID" "func=0x10"
+  assert_emulator_log_contains "$EMULATOR_PID" "addr=0x002B"
+  assert_emulator_log_contains "$EMULATOR_PID" "count=1"
+  # Verify value written (5 decimal = 0x0005 hex)
+  assert_emulator_log_contains "$EMULATOR_PID" "0x0005"
+}
+
+@test "write with verify logs both WRITE and READ operations" {
+  run start_test_emulator "fixtures/emulators/port1-single-device.json" "--verbose"
+  assert_success
+  EMULATOR_PID="$output"
+
+  # Write with verification enabled
+  run node "$CLI_BIN" write \
+    --port /tmp/ttyV1 \
+    --slave-id 1 \
+    --driver @ya-modbus/driver-ex9em \
+    --data-point device_address \
+    --value 10 \
+    --yes \
+    --verify
+
+  assert_success
+
+  # Verify WRITE operation logged (10 decimal = 0x000A hex)
+  assert_emulator_log_contains "$EMULATOR_PID" "\[VERBOSE\] WRITE"
+  assert_emulator_log_contains "$EMULATOR_PID" "addr=0x002B"
+  assert_emulator_log_contains "$EMULATOR_PID" "values=\[0x000A\]"
+
+  # Verify READ operation also logged (--verify flag triggers read-back)
+  assert_emulator_log_contains "$EMULATOR_PID" "\[VERBOSE\] READ"
+}

tests/e2e/tests/helpers.bash

@@ -84,19 +84,73 @@ stop_mqtt_subscriber() {
 }
 
 # Start emulator in background using CLI
+#
+# Starts the ya-modbus emulator in the background with output redirected to a log file.
+# The log file is created with a unique temporary name first, then symlinked to a
+# PID-based name for easy access by tests.
+#
+# LOG FILE APPROACH:
+# Tests need to read logs via PID-based filename (/tmp/emulator-$pid.log), but we
+# don't know the PID until AFTER starting the background process. Shell redirection
+# must be specified BEFORE the command runs, creating a chicken-and-egg problem.
+#
+# SOLUTION:
+# 1. Create temp log with guaranteed unique name using mktemp
+# 2. Start emulator with output redirected to temp log
+# 3. Capture PID from background process
+# 4. Create symlink from /tmp/emulator-$pid.log -> temp log
+# 5. Store temp log path for cleanup
+#
+# This ensures the log file is immediately writable and later accessible via PID.
+#
+# Arguments:
+#   $1 - config_file: Path to emulator configuration file
+#   $2 - verbose_flag: Optional "--verbose" flag to enable verbose logging
+#
+# Returns:
+#   Prints PID of started emulator to stdout
+#   Returns 0 on success, 1 on failure
+#
+# Example:
+#   run start_test_emulator "config.json"
+#   run start_test_emulator "config.json" "--verbose"
+#
 start_test_emulator() {
   local config_file=$1
-  local log_file="/tmp/emulator-$$.log"
+  local verbose_flag=${2:-""}
   local project_root
   project_root=$(get_project_root)
 
-  # Use the built emulator CLI (without --quiet to enable log checking)
-  node "$project_root/packages/emulator/dist/esm/bin/ya-modbus-emulator.js" \
-    --config "$config_file" \
-    > "$log_file" 2>&1 &
+  # Create guaranteed-unique temp log file
+  local temp_log
+  temp_log=$(mktemp /tmp/emulator-temp-XXXXXX.log) || {
+    echo "Failed to create temp log file" >&2
+    return 1
+  }
+
+  # Start emulator with output redirected to temp log
+  # Use proper quoting for optional verbose flag
+  if [ -n "$verbose_flag" ]; then
+    node "$project_root/packages/emulator/dist/esm/bin/ya-modbus-emulator.js" \
+      --config "$config_file" \
+      "$verbose_flag" \
+      > "$temp_log" 2>&1 &
+  else
+    node "$project_root/packages/emulator/dist/esm/bin/ya-modbus-emulator.js" \
+      --config "$config_file" \
+      > "$temp_log" 2>&1 &
+  fi
   local pid=$!
 
+  # Create symlink for PID-based access
+  local log_file="/tmp/emulator-$pid.log"
+  if ! ln -sf "$temp_log" "$log_file"; then
+    echo "Warning: Failed to create log symlink" >&2
+  fi
+
+  # Store metadata for cleanup
   echo "$pid" > "/tmp/emulator-$pid.pid"
+  echo "$temp_log" > "/tmp/emulator-$pid-logfile.txt"
 
   # Wait for emulator to be ready by checking log file
   local timeout=50
@@ -107,12 +161,12 @@ start_test_emulator() {
     # Check if process is still alive
     if ! kill -0 "$pid" 2>/dev/null; then
       echo "Emulator process died during startup" >&2
-      cat "$log_file" >&2
+      cat "$temp_log" >&2
       return 1
     fi
 
     # Check log file for "Emulator started successfully" message
-    if [ -f "$log_file" ] && grep -q "Emulator started successfully" "$log_file" 2>/dev/null; then
+    if [ -f "$temp_log" ] && grep -q "Emulator started successfully" "$temp_log" 2>/dev/null; then
       emulator_ready=1
       break
     fi
@@ -122,15 +176,14 @@ start_test_emulator() {
   done
 
   # If readiness not detected but process alive, it may have started without logging
-  # Skip the fallback sleep since we now have proper log output
   if [ $emulator_ready -eq 0 ] && kill -0 "$pid" 2>/dev/null; then
     echo "Warning: Emulator running but startup message not found in logs" >&2
   fi
 
   # Final check if still running
   if ! kill -0 "$pid" 2>/dev/null; then
     echo "Failed to start emulator" >&2
-    cat "$log_file" >&2
+    cat "$temp_log" >&2
     return 1
   fi
 
@@ -139,9 +192,17 @@ start_test_emulator() {
 }
 
 # Stop emulator
+#
+# Stops the emulator process and cleans up all associated files (PID file,
+# log symlink, and temporary log file).
+#
+# Arguments:
+#   $1 - pid: Process ID of the emulator to stop
+#
 stop_test_emulator() {
   local pid=$1
   local pid_file="/tmp/emulator-$pid.pid"
+  local log_file_ref="/tmp/emulator-$pid-logfile.txt"
 
   if [ -n "$pid" ] && kill -0 "$pid" 2>/dev/null; then
     kill "$pid" 2>/dev/null || true
@@ -181,7 +242,19 @@ stop_test_emulator() {
     wait "$pid" 2>/dev/null || true
   fi
 
+  # Clean up temp log file (read path from reference file)
+  if [ -f "$log_file_ref" ]; then
+    local temp_log
+    temp_log=$(cat "$log_file_ref" 2>/dev/null)
+    if [ -n "$temp_log" ]; then
+      rm -f "$temp_log" 2>/dev/null || true
+    fi
+    rm -f "$log_file_ref"
+  fi
+
+  # Clean up PID file and symlink
   rm -f "$pid_file"
+  rm -f "/tmp/emulator-$pid.log"
 }
 
 # Check if Docker service is healthy
@@ -238,6 +311,48 @@ assert_file_contains() {
   fi
 }
 
+# Assert emulator log contains expected pattern
+#
+# Reads the emulator log file for the given PID and verifies it contains
+# the specified pattern using extended regex matching (grep -E).
+#
+# The log file is accessed via the symlink at /tmp/emulator-$pid.log which
+# points to the actual temp log file created by start_test_emulator.
+#
+# Arguments:
+#   $1 - pid: Process ID of the emulator
+#   $2 - expected: Pattern to search for (supports grep extended regex)
+#
+# Returns:
+#   0 if pattern found
+#   1 if log file not found or pattern not found (dumps full log to stderr)
+#
+# Examples:
+#   assert_emulator_log_contains "$EMULATOR_PID" "\[VERBOSE\] READ"
+#   assert_emulator_log_contains "$EMULATOR_PID" "func=0x03"
+#   assert_emulator_log_contains "$EMULATOR_PID" "slave=1"
+#
+# Note: Brackets and special regex characters must be escaped with backslash
+#       when using grep -E. For example, to match literal "[VERBOSE]" use "\[VERBOSE\]"
+#
+assert_emulator_log_contains() {
+  local pid=$1
+  local expected=$2
+  local log_file="/tmp/emulator-$pid.log"
+
+  if [ ! -f "$log_file" ]; then
+    echo "Emulator log file not found: $log_file" >&2
+    return 1
+  fi
+
+  if ! grep -qE "$expected" "$log_file"; then
+    echo "Expected emulator log to contain: $expected" >&2
+    echo "Emulator log contents:" >&2
+    cat "$log_file" >&2
+    return 1
+  fi
+}
+
 # Get project root directory
 get_project_root() {
   local script_dir
@@ -249,5 +364,8 @@ get_project_root() {
 clean_test_artifacts() {
   rm -f /tmp/mqtt-messages-*.txt 2>/dev/null || true
   rm -f /tmp/emulator-*.log 2>/dev/null || true
+  rm -f /tmp/emulator-*.pid 2>/dev/null || true
+  rm -f /tmp/emulator-*-logfile.txt 2>/dev/null || true
+  rm -f /tmp/emulator-temp-*.log 2>/dev/null || true
   rm -f /tmp/bridge-*.log 2>/dev/null || true
 }