Merge pull request #240 from apitiot/master

throttling of log messages (code only, will be activated in 2021), and __noOutput

js/core/Logger.js

@@ -9,8 +9,8 @@
 
 
 import * as util from '../util/Util';
-import {MonotonicClock} from '../util/Clock';
+import {MonotonicClock} from '../util';
-import {ExperimentHandler} from '../data/ExperimentHandler';
+import {ExperimentHandler} from '../data';
 
 
 /**
@@ -44,6 +44,28 @@ export class Logger
 		// server logger:
 		this._serverLogs = [];
 		this._serverLevel = Logger.ServerLevel.WARNING;
+		this._serverLevelValue = this._getValue(this._serverLevel);
+
+		// throttling of server logs
+		this._throttling = {
+			// period of time (in seconds) over which we consider the number of logged messages:
+			window: 1,
+			// threshold (i.e. number of messages over the throttling window) at which point
+			// we start throttling:
+			threshold: 20,
+			// throttling factor: 10 -> only 1 in 10 messages is logged
+			factor: 10,
+			// minimum duration (in seconds) of throttling
+			minimumDuration: 2,
+			// time at which throttling started:
+			startOfThrottling: 0,
+			// whether or not we are currently throttling:
+			isThrottling: false,
+			// throttling message index:
+			index: 0,
+			// whether or not the designer has already been warned:
+			designerWasWarned: false
+		};
 	}
 
 
@@ -58,6 +80,7 @@ export class Logger
 	setLevel(serverLevel)
 	{
 		this._serverLevel = serverLevel;
+		this._serverLevelValue = this._getValue(this._serverLevel);
 	}
 
 
@@ -106,18 +129,106 @@ export class Logger
 	 */
 	log(msg, level, time, obj)
 	{
+		// only log if the level is higher or equal to the previously defined server level:
+		const levelValue = this._getValue(level);
+		if (levelValue < this._serverLevelValue)
+		{
+			return;
+		}
+
 		if (typeof time === 'undefined')
 		{
 			time = MonotonicClock.getReferenceTime();
 		}
 
+		/* [coming soon]
+		// check whether we need to throttle:
+		if (this._throttle(time))
+		{
+			return;
+		}
+	 */
+
 		this._serverLogs.push({
 			msg,
 			level,
 			time,
 			obj: util.toString(obj)
 		});
+	}
 
+
+
+	/**
+	 * Check whether or not a log messages must be throttled.
+	 *
+	 * @name module:core.Logger#_throttle
+	 * @protected
+	 *
+	 * @param {number} time - the time of the latest log message
+	 * @return {boolean} whether or not to log the message
+	 */
+	_throttle(time)
+	{
+		// if more messages than this._throttling.threshold have been logged between
+		// time and the start of the throttling window, we need to throttle:
+		if (this._serverLogs.length > this._throttling.threshold)
+		{
+			const timeAtStartThrottlingWindow = this._serverLogs[this._serverLogs.length - 1 - this._throttling.threshold].time;
+			if (time - timeAtStartThrottlingWindow < this._throttling.window)
+			{
+				// warn the designer if we are not already throttling:
+				if (!this._throttling.isThrottling)
+				{
+					const msg = `<p>[time= ${time.toFixed(3)}] More than ${this._throttling.threshold} messages were logged in the past ${this._throttling.window}s.</p>` +
+						`<p>We are now throttling: only 1 in ${this._throttling.factor} messages will be logged.</p>` +
+						`<p>You may want to change your experiment's logging level. Please see <a href="https://www.psychopy.org/api/logging.html">psychopy.org/api/logging.html</a> for details.</p>`;
+
+					// console warning:
+					this._psychoJS.logger.warn(msg);
+
+					// in PILOTING mode and locally, we also warn the experimenter with a dialog box,
+					// but only once:
+					if (!this._throttling.designerWasWarned &&
+						(this._psychoJS.getEnvironment() === ExperimentHandler.Environment.LOCAL ||
+							this._psychoJS.config.experiment.status === 'PILOTING'))
+					{
+						this._throttling.designerWasWarned = true;
+
+						this._psychoJS.gui.dialog({
+							warning: msg,
+							showOK: true
+						});
+					}
+
+					this._throttling.isThrottling = true;
+					this._throttling.startOfThrottling = time;
+					this._throttling.index = 0;
+				}
+
+				++ this._throttling.index;
+				if (this._throttling.index < this._throttling.factor)
+				{
+					// no logging
+					return true;
+				}
+				else
+				{
+					this._throttling.index = 0;
+				}
+			}
+			else
+			{
+				if (this._throttling.isThrottling &&
+					(time - this._throttling.startOfThrottling) > this._throttling.minimumDuration)
+				{
+					this._psychoJS.logger.info(`[time= ${time.toFixed(3)}] Log messages are not throttled any longer.`);
+					this._throttling.isThrottling = false;
+				}
+			}
+		}
+
+		return false;
 	}
 
 
