Command to enable a more useful debug log

lib/capybara/driver/webkit.rb

@@ -26,6 +26,10 @@ class Capybara::Driver::Webkit
     @browser = options[:browser] || Browser.new(Connection.new(options))
   end
 
+  def enable_logging
+    browser.enable_logging
+  end
+
   def current_url
     browser.current_url
   end

lib/capybara/driver/webkit/browser.rb

@@ -10,6 +10,10 @@ class Capybara::Driver::Webkit
       command("Authenticate", username, password)
     end
 
+    def enable_logging
+      command "EnableLogging"
+    end
+
     def visit(url)
       command "Visit", url
     end

lib/capybara/driver/webkit/connection.rb

@@ -12,6 +12,7 @@ class Capybara::Driver::Webkit
     def initialize(options = {})
       @socket_class = options[:socket_class] || TCPSocket
       @stdout = options.has_key?(:stdout) ?  options[:stdout] : $stdout
+      @command = options[:command] || SERVER_PATH
       start_server
       connect
     end
@@ -41,7 +42,7 @@ class Capybara::Driver::Webkit
     end
 
     def open_pipe
-      @pipe = IO.popen(SERVER_PATH)
+      @pipe = IO.popen(@command)
       @pid = @pipe.pid
       register_shutdown_hook
     end

lib/capybara/webkit.rb

@@ -6,8 +6,7 @@ Capybara.register_driver :webkit do |app|
 end
 
 Capybara.register_driver :webkit_debug do |app|
-  connection = Capybara::Driver::Webkit::Connection.new(
-    :socket_class => Capybara::Driver::Webkit::SocketDebugger)
-  browser = Capybara::Driver::Webkit::Browser.new(connection)
-  Capybara::Driver::Webkit.new(app, :browser => browser)
+  driver = Capybara::Driver::Webkit.new(app)
+  driver.enable_logging
+  driver
 end

spec/driver_spec.rb

@@ -4,8 +4,10 @@ require 'base64'
 
 describe Capybara::Driver::Webkit do
   subject { Capybara::Driver::Webkit.new(@app, :browser => $webkit_browser) }
-  before { subject.visit("/hello/world?success=true") }
-  after { subject.reset! }
+  before do
+    subject.reset!
+    subject.visit("/hello/world?success=true")
+  end
 
   context "iframe app" do
     before(:all) do
@@ -1767,4 +1769,37 @@ describe Capybara::Driver::Webkit do
       subject.body.should include("Basic "+Base64.encode64("user:password").strip)
     end
   end
+
+  describe "logger app" do
+    before(:all) do
+      @app = lambda do |env|
+        [200, { "Content-Type" => "text/html", "Content-Length" => "0" }, [""]]
+      end
+    end
+
+    it "logs nothing before turning on the logger" do
+      driver.visit("/")
+      log.should == ""
+    end
+
+    it "logs its commands after turning on the logger" do
+      driver.enable_logging
+      driver.visit("/")
+      log.should_not == ""
+    end
+
+    let(:driver) do
+      command = "#{Capybara::Driver::Webkit::Connection::SERVER_PATH} 2>&1"
+      connection = Capybara::Driver::Webkit::Connection.new(:command => command, :stdout => output)
+      browser = Capybara::Driver::Webkit::Browser.new(connection)
+      Capybara::Driver::Webkit.new(@app, :browser => browser)
+    end
+
+    let(:output) { StringIO.new }
+
+    def log
+      output.rewind
+      output.read
+    end
+  end
 end

src/Command.cpp

