1395223 - [Shield] Firefox fetches recipes and actions 2nd time in the same session 500s after startup (devmode on)

Status: RESOLVED INVALID

(Shield :: General, defect)

Description

[Adrian Florinescu [:aflorinescu]]

[Environment:]
Windows 10 x64 
56.0b7 20170828185355
extensions.shield-recipe-client.dev_mode - true



[Pre-conditions:]
You need access to Admin interface (for this Test Suite, https://normandy-admin.stage.mozaws.net/control
1. Obtain a copy of Firefox with the SHIELD recipe client system add-on installed. You can check about:support to ensure that you have it.
2. Set the extensions.shield-recipe-client.dev_mode preference to true to run recipes immediately on startup.
3. Set the extensions.shield-recipe-client.logging.level preference to 0 to enable more logging.
4. Set the security.content.signature.root_hash preference to DB:74:CE:58:E4:F9:D0:9E:E0:42:36:BE:6C:C5:C4:F6:6A:E7:74:7D:C0:21:42:7A:03:BC:2F:57:0C:8B:9B:90
5. Set the preference value for extensions.shield-recipe-client.api_url set to https://normandy.stage.mozaws.net/api/v1

[Steps:]
1. Open FF & browser console.
2. Wait 10 minutes.

[Actual Result:]
The fetch will run two times.


1504106356923    extensions.shield-recipe-client.normandy-api    DEBUG    Fetched 2 recipe from the server:: testqaa3, test recipe
1504106357402    extensions.shield-recipe-client.normandy-api    DEBUG    Fetched 4 action from the server:: show-heartbeat, preference-experiment, console-log, opt-out-study

 
1504106625521    extensions.shield-recipe-client.normandy-api    DEBUG    Fetched 2 recipe from the server:: testqaa3, test recipe
1504106625771    extensions.shield-recipe-client.normandy-api    DEBUG    Fetched 4 action from the server:: show-heartbeat, preference-experiment, console-log, opt-out-study


(1504106356923 - August 30, 2017 6:19:16.923 PM
(1504106625521  - August 30, 2017 6:23:45.521 PM 



[Note:] AFAIK for now, this is only reproducible with devmode on, so minor severity.

Comment 1

[Osmose [:osmose, :mkelly]]

Did we confirm that this is reproducible multiple times? Logically, this can happen when the update timer happens soon after startup with dev_mode on, but after the update timer runs, it shouldn't be reproducible for another 24 hours.

If this happens more than once in a row on the same profile then this bug may be different than what I think it is.

Comment 2

[Adrian Florinescu [:aflorinescu]]

(In reply to Michael Kelly [:mkelly,:Osmose] from comment #1)
> Did we confirm that this is reproducible multiple times? Logically, this can
> happen when the update timer happens soon after startup with dev_mode on,
> but after the update timer runs, it shouldn't be reproducible for another 24
> hours.
> 
> If this happens more than once in a row on the same profile then this bug
> may be different than what I think it is.

I only caught this during testing with devmode on. With devmode off and timer set to default 300, I didn't see the double execution. Given the fact that the difference between the example runs in comment 0 is roughly 5 minutes, I tend to agree with your assumption. 

I'll leave the NI flag on me and investigate a bit more.

Comment 3

[Adrian Florinescu [:aflorinescu]]

From my point of view, since this seems not to affect Shield behavior under normal functionality circumstances (devmode off), I would suggest a won't fix. 
:mythmon, do you think is there any value to follow this issue further?

Comment 4

[Michael Cooper [:mythmon]]

I think the explanation :Osmose gave in comment 1 is correct. This is likely an interaction between dev_mode (which always runs eagerly as soon as possible at startup) and our normal timers (which also run in dev_mode). I don't think this is a bug.