From c58d22061d944dc8b9b0b072082665c9f10877ac Mon Sep 17 00:00:00 2001
From: Charles Kerr <charles.kerr@canonical.com>
Date: Thu, 22 Sep 2016 09:10:48 -0500
Subject: add a plethora of log statements to help figure out what's causing
 the silo test failures

---
 src/adbd-client.cpp | 93 +++++++++++++++++++++++++++++++++++++++++++++++++++++
 src/usb-manager.cpp | 42 ++++++++++++++++++++++++
 2 files changed, 135 insertions(+)

diff --git a/src/adbd-client.cpp b/src/adbd-client.cpp
index 83b15ac..1539982 100644
--- a/src/adbd-client.cpp
+++ b/src/adbd-client.cpp
@@ -39,22 +39,31 @@ public:
         m_cancellable{g_cancellable_new()},
         m_worker_thread{&Impl::worker_func, this}
     {
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
     }
 
     ~Impl()
     {
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         // tell the worker thread to stop whatever it's doing and exit.
         g_debug("%s Client::Impl dtor, cancelling m_cancellable", G_STRLOC);
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         g_cancellable_cancel(m_cancellable);
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         m_pkresponse_cv.notify_one();
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         m_sleep_cv.notify_one();
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         if (m_worker_thread.joinable())
             m_worker_thread.join();
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         g_clear_object(&m_cancellable);
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
     }
 
     core::Signal<const PKRequest&>& on_pk_request()
     {
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         return m_on_pk_request;
     }
 