@@ -10,15 +10,18 @@ Command::Command(WebPageManager *manager, QStringList &arguments, QObject *paren
 void Command::start() {
 }
 
-WebPage *Command::page() {
+QString Command::toString() const {
+  return metaObject()->className();
+}
+
+WebPage *Command::page() const {
   return m_manager->currentPage();
 }
 
-QStringList &Command::arguments() {
+const QStringList &Command::arguments() const {
   return m_arguments;
 }
 
-WebPageManager *Command::manager() {
+WebPageManager *Command::manager() const {
   return m_manager;
 }
-

src/Command.h

@@ -14,14 +14,15 @@ class Command : public QObject {
   public:
     Command(WebPageManager *, QStringList &arguments, QObject *parent = 0);
     virtual void start();
+    virtual QString toString() const;
 
   signals:
     void finished(Response *response);
 
   protected:
-    WebPage *page();
-    QStringList &arguments();
-    WebPageManager *manager();
+    WebPage *page() const;
+    const QStringList &arguments() const;
+    WebPageManager *manager() const;
 
   private:
     QStringList m_arguments;

src/CommandFactory.cpp

@@ -30,6 +30,7 @@
 #include "GetWindowHandle.h"
 #include "WebPageManager.h"
 #include "Authenticate.h"
+#include "EnableLogging.h"
 
 CommandFactory::CommandFactory(WebPageManager *manager, QObject *parent) : QObject(parent) {
   m_manager = manager;

src/Connection.cpp

@@ -23,10 +23,13 @@ Connection::Connection(QTcpSocket *socket, WebPageManager *manager, QObject *par
 
 void Connection::commandReady(Command *command) {
   m_queuedCommand = command;
-  if (m_manager->isLoading())
+  m_manager->logger() << "Received" << command->toString();
+  if (m_manager->isLoading()) {
+    m_manager->logger() << command->toString() << "waiting for load to finish";
     m_commandWaiting = true;
-  else
+  } else {
     startCommand();
+  }
 }
 
 void Connection::startCommand() {
@@ -42,8 +45,9 @@ void Connection::startCommand() {
 
 void Connection::pendingLoadFinished(bool success) {
   m_pageSuccess = m_pageSuccess && success;
-  if (m_commandWaiting)
+  if (m_commandWaiting) {
     startCommand();
+  }
 }
 
 void Connection::writePageLoadFailure() {
@@ -64,6 +68,8 @@ void Connection::writeResponse(Response *response) {
   else
     m_socket->write("failure\n");
 
+  m_manager->logger() << "Wrote response" << response->isSuccess() << response->message();
+
   QByteArray messageUtf8 = response->message();
   QString messageLength = QString::number(messageUtf8.size()) + "\n";
   m_socket->write(messageLength.toAscii());

src/EnableLogging.cpp

@@ -0,0 +1,10 @@
+#include "EnableLogging.h"
+#include "WebPageManager.h"
+
+EnableLogging::EnableLogging(WebPageManager *manager, QStringList &arguments, QObject *parent) : Command(manager, arguments, parent) {
+}
+
+void EnableLogging::start() {
+  manager()->enableLogging();
+  emit finished(new Response(true));
+}

src/EnableLogging.h

@@ -0,0 +1,12 @@
+#include "Command.h"
+
+class WebPageManager;
+
+class EnableLogging : public Command {
+  Q_OBJECT
+
+  public:
+    EnableLogging(WebPageManager *, QStringList &arguments, QObject *parent = 0);
+    virtual void start();
+};
+

src/JavascriptInvocation.cpp

@@ -1,6 +1,6 @@
 #include "JavascriptInvocation.h"
 
-JavascriptInvocation::JavascriptInvocation(QString &functionName, QStringList &arguments, QObject *parent) : QObject(parent) {
+JavascriptInvocation::JavascriptInvocation(const QString &functionName, const QStringList &arguments, QObject *parent) : QObject(parent) {
   m_functionName = functionName;
   m_arguments = arguments;
 }

src/JavascriptInvocation.h

@@ -8,7 +8,7 @@ class JavascriptInvocation : public QObject {
   Q_PROPERTY(QStringList arguments READ arguments)
 
   public:
-    JavascriptInvocation(QString &functionName, QStringList &arguments, QObject *parent = 0);
+    JavascriptInvocation(const QString &functionName, const QStringList &arguments, QObject *parent = 0);
     QString &functionName();
     QStringList &arguments();
 

src/Node.cpp

@@ -13,3 +13,7 @@ void Node::start() {
   emit finished(new Response(true, attributeValue));
 }
 
+QString Node::toString() const {
+  QStringList functionArguments(arguments());
+  return QString("Node.") + functionArguments.takeFirst();
+}

src/Node.h

@@ -7,5 +7,6 @@ class Node : public Command {
   public:
     Node(WebPageManager *manager, QStringList &arguments, QObject *parent = 0);
     virtual void start();
+    virtual QString toString() const;
 };
 

src/PageLoadingCommand.cpp

@@ -14,6 +14,7 @@ PageLoadingCommand::PageLoadingCommand(Command *command, WebPageManager *manager
 }
 
 void PageLoadingCommand::start() {
+  m_manager->logger() << "Started" << m_command->toString();
   connect(m_command, SIGNAL(finished(Response *)), this, SLOT(commandFinished(Response *)));
   m_command->start();
 };
@@ -23,6 +24,7 @@ void PageLoadingCommand::pendingLoadFinished(bool success) {
   if (m_pageLoadingFromCommand) {
     m_pageLoadingFromCommand = false;
     if (m_pendingResponse) {
+      m_manager->logger() << "Page load from command finished";
       if (m_pageSuccess) {
         emit finished(m_pendingResponse);
       } else {
@@ -34,11 +36,13 @@ void PageLoadingCommand::pendingLoadFinished(bool success) {
 }
 
 void PageLoadingCommand::pageLoadingFromCommand() {
+  m_manager->logger() << m_command->toString() << "started page load";
   m_pageLoadingFromCommand = true;
 }
 
 void PageLoadingCommand::commandFinished(Response *response) {
   disconnect(m_manager, SIGNAL(loadStarted()), this, SLOT(pageLoadingFromCommand()));
+  m_manager->logger() << "Finished" << m_command->toString();
   m_command->deleteLater();
   if (m_pageLoadingFromCommand)
     m_pendingResponse = response;

src/WebPage.cpp

@@ -116,7 +116,7 @@ bool WebPage::shouldInterruptJavaScript() {
   return false;
 }
 
-QVariant WebPage::invokeCapybaraFunction(const char *name, QStringList &arguments) {
+QVariant WebPage::invokeCapybaraFunction(const char *name, const QStringList &arguments) {
   QString qname(name);
   QString objectName("CapybaraInvocation");
   JavascriptInvocation invocation(qname, arguments);
@@ -125,7 +125,7 @@ QVariant WebPage::invokeCapybaraFunction(const char *name, QStringList &argument
   return currentFrame()->evaluateJavaScript(javascript);
 }
 
-QVariant WebPage::invokeCapybaraFunction(QString &name, QStringList &arguments) {
+QVariant WebPage::invokeCapybaraFunction(QString &name, const QStringList &arguments) {
   return invokeCapybaraFunction(name.toAscii().data(), arguments);
 }
 

src/WebPage.h

@@ -9,8 +9,8 @@ class WebPage : public QWebPage {
 
   public:
     WebPage(WebPageManager *, QObject *parent = 0);
-    QVariant invokeCapybaraFunction(const char *name, QStringList &arguments);
-    QVariant invokeCapybaraFunction(QString &name, QStringList &arguments);
+    QVariant invokeCapybaraFunction(const char *name, const QStringList &arguments);
+    QVariant invokeCapybaraFunction(QString &name, const QStringList &arguments);
     QString failureString();
     QString userAgentForUrl(const QUrl &url ) const;
     void setUserAgent(QString userAgent);

src/WebPageManager.cpp

@@ -1,12 +1,13 @@
 #include "WebPageManager.h"
 #include "WebPage.h"
 #include "NetworkCookieJar.h"
-#include <stdio.h>
 
 WebPageManager::WebPageManager(QObject *parent) : QObject(parent) {
   m_ignoreSslErrors = false;
   m_cookieJar = new NetworkCookieJar(this);
   m_success = true;
+  m_loggingEnabled = false;
+  m_ignoredOutput = new QString();
   createPage(this)->setFocus();
 }
 
@@ -22,7 +23,7 @@ void WebPageManager::setCurrentPage(WebPage *page) {
   m_currentPage = page;
 }
 
-WebPage *WebPageManager::currentPage() {
+WebPage *WebPageManager::currentPage() const {
   return m_currentPage;
 }
 
@@ -31,7 +32,7 @@ WebPage *WebPageManager::createPage(QObject *parent) {
   connect(page, SIGNAL(loadStarted()),
           this, SLOT(emitLoadStarted()));
   connect(page, SIGNAL(pageFinished(bool)),
-          this, SLOT(emitPageFinished(bool)));
+          this, SLOT(setPageStatus(bool)));
   connect(page, SIGNAL(requestCreated(QNetworkReply *)),
           this, SLOT(requestCreated(QNetworkReply *)));
   connect(page, SIGNAL(replyFinished(QNetworkReply *)),
@@ -42,26 +43,40 @@ WebPage *WebPageManager::createPage(QObject *parent) {
 
 void WebPageManager::emitLoadStarted() {
   if (m_started.empty()) {
+    logger() << "Load started";
     emit loadStarted();
   }
 }
 
 void WebPageManager::requestCreated(QNetworkReply *reply) {
+  logger() << "Started request to" << reply->url().toString();
   m_started += reply;
 }
 
 void WebPageManager::replyFinished(QNetworkReply *reply) {
+  int status = reply->attribute(QNetworkRequest::HttpStatusCodeAttribute).toInt();
+  logger() << "Received" << status << "from" << reply->url().toString();
   m_started.remove(reply);
+  logger() << m_started.size() << "requests remaining";
+  if (m_started.empty() && !m_success) {
+    emitPageFinished();
+  }
 }
 
-void WebPageManager::emitPageFinished(bool success) {
+void WebPageManager::setPageStatus(bool success) {
+  logger() << "Page finished with" << success;
   m_success = success && m_success;
   if (m_started.empty()) {
-    emit pageFinished(m_success);
-    m_success = true;
+    emitPageFinished();
   }
 }
 
+void WebPageManager::emitPageFinished() {
+  logger() << "Load finished";
+  emit pageFinished(m_success);
+  m_success = true;
+}
+
 void WebPageManager::setIgnoreSslErrors(bool value) {
   m_ignoreSslErrors = value;
 }
@@ -89,3 +104,14 @@ bool WebPageManager::isLoading() const {
   }
   return false;
 }
+
+QDebug WebPageManager::logger() const {
+  if (m_loggingEnabled)
+    return qDebug();
+  else
+    return QDebug(m_ignoredOutput);
+}
+
+void WebPageManager::enableLogging() {
+  m_loggingEnabled = true;
+}

src/WebPageManager.h

@@ -4,6 +4,8 @@
 #include <QSet>
 #include <QObject>
 #include <QNetworkReply>
+#include <QDebug>
+#include <QFile>
 
 class WebPage;
 class NetworkCookieJar;
@@ -16,17 +18,19 @@ class WebPageManager : public QObject {
     void append(WebPage *value);
     QList<WebPage *> pages() const;
     void setCurrentPage(WebPage *);
-    WebPage *currentPage();
+    WebPage *currentPage() const;
     WebPage *createPage(QObject *parent);
     void setIgnoreSslErrors(bool);
     bool ignoreSslErrors();
     void reset();
     NetworkCookieJar *cookieJar();
     bool isLoading() const;
+    QDebug logger() const;
+    void enableLogging();
 
   public slots:
     void emitLoadStarted();
-    void emitPageFinished(bool);
+    void setPageStatus(bool);
     void requestCreated(QNetworkReply *reply);
     void replyFinished(QNetworkReply *reply);
 
@@ -35,12 +39,17 @@ class WebPageManager : public QObject {
     void loadStarted();
 
   private:
+    void emitPageFinished();
+    static void handleDebugMessage(QtMsgType type, const char *message);
+
     QList<WebPage *> m_pages;
     WebPage *m_currentPage;
     bool m_ignoreSslErrors;
     NetworkCookieJar *m_cookieJar;
     QSet<QNetworkReply*> m_started;
     bool m_success;
+    bool m_loggingEnabled;
+    QString *m_ignoredOutput;
 };
 
 #endif // _WEBPAGEMANAGER_H

src/find_command.h

@@ -31,3 +31,4 @@ CHECK_COMMAND(WindowFocus)
 CHECK_COMMAND(GetWindowHandles)
 CHECK_COMMAND(GetWindowHandle)
 CHECK_COMMAND(Authenticate)
+CHECK_COMMAND(EnableLogging)

src/webkit_server.pro

@@ -2,6 +2,7 @@ TEMPLATE = app
 TARGET = webkit_server
 DESTDIR = .
 HEADERS = \
+  EnableLogging.h \
   Authenticate.h \
   IgnoreSslErrors.h \
   ResizeWindow.h \
@@ -46,6 +47,7 @@ HEADERS = \
   GetWindowHandle.h \
 
 SOURCES = \
+  EnableLogging.cpp \
   Authenticate.cpp \
   IgnoreSslErrors.cpp \
   ResizeWindow.cpp \

templates/Command.cpp

@@ -1,10 +1,8 @@
 #include "NAME.h"
 #include "WebPage.h"
 
-NAME::NAME(WebPage *page, QObject *parent) : Command(page, parent) {
+NAME::NAME(WebPageManager *manager, QStringList &arguments, QObject *parent) : Command(manager, arguments, parent) {
 }
 
-void NAME::start(QStringList &arguments) {
-  Q_UNUSED(arguments);
+void NAME::start() {
 }
-

templates/Command.h

@@ -6,7 +6,7 @@ class NAME : public Command {
   Q_OBJECT
 
   public:
-    NAME(WebPage *page, QObject *parent = 0);
-    virtual void start(QStringList &arguments);
+    NAME(WebPageManager *, QStringList &arguments, QObject *parent = 0);
+    virtual void start();
 };