cordova-plugin-meteor-webapp

cordova-plugin-meteor-webapp copied to clipboard

Around 5% of the time (over 120 tests), HCP fails on Android with the below message. When I restart the app, the old version loads, and then it refreshes to the new version.

Versions: 1.6.0 (without the reattempt) and 1.6.3

=> Client modified -- refreshing (x32)I20190113-01:37:07.721(1)? W/MeteorWebApp(30776): Download failure
I20190113-01:37:07.721(1)? W/MeteorWebApp(30776): com.meteor.webapp.WebAppException: Error parsing asset manifest
I20190113-01:37:07.721(1)? W/MeteorWebApp(30776):       at com.meteor.webapp.AssetManifest.<init>(AssetManifest.java:80)
I20190113-01:37:07.721(1)? W/MeteorWebApp(30776):       at com.meteor.webapp.AssetBundleManager$1.onResponse(AssetBundleManager.java:112)
I20190113-01:37:07.722(1)? W/MeteorWebApp(30776):       at okhttp3.RealCall$AsyncCall.execute(RealCall.java:153)
I20190113-01:37:07.722(1)? W/MeteorWebApp(30776):       at okhttp3.internal.NamedRunnable.run(NamedRunnable.java:32)
I20190113-01:37:07.722(1)? W/MeteorWebApp(30776):       at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)
I20190113-01:37:07.722(1)? W/MeteorWebApp(30776):       at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
I20190113-01:37:07.722(1)? W/MeteorWebApp(30776):       at java.lang.Thread.run(Thread.java:818)
I20190113-01:37:07.722(1)? W/MeteorWebApp(30776): Caused by: org.json.JSONException: Value <!DOCTYPE of type java.lang.String cannot be converted to JSONObject
I20190113-01:37:07.722(1)? W/MeteorWebApp(30776):       at org.json.JSON.typeMismatch(JSON.java:111)
I20190113-01:37:07.722(1)? W/MeteorWebApp(30776):       at org.json.JSONObject.<init>(JSONObject.java:160)
I20190113-01:37:07.723(1)? W/MeteorWebApp(30776):       at org.json.JSONObject.<init>(JSONObject.java:173)
I20190113-01:37:07.723(1)? W/MeteorWebApp(30776):       at com.meteor.webapp.AssetManifest.<init>(AssetManifest.java:39)
I20190113-01:37:07.723(1)? W/MeteorWebApp(30776):       ... 6 more
I20190113-01:37:07.723(1)? E/MeteorWebApp(30776): Download failure
I20190113-01:37:07.723(1)? E/MeteorWebApp(30776): com.meteor.webapp.WebAppException: Error parsing asset manifest
I20190113-01:37:07.723(1)? E/MeteorWebApp(30776):       at com.meteor.webapp.AssetManifest.<init>(AssetManifest.java:80)
I20190113-01:37:07.724(1)? E/MeteorWebApp(30776):       at com.meteor.webapp.AssetBundleManager$1.onResponse(AssetBundleManager.java:112)
I20190113-01:37:07.724(1)? E/MeteorWebApp(30776):       at okhttp3.RealCall$AsyncCall.execute(RealCall.java:153)
I20190113-01:37:07.725(1)? E/MeteorWebApp(30776):       at okhttp3.internal.NamedRunnable.run(NamedRunnable.java:32)
I20190113-01:37:07.725(1)? E/MeteorWebApp(30776):       at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)
I20190113-01:37:07.725(1)? E/MeteorWebApp(30776):       at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
I20190113-01:37:07.725(1)? E/MeteorWebApp(30776):       at java.lang.Thread.run(Thread.java:818)
I20190113-01:37:07.725(1)? E/MeteorWebApp(30776): Caused by: org.json.JSONException: Value <!DOCTYPE of type java.lang.String cannot be converted to JSONObject
I20190113-01:37:07.725(1)? E/MeteorWebApp(30776):       at org.json.JSON.typeMismatch(JSON.java:111)
I20190113-01:37:07.725(1)? E/MeteorWebApp(30776):       at org.json.JSONObject.<init>(JSONObject.java:160)
I20190113-01:37:07.725(1)? E/MeteorWebApp(30776):       at org.json.JSONObject.<init>(JSONObject.java:173)
I20190113-01:37:07.725(1)? E/MeteorWebApp(30776):       at com.meteor.webapp.AssetManifest.<init>(AssetManifest.java:39)
I20190113-01:37:07.725(1)? E/MeteorWebApp(30776):       ... 6 more
I20190113-01:37:07.728(1) (android:http://localhost:12640/__cordova/packages/webapp.js:37) Error: Error parsing asset manifest

The Android HCP issues in meteor 1.7.0.3 through to 1.8.1-beta.13 are causing us severe issues. We have over 70K users and we're getting negative reviews in the Google Play store because of the large and consistent number of failures.

There's a chance that meteor update --release 1.8.1-beta.15 will fix this, though I can't say for sure because I haven't been able to reproduce this myself.

I still see the behavior in beta 15 after enough client bundle refreshes. Repro:

meteor create hcp --release 1.8.1-beta.13
cd hcp
meteor add-platform android
meteor run android-device --mobile-server="http://wifi-ip:3000"

1. wait for app to load
2. edit client/main.html
3. wait for app to either reload or throw above error
4. repeat steps 2 & 3 until reproduced (probably <20x)

@lorensr Do I understand you correctly that you still have this in beta-15 ? (your repro states 13) At the moment it seems beta.15 solves a lot of the HCP issues but I haven't come across this one yet but I would definitely try to reproduce by running many times.
Does a restart of the app help once reproduced or does is 'Brick' the app?

Do I understand you correctly that you still have this in beta-15 ?

Yes

Does a restart of the app help once reproduced or does is 'Brick' the app?

Restart helps (behavior in OP)

So it looks like this line is failing because the string is HTML starting with <!DOCTYPE… rather than JSON, which suggests that the web server is sometimes not ready to serve the manifest, and instead defaults to serving an HTML response instead.

I'm now getting a flavor of this on 1.8.0, though I haven't updated the plugin beyond the 1.6.2 with the iOS fix.

04-04 13:09:17.209 26175 26273 D MeteorWebApp: Downloaded asset manifest for version: a78a0c6399a158c9e9fe5fdc86e37058b9d0b42d

04-04 13:09:17.210 26175 26273 E MeteorWebApp: Download failure

04-04 13:09:17.210 26175 26273 E MeteorWebApp: com.meteor.webapp.WebAppException: Skipping downloading blacklisted version: a78a0c6399a158c9e9fe5fdc86e37058b9d0b42d

04-04 13:09:17.210 26175 26273 E MeteorWebApp: 	at com.meteor.webapp.WebAppLocalServer.shouldDownloadBundleForManifest(WebAppLocalServer.java:363)

Testing on two different phones:

1. phone A was at v138 of the app, failing to get v139. Phone B on v139.
2. I pushed v140 to galaxy.
3. Phone A went to v139 (not v140), but after restart and the above log error, went back to v138. Phone B briefly went backwards from v139 to v138, then updated to v140.

I only see one place in the java code where it blacklists a version, WebAppLocalServer.java lines 327-329,

    private void revertToLastKnownGoodVersion() {
        // Blacklist the current version, so we don't update to it again right away
        configuration.addBlacklistedVersion(currentAssetBundle.getVersion());

and that's due to a timeout issue, as shown by the call to revertToLastKnownGoodVersion() in WebAppLocalServer.java lines 197-208. But there's no mention in the log of the timeout, though this code looks like there should be a log line about it.

    private void startStartupTimer() {
        removeStartupTimer();


        startupTimer = new Timer();
        startupTimer.schedule(new TimerTask() {
            @Override
            public void run() {
                Log.w(LOG_TAG, "App startup timed out, reverting to last known good version");
                revertToLastKnownGoodVersion();
            }
        }, startupTimeout);
    }