Thu, 22 Jan 2015 13:21:57 +0100
Incorporate requested changes from Mozilla in review:
https://bugzilla.mozilla.org/show_bug.cgi?id=1123480#c6
michael@0 | 1 | /* This Source Code Form is subject to the terms of the Mozilla Public |
michael@0 | 2 | * License, v. 2.0. If a copy of the MPL was not distributed with this |
michael@0 | 3 | * file, You can obtain one at http://mozilla.org/MPL/2.0/. */ |
michael@0 | 4 | |
michael@0 | 5 | "use strict"; |
michael@0 | 6 | |
michael@0 | 7 | const Cu = Components.utils; |
michael@0 | 8 | const Cc = Components.classes; |
michael@0 | 9 | const Ci = Components.interfaces; |
michael@0 | 10 | |
michael@0 | 11 | Cu.import("resource://gre/modules/osfile.jsm"); |
michael@0 | 12 | Cu.import("resource://gre/modules/Promise.jsm"); |
michael@0 | 13 | |
michael@0 | 14 | // Make it possible to mock out timers for testing |
michael@0 | 15 | let MakeTimer = () => Cc["@mozilla.org/timer;1"].createInstance(Ci.nsITimer); |
michael@0 | 16 | |
michael@0 | 17 | this.EXPORTED_SYMBOLS = ["DeferredSave"]; |
michael@0 | 18 | |
michael@0 | 19 | // If delay parameter is not provided, default is 50 milliseconds. |
michael@0 | 20 | const DEFAULT_SAVE_DELAY_MS = 50; |
michael@0 | 21 | |
michael@0 | 22 | Cu.import("resource://gre/modules/Log.jsm"); |
michael@0 | 23 | //Configure a logger at the parent 'DeferredSave' level to format |
michael@0 | 24 | //messages for all the modules under DeferredSave.* |
michael@0 | 25 | const DEFERREDSAVE_PARENT_LOGGER_ID = "DeferredSave"; |
michael@0 | 26 | let parentLogger = Log.repository.getLogger(DEFERREDSAVE_PARENT_LOGGER_ID); |
michael@0 | 27 | parentLogger.level = Log.Level.Warn; |
michael@0 | 28 | let formatter = new Log.BasicFormatter(); |
michael@0 | 29 | //Set parent logger (and its children) to append to |
michael@0 | 30 | //the Javascript section of the Browser Console |
michael@0 | 31 | parentLogger.addAppender(new Log.ConsoleAppender(formatter)); |
michael@0 | 32 | //Set parent logger (and its children) to |
michael@0 | 33 | //also append to standard out |
michael@0 | 34 | parentLogger.addAppender(new Log.DumpAppender(formatter)); |
michael@0 | 35 | |
michael@0 | 36 | //Provide the ability to enable/disable logging |
michael@0 | 37 | //messages at runtime. |
michael@0 | 38 | //If the "extensions.logging.enabled" preference is |
michael@0 | 39 | //missing or 'false', messages at the WARNING and higher |
michael@0 | 40 | //severity should be logged to the JS console and standard error. |
michael@0 | 41 | //If "extensions.logging.enabled" is set to 'true', messages |
michael@0 | 42 | //at DEBUG and higher should go to JS console and standard error. |
michael@0 | 43 | Cu.import("resource://gre/modules/Services.jsm"); |
michael@0 | 44 | |
michael@0 | 45 | const PREF_LOGGING_ENABLED = "extensions.logging.enabled"; |
michael@0 | 46 | const NS_PREFBRANCH_PREFCHANGE_TOPIC_ID = "nsPref:changed"; |
michael@0 | 47 | |
michael@0 | 48 | /** |
michael@0 | 49 | * Preference listener which listens for a change in the |
michael@0 | 50 | * "extensions.logging.enabled" preference and changes the logging level of the |
michael@0 | 51 | * parent 'addons' level logger accordingly. |
michael@0 | 52 | */ |
michael@0 | 53 | var PrefObserver = { |
michael@0 | 54 | init: function PrefObserver_init() { |
michael@0 | 55 | Services.prefs.addObserver(PREF_LOGGING_ENABLED, this, false); |
michael@0 | 56 | Services.obs.addObserver(this, "xpcom-shutdown", false); |
michael@0 | 57 | this.observe(null, NS_PREFBRANCH_PREFCHANGE_TOPIC_ID, PREF_LOGGING_ENABLED); |
michael@0 | 58 | }, |
michael@0 | 59 | |
michael@0 | 60 | observe: function PrefObserver_observe(aSubject, aTopic, aData) { |
michael@0 | 61 | if (aTopic == "xpcom-shutdown") { |
michael@0 | 62 | Services.prefs.removeObserver(PREF_LOGGING_ENABLED, this); |
michael@0 | 63 | Services.obs.removeObserver(this, "xpcom-shutdown"); |
michael@0 | 64 | } |
michael@0 | 65 | else if (aTopic == NS_PREFBRANCH_PREFCHANGE_TOPIC_ID) { |
michael@0 | 66 | let debugLogEnabled = false; |
michael@0 | 67 | try { |
michael@0 | 68 | debugLogEnabled = Services.prefs.getBoolPref(PREF_LOGGING_ENABLED); |
michael@0 | 69 | } |
michael@0 | 70 | catch (e) { |
michael@0 | 71 | } |
michael@0 | 72 | if (debugLogEnabled) { |
michael@0 | 73 | parentLogger.level = Log.Level.Debug; |
michael@0 | 74 | } |
michael@0 | 75 | else { |
michael@0 | 76 | parentLogger.level = Log.Level.Warn; |
michael@0 | 77 | } |
michael@0 | 78 | } |
michael@0 | 79 | } |
michael@0 | 80 | }; |
michael@0 | 81 | |
michael@0 | 82 | PrefObserver.init(); |
michael@0 | 83 | |
michael@0 | 84 | /** |
michael@0 | 85 | * A module to manage deferred, asynchronous writing of data files |
michael@0 | 86 | * to disk. Writing is deferred by waiting for a specified delay after |
michael@0 | 87 | * a request to save the data, before beginning to write. If more than |
michael@0 | 88 | * one save request is received during the delay, all requests are |
michael@0 | 89 | * fulfilled by a single write. |
michael@0 | 90 | * |
michael@0 | 91 | * @constructor |
michael@0 | 92 | * @param aPath |
michael@0 | 93 | * String representing the full path of the file where the data |
michael@0 | 94 | * is to be written. |
michael@0 | 95 | * @param aDataProvider |
michael@0 | 96 | * Callback function that takes no argument and returns the data to |
michael@0 | 97 | * be written. If aDataProvider returns an ArrayBufferView, the |
michael@0 | 98 | * bytes it contains are written to the file as is. |
michael@0 | 99 | * If aDataProvider returns a String the data are UTF-8 encoded |
michael@0 | 100 | * and then written to the file. |
michael@0 | 101 | * @param [optional] aDelay |
michael@0 | 102 | * The delay in milliseconds between the first saveChanges() call |
michael@0 | 103 | * that marks the data as needing to be saved, and when the DeferredSave |
michael@0 | 104 | * begins writing the data to disk. Default 50 milliseconds. |
michael@0 | 105 | */ |
michael@0 | 106 | this.DeferredSave = function (aPath, aDataProvider, aDelay) { |
michael@0 | 107 | // Create a new logger (child of 'DeferredSave' logger) |
michael@0 | 108 | // for use by this particular instance of DeferredSave object |
michael@0 | 109 | let leafName = OS.Path.basename(aPath); |
michael@0 | 110 | let logger_id = DEFERREDSAVE_PARENT_LOGGER_ID + "." + leafName; |
michael@0 | 111 | this.logger = Log.repository.getLogger(logger_id); |
michael@0 | 112 | |
michael@0 | 113 | // @type {Deferred|null}, null when no data needs to be written |
michael@0 | 114 | // @resolves with the result of OS.File.writeAtomic when all writes complete |
michael@0 | 115 | // @rejects with the error from OS.File.writeAtomic if the write fails, |
michael@0 | 116 | // or with the error from aDataProvider() if that throws. |
michael@0 | 117 | this._pending = null; |
michael@0 | 118 | |
michael@0 | 119 | // @type {Promise}, completes when the in-progress write (if any) completes, |
michael@0 | 120 | // kept as a resolved promise at other times to simplify logic. |
michael@0 | 121 | // Because _deferredSave() always uses _writing.then() to execute |
michael@0 | 122 | // its next action, we don't need a special case for whether a write |
michael@0 | 123 | // is in progress - if the previous write is complete (and the _writing |
michael@0 | 124 | // promise is already resolved/rejected), _writing.then() starts |
michael@0 | 125 | // the next action immediately. |
michael@0 | 126 | // |
michael@0 | 127 | // @resolves with the result of OS.File.writeAtomic |
michael@0 | 128 | // @rejects with the error from OS.File.writeAtomic |
michael@0 | 129 | this._writing = Promise.resolve(0); |
michael@0 | 130 | |
michael@0 | 131 | // Are we currently waiting for a write to complete |
michael@0 | 132 | this.writeInProgress = false; |
michael@0 | 133 | |
michael@0 | 134 | this._path = aPath; |
michael@0 | 135 | this._dataProvider = aDataProvider; |
michael@0 | 136 | |
michael@0 | 137 | this._timer = null; |
michael@0 | 138 | |
michael@0 | 139 | // Some counters for telemetry |
michael@0 | 140 | // The total number of times the file was written |
michael@0 | 141 | this.totalSaves = 0; |
michael@0 | 142 | |
michael@0 | 143 | // The number of times the data became dirty while |
michael@0 | 144 | // another save was in progress |
michael@0 | 145 | this.overlappedSaves = 0; |
michael@0 | 146 | |
michael@0 | 147 | // Error returned by the most recent write (if any) |
michael@0 | 148 | this._lastError = null; |
michael@0 | 149 | |
michael@0 | 150 | if (aDelay && (aDelay > 0)) |
michael@0 | 151 | this._delay = aDelay; |
michael@0 | 152 | else |
michael@0 | 153 | this._delay = DEFAULT_SAVE_DELAY_MS; |
michael@0 | 154 | } |
michael@0 | 155 | |
michael@0 | 156 | this.DeferredSave.prototype = { |
michael@0 | 157 | get dirty() { |
michael@0 | 158 | return this._pending || this.writeInProgress; |
michael@0 | 159 | }, |
michael@0 | 160 | |
michael@0 | 161 | get lastError() { |
michael@0 | 162 | return this._lastError; |
michael@0 | 163 | }, |
michael@0 | 164 | |
michael@0 | 165 | // Start the pending timer if data is dirty |
michael@0 | 166 | _startTimer: function() { |
michael@0 | 167 | if (!this._pending) { |
michael@0 | 168 | return; |
michael@0 | 169 | } |
michael@0 | 170 | |
michael@0 | 171 | this.logger.debug("Starting timer"); |
michael@0 | 172 | if (!this._timer) |
michael@0 | 173 | this._timer = MakeTimer(); |
michael@0 | 174 | this._timer.initWithCallback(() => this._deferredSave(), |
michael@0 | 175 | this._delay, Ci.nsITimer.TYPE_ONE_SHOT); |
michael@0 | 176 | }, |
michael@0 | 177 | |
michael@0 | 178 | /** |
michael@0 | 179 | * Mark the current stored data dirty, and schedule a flush to disk |
michael@0 | 180 | * @return A Promise<integer> that will be resolved after the data is written to disk; |
michael@0 | 181 | * the promise is resolved with the number of bytes written. |
michael@0 | 182 | */ |
michael@0 | 183 | saveChanges: function() { |
michael@0 | 184 | this.logger.debug("Save changes"); |
michael@0 | 185 | if (!this._pending) { |
michael@0 | 186 | if (this.writeInProgress) { |
michael@0 | 187 | this.logger.debug("Data changed while write in progress"); |
michael@0 | 188 | this.overlappedSaves++; |
michael@0 | 189 | } |
michael@0 | 190 | this._pending = Promise.defer(); |
michael@0 | 191 | // Wait until the most recent write completes or fails (if it hasn't already) |
michael@0 | 192 | // and then restart our timer |
michael@0 | 193 | this._writing.then(count => this._startTimer(), error => this._startTimer()); |
michael@0 | 194 | } |
michael@0 | 195 | return this._pending.promise; |
michael@0 | 196 | }, |
michael@0 | 197 | |
michael@0 | 198 | _deferredSave: function() { |
michael@0 | 199 | let pending = this._pending; |
michael@0 | 200 | this._pending = null; |
michael@0 | 201 | let writing = this._writing; |
michael@0 | 202 | this._writing = pending.promise; |
michael@0 | 203 | |
michael@0 | 204 | // In either the success or the exception handling case, we don't need to handle |
michael@0 | 205 | // the error from _writing here; it's already being handled in another then() |
michael@0 | 206 | let toSave = null; |
michael@0 | 207 | try { |
michael@0 | 208 | toSave = this._dataProvider(); |
michael@0 | 209 | } |
michael@0 | 210 | catch(e) { |
michael@0 | 211 | this.logger.error("Deferred save dataProvider failed", e); |
michael@0 | 212 | writing.then(null, error => {}) |
michael@0 | 213 | .then(count => { |
michael@0 | 214 | pending.reject(e); |
michael@0 | 215 | }); |
michael@0 | 216 | return; |
michael@0 | 217 | } |
michael@0 | 218 | |
michael@0 | 219 | writing.then(null, error => {return 0;}) |
michael@0 | 220 | .then(count => { |
michael@0 | 221 | this.logger.debug("Starting write"); |
michael@0 | 222 | this.totalSaves++; |
michael@0 | 223 | this.writeInProgress = true; |
michael@0 | 224 | |
michael@0 | 225 | OS.File.writeAtomic(this._path, toSave, {tmpPath: this._path + ".tmp"}) |
michael@0 | 226 | .then( |
michael@0 | 227 | result => { |
michael@0 | 228 | this._lastError = null; |
michael@0 | 229 | this.writeInProgress = false; |
michael@0 | 230 | this.logger.debug("Write succeeded"); |
michael@0 | 231 | pending.resolve(result); |
michael@0 | 232 | }, |
michael@0 | 233 | error => { |
michael@0 | 234 | this._lastError = error; |
michael@0 | 235 | this.writeInProgress = false; |
michael@0 | 236 | this.logger.warn("Write failed", error); |
michael@0 | 237 | pending.reject(error); |
michael@0 | 238 | }); |
michael@0 | 239 | }); |
michael@0 | 240 | }, |
michael@0 | 241 | |
michael@0 | 242 | /** |
michael@0 | 243 | * Immediately save the dirty data to disk, skipping |
michael@0 | 244 | * the delay of normal operation. Note that the write |
michael@0 | 245 | * still happens asynchronously in the worker |
michael@0 | 246 | * thread from OS.File. |
michael@0 | 247 | * |
michael@0 | 248 | * There are four possible situations: |
michael@0 | 249 | * 1) Nothing to flush |
michael@0 | 250 | * 2) Data is not currently being written, in-memory copy is dirty |
michael@0 | 251 | * 3) Data is currently being written, in-memory copy is clean |
michael@0 | 252 | * 4) Data is being written and in-memory copy is dirty |
michael@0 | 253 | * |
michael@0 | 254 | * @return Promise<integer> that will resolve when all in-memory data |
michael@0 | 255 | * has finished being flushed, returning the number of bytes |
michael@0 | 256 | * written. If all in-memory data is clean, completes with the |
michael@0 | 257 | * result of the most recent write. |
michael@0 | 258 | */ |
michael@0 | 259 | flush: function() { |
michael@0 | 260 | // If we have pending changes, cancel our timer and set up the write |
michael@0 | 261 | // immediately (_deferredSave queues the write for after the most |
michael@0 | 262 | // recent write completes, if it hasn't already) |
michael@0 | 263 | if (this._pending) { |
michael@0 | 264 | this.logger.debug("Flush called while data is dirty"); |
michael@0 | 265 | if (this._timer) { |
michael@0 | 266 | this._timer.cancel(); |
michael@0 | 267 | this._timer = null; |
michael@0 | 268 | } |
michael@0 | 269 | this._deferredSave(); |
michael@0 | 270 | } |
michael@0 | 271 | |
michael@0 | 272 | return this._writing; |
michael@0 | 273 | } |
michael@0 | 274 | }; |