@@ -140,28 +251,20 @@ export class Logger
 
 		this._psychoJS.logger.info('[PsychoJS] Flush server logs.');
 
-		// server level value:
+		// prepare the formatted logs:
-		const serverLevelValue = this._getValue(this._serverLevel);
-
-		// prepare formatted logs:
 		let formattedLogs = '';
 		for (const log of this._serverLogs)
 		{
-			// we add the log message only if its level is >= _serverLevel
+			let formattedLog = util.toString(log.time) +
-			const levelValue = this._getValue(log.level);
+				'\t' + Symbol.keyFor(log.level) +
-			if (levelValue >= serverLevelValue)
+				'\t' + log.msg;
+			if (log.obj !== 'undefined')
 			{
-				let formattedLog = util.toString(log.time) +
+				formattedLog += '\t' + log.obj;
-					'\t' + Symbol.keyFor(log.level) +
-					'\t' + log.msg;
-				if (log.obj !== 'undefined')
-				{
-					formattedLog += '\t' + log.obj;
-				}
-				formattedLog += '\n';
-
-				formattedLogs += formattedLog;
 			}
+			formattedLog += '\n';
+
+			formattedLogs += formattedLog;
 		}
 
 		// send logs to the server or display them in the console:

js/core/PsychoJS.js

@@ -353,8 +353,8 @@ export class PsychoJS
 				window.addEventListener('beforeunload', this.beforeunloadCallback);
 
 
-				// when the user closes the tab or browser, we attempt to close the session, optionally save the results,
+				// when the user closes the tab or browser, we attempt to close the session,
-				// and release the WebGL context
+				// optionally save the results, and release the WebGL context
 				// note: we communicate with the server using the Beacon API
 				const self = this;
 				window.addEventListener('unload', (event) =>
@@ -485,8 +485,11 @@ export class PsychoJS
 			});
 			if (isCompleted || this._config.experiment.saveIncompleteResults)
 			{
-				await this._experiment.save();
+				if (!this._serverMsg.has('__noOutput'))
-				await this._logger.flush();
+				{
+					await this._experiment.save();
+					await this._logger.flush();
+				}
 			}
 
 			// close the session:
@@ -546,7 +549,10 @@ export class PsychoJS
 	 */
 	async _configure(configURL, name)
 	{
-		const response = {origin: 'PsychoJS.configure', context: 'when configuring PsychoJS for the experiment'};
+		const response = {
+			origin: 'PsychoJS.configure',
+			context: 'when configuring PsychoJS for the experiment'
+		};
 
 		try
 		{
@@ -559,8 +565,8 @@ export class PsychoJS
 				const serverResponse = await this._serverManager.getConfiguration(configURL);
 				this._config = serverResponse.config;
 
-				// legacy experiments had a psychoJsManager block instead of a pavlovia block, and the URL
+				// legacy experiments had a psychoJsManager block instead of a pavlovia block,
-				// pointed to https://pavlovia.org/server
+				// and the URL pointed to https://pavlovia.org/server
 				if ('psychoJsManager' in this._config)
 				{
 					delete this._config.psychoJsManager;

js/core/Window.js

@@ -7,9 +7,9 @@
  * @license Distributed under the terms of the MIT License
  */
 
-import {Color} from '../util/Color';
+import {Color} from '../util';
-import {PsychObject} from '../util/PsychObject';
+import {PsychObject} from '../util';
-import {MonotonicClock} from '../util/Clock';
+import {MonotonicClock} from '../util';
 import {Logger} from "./Logger";
 
 /**

js/visual/Slider.js

@@ -423,7 +423,7 @@ export class Slider extends util.mix(VisualStim).with(ColorMixin, WindowMixin)
 		{
 			const tickPositionIndex = Math.round( l / (this._labels.length - 1) * (this._ticks.length - 1) );
 			this._labelPositions_px[l] = this._tickPositions_px[tickPositionIndex];
-			const labelBounds = PIXI.TextMetrics.measureText(this._labels[l], labelTextStyle);
+			const labelBounds = PIXI.TextMetrics.measureText(this._labels[l].toString(), labelTextStyle);
 
 			// horizontal slider:
 			if (this._isHorizontal())