From c58d22061d944dc8b9b0b072082665c9f10877ac Mon Sep 17 00:00:00 2001 From: Charles Kerr 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 +++++++++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 93 insertions(+) (limited to 'src/adbd-client.cpp') 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& 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(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 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 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 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