DevTools protocol logs captured by Grover are incomplete

[ktreis]

While trying to diagnose a timeout issue in one of our Rails apps, we discovered that the DevTools logs captured by Grover were incomplete. We would see the HTML captured by middleware handed to Puppeteer, see it set up interceptions for JS/stylesheet assets, send some (but not all) of the Fetch.continueRequest messages... and that was all.

I think the problem comes down to the way Grover uses async IO to read from stderr in Grover::Processor#capture_debug_output. The output that we're trying to read from stderr might be sent asynchronously as well. I haven't done much async IO in Ruby, but I rewrote the capture_debug_output method as follows:

    def capture_debug_output
      error_output = ''
      loop do
        begin
          error_output += stderr.read_nonblock(4096)
        rescue IO::WaitReadable
          retry if IO.select([stderr], [], [], 2)
          break
        end
      end
      @debug_output = Grover::DevToolsParser.parse(error_output.force_encoding('UTF-8'))
    end

And with that, I got a much more complete set of logs, even up to and including the PDF bytes themselves followed by a Browser.close and other teardown events. Finally, the DevTools protocol logs were telling us the whole story!

Granted, my simplistic implementation here introduces a 2-second delay after the final log event is received. But I'm not sure how to determine the right timeout to use here; maybe there's a better way to know when the node/puppeteer process is done spewing debug info on stderr. But for our debugging purposes, it's a small price to pay for a full set of debug logs.