User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.0.5) Gecko/2008120122 Firefox/3.0.5 (.NET CLR 3.5.30729) Build Identifier: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.0.5) Gecko/2008120122 Firefox/3.0.5 (.NET CLR 3.5.30729) I've added various useful logs for nsExtensionManager.js, which makes debugging the process of updating an extension much easier. I want to suggest to add them to the build. The enhancements include: 1. Time stamps for logs. 2. Option to filter logs to show only specific addons. 3. More logs. 4. Logging of strings of numeric constants. Please contact me so I can send you the source code. Reproducible: Always

Please attach the patch to this bug using the "Add an attachment" link.

I think that if we want to go further into logging for the extension manager then we'd want bug 451283 fixed and use that framework.

The changes are: 1) new preference "extensions.logging.filter" , which allow user to log only certain addons. This is used by new function LOG_EX 2) added time stamp in function LOG 3) added description to status numeric values: gStatusDescriptions 4) added details for errors in "onXMLLoad" 5) new function "logNextUpdateTime" which logs the next expected time for update check

Please attach patches as diffs to the original source (diff against the trunk version rather than the version you find in the binary) https://developer.mozilla.org/en/Creating_a_patch

__ Note regarding new function "logNextUpdateTime" __ When reviewing\checking these changes, I would like to ask you to see the values logged by "logNextUpdateTime". This was a major issue by the QA where I employed. They have asked me to predict when will be the next "automatic update check", so they can check in the web server logs or via "Fiddler". Otherwise they waited and waited and nothing happened. I've tried to calculate it in "logNextUpdateTime", but the expected results are not the actual results. I came out to the conclusion that the next check time depends not only on "extensions.update.interval", but is correlated also with value of "app.update.timer". I've tried to find out the exact correlation, and I thought I had it, but then I've picked up various pairs of _different_ _prime_ numbers as values, and the results were always different. I wish someone could refer to this issue. 10x for your help.

