Ticket Created
over 3 years ago

WERETECH-12052

Conflict/race between makeWebRequest and Storage.setValue called from onUpdate on a watchface.

Hi, I was able to reproduce the following problem (both in simulator and in a Descent MK1 using SDK 3.2.5 and 4.0.6):

If the function setValue is called from onUpdate while makeWebRequest is still waiting for the webserver to return data,

the callback function is "lost" (and not called).

The following code reproduce the problem 100% of the time.



using Toybox.Application;
using Toybox.Background;
using Toybox.System;
using Toybox.WatchUi;
using Toybox.Time;
using Toybox.Communications;
using Toybox.Application.Storage;

(:background)
class PiServiceDelegate extends Toybox.System.ServiceDelegate {
  function initialize() {
    System.ServiceDelegate.initialize();
  }
  function onTemporalEvent() {
    // That URI takes about 3 seconds to answer
    var uri = "https://wb.elaine.fi/pi_slow";
    System.println("Before query");
    var options = {
      :methods => Communications.HTTP_REQUEST_METHOD_GET,
      :responseType => Communications.HTTP_RESPONSE_CONTENT_TYPE_JSON
    };
    Communications.makeWebRequest(uri, null, options,
                                  method(:pi_received));
  }
  function pi_received(code, data) {
    System.println(code);
    System.println(data);
    if (code == 200) {
      Background.exit(data);
    }
  }
}

(:background)
class PiWatch extends Application.AppBase {
  public function initialize() {
    AppBase.initialize();
  }
  function onBackgroundData(data) {
    System.println("onBackgroundData: " + data);
  }
  function getServiceDelegate() {
    return [new PiServiceDelegate()];
  }
  function getInitialView() {
    Background.registerForTemporalEvent(new Time.Duration(5 * 60));
    return [new PiWatchView(), new PiWatchDelegate()];
  }
}

class PiWatchView extends WatchUi.WatchFace {
  public function initialize() {
    WatchFace.initialize();
  }
  public function onUpdate(dc) {
    System.println("onUpdate");
    // On simulator, onUpdate is ran every seconds
    // So we will call Storage.setValue between the http request
    // and the result
    // On watch same problem exists
    Storage.setValue("foo", "bar");
    // Note that problem does not exists if Storage.setValue
    // is called in onPartialUpdate
  }
}

class PiWatchDelegate extends WatchUi.WatchFaceDelegate {
  public function initialize() {
    WatchFaceDelegate.initialize();
  }
}


Here is the output:


onUpdate
onUpdate
onUpdate
Background: Before query
onUpdate
onUpdate
onUpdate
Error: Symbol Not Found Error
Details: Failed invoking <symbol>
Stack: 
onUpdate
onUpdate
onUpdate



If I comment the setValue line, I get the expected result:

onUpdate
onUpdate
onUpdate
onUpdate
Background: Before query
onUpdate
onUpdate
onUpdate
Background: 200
Background: {pi=>3.140000}
onBackgroundData: {pi=>3.140000}
onUpdate
onUpdate
onUpdate
jeansch
Parents
  • over 3 years ago in reply to jeansch

    There are two things going on here.  Starting with onPartialUpdate.  It's the only way that the watch face delegate/onPowerBudgetExceeped is called.

    It occurs when the average time (over the span of 1 minute) used in onPartialUpdate exceeds 30ms.  You can see what's going on in the sim with "view watch face diagnostics" when you are running a watch face in low power mode.  Once the power budget is exceeped, onPartialUpdate is no longer called until you restart the watch face.

    There are a number of things that can cause this, including running long complex code, having too large a clip region on the display, or using the file system for things like loadResource, setValue, etc.

    The other thing here seems to be in onUpdate, where there may be a conflict between onUpdate and doing a makeWebRequest in a background service, when doing a setValue in onUpdate. 

    onPartialUpdate has no impact on the background service, and the background has no impact on onPartialUpdate.  Two different issues.  When you see the budget exceeded (675 in this case, it's do to running 20 times longer than allowed, and is due to the for loop of 6000 times.  Not only do you exceed the power budget. but that's where you could risk causing the watchdog timer to trip if the loop was longer or more complex.

    The first thing to do in in onPartialUpdate(), as the first line, do return;  That's taking onPartialUpdate out of the picture all together.  Other than maybe "stuck seconds" on your watchface. it should run and look fine. (or just comment out the entire onPartialUpdate() function)

Comment
  • over 3 years ago in reply to jeansch

    There are two things going on here.  Starting with onPartialUpdate.  It's the only way that the watch face delegate/onPowerBudgetExceeped is called.

    It occurs when the average time (over the span of 1 minute) used in onPartialUpdate exceeds 30ms.  You can see what's going on in the sim with "view watch face diagnostics" when you are running a watch face in low power mode.  Once the power budget is exceeped, onPartialUpdate is no longer called until you restart the watch face.

    There are a number of things that can cause this, including running long complex code, having too large a clip region on the display, or using the file system for things like loadResource, setValue, etc.

    The other thing here seems to be in onUpdate, where there may be a conflict between onUpdate and doing a makeWebRequest in a background service, when doing a setValue in onUpdate. 

    onPartialUpdate has no impact on the background service, and the background has no impact on onPartialUpdate.  Two different issues.  When you see the budget exceeded (675 in this case, it's do to running 20 times longer than allowed, and is due to the for loop of 6000 times.  Not only do you exceed the power budget. but that's where you could risk causing the watchdog timer to trip if the loop was longer or more complex.

    The first thing to do in in onPartialUpdate(), as the first line, do return;  That's taking onPartialUpdate out of the picture all together.  Other than maybe "stuck seconds" on your watchface. it should run and look fine. (or just comment out the entire onPartialUpdate() function)

Children
  • over 3 years ago in reply to _psx_

    The order that these calls happen can vary, and it's something you need to account for in your code.  onAppUpdate/onAppInstall will happen before getInitialView, and even if you don't override them, getserviceDelate will be called.  And then there's the thing in your appBase (initialize(), onStart. onStop, etc,) that are called when the main app or the background service runs.

  • over 3 years ago in reply to jim_m_58

    I've observed how background run and it was very strange, ones starts and exit for nothing, completely understandable Slight smile

    But it should be call getServiceDelegate first to obtain object that processes flow. So if getInitialView is before getServiceDelegate there will be problem to run BAG.

  • over 3 years ago in reply to _psx_

    When something starts, the background can run a couple times before getInitalView.  For onAppInstall and onAppUpdate.  This isn't a bug.  It's the way it works.  The temporal event can also run before onInitialView, as can onBackground data.  Again, that's the way it works.

    If the background has run since the last time the full app runs, that's a case where onBackground data can run before the view is created.

  • over 3 years ago in reply to jim_m_58

    I think the problem is to early calling BAG/webREQ I haven't tested if getServiceDelegate is called before getInitialView) - It's known bug (in widget somebody had similar problem). I'm just curious where the bug is and first try lo localise it.