@@ -78,6 +87,7 @@ private:
 
     void pass_public_key_to_main_thread(const std::string& public_key)
     {
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         g_idle_add_full(G_PRIORITY_DEFAULT_IDLE,
                         on_public_key_request_static,
                         new PKIdleData{this, m_cancellable, public_key},
@@ -88,30 +98,47 @@ private:
     {
         /* NB: It's possible (though unlikely) that data.self was destroyed
            while this callback was pending, so we must check is-cancelled FIRST */
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         auto data = static_cast<PKIdleData*>(gdata);
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         if (!g_cancellable_is_cancelled(data->cancellable))
         {
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
             // notify our listeners of the request
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
             auto self = data->self;
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
             struct PKRequest req;
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
             req.public_key = data->public_key;
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
             req.fingerprint = get_fingerprint(req.public_key);
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
             req.respond = [self](PKResponse response){self->on_public_key_response(response);};
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
             self->m_on_pk_request(req);
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         }
 
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         return G_SOURCE_REMOVE;
     }
 
     void on_public_key_response(PKResponse response)
     {
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         g_debug("%s got response %d", G_STRLOC, int(response));
 
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         // set m_pkresponse and wake up the waiting worker thread
         std::unique_lock<std::mutex> lk(m_pkresponse_mutex);
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         m_pkresponse = response;
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         m_pkresponse_ready = true;
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         m_pkresponse_cv.notify_one();
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
     }
 
     /***
@@ -120,59 +147,89 @@ private:
 
     void worker_func() // runs in worker thread
     {
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         const std::string socket_path {m_socket_path};
 
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         while (!g_cancellable_is_cancelled(m_cancellable))
         {
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
             g_debug("%s thread %p creating a client socket to '%s'", G_STRLOC, g_thread_self(), socket_path.c_str());
             auto socket = create_client_socket(socket_path);
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
             bool got_valid_req = false;
 
             g_debug("%s thread %p calling read_request", g_thread_self(), G_STRLOC);
             std::string reqstr;
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
             if (socket != nullptr)
                 reqstr = read_request(socket);
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
             if (!reqstr.empty())
                 g_debug("%s got request [%s]", G_STRLOC, reqstr.c_str());
 
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
             if (reqstr.substr(0,2) == "PK") {
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
                 PKResponse response = PKResponse::DENY;
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
                 const auto public_key = reqstr.substr(2);
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
                 g_debug("%s thread %p got pk [%s]", G_STRLOC, g_thread_self(), public_key.c_str());
                 if (!public_key.empty()) {
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
                     got_valid_req = true;
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
                     std::unique_lock<std::mutex> lk(m_pkresponse_mutex);
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
                     m_pkresponse_ready = false;
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
                     m_pkresponse = AdbdClient::PKResponse::DENY;
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
                     pass_public_key_to_main_thread(public_key);
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
                     g_debug("%s thread %p waiting", G_STRLOC, g_thread_self());
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
                     try {
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
                         m_pkresponse_cv.wait(lk, [this](){
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
                             return m_pkresponse_ready || g_cancellable_is_cancelled(m_cancellable);
                         });
                     } catch (std::system_error& e) {
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
                         g_critical("%s thread %p unable to wait for response because of unexpected error '%s'", G_STRLOC, g_thread_self(), e.what());
                     }
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
                     response = m_pkresponse;
                     g_debug("%s thread %p got response '%d', is-cancelled %d", G_STRLOC,
                             g_thread_self(),
                             int(response),
                             int(g_cancellable_is_cancelled(m_cancellable)));
                 }
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
                 if (!g_cancellable_is_cancelled(m_cancellable))
                     send_pk_response(socket, response);
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
             } else if (!reqstr.empty()) {
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
                 g_warning("Invalid ADB request: [%s]", reqstr.c_str());
             }
 
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
             g_clear_object(&socket);
 
             // If nothing interesting's happening, sleep a bit.
             // (Interval copied from UsbDebuggingManager.java)
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
             static constexpr std::chrono::seconds sleep_interval {std::chrono::seconds(1)};
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
             if (!got_valid_req && !g_cancellable_is_cancelled(m_cancellable)) {
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
                 std::unique_lock<std::mutex> lk(m_sleep_mutex);
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
                 m_sleep_cv.wait_for(lk, sleep_interval);
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
             }
         }
     }
@@ -181,10 +238,12 @@ private:
     GSocket* create_client_socket(const std::string& socket_path)
     {
         GError* error {};
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         auto socket = g_socket_new(G_SOCKET_FAMILY_UNIX,
                                    G_SOCKET_TYPE_STREAM,
                                    G_SOCKET_PROTOCOL_DEFAULT,
                                    &error);
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         if (error != nullptr) {
             g_warning("Error creating adbd client socket: %s", error->message);
             g_clear_error(&error);
@@ -192,55 +251,80 @@ private:
             return nullptr;
         }
 
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         auto address = g_unix_socket_address_new(socket_path.c_str());
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         const auto connected = g_socket_connect(socket, address, m_cancellable, &error);
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         g_clear_object(&address);
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         if (!connected) {
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
             g_debug("unable to connect to '%s': %s", socket_path.c_str(), error->message);
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
             g_clear_error(&error);
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
             g_clear_object(&socket);
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
             return nullptr;
         }
 
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         return socket;
     }
 
     std::string read_request(GSocket* socket)
     {
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         char buf[4096] = {};
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         g_debug("%s calling g_socket_receive()", G_STRLOC);
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         const auto n_bytes = g_socket_receive (socket, buf, sizeof(buf), m_cancellable, nullptr);
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         std::string ret;
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         if (n_bytes > 0)
             ret.append(buf, std::string::size_type(n_bytes));
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         g_debug("%s g_socket_receive got %d bytes: [%s]", G_STRLOC, int(n_bytes), ret.c_str());
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         return ret;
     }
 
     void send_pk_response(GSocket* socket, PKResponse response)
     {
         std::string response_str;
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         switch(response) {
             case PKResponse::ALLOW: response_str = "OK"; break;
             case PKResponse::DENY:  response_str = "NO"; break;
         }
         g_debug("%s sending reply: [%s]", G_STRLOC, response_str.c_str());
 
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         GError* error {};
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         g_socket_send(socket,
                       response_str.c_str(),
                       response_str.size(),
                       m_cancellable,
                       &error);
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         if (error != nullptr) {
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
             if (!g_error_matches(error, G_IO_ERROR, G_IO_ERROR_CANCELLED))
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
                 g_warning("GAdbdServer: Error accepting socket connection: %s", error->message);
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
             g_clear_error(&error);
         }
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
     }
 
     static std::string get_fingerprint(const std::string& public_key)
     {
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         // The first token is base64-encoded data, so cut on the first whitespace
         const std::string base64 (
             public_key.begin(),
@@ -250,14 +334,20 @@ private:
             )
         );
 
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         gsize digest_len {};
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         auto digest = g_base64_decode(base64.c_str(), &digest_len);
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
 
         auto checksum = g_compute_checksum_for_data(G_CHECKSUM_MD5, digest, digest_len);
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         const gsize checksum_len = checksum ? strlen(checksum) : 0;
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
 
         // insert ':' between character pairs; eg "ff27b5f3" --> "ff:27:b5:f3"
         std::string fingerprint;
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         for (gsize i=0; i<checksum_len; ) {
             fingerprint.append(checksum+i, checksum+i+2);
             if (i < checksum_len-2)
@@ -265,8 +355,11 @@ private:
             i += 2;
         }
 
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         g_clear_pointer(&digest, g_free);
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         g_clear_pointer(&checksum, g_free);
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         return fingerprint;
     }
 
diff --git a/src/usb-manager.cpp b/src/usb-manager.cpp
index aac289a..8d6a0c9 100644
--- a/src/usb-manager.cpp
+++ b/src/usb-manager.cpp
@@ -45,89 +45,127 @@ public:
         m_usb_monitor{usb_monitor},
         m_greeter{greeter}
     {
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         m_usb_monitor->on_usb_disconnected().connect([this](const std::string& /*usb_name*/) {
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
             restart();
         });
 
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         m_greeter->is_active().changed().connect([this](bool /*is_active*/) {
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
             maybe_snap();
         });
 
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         restart();
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
     }
 
     ~Impl()
     {
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         if (m_restart_idle_tag)
             g_source_remove(m_restart_idle_tag);
 
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         clear();
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
     }
 
 private:
 
     void clear()
     {
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         // clear out old state
         m_snap_connections.clear();
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         m_snap.reset();
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         m_req = decltype(m_req)();
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         m_adbd_client.reset();
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
     }
 
     void restart()
     {
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         clear();
 
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         // set a new client
         m_adbd_client.reset(new GAdbdClient{m_socket_path});
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         m_adbd_client->on_pk_request().connect(
             [this](const AdbdClient::PKRequest& req) {
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
                 g_debug("%s got pk request: %s", G_STRLOC, req.fingerprint.c_str());
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
                 m_req = req;
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
                 maybe_snap();
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
             }
         );
     }
 
     void maybe_snap()
     {
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         // don't prompt in the greeter!
         if (!m_req.public_key.empty() && !m_greeter->is_active().get())
             snap();
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
     }
 
     void snap()
     {
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         m_snap = std::make_shared<UsbSnap>(m_req.fingerprint);
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         m_snap_connections.insert((*m_snap).on_user_response().connect(
             [this](AdbdClient::PKResponse response, bool remember_choice){
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
                 g_debug("%s thread %p user responded! response %d, remember %d", G_STRLOC, g_thread_self(), int(response), int(remember_choice));
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
                 m_req.respond(response);
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
                 if (remember_choice && (response == AdbdClient::PKResponse::ALLOW))
                     write_public_key(m_req.public_key);
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
                 m_restart_idle_tag = g_idle_add([](gpointer gself){
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
                     auto self = static_cast<Impl*>(gself);
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
                     self->m_restart_idle_tag = 0;
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
                     self->restart();
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
                     return G_SOURCE_REMOVE;
                 }, this);
             }
         ));
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
     }
 
     void write_public_key(const std::string& public_key)
     {
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         g_debug("%s writing public key '%s' to '%s'", G_STRLOC, public_key.c_str(), m_public_keys_filename.c_str());
 
         // confirm the directory exists
         auto dirname = g_path_get_dirname(m_public_keys_filename.c_str());
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         const auto dir_exists = g_file_test(dirname, G_FILE_TEST_IS_DIR);
         if (!dir_exists)
             g_warning("ADB data directory '%s' does not exist", dirname);
         g_clear_pointer(&dirname, g_free);
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         if (!dir_exists)
             return;
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
 
         // open the file in append mode, with user rw and group r permissions
         const auto fd = open(
@@ -135,16 +173,20 @@ private:
             O_APPEND|O_CREAT|O_WRONLY,
             S_IRUSR|S_IWUSR|S_IRGRP
         );
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
         if (fd == -1) {
             g_warning("Error opening ADB datafile: %s", g_strerror(errno));
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
             return;
         }
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
 
         // write the new public key on its own line
         std::string buf {public_key + '\n'};
         if (write(fd, buf.c_str(), buf.size()) == -1)
             g_warning("Error writing ADB datafile: %d %s", errno, g_strerror(errno));
         close(fd);
+g_debug("%s %s", G_STRLOC, G_STRFUNC);
     }
 
     const std::string m_socket_path;
-- 
cgit v1.2.3