(In reply to comment #6) > __ Note regarding new function "logNextUpdateTime" __ > > When reviewing\checking these changes, I would like to ask you to see the > values logged by "logNextUpdateTime". > > This was a major issue by the QA where I employed. > They have asked me to predict when will be the next "automatic update check", > so they can check in the web server logs or via "Fiddler". > Otherwise they waited and waited and nothing happened. > > I've tried to calculate it in "logNextUpdateTime", but the expected results are > not the actual results. > I came out to the conclusion that the next check time depends not only on > "extensions.update.interval", but is correlated also with value of > "app.update.timer". > I've tried to find out the exact correlation, and I thought I had it, > but then I've picked up various pairs of _different_ _prime_ numbers as values, > and the results were always different. > I wish someone could refer to this issue. This would be better discussed in the newsgroups but essentially the application checks to see if any operation waiting to perform evert app.update.timer milliseconds. There is also some randomness thrown in to ensure that not every operation (blocklist check, app update check, add-on update check) runs at the same time.

(In reply to comment #7) Do u suggest I open this issue as a separate bug ? In which newsgroup in can be discussed ? I've added a sample log. This is a log for the following values: extensions.update.interval - 7 minutes app.update.timer - 5 minutes As you can see in the log results, These are intervals of update checks: 5,14,10,10 minutes. Is it possible at all to predict time of next update check (to a reasonable time span) ? This the logs results (omitted some stuff): =============================================== *** 2009-02-05 10:54:03 - EM _startTimers - interval of 'extensions.update.interval' is: 420 seconds (7 minutes) *** 2009-02-05 10:54:03 - EM _startTimers - Note that 'extensions.update.interval' is correlated with 'app.update.timer' which is: 300 seconds (5 minutes) *** 2009-02-05 10:54:04 - Next expected update check: 2009-02-05 11:01:04 *** 2009-02-05 10:58:59 - Datasource: Update Started *** 2009-02-05 10:59:00 - Datasource: Update Ended *** 2009-02-05 10:59:00 - Next expected update check: 2009-02-05 11:06:00 *** 2009-02-05 11:14:00 - Datasource: Update Started *** 2009-02-05 11:14:01 - Datasource: Update Ended *** 2009-02-05 11:14:01 - Next expected update check: 2009-02-05 11:21:01 *** 2009-02-05 11:23:59 - Datasource: Update Started *** 2009-02-05 11:24:01 - Datasource: Update Ended *** 2009-02-05 11:24:01 - Next expected update check: 2009-02-05 11:31:01 *** 2009-02-05 11:33:59 - Datasource: Update Started *** 2009-02-05 11:34:01 - Datasource: Update Ended *** 2009-02-05 11:34:01 - Next expected update check: 2009-02-05 11:41:01

(In reply to comment #8) > (In reply to comment #7) > > Do u suggest I open this issue as a separate bug ? If there is actually a bug, but it doesn't seem that there is. Being unable to predict exactly when an update check will occur is not a bug (at least not something that is going to change). > In which newsgroup in can be discussed ? mozilla.dev.extensions is probably appropriate.

Currently I wouldn't want to take the patch as it stands. It does add some useful information to the log however I don't really want to do this until without a more sensible logging framework in place (bug 451283). At that time we'd probably use that framework to log much of what you have here, but I'd also want to see even more logging points added. I'm going to dupe this to the general bug looking for improving logging in the EM.

(In reply to comment #9) > "Being unable to predict exactly when an update check will occur is not a bug > (at least not something that is going to change)." When one sets the value of "extensions.update.interval" to 7 minutes, and the updates happens after 5,14,10,10 minutes etc. (didnt check more intervals later), then something happens not like the user expected. I agree with you, that most users dont even know I about it, and that even most extensions programmers dont test it. However, "our" QA did try to test it, without success, and that's why they have asked me to investigate it, which led to the mentioned above results. You must agree that you wouldn't accept such behavior from Win32 "SetTimer". There might others which encounter it, and just dont have the time or the knowledge to check it, or it might happens with other "intervals"\"timers" used by FF. I hope this issue will be addressed. I'm a "Leave no stone unturned" guy. If I can be of help in checking\testing extensions for this purpose, I will be glad to. 10x for your help.

(In reply to comment #11) > (In reply to comment #9) > > > "Being unable to predict exactly when an update check will occur is not a bug > > (at least not something that is going to change)." > > When one sets the value of "extensions.update.interval" to 7 minutes, > and the updates happens after 5,14,10,10 minutes etc. (didnt check more > intervals later), then something happens not like the user expected. > I agree with you, that most users dont even know I about it, > and that even most extensions programmers dont test it. > However, "our" QA did try to test it, without success, and that's why they have > asked me to investigate it, which led to the mentioned above results. Preferences aren't meant to be altered directly by users in general. And just because altering a hidden pref doesn't have the exact effect the user expected does not mean there is a bug. Many prefs have constraints on them which mean they do not work above or below certain values. > You must agree that you wouldn't accept such behavior from Win32 "SetTimer". No because SetTimer is presumably about giving a guaranteed delay (I am not a windows programmer), the update interval is not and never was. Update checks do not need to be performed at precise times, in fact we avoid that to stop the update servers getting overloaded. > There might others which encounter it, and just dont have the time or the > knowledge to check it, or it might happens with other "intervals"\"timers" used > by FF. This question has been raised multiple times yes, in fact we have it documented somewhere. Perhaps it would be worth adding an entry to MDC about it. > I hope this issue will be addressed. I'm a "Leave no stone unturned" guy. > If I can be of help in checking\testing extensions for this purpose, I will be > glad to. If you are asking for a code change so extensions.update.interval will define the exact time between update checks then no, I see no reason to make this change. There are benefits to the intervals being semi-random and I don't see anywhere you've given a benefit for it being non-random. It is also possible to manage this yourselves by setting app.update.timer as I think you have found, of course you have to be aware of the impact there for all the timers that it controls.