From 455ec039b9de3c396dd5c4fcbe1aeb535345cd7a Mon Sep 17 00:00:00 2001 From: James McQuillan Date: Mon, 28 Mar 2016 03:18:49 -0400 Subject: [PATCH 1/2] MSFTMPP-426: Improve throttling functionality --- classes/healthcheck/ratelimit.php | 92 +++++++++++++++++++++++++++++++ classes/page/acp.php | 17 ++++-- classes/rest/o365api.php | 49 +++++++++++++--- classes/rest/unified.php | 2 - lang/en/local_o365.php | 5 ++ 5 files changed, 151 insertions(+), 14 deletions(-) create mode 100644 classes/healthcheck/ratelimit.php diff --git a/classes/healthcheck/ratelimit.php b/classes/healthcheck/ratelimit.php new file mode 100644 index 000000000..3d562dcb4 --- /dev/null +++ b/classes/healthcheck/ratelimit.php @@ -0,0 +1,92 @@ +. + +/** + * @package local_o365 + * @author James McQuillan + * @license http://www.gnu.org/copyleft/gpl.html GNU GPL v3 or later + * @copyright (C) 2014 onwards Microsoft Open Technologies, Inc. (http://msopentech.com/) + */ + +namespace local_o365\healthcheck; + +/** + * Checks current recorded rate limit + */ +class ratelimit implements \local_o365\healthcheck\healthcheckinterface { + /** + * Run the health check. + * + * @return array Array of result data. Must include: + * bool result Whether the health check passed or not. + * int severity If the health check failed, how bad a problem is it? This is one of the SEVERITY_* constants. + * string message A message to show the user. + * string fixlink If the healthcheck failed, a link to help resolve the problem. + */ + public function run() { + $ratelimitdisabled = get_config('local_o365', 'ratelimitdisabled'); + if (!empty($ratelimitdisabled)) { + return [ + 'result' => false, + 'severity' => static::SEVERITY_TRIVIAL, + 'message' => get_string('healthcheck_ratelimit_result_disabled', 'local_o365'), + ]; + } + + $ratelimit = get_config('local_o365', 'ratelimit'); + $ratelimit = explode(':', $ratelimit, 2); + + if (!empty($ratelimit[0]) && $ratelimit[1] > (time() - (10 * MINSECS))) { + $a = new \stdClass; + $a->level = $ratelimit[0]; + $a->timestart = date('c', $ratelimit[1]); + if ($ratelimit[0] < 4) { + return [ + 'result' => false, + 'severity' => static::SEVERITY_TRIVIAL, + 'message' => get_string('healthcheck_ratelimit_result_notice', 'local_o365', $a), + ]; + } else { + return [ + 'result' => false, + 'severity' => static::SEVERITY_TRIVIAL, + 'message' => get_string('healthcheck_ratelimit_result_warning', 'local_o365', $a), + ]; + } + } else { + return [ + 'result' => true, + 'severity' => static::SEVERITY_OK, + 'message' => get_string('healthcheck_ratelimit_result_passed', 'local_o365'), + ]; + } + + if (empty($systemtoken)) { + + } else { + + } + } + + /** + * Get a human-readable name for the health check. + * + * @return string A name for the health check. + */ + public function get_name() { + return get_string('healthcheck_ratelimit_title', 'local_o365'); + } +} \ No newline at end of file diff --git a/classes/page/acp.php b/classes/page/acp.php index c4c17fd6e..88ea5fdc2 100644 --- a/classes/page/acp.php +++ b/classes/page/acp.php @@ -54,7 +54,7 @@ public function mode_healthcheck() { echo \html_writer::tag('h2', get_string('acp_healthcheck', 'local_o365')); echo '
'; - $healthchecks = ['systemapiuser']; + $healthchecks = ['systemapiuser', 'ratelimit']; foreach ($healthchecks as $healthcheck) { $healthcheckclass = '\local_o365\healthcheck\\'.$healthcheck; $healthcheck = new $healthcheckclass(); @@ -62,14 +62,23 @@ public function mode_healthcheck() { echo '
'.$healthcheck->get_name().'
'; if ($result['result'] === true) { - echo '
'.$result['message'].'
'; + echo '
'.$result['message'].'

'; } else { - echo '
'; + switch ($result['severity']) { + case \local_o365\healthcheck\healthcheckinterface::SEVERITY_TRIVIAL: + $severityclass = 'alert-info'; + break; + + default: + $severityclass = 'alert-error'; + } + + echo '
'; echo $result['message']; if (isset($result['fixlink'])) { echo '

'.\html_writer::link($result['fixlink'], get_string('healthcheck_fixlink', 'local_o365')); } - echo '
'; + echo '

'; } } diff --git a/classes/rest/o365api.php b/classes/rest/o365api.php index 4a065d66e..4d7179b62 100644 --- a/classes/rest/o365api.php +++ b/classes/rest/o365api.php @@ -33,9 +33,6 @@ abstract class o365api { /** @var \local_o365\httpclientinterface An HTTP client to use for communication. */ protected $httpclient; - /** @var bool Disable rate limit protection. */ - protected $disableratelimit = false; - /** * Constructor. * @@ -135,6 +132,14 @@ protected function transform_full_request_uri($requesturi) { * @return string The result of the API call. */ public function apicall($httpmethod, $apimethod, $params = '', $options = array()) { + // Used if we have to retry due to rate limiting. + $origparam = [ + 'httpmethod' => $httpmethod, + 'apimethod' => $apimethod, + 'params' => $params, + 'options' => $options, + ]; + $tokenvalid = $this->checktoken(); if ($tokenvalid !== true) { throw new \moodle_exception('erroro365apiinvalidtoken', 'local_o365'); @@ -168,14 +173,42 @@ public function apicall($httpmethod, $apimethod, $params = '', $options = array( $this->httpclient->resetHeader(); $this->httpclient->setHeader($header); - // Sleep to avoid rate limiting. - if (empty($this->disableratelimit)) { - usleep(1050000); + // Check if we were rate limited in the last 10 minutes. + $ratelimitlevel = 0; + $ratelimittime = 0; + $ratelimit = get_config('local_o365', 'ratelimit'); + $ratelimitdisabled = get_config('local_o365', 'ratelimitdisabled'); + if (empty($ratelimitdisabled)) { + if (!empty($ratelimit)) { + $ratelimit = explode(':', $ratelimit, 2); + if ($ratelimit[1] > (time() - (10 * MINSECS))) { + // Rate limiting enabled. + $ratelimittime = $ratelimit[1]; + $ratelimitlevel = $ratelimit[0]; + if ($ratelimitlevel >= 4) { + $ratelimitlevel = 4; + } + } + } + } + + // Throttle if enabled. + if (!empty($ratelimitlevel)) { + usleep((260000 * $ratelimitlevel)); } else { - usleep(250000); + // Small sleep to help prevent throttling in the first place. + usleep(100000); } - return $this->httpclient->$httpmethod($requesturi, $params, $options); + $result = $this->httpclient->$httpmethod($requesturi, $params, $options); + if ($this->httpclient->info['http_code'] == 429) { + // We are being throttled. + $ratelimitlevel++; + set_config('ratelimit', $ratelimitlevel.':'.time(), 'local_o365'); + return $this->apicall($origparam['httpmethod'], $origparam['apimethod'], $origparam['params'], $origparam['options']); + } else { + return $result; + } } /** diff --git a/classes/rest/unified.php b/classes/rest/unified.php index 31afe9fd4..483db03dd 100644 --- a/classes/rest/unified.php +++ b/classes/rest/unified.php @@ -685,11 +685,9 @@ public function get_required_permissions() { */ public function check_permissions() { $this->token->refresh(); - $this->disableratelimit = true; $currentperms = $this->get_unified_api_permissions(); $neededperms = $this->get_required_permissions(); $availableperms = $this->get_available_permissions(); - $this->disableratelimit = false; if ($currentperms === null || $availableperms === null) { return null; diff --git a/lang/en/local_o365.php b/lang/en/local_o365.php index 6c325a825..ccf904040 100644 --- a/lang/en/local_o365.php +++ b/lang/en/local_o365.php @@ -90,6 +90,11 @@ $string['healthcheck_systemtoken_result_noclientcreds'] = 'There are not application credentials present in the OpenID Connect plugin. Without these credentials, Moodle cannot perform any communication with Office 365. Click here to visit the settings page and enter your credentials.'; $string['healthcheck_systemtoken_result_badtoken'] = 'There was a problem communicating with Office 365 as the system API user. This can usually be resolved by resetting the system API user.'; $string['healthcheck_systemtoken_result_passed'] = 'Moodle can communicate with Office 365 as the system API user.'; +$string['healthcheck_ratelimit_title'] = 'API Throttling'; +$string['healthcheck_ratelimit_result_notice'] = 'Slight throttling has been enabled to handle increased Moodle site load.

All Office 365 features are functional, this just spaces out requests slightly to prevent interruption of Office 365 services. Once Moodle activity decreases, everything will return to normal.
(Level {$a->level} / started {$a->timestart})'; +$string['healthcheck_ratelimit_result_warning'] = 'Increased throttling has been enabled to handle significant Moodle site load.

All Office 365 features are still functional, but Office 365 requests may take longer to complete. Once Moodle site activity has decreased, everything will return to normal.
(Level {$a->level} / started {$a->timestart})'; +$string['healthcheck_ratelimit_result_disabled'] = 'Rate limiting features have been disabled.'; +$string['healthcheck_ratelimit_result_passed'] = 'Office 365 API calls are executing at full speed.'; $string['settings_aadsync'] = 'Sync users with Azure AD'; $string['settings_aadsync_details'] = 'When enabled, Moodle and Azure AD users are synced according to the above options.

Note: The sync job runs in the Moodle cron, and syncs 1000 users at a time. By default, this runs once per day at 1:00 AM in the time zone local to your server. To sync large sets of users more quickly, you can increase the freqency of the Sync users with Azure AD task using the Scheduled tasks management page.

For more detailed instructions, see the user sync documentation.

'; From ab4194f1907d07b45776597f3df5309376e30794 Mon Sep 17 00:00:00 2001 From: James McQuillan Date: Mon, 28 Mar 2016 17:41:32 -0400 Subject: [PATCH 2/2] MSFTMPP-426: Additional debug information in debug logging --- .../feature/calsync/task/importfromoutlook.php | 2 +- classes/feature/calsync/task/syncoldevents.php | 2 +- classes/observers.php | 10 +++++----- classes/page/ajax.php | 8 ++++---- classes/rest/azuread.php | 2 +- classes/utils.php | 18 ++++++++++++++++++ lang/en/local_o365.php | 2 +- settings.php | 3 ++- 8 files changed, 33 insertions(+), 14 deletions(-) diff --git a/classes/feature/calsync/task/importfromoutlook.php b/classes/feature/calsync/task/importfromoutlook.php index 671d81e71..88beb1c47 100644 --- a/classes/feature/calsync/task/importfromoutlook.php +++ b/classes/feature/calsync/task/importfromoutlook.php @@ -120,7 +120,7 @@ public function execute() { mtrace($errmsg); } } catch (\Exception $e) { - \local_o365\utils::debug('Error syncing events', 'importfromoutlook', $e->getMessage()); + \local_o365\utils::debug('Error syncing events: '.$e->getMessage(), 'importfromoutlook', $e); mtrace('Error: '.$e->getMessage()); } } diff --git a/classes/feature/calsync/task/syncoldevents.php b/classes/feature/calsync/task/syncoldevents.php index 21901d843..e5f75c87e 100644 --- a/classes/feature/calsync/task/syncoldevents.php +++ b/classes/feature/calsync/task/syncoldevents.php @@ -331,7 +331,7 @@ protected function sync_userevents($userid, $timecreated) { $usertoken = $calsync->get_user_token($userid); if (empty($usertoken)) { // No token, can't sync. - \local_o365\utils::debug('Could not get user token for calendar sync.'); + \local_o365\utils::debug('Could not get user token for calendar sync.', 'sync_userevents'); return false; } diff --git a/classes/observers.php b/classes/observers.php index 56d3063bd..e96cc2272 100644 --- a/classes/observers.php +++ b/classes/observers.php @@ -79,7 +79,7 @@ public static function handle_oidc_user_connected(\auth_oidc\event\user_connecte $token = \local_o365\oauth2\token::instance($eventdata['userid'], $azureresource, $clientdata, $httpclient); return true; } catch (\Exception $e) { - \local_o365\utils::debug($e->getMessage()); + \local_o365\utils::debug($e->getMessage(), 'handle_oidc_user_connected', $e); return false; } } @@ -202,7 +202,7 @@ public static function get_additional_user_info($userid, $eventtype) { } return true; } catch (\Exception $e) { - \local_o365\utils::debug($e->getMessage()); + \local_o365\utils::debug($e->getMessage(), 'get_additional_user_info', $e); } return false; } @@ -237,7 +237,7 @@ public static function handle_user_enrolment_created(\core\event\user_enrolment_ return true; } } catch (\Exception $e) { - \local_o365\utils::debug($e->getMessage()); + \local_o365\utils::debug($e->getMessage(), 'handle_user_enrolment_created', $e); } return false; } @@ -277,7 +277,7 @@ public static function handle_user_enrolment_deleted(\core\event\user_enrolment_ return true; } } catch (\Exception $e) { - \local_o365\utils::debug($e->getMessage()); + \local_o365\utils::debug($e->getMessage(), 'handle_user_enrolment_deleted', $e); } return false; } @@ -300,7 +300,7 @@ public static function construct_sharepoint_api_with_system_user() { } } } catch (\Exception $e) { - \local_o365\utils::debug($e->getMessage(), get_called_class()); + \local_o365\utils::debug($e->getMessage(), get_called_class(), $e); } return false; } diff --git a/classes/page/ajax.php b/classes/page/ajax.php index df13bb482..0f54f076c 100644 --- a/classes/page/ajax.php +++ b/classes/page/ajax.php @@ -163,7 +163,7 @@ public function mode_detectserviceresource() { die(); } } catch (\Exception $e) { - \local_o365\utils::debug($e->getMessage(), 'detect aadtenant'); + \local_o365\utils::debug($e->getMessage(), 'detect aadtenant', $e); echo $this->error_response(get_string('settings_serviceresourceabstract_noperms', 'local_o365')); die(); } @@ -179,7 +179,7 @@ public function mode_detectserviceresource() { die(); } } catch (\Exception $e) { - \local_o365\utils::debug($e->getMessage(), 'detect odburl'); + \local_o365\utils::debug($e->getMessage(), 'detect odburl', $e); echo $this->error_response(get_string('settings_serviceresourceabstract_noperms', 'local_o365')); die(); } @@ -223,7 +223,7 @@ public function mode_checksetup() { $legacyapi->missingperms = $missingperms; $legacyapi->haswrite = $haswrite; } catch (\Exception $e) { - \local_o365\utils::debug($e->getMessage(), 'mode_checksetup:legacy'); + \local_o365\utils::debug($e->getMessage(), 'mode_checksetup:legacy', $e); $legacyapi->error = $e->getMessage(); } $data->legacyapi = $legacyapi; @@ -249,7 +249,7 @@ public function mode_checksetup() { } } catch (\Exception $e) { $unifiedapi->active = false; - \local_o365\utils::debug($e->getMessage(), 'mode_checksetup:unified'); + \local_o365\utils::debug($e->getMessage(), 'mode_checksetup:unified', $e); $unifiedapi->error = $e->getMessage(); } } diff --git a/classes/rest/azuread.php b/classes/rest/azuread.php index 44bfd24ed..23384ea33 100644 --- a/classes/rest/azuread.php +++ b/classes/rest/azuread.php @@ -457,7 +457,7 @@ public static function get_muser_upn($user) { try { $clientdata = \local_o365\oauth2\clientdata::instance_from_oidc(); } catch (\Exception $e) { - \local_o365\utils::debug($e->getMessage()); + \local_o365\utils::debug($e->getMessage(), 'rest\azuread\get_muser_upn', $e); return false; } $resource = static::get_resource(); diff --git a/classes/utils.php b/classes/utils.php index 59882cc2c..9b15fe5dd 100644 --- a/classes/utils.php +++ b/classes/utils.php @@ -101,6 +101,12 @@ public static function is_o365_connected($userid) { } } + /** + * Convert any value into a debuggable string. + * + * @param mixed $val The variable to convert. + * @return string A string representation. + */ public static function tostring($val) { if (is_scalar($val)) { if (is_bool($val)) { @@ -110,6 +116,18 @@ public static function tostring($val) { } } else if (is_null($val)) { return '(null)'; + } else if ($val instanceof \Exception) { + $valinfo = [ + 'file' => $val->getFile(), + 'line' => $val->getLine(), + 'message' => $val->getMessage(), + ]; + if ($val instanceof \moodle_exception) { + $valinfo['debuginfo'] = $val->debuginfo; + $valinfo['errorcode'] = $val->errorcode; + $valinfo['module'] = $val->module; + } + return print_r($valinfo, true); } else { return print_r($val, true); } diff --git a/lang/en/local_o365.php b/lang/en/local_o365.php index ccf904040..4e39eca32 100644 --- a/lang/en/local_o365.php +++ b/lang/en/local_o365.php @@ -135,7 +135,7 @@ $string['settings_o365china'] = 'Office 365 for China'; $string['settings_o365china_details'] = 'Check this if you are using Office 365 for China.'; $string['settings_debugmode'] = 'Record debug messages'; -$string['settings_debugmode_details'] = 'If enabled, information will be logged to the Moodle log that can help in identifying problems.'; +$string['settings_debugmode_details'] = 'If enabled, information will be logged to the Moodle log that can help in identifying problems. View recorded log messages.'; $string['settings_detectoidc'] = 'Application Credentials'; $string['settings_detectoidc_details'] = 'To communicate with Office 365, Moodle needs credentials to identify itself. These are set in the "OpenID Connect" authentication plugin.'; $string['settings_detectoidc_credsvalid'] = 'Credentials have been set.'; diff --git a/settings.php b/settings.php index ea7b95bc1..02c5a7494 100644 --- a/settings.php +++ b/settings.php @@ -104,7 +104,8 @@ $settings->add(new \admin_setting_configcheckbox('local_o365/creategroups', $label, $desc, '0')); $label = get_string('settings_debugmode', 'local_o365'); - $desc = get_string('settings_debugmode_details', 'local_o365'); + $logurl = new \moodle_url('/report/log/index.php', ['chooselog' => '1', 'modid' => 'site_errors']); + $desc = get_string('settings_debugmode_details', 'local_o365', $logurl->out()); $settings->add(new \admin_setting_configcheckbox('local_o365/debugmode', $label, $desc, '0')); $label = get_string('settings_photoexpire', 'local_o365');