Merge pull request #1040 from thoughtbot/logger_time

Add time to logging - continuation of PR #921

spec/server_spec.rb

@@ -89,7 +89,7 @@ describe Capybara::Webkit::Connection do
     socket.puts script.to_s.bytesize
     socket.print script
 
-    expect(read_io).to include_response "\nhello world"
+    expect(read_io).to include_response /\n\d{2}:\d{2}:\d{2}\.\d{3} hello world/
   end
 
   it "does not forward stderr to nil" do

spec/support/matchers/include_response.rb

@@ -8,7 +8,11 @@ RSpec::Matchers.define :include_response do |expected_response|
 
     while !found_response && IO.select([read_io], nil, nil, read_timeout) do
       response += read_io.read_nonblock(read_bytes)
-      found_response = response.include?(expected_response)
+      found_response = if expected_response.is_a? Regexp
+        response.match(expected_response)
+      else
+        response.include?(expected_response)
+      end
     end
 
     found_response

src/Connection.cpp

@@ -24,7 +24,7 @@ Connection::Connection(QTcpSocket *socket, WebPageManager *manager, QObject *par
 }
 
 void Connection::commandReady(Command *command) {
-  m_manager->logger() << "Received" << command->toString();
+  m_manager->log() << "Received" << command->toString();
   startCommand(command);
 }
 
@@ -65,7 +65,7 @@ void Connection::writeResponse(Response *response) {
   else
     m_socket->write("failure\n");
 
-  m_manager->logger() << "Wrote response" << response->isSuccess() << response->message();
+  m_manager->log() << "Wrote response" << response->isSuccess() << response->message();
 
   QByteArray messageUtf8 = response->message();
   QString messageLength = QString::number(messageUtf8.size()) + "\n";

src/PageLoadingCommand.cpp

@@ -14,7 +14,7 @@ PageLoadingCommand::PageLoadingCommand(Command *command, WebPageManager *manager
 }
 
 void PageLoadingCommand::start() {
-  m_manager->logger() << "Started" << m_command->toString();
+  m_manager->log() << "Started" << m_command->toString();
   connect(m_command, SIGNAL(finished(Response *)), this, SLOT(commandFinished(Response *)));
   connect(m_manager, SIGNAL(loadStarted()), this, SLOT(pageLoadingFromCommand()));
   connect(m_manager, SIGNAL(pageFinished(bool)), this, SLOT(pendingLoadFinished(bool)));
@@ -26,7 +26,7 @@ void PageLoadingCommand::pendingLoadFinished(bool success) {
   if (m_pageLoadingFromCommand) {
     m_pageLoadingFromCommand = false;
     if (m_pendingResponse) {
-      m_manager->logger() << "Page load from command finished";
+      m_manager->log() << "Page load from command finished";
       if (m_pageSuccess) {
         emit finished(m_pendingResponse);
       } else {
@@ -38,13 +38,13 @@ void PageLoadingCommand::pendingLoadFinished(bool success) {
 }
 
 void PageLoadingCommand::pageLoadingFromCommand() {
-  m_manager->logger() << m_command->toString() << "started page load";
+  m_manager->log() << 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() << "with response" << response->toString();
+  m_manager->log() << "Finished" << m_command->toString() << "with response" << response->toString();
 
   if (m_pageLoadingFromCommand)
     m_pendingResponse = response;

src/TimeoutCommand.cpp

@@ -19,7 +19,7 @@ TimeoutCommand::TimeoutCommand(Command *command, WebPageManager *manager, QObjec
 void TimeoutCommand::start() {
   QApplication::processEvents();
   if (m_manager->isLoading()) {
-    m_manager->logger() << this->toString() << "waiting for load to finish";
+    m_manager->log() << this->toString() << "waiting for load to finish";
     connect(m_manager, SIGNAL(pageFinished(bool)), this, SLOT(pendingLoadFinished(bool)));
     startTimeout();
   } else {

src/WebPage.cpp

@@ -177,7 +177,7 @@ void WebPage::javaScriptConsoleMessage(const QString &message, int lineNumber, c
     m["line_number"] = lineNumber;
   }
   m_consoleMessages.append(m);
-  m_manager->logger() << qPrintable(fullMessage);
+  m_manager->log() << qPrintable(fullMessage);
 }
 
 void WebPage::javaScriptAlert(QWebFrame *frame, const QString &message) {
@@ -194,7 +194,7 @@ void WebPage::javaScriptAlert(QWebFrame *frame, const QString &message) {
     addModalMessage(expectedType, message, expectedMessage);
   }
 
-  m_manager->logger() << "ALERT:" << qPrintable(message);
+  m_manager->log() << "ALERT:" << qPrintable(message);
 }
 
 bool WebPage::javaScriptConfirm(QWebFrame *frame, const QString &message) {

src/WebPageManager.cpp

@@ -81,14 +81,14 @@ void WebPageManager::removePage(WebPage *page) {
 
 void WebPageManager::emitLoadStarted() {
   if (m_started.empty()) {
-    logger() << "Load started";
+    log() << "Load started";
     emit loadStarted();
   }
   m_started += qobject_cast<WebPage *>(sender());
 }
 
 void WebPageManager::requestCreated(QByteArray &url, QNetworkReply *reply) {
-  logger() << "Started request to" << url;
+  log() << "Started request to" << url;
   if (reply->isFinished())
     replyFinished(reply);
   else {
@@ -110,7 +110,7 @@ void WebPageManager::handleReplyFinished() {
 
 void WebPageManager::replyFinished(QNetworkReply *reply) {
   int status = reply->attribute(QNetworkRequest::HttpStatusCodeAttribute).toInt();
-  logger() << "Received" << status << "from" << reply->url().toString();
+  log() << "Received" << status << "from" << reply->url().toString();
   m_pendingReplies.removeAll(reply);
 }
 
@@ -119,7 +119,7 @@ void WebPageManager::replyDestroyed(QObject *reply) {
 }
 
 void WebPageManager::setPageStatus(bool success) {
-  logger() << "Page finished with" << success;
+  log() << "Page finished with" << success;
   m_started.remove(qobject_cast<WebPage *>(sender()));
   m_success = success && m_success;
   if (m_started.empty()) {
@@ -128,7 +128,7 @@ void WebPageManager::setPageStatus(bool success) {
 }
 
 void WebPageManager::emitPageFinished() {
-  logger() << "Load finished";
+  log() << "Load finished";
   emit pageFinished(m_success);
   m_success = true;
 }
@@ -151,7 +151,7 @@ void WebPageManager::setTimeout(int timeout) {
 
 void WebPageManager::reset() {
   foreach(QNetworkReply *reply, m_pendingReplies) {
-    logger() << "Aborting request to" << reply->url().toString();
+    log() << "Aborting request to" << reply->url().toString();
     reply->abort();
   }
   m_pendingReplies.clear();
@@ -191,9 +191,9 @@ bool WebPageManager::isLoading() const {
   return false;
 }
 
-QDebug WebPageManager::logger() const {
+QDebug WebPageManager::log() const {
   if (m_loggingEnabled) {
-    return qCritical();
+    return qCritical() << qPrintable(QTime::currentTime().toString("hh:mm:ss.zzz"));
   } else {
     return QDebug(m_ignoredOutput);
   }

src/WebPageManager.h

@@ -33,7 +33,7 @@ class WebPageManager : public QObject {
     void reset();
     NetworkCookieJar *cookieJar();
     bool isLoading() const;
-    QDebug logger() const;
+    QDebug log() const;
     void enableLogging();
     void replyFinished(QNetworkReply *reply);
     NetworkAccessManager *networkAccessManager();