|
| 1 | +# Stream Reading Improvements for CI Testing |
| 2 | + |
| 3 | +## Problem Statement |
| 4 | +Tests fail on CI (GitHub Actions) because `stream_select` behavior differs from local environment. The REPL process outputs to stdout, but tests only capture the banner and miss command output. This is likely due to: |
| 5 | +- GitHub Actions TTY limitations |
| 6 | +- Stderr writes that unblock select |
| 7 | +- Different buffering behavior in CI |
| 8 | + |
| 9 | +## Core Considerations |
| 10 | + |
| 11 | +### 1. ✅ Fix the Loop Logic (DONE) |
| 12 | +**Problem**: Current loop exits on first timeout without a prompt, even with longer timeouts. |
| 13 | +**Solution**: Continue polling on timeout instead of breaking. Use overall timeout guard. |
| 14 | +**Status**: Implemented in `ReplOutputReader::readOutput()` |
| 15 | +- Changed `break` to `continue` on timeout without prompt |
| 16 | +- Added overall timeout tracking |
| 17 | + |
| 18 | +### 2. ✅ Environment Configuration (DONE) |
| 19 | +**Solution**: Use .env for local, .env.test for CI with configurable timeouts |
| 20 | +**Status**: Implemented |
| 21 | +- `.env` with 1.5s timeout (local, gitignored) |
| 22 | +- `.env.test` with 5.0s timeout (CI, tracked) |
| 23 | +- ReplOutputReader reads from environment |
| 24 | + |
| 25 | +### 3. ✅ Read from Both stdout AND stderr (DONE) |
| 26 | +**Problem**: GitHub Actions might write to stderr, causing stream_select to unblock, but we only read stdout. |
| 27 | +**Solution**: |
| 28 | +- Pass both `$pipes[1]` (stdout) and `$pipes[2]` (stderr) to stream_select |
| 29 | +- Read from whichever is ready |
| 30 | +- Only append stdout to output (discard stderr noise, or log it) |
| 31 | +**Status**: IMPLEMENTED in `ReplOutputReader::readOutput()` |
| 32 | +- Modified signature to accept `$stderrStream` parameter |
| 33 | +- Loop reads from both streams |
| 34 | +- stderr output logged but not included in return value |
| 35 | +- Updated `ReplSteps::readOutput()` to pass stderr |
| 36 | + |
| 37 | +### 4. ✅ Debug Logging for CI (DONE) |
| 38 | +**Problem**: Can't see what's happening in CI without visibility, but don't want noise on passing tests |
| 39 | +**Solution**: Add conditional debug logging to ReplOutputReader |
| 40 | +**Status**: IMPLEMENTED |
| 41 | +- Buffers log messages instead of immediately outputting |
| 42 | +- Only outputs logs when: |
| 43 | + - `REPL_DEBUG=true` in .env (always log) |
| 44 | + - Timeout occurs with no output (indicates failure) |
| 45 | + - stream_select error occurs |
| 46 | +- Keeps local test output clean (.env has `REPL_DEBUG=false`) |
| 47 | +- CI gets full logs (.env.test has `REPL_DEBUG=true`) |
| 48 | +- Added to `ReplProcessManager::sendInput()` as well |
| 49 | + |
| 50 | +### 5. ✅ Process Management Review (DONE) |
| 51 | +**Current**: Using `proc_open` with pipes, streams set to non-blocking |
| 52 | +**Considerations**: |
| 53 | +- After writing to stdin (`$pipes[0]`), explicitly `fflush($pipes[0])` |
| 54 | +- Consider `fclose($pipes[0])` after all input to signal EOF (may not be appropriate for REPL) |
| 55 | +- Ensure both stdout and stderr are non-blocking |
| 56 | +**Status**: REVIEWED - Already doing `fflush()` after writes |
| 57 | +- Added logging to `sendInput()` to verify bytes written |
| 58 | + |
| 59 | +### 6. 🔮 Sentinel/Test Mode Approach (FUTURE) |
| 60 | +**Alternative**: Instead of guessing prompts, have REPL print a sentinel in test mode |
| 61 | +```php |
| 62 | +// In test mode, REPL prints: |
| 63 | +echo "COMMAND_DONE_MARKER\n"; |
| 64 | +``` |
| 65 | +Then look for sentinel instead of prompt patterns. |
| 66 | +**Status**: NOT IMPLEMENTED - Requires REPL changes |
| 67 | +**Priority**: LOW - Nice to have, but invasive |
| 68 | + |
| 69 | +### 7. 🔮 Phunkie Streams Solution (FUTURE) |
| 70 | +**Idea**: Extract this into a reusable Phunkie Streams component |
| 71 | +- `Stream\Process\asyncRead($stream, $predicate, $timeout)` |
| 72 | +- Handles non-blocking reads, multiple streams, sentinel detection |
| 73 | +**Status**: NOT IMPLEMENTED |
| 74 | +**Priority**: LOW - After we solve the immediate problem |
| 75 | + |
| 76 | +## Action Items (Prioritized) |
| 77 | + |
| 78 | +### Immediate (Baby Steps) |
| 79 | +1. ✅ Fix loop to continue polling instead of breaking on timeout |
| 80 | +2. ✅ Add .env configuration for timeouts |
| 81 | +3. ✅ Modify `ReplOutputReader::readOutput()` to accept stderr stream |
| 82 | +4. ✅ Update `ReplSteps` to pass stderr to `readOutput()` |
| 83 | +5. ✅ Read from both streams in the loop, only append stdout to output |
| 84 | +6. ✅ Add debug logging (error_log) to see what's happening in CI |
| 85 | +7. ✅ Review `ReplProcessManager` for proper fflush() usage |
| 86 | +8. ⏳ **NEXT**: Test locally to verify changes don't break existing tests |
| 87 | +9. ⏳ **NEXT**: Test on CI with full test suite |
| 88 | + |
| 89 | +### Long Term |
| 90 | +10. Review CI logs to see if stderr reading solves the issue |
| 91 | +11. Consider reducing timeouts if tests are passing consistently |
| 92 | +12. Consider sentinel-based approach for more reliable testing |
| 93 | +13. Extract pattern into Phunkie Streams if successful |
| 94 | + |
| 95 | +## Notes |
| 96 | +- **Don't just increase timeouts** - that makes CI slow and doesn't address root cause |
| 97 | +- **Stderr reading is likely the key** - GitHub Actions might be writing to stderr |
| 98 | +- **Keep local tests fast** - use .env for short timeouts locally |
| 99 | +- **Baby steps** - implement one thing at a time and test |
| 100 | + |
| 101 | +## Current Status |
| 102 | +- Loop logic fixed ✅ |
| 103 | +- Environment config added ✅ |
| 104 | +- Stderr reading implemented ✅ |
| 105 | +- Debug logging implemented with buffering ✅ |
| 106 | +- **SENTINEL APPROACH IMPLEMENTED** ✅ |
| 107 | +- **LOCAL TESTS**: All 418 scenarios, 2056 steps PASSING in ~18s ✅ |
| 108 | +- **NEXT**: Test on CI to verify sentinel approach works in GitHub Actions |
| 109 | + |
| 110 | +## Test Results |
| 111 | +- **Local (PHP 8.4)**: 418 scenarios, 2056 steps - ALL PASSED ✅ |
| 112 | +- **CI**: Pending - need to push and test |
| 113 | + |
| 114 | +## Sentinel Approach + Blocking Read Strategy |
| 115 | + |
| 116 | +### The Problem |
| 117 | +GitHub Actions has different TTY/buffering behavior than local environments. The original non-blocking, short-timeout polling approach with `stream_select` would break too aggressively on timeouts, exiting the read loop before all data arrived. This caused tests to only capture the REPL banner, missing actual command output. |
| 118 | + |
| 119 | +### The Solution: Two-Part Fix |
| 120 | + |
| 121 | +#### Part 1: Sentinel Marker (Explicit Ready Signal) |
| 122 | +Instead of guessing when the REPL is ready by detecting prompt patterns, the REPL explicitly prints `__PHUNKIE_READY__` when ready for input. |
| 123 | + |
| 124 | +**REPL side** (`src/Repl/ReplLoop.php`): |
| 125 | +- Added `isTestMode()` to check `REPL_TEST_MODE` environment variable |
| 126 | +- Added `printTestSentinel()` that prints `__PHUNKIE_READY__\n` in test mode |
| 127 | +- Called before each prompt in `replLoopTrampoline()` |
| 128 | + |
| 129 | +**Test side**: |
| 130 | +- `ReplProcessManager` loads `.env` and passes `REPL_TEST_MODE` to child process |
| 131 | +- `ReplOutputReader` detects sentinel instead of prompt patterns in test mode |
| 132 | +- Sentinel is stripped from output before returning to tests |
| 133 | +- `ReplSteps.waitForPrompt()` uses `ReplOutputReader` for consistent detection |
| 134 | + |
| 135 | +#### Part 2: Blocking Read Strategy (Patience Over Speed) |
| 136 | +Changed from aggressive timeout-based polling to blocking reads that wait naturally for data. |
| 137 | + |
| 138 | +**Key changes in `ReplOutputReader::readOutput()`**: |
| 139 | +1. **Longer `stream_select` timeout**: Up to 1 second (vs 50ms) to let data arrive naturally |
| 140 | +2. **No early exits on timeout**: Only breaks when: |
| 141 | + - Prompt/sentinel found ✅ |
| 142 | + - Overall timeout hit ⏱️ |
| 143 | + - EOF/error encountered ❌ |
| 144 | +3. **Calculated remaining timeout**: Uses `min(1.0, remainingTimeout)` for smart waiting |
| 145 | +4. **Smaller read chunks**: 4096 bytes for more incremental reading |
| 146 | +5. **Proper error handling**: Detects EOF and read errors explicitly |
| 147 | + |
| 148 | +**Before (aggressive)**: |
| 149 | +```php |
| 150 | +// 50ms timeout on stream_select |
| 151 | +$result = @stream_select($read, $write, $except, 0, 50000); |
| 152 | +if ($result === 0) { |
| 153 | + break; // ❌ Exits too early! |
| 154 | +} |
| 155 | +``` |
| 156 | + |
| 157 | +**After (patient)**: |
| 158 | +```php |
| 159 | +// Up to 1 second timeout, calculated from remaining time |
| 160 | +$selectTimeout = min(1.0, $remainingTimeout); |
| 161 | +$result = @stream_select($read, $write, $except, $selectTimeoutSec, $selectTimeoutUsec); |
| 162 | +if ($result === 0) { |
| 163 | + if (self::endsWithPrompt($output)) { |
| 164 | + break; // ✅ Only exit if we have complete response |
| 165 | + } |
| 166 | + continue; // ✅ Keep waiting for data |
| 167 | +} |
| 168 | +``` |
| 169 | + |
| 170 | +### Benefits |
| 171 | +- ✅ **Reliable in CI**: Doesn't break early when I/O is slow |
| 172 | +- ✅ **Explicit ready signal**: Sentinel removes guesswork |
| 173 | +- ✅ **Fast locally**: ~18 seconds for 418 scenarios |
| 174 | +- ✅ **Handles slow environments**: Waits patiently up to overall timeout |
| 175 | +- ✅ **Clean output**: Sentinel stripped automatically |
| 176 | +- ✅ **Proper error handling**: Detects EOF and errors gracefully |
| 177 | + |
| 178 | +### Configuration |
| 179 | +- `.env` (local): `REPL_TEST_MODE=true`, `REPL_OUTPUT_TIMEOUT=1.5` |
| 180 | +- `.env.test` (CI): `REPL_TEST_MODE=true`, `REPL_OUTPUT_TIMEOUT=5.0` |
| 181 | + |
| 182 | +### Files Modified |
| 183 | +- `src/Repl/ReplLoop.php` - Sentinel printing |
| 184 | +- `tests/Acceptance/Support/ReplProcessManager.php` - Environment passing |
| 185 | +- `tests/Acceptance/Support/ReplOutputReader.php` - **Blocking read strategy + sentinel detection** |
| 186 | +- `tests/Acceptance/ReplSteps.php` - Use ReplOutputReader in test mode |
| 187 | +- `.env` and `.env.test` - Configuration |
0 commit comments