From 7188239a1a38aaaebe04ffb126e887a6c0f2f546 Mon Sep 17 00:00:00 2001 From: David Kocik Date: Wed, 1 Jan 2025 18:07:52 +0100 Subject: [PATCH] Sharing tokens among instances --- src/slic3r/GUI/Plater.cpp | 5 + src/slic3r/GUI/UserAccount.cpp | 9 +- src/slic3r/GUI/UserAccount.hpp | 1 + src/slic3r/GUI/UserAccountCommunication.cpp | 411 ++++++++++++++++--- src/slic3r/GUI/UserAccountCommunication.hpp | 24 +- src/slic3r/GUI/UserAccountSession.cpp | 84 +++- src/slic3r/GUI/UserAccountSession.hpp | 9 +- src/slic3r/GUI/WebViewPanel.cpp | 5 +- src/slic3r/GUI/WebViewPanel.hpp | 1 + src/slic3r/GUI/WebViewPlatformUtilsWin32.cpp | 2 +- 10 files changed, 475 insertions(+), 76 deletions(-) diff --git a/src/slic3r/GUI/Plater.cpp b/src/slic3r/GUI/Plater.cpp index ef3d164865..a7f0b8ee3b 100644 --- a/src/slic3r/GUI/Plater.cpp +++ b/src/slic3r/GUI/Plater.cpp @@ -1009,6 +1009,11 @@ void Plater::priv::init() BOOST_LOG_TRIVIAL(error) << "Failed communication with Prusa Account: " << evt.data; user_account->on_communication_fail(); }); + this->q->Bind(EVT_UA_RACE_LOST, [this](UserAccountFailEvent& evt) { + BOOST_LOG_TRIVIAL(debug) << "Renew token race lost: " << evt.data; + user_account->on_race_lost(); + }); + this->q->Bind(EVT_UA_PRUSACONNECT_STATUS_SUCCESS, [this](UserAccountSuccessEvent& evt) { std::string text; bool printers_changed = false; diff --git a/src/slic3r/GUI/UserAccount.cpp b/src/slic3r/GUI/UserAccount.cpp index 7192ec6a0f..a1c52aa153 100644 --- a/src/slic3r/GUI/UserAccount.cpp +++ b/src/slic3r/GUI/UserAccount.cpp @@ -136,7 +136,7 @@ bool UserAccount::on_user_id_success(const std::string data, std::string& out_us for (const auto& section : ptree) { const auto opt = ptree.get_optional(section.first); if (opt) { - BOOST_LOG_TRIVIAL(debug) << static_cast(section.first) << " " << *opt; + //BOOST_LOG_TRIVIAL(debug) << static_cast(section.first) << " " << *opt; m_account_user_data[section.first] = *opt; } @@ -181,11 +181,14 @@ void UserAccount::on_communication_fail() } } - +void UserAccount::on_race_lost() +{ + m_communication->on_race_lost(); +} bool UserAccount::on_connect_printers_success(const std::string& data, AppConfig* app_config, bool& out_printers_changed) { - BOOST_LOG_TRIVIAL(debug) << "Prusa Connect printers message: " << data; + BOOST_LOG_TRIVIAL(trace) << "Prusa Connect printers message: " << data; pt::ptree ptree; try { std::stringstream ss(data); diff --git a/src/slic3r/GUI/UserAccount.hpp b/src/slic3r/GUI/UserAccount.hpp index 0db94c3284..8049233ec3 100644 --- a/src/slic3r/GUI/UserAccount.hpp +++ b/src/slic3r/GUI/UserAccount.hpp @@ -59,6 +59,7 @@ public: bool on_user_id_success(const std::string data, std::string& out_username); // Called on EVT_UA_FAIL, triggers test after several calls void on_communication_fail(); + void on_race_lost(); bool on_connect_printers_success(const std::string& data, AppConfig* app_config, bool& out_printers_changed); bool on_connect_uiid_map_success(const std::string& data, AppConfig* app_config, bool& out_printers_changed); diff --git a/src/slic3r/GUI/UserAccountCommunication.cpp b/src/slic3r/GUI/UserAccountCommunication.cpp index cc0cdf6318..9afe5635bd 100644 --- a/src/slic3r/GUI/UserAccountCommunication.cpp +++ b/src/slic3r/GUI/UserAccountCommunication.cpp @@ -42,6 +42,8 @@ #include #include #include + +#include #endif // __linux__ @@ -139,7 +141,7 @@ bool load_secret(const std::string& opt, std::string& usr, std::string& psswd) } #ifdef __linux__ -void load_refresh_token_linux(std::string& refresh_token) +void load_tokens_linux(UserAccountCommunication::StoreData& result) { // Load refresh token from UserAccount.dat boost::filesystem::path source(boost::filesystem::path(Slic3r::data_dir()) / "UserAccount.dat") ; @@ -157,18 +159,80 @@ void load_refresh_token_linux(std::string& refresh_token) } boost::nowide::ifstream stream(source.generic_string(), std::ios::in | std::ios::binary); if (!stream) { - BOOST_LOG_TRIVIAL(error) << "UserAccount: Failed to read token from " << source; + BOOST_LOG_TRIVIAL(error) << "UserAccount: Failed to read tokens from " << source; return; } - std::getline(stream, refresh_token); + std::string token_data; + std::getline(stream, token_data); stream.close(); if (delete_after_read) { ec.clear(); if (!boost::filesystem::remove(source, ec) || ec) { BOOST_LOG_TRIVIAL(error) << "UserAccount: Failed to remove file " << source; } - } + + // read data + std::vector token_list; + boost::split(token_list, token_data, boost::is_any_of("|"), boost::token_compress_off); + assert(token_list.empty() || token_list.size() == 5); + if (token_list.size() < 5) { + BOOST_LOG_TRIVIAL(error) << "Size of read secrets is only: " << token_list.size() << " (expected 5). Data: " << token_data; + } + result.access_token = token_list.size() > 0 ? token_list[0] : std::string(); + result.refresh_token = token_list.size() > 1 ? token_list[1] : std::string(); + result.next_timeout = token_list.size() > 2 ? token_list[2] : std::string(); + result.master_pid = token_list.size() > 3 ? token_list[3] : std::string(); + result.shared_session_key = token_list.size() > 4 ? token_list[4] : std::string(); +} +bool concurrent_write_file(const std::string& secret_to_store, const boost::filesystem::path& filename) +{ + BOOST_LOG_TRIVIAL(debug) << __FUNCTION__; + // Open the file + int fd = open(filename.string().c_str(), O_WRONLY | O_CREAT, S_IRUSR | S_IWUSR); + if (fd == -1) { + BOOST_LOG_TRIVIAL(error) << "Unable to open store file " << filename << ": " << strerror(errno); + return false; + } + // Close the file when the guard dies + Slic3r::ScopeGuard sg_fd([fd]() { + close(fd); + BOOST_LOG_TRIVIAL(debug) << "Closed file."; + }); + + // Configure the lock + struct flock lock; + memset(&lock, 0, sizeof(lock)); + lock.l_type = F_WRLCK; // Write lock + lock.l_whence = SEEK_SET; // Lock from the start of the file + lock.l_start = 0; + lock.l_len = 0; // 0 means lock the entire file + + // Try to acquire the lock + BOOST_LOG_TRIVIAL(debug) << "Waiting to acquire lock on file: " << filename; + if (fcntl(fd, F_SETLKW, &lock) == -1) { + BOOST_LOG_TRIVIAL(error) << "Unable to acquire lock: " << strerror(errno); + return false; + } + BOOST_LOG_TRIVIAL(debug) << "Lock acquired on file: " << filename; + + Slic3r::ScopeGuard sg_lock([&lock, fd, filename]() { + // Release the lock when guard dies. + lock.l_type = F_UNLCK; // Unlock the file + if (fcntl(fd, F_SETLK, &lock) == -1) { + BOOST_LOG_TRIVIAL(error) << "Unable to release lock ("<< filename <<"): " << strerror(errno); + } else { + BOOST_LOG_TRIVIAL(debug) << "Lock released on file: " << filename; + } + }); + + // Write content to the file + if (write(fd, secret_to_store.c_str(), strlen(secret_to_store.c_str())) == -1) { + BOOST_LOG_TRIVIAL(error) << "Unable to write to file: " << strerror(errno); + return false; + } + BOOST_LOG_TRIVIAL(debug) << "Content written to file."; + return true; } #endif //__linux__ } @@ -179,42 +243,33 @@ UserAccountCommunication::UserAccountCommunication(wxEvtHandler* evt_handler, Ap , m_app_config(app_config) , m_polling_timer(std::make_unique(this)) , m_token_timer(std::make_unique(this)) + , m_slave_read_timer(new wxTimer(this)) + , m_after_race_lost_timer(new wxTimer(this)) { Bind(wxEVT_TIMER, &UserAccountCommunication::on_token_timer, this, m_token_timer->GetId()); Bind(wxEVT_TIMER, &UserAccountCommunication::on_polling_timer, this, m_polling_timer->GetId()); + Bind(wxEVT_TIMER, &UserAccountCommunication::on_slave_read_timer, this, m_slave_read_timer->GetId()); + Bind(wxEVT_TIMER, &UserAccountCommunication::on_after_race_lost_timer, this, m_after_race_lost_timer->GetId()); - std::string access_token, refresh_token, shared_session_key, next_timeout; - if (is_secret_store_ok()) { - std::string key0, key1, key2, tokens; - if (load_secret("tokens", key0, tokens)) { - std::vector token_list; - boost::split(token_list, tokens, boost::is_any_of("|"), boost::token_compress_off); - assert(token_list.empty() || token_list.size() == 3); - access_token = token_list.size() > 0 ? token_list[0] : std::string(); - refresh_token = token_list.size() > 1 ? token_list[1] : std::string(); - next_timeout = token_list.size() > 2 ? token_list[2] : std::string(); - } else { - load_secret("access_token", key0, access_token); - load_secret("refresh_token", key1, refresh_token); - load_secret("access_token_timeout", key2, next_timeout); - assert(key0 == key1); - } - shared_session_key = key0; + StoreData stored_data; + read_stored_data(stored_data); - } else { -#ifdef __linux__ - load_refresh_token_linux(refresh_token); -#endif - } - long long next = next_timeout.empty() ? 0 : std::stoll(next_timeout); - long long remain_time = next - std::time(nullptr); + long long next_timeout_long = stored_data.next_timeout.empty() ? 0 : std::stoll(stored_data.next_timeout); + long long remain_time = next_timeout_long - std::time(nullptr); if (remain_time <= 0) { - access_token.clear(); + stored_data.access_token.clear(); + // if there is no access token to be used - consider yourself as master (either for case refresh token is going to be used now or future login) + m_behave_as_master = true; } else { set_refresh_time((int)remain_time); } - bool has_token = !refresh_token.empty(); - m_session = std::make_unique(evt_handler, access_token, refresh_token, shared_session_key, m_app_config->get_bool("connect_polling")); + if (!stored_data.access_token.empty()) { + BOOST_LOG_TRIVIAL(debug) << __FUNCTION__ <<" access_token: " << stored_data.access_token.substr(0,5) << "..." << stored_data.access_token.substr(stored_data.access_token.size()-5); + } else { + BOOST_LOG_TRIVIAL(debug) << __FUNCTION__ <<" access_token empty!"; + } + bool has_token = !stored_data.refresh_token.empty(); + m_session = std::make_unique(evt_handler, stored_data.access_token, stored_data.refresh_token, stored_data.shared_session_key, next_timeout_long, m_app_config->get_bool("connect_polling")); init_session_thread(); // perform login at the start, but only with tokens if (has_token) { @@ -243,21 +298,35 @@ UserAccountCommunication::~UserAccountCommunication() void UserAccountCommunication::set_username(const std::string& username) { m_username = username; + if (!m_behave_as_master && !username.empty()) { + return; + } { + BOOST_LOG_TRIVIAL(debug) << __FUNCTION__ << " empty: " << username.empty(); if (is_secret_store_ok()) { - std::string tokens; - if (m_remember_session) { + std::string tokens = "|||"; + if (m_remember_session && !username.empty()) { tokens = m_session->get_access_token() + - "|" + m_session->get_refresh_token() + - "|" + std::to_string(m_session->get_next_token_timeout()); + "|" + m_session->get_refresh_token() + + "|" + std::to_string(m_session->get_next_token_timeout()) + + "|" + std::to_string(get_current_pid()); } - save_secret("tokens", m_session->get_shared_session_key(), tokens); - } - else { -#ifdef __linux__ + if (!save_secret("tokens", m_session->get_shared_session_key(), tokens)) { + BOOST_LOG_TRIVIAL(error) << "Failed to write tokens to the secret store."; + } + } else { +//#ifdef __linux__ // If we can't store the tokens in secret store, store them in file with chmod 600 boost::filesystem::path target(boost::filesystem::path(Slic3r::data_dir()) / "UserAccount.dat") ; - std::string data = m_session->get_refresh_token(); + std::string data = "||||"; + if (m_remember_session && !username.empty()) { + data = m_session->get_access_token() + + "|" + m_session->get_refresh_token() + + "|" + std::to_string(m_session->get_next_token_timeout()) + + "|" + std::to_string(get_current_pid()) + + "|" + m_session->get_shared_session_key(); + } + FILE* file; static const auto perms = boost::filesystem::owner_read | boost::filesystem::owner_write; // aka 600 @@ -267,17 +336,15 @@ void UserAccountCommunication::set_username(const std::string& username) BOOST_LOG_TRIVIAL(debug) << "UserAccount: boost::filesystem::permisions before write error message (this could be irrelevant message based on file system): " << ec.message(); ec.clear(); - file = boost::nowide::fopen(target.generic_string().c_str(), "wb"); - if (file == NULL) { - BOOST_LOG_TRIVIAL(error) << "UserAccount: Failed to open file to store token: " << target; - return; + if (!concurrent_write_file(data, target)) { + BOOST_LOG_TRIVIAL(error) << "Failed to store secret."; } - fwrite(data.c_str(), 1, data.size(), file); - fclose(file); boost::filesystem::permissions(target, perms, ec); if (ec) BOOST_LOG_TRIVIAL(debug) << "UserAccount: boost::filesystem::permisions after write error message (this could be irrelevant message based on file system): " << ec.message(); +#else + BOOST_LOG_TRIVIAL(error) << "Failed to write tokens to the secret store: Store is not ok."; #endif } } @@ -285,6 +352,7 @@ void UserAccountCommunication::set_username(const std::string& username) void UserAccountCommunication::set_remember_session(bool b) { + BOOST_LOG_TRIVIAL(debug) << __FUNCTION__; m_remember_session = b; // tokens needs to be stored or deleted set_username(m_username); @@ -327,7 +395,7 @@ wxString UserAccountCommunication::generate_login_redirect_url() const std::string REDIRECT_URI = "prusaslicer://login"; CodeChalengeGenerator ccg; m_code_verifier = ccg.generate_verifier(); - std::string code_challenge = ccg.generate_chalenge(m_code_verifier); + std::string code_challenge = ccg.generate_challenge(m_code_verifier); wxString language = GUI::wxGetApp().current_language_code(); language = language.SubString(0, 1); BOOST_LOG_TRIVIAL(info) << "code verifier: " << m_code_verifier; @@ -343,7 +411,7 @@ wxString UserAccountCommunication::get_login_redirect_url(const std::string& ser const std::string CLIENT_ID = client_id(); const std::string REDIRECT_URI = "prusaslicer://login"; CodeChalengeGenerator ccg; - std::string code_challenge = ccg.generate_chalenge(m_code_verifier); + std::string code_challenge = ccg.generate_challenge(m_code_verifier); wxString language = GUI::wxGetApp().current_language_code(); language = language.SubString(0, 1); @@ -380,6 +448,7 @@ void UserAccountCommunication::do_logout() void UserAccountCommunication::do_clear() { + BOOST_LOG_TRIVIAL(debug) << __FUNCTION__; m_session->clear(); set_username({}); m_token_timer->Stop(); @@ -414,7 +483,7 @@ void UserAccountCommunication::enqueue_connect_status_action() void UserAccountCommunication::enqueue_test_connection() { if (!m_session->is_initialized()) { - BOOST_LOG_TRIVIAL(error) << "Connect Printers endpoint connection failed - Not Logged in."; + BOOST_LOG_TRIVIAL(error) << "Connect test endpoint connection failed - Not Logged in."; return; } m_session->enqueue_test_with_refresh(); @@ -424,7 +493,7 @@ void UserAccountCommunication::enqueue_test_connection() void UserAccountCommunication::enqueue_avatar_old_action(const std::string& url) { if (!m_session->is_initialized()) { - BOOST_LOG_TRIVIAL(error) << "Connect Printers endpoint connection failed - Not Logged in."; + BOOST_LOG_TRIVIAL(error) << "Connect avatar endpoint connection failed - Not Logged in."; return; } m_session->enqueue_action(UserAccountActionID::USER_ACCOUNT_ACTION_AVATAR_OLD, nullptr, nullptr, url); @@ -441,6 +510,16 @@ void UserAccountCommunication::enqueue_avatar_new_action(const std::string& url) wakeup_session_thread(); } +void UserAccountCommunication::enqueue_id_action() +{ + if (!m_session->is_initialized()) { + BOOST_LOG_TRIVIAL(error) << "Connect id endpoint connection failed - Not Logged in."; + return; + } + m_session->enqueue_action(UserAccountActionID::USER_ACCOUNT_ACTION_USER_ID, nullptr, nullptr, {}); + wakeup_session_thread(); +} + void UserAccountCommunication::enqueue_printer_data_action(const std::string& uuid) { if (!m_session->is_initialized()) { @@ -451,12 +530,6 @@ void UserAccountCommunication::enqueue_printer_data_action(const std::string& uu wakeup_session_thread(); } -void UserAccountCommunication::request_refresh() -{ - m_token_timer->Stop(); - enqueue_refresh(); -} - void UserAccountCommunication::enqueue_refresh() { if (!m_session->is_initialized()) { @@ -467,6 +540,7 @@ void UserAccountCommunication::enqueue_refresh() BOOST_LOG_TRIVIAL(debug) << "User Account: Token refresh already enqueued, skipping..."; return; } + m_behave_as_master = true; m_session->enqueue_refresh({}); wakeup_session_thread(); } @@ -501,7 +575,7 @@ void UserAccountCommunication::on_activate_app(bool active) m_window_is_active = active; } auto now = std::time(nullptr); - BOOST_LOG_TRIVIAL(info) << "UserAccountCommunication activate: active " << active; + //BOOST_LOG_TRIVIAL(info) << "UserAccountCommunication activate: active " << active; #ifndef _NDEBUG // constexpr auto refresh_threshold = 110 * 60; constexpr auto refresh_threshold = 60; @@ -509,13 +583,22 @@ void UserAccountCommunication::on_activate_app(bool active) constexpr auto refresh_threshold = 60; #endif if (active && m_next_token_refresh_at > 0 && m_next_token_refresh_at - now < refresh_threshold) { - BOOST_LOG_TRIVIAL(info) << "Enqueue access token refresh on activation"; + // Commented during implementation of sharing access token among instances - TODO + BOOST_LOG_TRIVIAL(debug) << " Requesting refresh when app was activated: next token refresh is at " << m_next_token_refresh_at - now; request_refresh(); + return; + } + // When no token timers are running but we have token -> refresh it. + if (active && m_next_token_refresh_at > 0 && m_token_timer->IsRunning() && m_slave_read_timer->IsRunning() && m_after_race_lost_timer->IsRunning()) { + BOOST_LOG_TRIVIAL(debug) << " Requesting refresh when app was activated when no timers are running, next token refresh is at " << m_next_token_refresh_at - now; + request_refresh(); + return; } } void UserAccountCommunication::wakeup_session_thread() { + //BOOST_LOG_TRIVIAL(debug) << __FUNCTION__; { std::lock_guard lck(m_thread_stop_mutex); m_thread_wakeup = true; @@ -527,6 +610,7 @@ void UserAccountCommunication::set_refresh_time(int seconds) { assert(m_token_timer); m_token_timer->Stop(); + m_last_token_duration_seconds = seconds; const auto prior_expiration_secs = std::max(seconds / 24, 10); int milliseconds = std::max((seconds - prior_expiration_secs) * 1000, 1000); m_next_token_refresh_at = std::time(nullptr) + milliseconds / 1000; @@ -534,21 +618,224 @@ void UserAccountCommunication::set_refresh_time(int seconds) m_token_timer->StartOnce(milliseconds); } +void UserAccountCommunication::read_stored_data(UserAccountCommunication::StoreData& result) +{ + if (is_secret_store_ok()) { + std::string key0, tokens; + if (load_secret("tokens", key0, tokens)) { + std::vector token_list; + boost::split(token_list, tokens, boost::is_any_of("|"), boost::token_compress_off); + assert(token_list.empty() || token_list.size() == 4); + if (token_list.size() < 3) { + BOOST_LOG_TRIVIAL(error) << "Size of read secrets is only: " << token_list.size() << " (expected 4). Data: " << tokens; + } + result.access_token = token_list.size() > 0 ? token_list[0] : std::string(); + result.refresh_token = token_list.size() > 1 ? token_list[1] : std::string(); + result.next_timeout = token_list.size() > 2 ? token_list[2] : std::string(); + result.master_pid = token_list.size() > 3 ? token_list[3] : std::string(); + } + result.shared_session_key = key0; + } else { +#ifdef __linux__ + load_tokens_linux(result); +#endif + } +} + +void UserAccountCommunication::request_refresh() +{ + // This function is called when Printables requests new token - same token as we have now wont do. + // Or from UserAccountCommunication::on_activate_app(true) when current token has too small refresh or is dead + // See if there is different token stored, if not - proceed to T3 (there might be more than 1 app doing this). + BOOST_LOG_TRIVIAL(debug) << __FUNCTION__; + if (m_token_timer->IsRunning()) { + m_token_timer->Stop(); + } + if (m_slave_read_timer->IsRunning()) { + m_slave_read_timer->Stop(); + } + if (m_after_race_lost_timer->IsRunning()) { + m_after_race_lost_timer->Stop(); + } + + std::string current_access_token = m_session->get_access_token(); + StoreData stored_data; + read_stored_data(stored_data); + if (stored_data.refresh_token.empty()) { + BOOST_LOG_TRIVIAL(warning) << "Store is empty - logging out."; + do_logout(); + return; + } + + long long expires_in_second = stored_data.next_timeout.empty() ? 0 : std::stoll(stored_data.next_timeout) - std::time(nullptr); + if (stored_data.access_token != current_access_token && expires_in_second > 0) { + BOOST_LOG_TRIVIAL(debug) << "Found usable token"; + set_tokens(stored_data); + } else { + BOOST_LOG_TRIVIAL(debug) << "No new token"; + enqueue_refresh_race(stored_data.refresh_token); + } +} void UserAccountCommunication::on_token_timer(wxTimerEvent& evt) { - BOOST_LOG_TRIVIAL(info) << "UserAccountCommunication: Token refresh timer fired"; - enqueue_refresh(); + BOOST_LOG_TRIVIAL(debug) << __FUNCTION__ << " T1"; + // Read PID from current stored token and decide if master / slave + + std::string my_pid = std::to_string(get_current_pid()); + StoreData stored_data; + read_stored_data(stored_data); + + if (stored_data.refresh_token.empty()) { + BOOST_LOG_TRIVIAL(warning) << "Store is empty - logging out."; + do_logout(); + return; + } + + long long expires_in_second = stored_data.next_timeout.empty() ? 0 : std::stoll(stored_data.next_timeout) - std::time(nullptr); + if (my_pid == stored_data.master_pid) { + // this is master instance - writing to secret store is permited + m_behave_as_master = true; + enqueue_refresh(); + return; + } + // this is not master instance - writing to secret store is not permited until it is clear current master did not renew + m_behave_as_master = false; + + // token could be either already new -> we want to start using it now + const auto prior_expiration_secs = std::max(m_last_token_duration_seconds / 24, 10); + if (expires_in_second >= 0 && expires_in_second > prior_expiration_secs) { + BOOST_LOG_TRIVIAL(debug) << "Current token has different PID - expiration is " << expires_in_second << " while longest expected was " << prior_expiration_secs << ". Using this token."; + set_tokens(stored_data); + return; + } + // or yet to be renewed -> we should wait to give time to master to renew it + if (expires_in_second >= 0) { + BOOST_LOG_TRIVIAL(debug) << "Current token has different PID - waiting " << expires_in_second / 2; + m_slave_read_timer->StartOnce((expires_in_second / 2) * 1000); + return; + } + // or expired -> renew now. + BOOST_LOG_TRIVIAL(debug) << "Current token has different PID and is expired."; + enqueue_refresh_race(stored_data.refresh_token); } +void UserAccountCommunication::on_slave_read_timer(wxTimerEvent& evt) +{ + BOOST_LOG_TRIVIAL(debug) << __FUNCTION__ << " T2"; + std::string current_access_token = m_session->get_access_token(); + StoreData stored_data; + read_stored_data(stored_data); + + if (stored_data.refresh_token.empty()) { + BOOST_LOG_TRIVIAL(warning) << "Store is empty - logging out."; + do_logout(); + return; + } + + long long expires_in_second = stored_data.next_timeout.empty() ? 0 : std::stoll(stored_data.next_timeout) - std::time(nullptr); + if (stored_data.access_token != current_access_token) { + // consider stored_data as renewed token from master + BOOST_LOG_TRIVIAL(debug) << "Token in store seems to be new - using it."; + set_tokens(stored_data); + return; + } + if (stored_data.access_token != current_access_token) { + // token is expired + BOOST_LOG_TRIVIAL(debug) << "Token in store seems to be new but expired - refreshing now."; + enqueue_refresh_race(stored_data.refresh_token); + return; + } + BOOST_LOG_TRIVIAL(debug) <<"No new token, enqueueing refresh (race expected)."; + enqueue_refresh_race(); +} + +void UserAccountCommunication::enqueue_refresh_race(const std::string refresh_token_from_store/* = std::string()*/) +{ + BOOST_LOG_TRIVIAL(debug) << __FUNCTION__ << " T3"; + if (!m_session->is_initialized()) { + BOOST_LOG_TRIVIAL(error) << "Connect Printers endpoint connection failed - Not Logged in."; + return; + } + if (refresh_token_from_store.empty() && m_session->is_enqueued(UserAccountActionID::USER_ACCOUNT_ACTION_REFRESH_TOKEN)) { + BOOST_LOG_TRIVIAL(error) << __FUNCTION__ << " Token refresh already enqueued, skipping..."; + return; + } + // At this point, last master did not renew the tokens, behave like master + m_behave_as_master = true; + m_session->enqueue_refresh_race(); + wakeup_session_thread(); +} + +void UserAccountCommunication::on_race_lost() +{ + BOOST_LOG_TRIVIAL(debug) << __FUNCTION__ << " T4"; + // race from on_slave_read_timer has been lost + // other instance was faster to renew tokens so refresh token from this app was denied (invalid grant) + // we should read the other token now. + m_behave_as_master = false; + std::string current_access_token = m_session->get_access_token(); + StoreData stored_data; + read_stored_data(stored_data); + + if (stored_data.refresh_token.empty()) { + BOOST_LOG_TRIVIAL(warning) << "Store is empty - logging out."; + do_logout(); + return; + } + + long long expires_in_second = stored_data.next_timeout.empty() ? 0 : std::stoll(stored_data.next_timeout) - std::time(nullptr); + const auto prior_expiration_secs = std::max(m_last_token_duration_seconds / 24, 10); + if (expires_in_second > 0 && expires_in_second > prior_expiration_secs) { + BOOST_LOG_TRIVIAL(debug) << "Token is alive - using it."; + set_tokens(stored_data); + return; + } + BOOST_LOG_TRIVIAL(debug) << "No suitable token found waiting " << std::max((expires_in_second / 2), (long long)2); + m_after_race_lost_timer->StartOnce(std::max((expires_in_second / 2) * 1000, (long long)2000)); +} + +void UserAccountCommunication::on_after_race_lost_timer(wxTimerEvent& evt) +{ + BOOST_LOG_TRIVIAL(debug) << __FUNCTION__ << " T5"; + + std::string current_access_token = m_session->get_access_token(); + StoreData stored_data; + read_stored_data(stored_data); + + if (stored_data.refresh_token.empty()) { + BOOST_LOG_TRIVIAL(warning) << "Store is empty - logging out."; + do_logout(); + return; + } + + long long expires_in_second = stored_data.next_timeout.empty() ? 0 : std::stoll(stored_data.next_timeout) - std::time(nullptr); + const auto prior_expiration_secs = std::max(m_last_token_duration_seconds / 24, 10); + if (expires_in_second > 0 && expires_in_second > prior_expiration_secs) { + BOOST_LOG_TRIVIAL(debug) << "Token is alive - using it."; + set_tokens(stored_data); + return; + } + BOOST_LOG_TRIVIAL(warning) << "No new token is stored - This is error state. Logging out."; + do_logout(); +} + +void UserAccountCommunication::set_tokens(const StoreData store_data) +{ + long long next = store_data.next_timeout.empty() ? 0 : std::stoll(store_data.next_timeout); + m_session->set_tokens(store_data.access_token, store_data.refresh_token, store_data.shared_session_key, next); + enqueue_id_action(); +} + void UserAccountCommunication::on_polling_timer(wxTimerEvent& evt) { + if (!m_window_is_active) { return; } wakeup_session_thread(); } -std::string CodeChalengeGenerator::generate_chalenge(const std::string& verifier) +std::string CodeChalengeGenerator::generate_challenge(const std::string& verifier) { std::string code_challenge; try @@ -558,7 +845,7 @@ std::string CodeChalengeGenerator::generate_chalenge(const std::string& verifier } catch (const std::exception& e) { - BOOST_LOG_TRIVIAL(error) << "Code Chalenge Generator failed: " << e.what(); + BOOST_LOG_TRIVIAL(error) << "Code Challenge Generator failed: " << e.what(); } assert(!code_challenge.empty()); return code_challenge; diff --git a/src/slic3r/GUI/UserAccountCommunication.hpp b/src/slic3r/GUI/UserAccountCommunication.hpp index e8d1e42aa0..3d5ce0abf3 100644 --- a/src/slic3r/GUI/UserAccountCommunication.hpp +++ b/src/slic3r/GUI/UserAccountCommunication.hpp @@ -22,7 +22,7 @@ class CodeChalengeGenerator public: CodeChalengeGenerator() {} ~CodeChalengeGenerator() {} - std::string generate_chalenge(const std::string& verifier); + std::string generate_challenge(const std::string& verifier); std::string generate_verifier(); private: std::string generate_code_verifier(size_t length); @@ -32,6 +32,14 @@ private: class UserAccountCommunication : public wxEvtHandler { + public: + struct StoreData { + std::string access_token; + std::string refresh_token; + std::string shared_session_key; + std::string next_timeout; + std::string master_pid; + }; public: UserAccountCommunication(wxEvtHandler* evt_handler, AppConfig* app_config); ~UserAccountCommunication(); @@ -51,6 +59,7 @@ public: void enqueue_connect_printer_models_action(); void enqueue_avatar_old_action(const std::string& url); void enqueue_avatar_new_action(const std::string& url); + void enqueue_id_action(); void enqueue_test_connection(); void enqueue_printer_data_action(const std::string& uuid); void enqueue_refresh(); @@ -79,6 +88,9 @@ public: void set_refresh_time(int seconds); void on_token_timer(wxTimerEvent& evt); void on_polling_timer(wxTimerEvent& evt); + void set_tokens(const StoreData store_data); + + void on_race_lost(); // T5 private: std::unique_ptr m_session; std::thread m_thread; @@ -104,8 +116,16 @@ private: void login_redirect(); std::string client_id() const { return Utils::ServiceConfig::instance().account_client_id(); } + // master / slave logic + bool m_behave_as_master {false}; + wxTimer* m_slave_read_timer; // T2 timer + wxTimer* m_after_race_lost_timer; // T5 timer + int m_last_token_duration_seconds {0}; - + void on_slave_read_timer(wxTimerEvent& evt); // T2 + void read_stored_data(StoreData& result); + void enqueue_refresh_race(const std::string refresh_token_from_store = std::string()); // T3 + void on_after_race_lost_timer(wxTimerEvent& evt); // T4 }; } } diff --git a/src/slic3r/GUI/UserAccountSession.cpp b/src/slic3r/GUI/UserAccountSession.cpp index 62b7bb00c4..5e0fb6fa15 100644 --- a/src/slic3r/GUI/UserAccountSession.cpp +++ b/src/slic3r/GUI/UserAccountSession.cpp @@ -28,6 +28,7 @@ wxDEFINE_EVENT(EVT_UA_AVATAR_SUCCESS, UserAccountSuccessEvent); wxDEFINE_EVENT(EVT_UA_PRUSACONNECT_PRINTER_DATA_SUCCESS, UserAccountSuccessEvent); wxDEFINE_EVENT(EVT_UA_FAIL, UserAccountFailEvent); wxDEFINE_EVENT(EVT_UA_RESET, UserAccountFailEvent); +wxDEFINE_EVENT(EVT_UA_RACE_LOST, UserAccountFailEvent); wxDEFINE_EVENT(EVT_UA_PRUSACONNECT_PRINTER_DATA_FAIL, UserAccountFailEvent); wxDEFINE_EVENT(EVT_UA_REFRESH_TIME, UserAccountTimeEvent); wxDEFINE_EVENT(EVT_UA_ENQUEUED_REFRESH, SimpleEvent); @@ -35,26 +36,35 @@ wxDEFINE_EVENT(EVT_UA_ENQUEUED_REFRESH, SimpleEvent); void UserActionPost::perform(/*UNUSED*/ wxEvtHandler* evt_handler, /*UNUSED*/ const std::string& access_token, UserActionSuccessFn success_callback, UserActionFailFn fail_callback, const std::string& input) const { std::string url = m_url; - BOOST_LOG_TRIVIAL(debug) << __FUNCTION__ << " " << url; + BOOST_LOG_TRIVIAL(trace) << __FUNCTION__ << " " << url; auto http = Http::post(std::move(url)); if (!input.empty()) http.set_post_body(input); http.header("Content-type", "application/x-www-form-urlencoded"); http.on_error([fail_callback](std::string body, std::string error, unsigned status) { + BOOST_LOG_TRIVIAL(trace) << "UserActionPost::perform on_error"; if (fail_callback) fail_callback(body); }); http.on_complete([success_callback](std::string body, unsigned status) { + BOOST_LOG_TRIVIAL(trace) << "UserActionPost::perform on_complete"; if (success_callback) success_callback(body); }); + http.on_retry([&](int attempt, unsigned delay) { + BOOST_LOG_TRIVIAL(trace) << "UserActionPost::perform on_retry " << attempt; + if (attempt > 1) { + wxQueueEvent(evt_handler, new UserAccountFailEvent(EVT_UA_RETRY_NOTIFY, GUI::format(_u8L("Communication with Prusa Account is taking longer than expected. Retrying. Attempt %1%."), std::to_string(attempt)))); + } + return true; + }); http.perform_sync(HttpRetryOpt::default_retry()); } void UserActionGetWithEvent::perform(wxEvtHandler* evt_handler, const std::string& access_token, UserActionSuccessFn success_callback, UserActionFailFn fail_callback, const std::string& input) const { std::string url = m_url + input; - BOOST_LOG_TRIVIAL(debug) << __FUNCTION__ << " " << url; + BOOST_LOG_TRIVIAL(trace) << __FUNCTION__ << " " << url; auto http = Http::get(std::move(url)); if (!access_token.empty()) { http.header("Authorization", "Bearer " + access_token); @@ -68,6 +78,7 @@ void UserActionGetWithEvent::perform(wxEvtHandler* evt_handler, const std::strin #endif } http.on_error([evt_handler, fail_callback, action_name = &m_action_name, fail_evt_type = m_fail_evt_type](std::string body, std::string error, unsigned status) { + BOOST_LOG_TRIVIAL(trace) << "UserActionGetWithEvent::perform on_error"; if (fail_callback) fail_callback(body); std::string message = GUI::format("%1% action failed (%2%): %3%", action_name, std::to_string(status), body); @@ -75,12 +86,19 @@ void UserActionGetWithEvent::perform(wxEvtHandler* evt_handler, const std::strin wxQueueEvent(evt_handler, new UserAccountFailEvent(fail_evt_type, std::move(message))); }); http.on_complete([evt_handler, success_callback, succ_evt_type = m_succ_evt_type](std::string body, unsigned status) { + BOOST_LOG_TRIVIAL(trace) << "UserActionGetWithEvent::perform on_complete"; if (success_callback) success_callback(body); if (succ_evt_type != wxEVT_NULL) wxQueueEvent(evt_handler, new UserAccountSuccessEvent(succ_evt_type, body)); }); - + http.on_retry([&](int attempt, unsigned delay) { + BOOST_LOG_TRIVIAL(trace) << "UserActionGetWithEvent::perform on_retry " << attempt; + if (attempt > 1) { + wxQueueEvent(evt_handler, new UserAccountFailEvent(EVT_UA_RETRY_NOTIFY, GUI::format(_u8L("Communication with Prusa Account is taking longer than expected. Retrying. Attempt %1%."), std::to_string(attempt)))); + } + return true; + }); http.perform_sync(HttpRetryOpt::default_retry()); } @@ -101,6 +119,7 @@ void UserAccountSession::process_action_queue() std::lock_guard lock(m_session_mutex); if (!m_proccessing_enabled) return; + BOOST_LOG_TRIVIAL(trace) << "action queue: " << m_priority_action_queue.size() << " " << m_action_queue.size(); if (m_priority_action_queue.empty() && m_action_queue.empty()) { // update printers periodically enqueue_action_inner(m_polling_action, nullptr, nullptr, {}); @@ -177,7 +196,7 @@ void UserAccountSession::token_success_callback(const std::string& body) { // No need to use lock m_session_mutex here - BOOST_LOG_TRIVIAL(debug) << "Access token refreshed"; + BOOST_LOG_TRIVIAL(debug) << __FUNCTION__ << " Access token refreshed"; // Data we need std::string access_token, refresh_token, shared_session_key; try { @@ -209,14 +228,21 @@ void UserAccountSession::token_success_callback(const std::string& body) m_access_token = std::string(); m_refresh_token = std::string(); m_shared_session_key = std::string(); + m_next_token_timeout = 0; } wxQueueEvent(p_evt_handler, new UserAccountFailEvent(EVT_UA_RESET, std::move(msg))); return; } - //BOOST_LOG_TRIVIAL(info) << "access_token: " << access_token; + if (!access_token.empty()) { + BOOST_LOG_TRIVIAL(debug) << __FUNCTION__ <<" access_token: " << access_token.substr(0,5) << "..." << access_token.substr(access_token.size()-5); + } else { + BOOST_LOG_TRIVIAL(debug) << __FUNCTION__ <<" access_token empty!"; + } + //BOOST_LOG_TRIVIAL(info) << __FUNCTION__ <<" access_token: " << access_token; //BOOST_LOG_TRIVIAL(info) << "refresh_token: " << refresh_token; //BOOST_LOG_TRIVIAL(info) << "shared_session_key: " << shared_session_key; + //BOOST_LOG_TRIVIAL(info) << __FUNCTION__ <<" expires_in: " << std::time(nullptr) + expires_in; { std::lock_guard lock(m_credentials_mutex); m_access_token = access_token; @@ -228,6 +254,25 @@ void UserAccountSession::token_success_callback(const std::string& body) wxQueueEvent(p_evt_handler, new UserAccountTimeEvent(EVT_UA_REFRESH_TIME, expires_in)); } +void UserAccountSession::set_tokens(const std::string& access_token, const std::string& refresh_token, const std::string& shared_session_key, long long expires_in) +{ + if (!access_token.empty()) { + BOOST_LOG_TRIVIAL(debug) << __FUNCTION__ <<" access_token: " << access_token.substr(0,5) << "..." << access_token.substr(access_token.size()-5); + } else { + BOOST_LOG_TRIVIAL(debug) << __FUNCTION__ <<" access_token empty!"; + } + + { + std::lock_guard lock(m_credentials_mutex); + m_access_token = access_token; + m_refresh_token = refresh_token; + m_shared_session_key = shared_session_key; + m_next_token_timeout = /*std::time(nullptr) +*/ expires_in; + } + long long exp = expires_in - std::time(nullptr); + wxQueueEvent(p_evt_handler, new UserAccountTimeEvent(EVT_UA_REFRESH_TIME, exp)); +} + void UserAccountSession::code_exchange_fail_callback(const std::string& body) { @@ -240,6 +285,7 @@ void UserAccountSession::code_exchange_fail_callback(const std::string& body) void UserAccountSession::enqueue_test_with_refresh() { + BOOST_LOG_TRIVIAL(debug) << __FUNCTION__; { std::lock_guard lock(m_session_mutex); // on test fail - try refresh @@ -250,6 +296,7 @@ void UserAccountSession::enqueue_test_with_refresh() void UserAccountSession::enqueue_refresh(const std::string& body) { + BOOST_LOG_TRIVIAL(debug) << __FUNCTION__; wxQueueEvent(p_evt_handler, new SimpleEvent(EVT_UA_ENQUEUED_REFRESH)); std::string post_fields; { @@ -278,6 +325,33 @@ void UserAccountSession::refresh_fail_callback(const std::string& body) wxQueueEvent(p_evt_handler, new UserAccountFailEvent(EVT_UA_RESET, body)); } +void UserAccountSession::enqueue_refresh_race(const std::string refresh_token_from_store/* = std::string()*/) +{ + BOOST_LOG_TRIVIAL(debug) << __FUNCTION__; + wxQueueEvent(p_evt_handler, new SimpleEvent(EVT_UA_ENQUEUED_REFRESH)); + std::string post_fields; + { + std::lock_guard lock(m_credentials_mutex); + assert(!m_refresh_token.empty()); + post_fields = "grant_type=refresh_token" + "&client_id=" + client_id() + + "&refresh_token=" + (refresh_token_from_store.empty() ? m_refresh_token :refresh_token_from_store); + } + { + std::lock_guard lock(m_session_mutex); + m_priority_action_queue.push_back({ UserAccountActionID::USER_ACCOUNT_ACTION_REFRESH_TOKEN + , std::bind(&UserAccountSession::token_success_callback, this, std::placeholders::_1) + , std::bind(&UserAccountSession::refresh_fail_soft_callback, this, std::placeholders::_1) + , post_fields }); + } +} + +void UserAccountSession::refresh_fail_soft_callback(const std::string& body) +{ + cancel_queue(); + wxQueueEvent(p_evt_handler, new UserAccountFailEvent(EVT_UA_RACE_LOST, body)); +} + void UserAccountSession::cancel_queue() { { diff --git a/src/slic3r/GUI/UserAccountSession.hpp b/src/slic3r/GUI/UserAccountSession.hpp index 23ae62263a..317047ea9f 100644 --- a/src/slic3r/GUI/UserAccountSession.hpp +++ b/src/slic3r/GUI/UserAccountSession.hpp @@ -28,6 +28,7 @@ wxDECLARE_EVENT(EVT_UA_AVATAR_SUCCESS, UserAccountSuccessEvent); wxDECLARE_EVENT(EVT_UA_PRUSACONNECT_PRINTER_DATA_SUCCESS, UserAccountSuccessEvent); wxDECLARE_EVENT(EVT_UA_FAIL, UserAccountFailEvent); // Soft fail - clears only after some number of fails wxDECLARE_EVENT(EVT_UA_RESET, UserAccountFailEvent); // Hard fail - clears all +wxDECLARE_EVENT(EVT_UA_RACE_LOST, UserAccountFailEvent); // Hard fail - clears all wxDECLARE_EVENT(EVT_UA_PRUSACONNECT_PRINTER_DATA_FAIL, UserAccountFailEvent); // Failed to get data for printer to select, soft fail, action does not repeat wxDECLARE_EVENT(EVT_UA_REFRESH_TIME, UserAccountTimeEvent); wxDECLARE_EVENT(EVT_UA_ENQUEUED_REFRESH, SimpleEvent); @@ -104,11 +105,12 @@ struct ActionQueueData class UserAccountSession { public: - UserAccountSession(wxEvtHandler* evt_handler, const std::string& access_token, const std::string& refresh_token, const std::string& shared_session_key, bool polling_enabled) + UserAccountSession(wxEvtHandler* evt_handler, const std::string& access_token, const std::string& refresh_token, const std::string& shared_session_key, long long next_token_timeout, bool polling_enabled) : p_evt_handler(evt_handler) , m_access_token(access_token) , m_refresh_token(refresh_token) , m_shared_session_key(shared_session_key) + , m_next_token_timeout(next_token_timeout) , m_polling_action(polling_enabled ? UserAccountActionID::USER_ACCOUNT_ACTION_CONNECT_PRINTER_MODELS : UserAccountActionID::USER_ACCOUNT_ACTION_DUMMY) { @@ -159,6 +161,7 @@ public: // Special enques, that sets callbacks. void enqueue_test_with_refresh(); void enqueue_refresh(const std::string& body); + void enqueue_refresh_race(const std::string refresh_token_from_store = std::string()); void process_action_queue(); bool is_initialized() const { @@ -183,13 +186,15 @@ public: return m_next_token_timeout; } - //void set_polling_enabled(bool enabled) {m_polling_action = enabled ? UserAccountActionID::USER_ACCOUNT_ACTION_CONNECT_PRINTER_MODELS : UserAccountActionID::USER_ACCOUNT_ACTION_DUMMY; } + void set_tokens(const std::string& access_token, const std::string& refresh_token, const std::string& shared_session_key, long long expires_in); + void set_polling_action(UserAccountActionID action) { std::lock_guard lock(m_session_mutex); m_polling_action = action; } private: void refresh_fail_callback(const std::string& body); + void refresh_fail_soft_callback(const std::string& body); void cancel_queue(); void code_exchange_fail_callback(const std::string& body); void token_success_callback(const std::string& body); diff --git a/src/slic3r/GUI/WebViewPanel.cpp b/src/slic3r/GUI/WebViewPanel.cpp index 15fb080d40..9bbf39fd5b 100644 --- a/src/slic3r/GUI/WebViewPanel.cpp +++ b/src/slic3r/GUI/WebViewPanel.cpp @@ -422,7 +422,7 @@ void WebViewPanel::run_script(const wxString& javascript) // Remember the script we run in any case, so the next time the user opens // the "Run Script" dialog box, it is shown there for convenient updating. m_javascript = javascript; - BOOST_LOG_TRIVIAL(debug) << "RunScript " << javascript << "\n"; + BOOST_LOG_TRIVIAL(trace) << "RunScript " << javascript << "\n"; m_browser->RunScriptAsync(javascript); } @@ -1377,6 +1377,7 @@ void PrintablesWebViewPanel::send_refreshed_token(const std::string& access_toke if (m_load_default_url) { return; } + BOOST_LOG_TRIVIAL(debug) << __FUNCTION__; hide_loading_overlay(); wxString script = GUI::format_wxstr("window.postMessage(JSON.stringify({" "event: 'accessTokenChange'," @@ -1390,6 +1391,7 @@ void PrintablesWebViewPanel::send_will_refresh() if (m_load_default_url) { return; } + BOOST_LOG_TRIVIAL(debug) << __FUNCTION__; wxString script = "window.postMessage(JSON.stringify({ event: 'accessTokenWillChange' }))"; run_script(script); } @@ -1420,6 +1422,7 @@ void PrintablesWebViewPanel::on_printables_event_access_token_expired(const std: BOOST_LOG_TRIVIAL(debug) << __FUNCTION__; m_refreshing_token = true; show_loading_overlay(); + wxGetApp().plater()->get_user_account()->request_refresh(); } diff --git a/src/slic3r/GUI/WebViewPanel.hpp b/src/slic3r/GUI/WebViewPanel.hpp index 17d0a41710..74b223bf2a 100644 --- a/src/slic3r/GUI/WebViewPanel.hpp +++ b/src/slic3r/GUI/WebViewPanel.hpp @@ -218,6 +218,7 @@ private: void on_printables_event_slice_file(const std::string& message_data); void on_printables_event_required_login(const std::string& message_data); void on_printables_event_open_url(const std::string& message_data); + void on_dummy_event(const std::string& message_data) {} void load_default_url() override; std::string get_url_lang_theme(const wxString& url) const; void show_download_notification(const std::string& filename); diff --git a/src/slic3r/GUI/WebViewPlatformUtilsWin32.cpp b/src/slic3r/GUI/WebViewPlatformUtilsWin32.cpp index a03a573965..0f5f697f04 100644 --- a/src/slic3r/GUI/WebViewPlatformUtilsWin32.cpp +++ b/src/slic3r/GUI/WebViewPlatformUtilsWin32.cpp @@ -238,7 +238,7 @@ void RequestHeadersToLog(ICoreWebView2HttpRequestHeaders* requestHeaders) wchar_t* value = nullptr; iterator->GetCurrentHeader(&name, &value); - BOOST_LOG_TRIVIAL(debug) <<"name: " << name << L", value: " << value; + BOOST_LOG_TRIVIAL(trace) <<"name: " << name << L", value: " << value; if (name) { CoTaskMemFree(name); }