[Android] Stuck on CHECKING_FOR_UPDATE

[microsoft]

[Android] Stuck on CHECKING_FOR_UPDATE

[geof90]

@dylanvdmerwe Thanks for reporting! To help us diagnose this issue, do you see any error being printed out in the console logs after the update is instaled? e.g. https://github.com/Microsoft/cordova-plugin-code-push/blob/master/www/codePush.ts#L286

[dylanvdmerwe]

Everything seemed to run perfectly. Even when the app is restarted, the new version runs as intended but nothing happens when the sync method tries to check for an update.

DEVICE READY FIRED AFTER 2180 ms
Checking for update.
Failed to load resource: net::ERR_FILE_NOT_FOUND
[CodePush] An update is available. {"appVersion":"1.0.0","deploymentKey":"","description":"","downloadUrl":"","isMandatory":false,"label":"v3","packageHash":"628ebf1f52c080abf3365a9aadfc5699c1df012b827df4bfbf3842b129aac258","packageSize":2871922,"failedInstall":false}

Downloading package.
[CodePush] Downloading update package ...
Downloading 7756 of 2871922 bytes.
Downloading 15948 of 2871922 bytes.
...

[CodePush] Package download success: {"deploymentKey":"","description":"","label":"v3","appVersion":"1.0.0","isMandatory":false,"packageHash":"628ebf1f52c080abf3365a9aadfc5699c1df012b827df4bfbf3842b129aac258","isFirstRun":false,"failedInstall":false,"localPath":"cdvfile://localhost/files/codepush/download/update.zip"}
Installing update
[CodePush] Installing update package ...
[CodePush] First update: back up package information skipped.
[CodePush] Install succeeded.
The update was installed successfully.

[geof90]

@dylanvdmerwe The logs you just pasted was before the update was installed right? Do you see any logs after the update is installed and the app is restarted?

[dylanvdmerwe]

Near the bottom of the logs it states that it is installing the update and the install succeeded? Nothing else is shown from the logs.

[geof90]

@dylanvdmerwe So I assume after all this is printed, the app then restarts by itself (since you are using InstallMode.IMMEDIATE), perfect, right? From what I understand from your problem description, you are seeing the sync process get stuck after the app restarts. Do you see anything in the logs after the app restarts?

[geof90]

Or rather, how did you know/diagnose that it got stuck?

[dylanvdmerwe]

After the restart:

DEVICE READY FIRED AFTER 2334 ms
Checking for update.

The syncStatusCallback method fires once for CHECKING_FOR_UPDATE and then never fires again. There are no network requests being made either.

[geof90]

@dylanvdmerwe how did you release updates to CodePush? Did u use code-push release-cordova, or just code-push release? If it is the later, which "www" folder did u release?

[dylanvdmerwe]

code-push release-cordova <appName> android

and

code-push release <appName> ./platforms/android/assets/www 1.0.0

Both give me the same thing.

[geof90]

Its weird that you are not seeing any network request being fired, and there's nothing in the console notifying you that the request was somehow blocked or something. I did a test and I am definitely seeing it working with a blank app, I can release multiple updates and the app always successfully update from one version to another. The only thing I can think of is some conflict with another of your installed plugins? I will try to investigate further tomorrow. Sorry that you are hitting this issue!

[lostintangent]

@dylanvdmerwe Are you testing on an emulator or a device? And how are you deploying the app? I noticed you're using Ionic. Are you just running "ionic run android"? Are you using live reload? It would be helpful to repro this to know you're exact setup.

[dylanvdmerwe]

It's on a device. Deploying the app using ionic run android command. No live reload.

I'm going to try grab one of their more 'complicated' sample projects and see if I can reproduce the issue.

[lostintangent]

What version of Android is your device?

[dylanvdmerwe]

Nexus 5 running Android 6.0.1 targeting API 22

[dylanvdmerwe]

Note, the same code works on iOS.

[dylanvdmerwe]

Some more information from logs...

03-31 10:56:35.983 13786-13878/com.dariel.graduate E/AndroidProtocolHandler: Unable to open asset URL: file:///android_asset/www/undefined
03-31 10:56:36.271 13786-13918/com.dariel.graduate W/PluginManager: THREAD WARNING: exec() call to CodePush.updateSuccess blocked the main thread for 26ms. Plugin should use CordovaInterface.getThreadPool().
03-31 10:56:36.274 13786-13786/com.dariel.graduate I/chromium: [INFO:CONSOLE(67883)] "Checking for update.", source: file:///android_asset/www/build/js/app.bundle.js (67883)
03-31 10:56:36.348 13786-13919/com.dariel.graduate W/AssetFilesystem: Asset manifest not found. Recursive copies and directory listing will be slow.
03-31 10:56:36.441 13786-13786/com.dariel.graduate I/chromium: [INFO:CONSOLE(37)] "[CodePush] Checking for update.", source: file:///android_asset/www/plugins/cordova-plugin-code-push/bin/www/codePushUtil.js (37)
03-31 10:56:39.101 13786-13786/com.dariel.graduate I/chromium: [INFO:CONSOLE(37)] "[CodePush] An update is available. {"appVersion":"1.0.0","deploymentKey":"...","description":"","downloadUrl":"https://codepush.blob.core.windows.net/storagev2/...","isMandatory":false,"label":"v3","packageHash":"214d1382cdc568e9c98752ff9bd54ee24732f94bedaca1fe9413e4c25d98898c","packageSize":2873121,"failedInstall":false}", source: file:///android_asset/www/plugins/cordova-plugin-code-push/bin/www/codePushUtil.js (37)
03-31 10:56:39.105 13786-13786/com.dariel.graduate I/chromium: [INFO:CONSOLE(67890)] "Downloading package.", source: file:///android_asset/www/build/js/app.bundle.js (67890)
03-31 10:56:39.113 13786-13786/com.dariel.graduate I/chromium: [INFO:CONSOLE(37)] "[CodePush] Downloading update", source: file:///android_asset/www/plugins/cordova-plugin-code-push/bin/www/codePushUtil.js (37)
03-31 10:56:39.119 13786-13918/com.dariel.graduate D/FileTransfer: download https://codepush.blob.core.windows.net/storagev2/Tl... to file:///data/user/0/com.dariel.graduate/files/codepush/download/update.zip
03-31 10:56:39.125 13786-13919/com.dariel.graduate D/FileTransfer: Download file:https://codepush.blob.core.windows.net/storagev2/T...
03-31 10:56:41.635 13786-13786/com.dariel.graduate E/chromium: [ERROR:xwalk_autofill_client.cc(172)] Not implemented reached in virtual void xwalk::XWalkAutofillClient::OnFirstUserGestureObserved()
03-31 10:56:41.661 13786-13786/com.dariel.graduate E/chromium: [ERROR:xwalk_autofill_client.cc(172)] Not implemented reached in virtual void xwalk::XWalkAutofillClient::OnFirstUserGestureObserved()
03-31 10:56:42.828 13786-13786/com.dariel.graduate I/chromium: [INFO:CONSOLE(67856)] "Downloading 7756 of 2873121 bytes.", source: file:///android_asset/www/build/js/app.bundle.js (67856)
...


03-31 10:56:50.055 13786-13919/com.dariel.graduate D/FileTransfer: Saved file: file:///data/user/0/com.dariel.graduate/files/codepush/download/update.zip
03-31 10:56:50.105 13786-13786/com.dariel.graduate I/chromium: [INFO:CONSOLE(37)] "[CodePush] Package download success: {"deploymentKey":"..","description":"","label":"v3","appVersion":"1.0.0","isMandatory":false,"packageHash":"214d1382cdc568e9c98752ff9bd54ee24732f94bedaca1fe9413e4c25d98898c","isFirstRun":false,"failedInstall":false,"localPath":"cdvfile://localhost/files/codepush/download/update.zip"}", source: file:///android_asset/www/plugins/cordova-plugin-code-push/bin/www/codePushUtil.js (37)
03-31 10:56:50.105 13786-13786/com.dariel.graduate I/chromium: [INFO:CONSOLE(67894)] "Installing update", source: file:///android_asset/www/build/js/app.bundle.js (67894)
03-31 10:56:50.108 13786-13786/com.dariel.graduate I/chromium: [INFO:CONSOLE(37)] "[CodePush] Installing update", source: file:///android_asset/www/plugins/cordova-plugin-code-push/bin/www/codePushUtil.js (37)
03-31 10:56:50.159 13786-13919/com.dariel.graduate W/Zip: extracting: /data/user/0/com.dariel.graduate/files/codepush/download/unzipped/www/cordova.js
...

03-31 10:56:51.374 13786-13786/com.dariel.graduate I/chromium: [INFO:CONSOLE(37)] "[CodePush] First update: back up package information skipped. ", source: file:///android_asset/www/plugins/cordova-plugin-code-push/bin/www/codePushUtil.js (37)
03-31 10:56:51.426 13786-13919/com.dariel.graduate D/TEST: cdvfile://localhost/files/codepush/currentPackage.json: 390
03-31 10:56:51.441 13786-13786/com.dariel.graduate I/chromium: [INFO:CONSOLE(37)] "[CodePush] Install succeeded.", source: file:///android_asset/www/plugins/cordova-plugin-code-push/bin/www/codePushUtil.js (37)
03-31 10:56:51.441 13786-13786/com.dariel.graduate I/chromium: [INFO:CONSOLE(67865)] "The update was installed successfully.", source: file:///android_asset/www/build/js/app.bundle.js (67865)
03-31 10:56:51.495 13786-13918/com.dariel.graduate W/PluginManager: THREAD WARNING: exec() call to CodePush.install blocked the main thread for 52ms. Plugin should use CordovaInterface.getThreadPool().
03-31 10:56:51.502 13786-13786/com.dariel.graduate D/JsMessageQueue: Set native->JS mode to null
03-31 10:56:51.665 13786-13786/com.dariel.graduate W/cr.BindingManager: Cannot call determinedVisibility() - never saw a connection for the pid: 13786
03-31 10:56:51.665 13786-13786/com.dariel.graduate E/chromium: [ERROR:runtime_javascript_dialog_manager.cc(118)] Not implemented reached in virtual void xwalk::RuntimeJavaScriptDialogManager::CancelActiveAndPendingDialogs(content::WebContents*)
03-31 10:56:51.740 13786-13786/com.dariel.graduate D/JsMessageQueue: Set native->JS mode to OnlineEventsBridgeMode
03-31 10:56:52.031 13786-13918/com.dariel.graduate V/StatusBar: Executing action: _ready
03-31 10:56:54.772 13786-13786/com.dariel.graduate I/chromium: [INFO:CONSOLE(63774)] "DEVICE READY FIRED AFTER", source: file:///data/user/0/com.dariel.graduate/files/codepush/deploy/versions/214d1382cdc568e9c98752ff9bd54ee24732f94bedaca1fe9413e4c25d98898c/www/build/js/app.bundle.js (63774)
03-31 10:56:54.776 13786-13918/com.dariel.graduate V/StatusBar: Executing action: styleDefault
03-31 10:56:55.081 13786-13786/com.dariel.graduate I/chromium: [INFO:CONSOLE(67885)] "Checking for update.", source: file:///data/user/0/com.dariel.graduate/files/codepush/deploy/versions/214d1382cdc568e9c98752ff9bd54ee24732f94bedaca1fe9413e4c25d98898c/www/build/js/app.bundle.js (67885)
03-31 10:57:11.721 13786-13786/com.dariel.graduate I/chromium: [INFO:CONSOLE(30)] "Reporting status: 0 undefined undefined", source: file:///data/user/0/com.dariel.graduate/files/codepush/deploy/versions/214d1382cdc568e9c98752ff9bd54ee24732f94bedaca1fe9413e4c25d98898c/www/plugins/cordova-plugin-code-push/bin/www/codePush.js (30)
03-31 10:57:11.721 13786-13786/com.dariel.graduate I/chromium: [INFO:CONSOLE(30)] "Reporting status: 1 v3 1.0.0", source: file:///data/user/0/com.dariel.graduate/files/codepush/deploy/versions/214d1382cdc568e9c98752ff9bd54ee24732f94bedaca1fe9413e4c25d98898c/www/plugins/cordova-plugin-code-push/bin/www/codePush.js (30)

[dylanvdmerwe]

I've managed to track down where the process is getting stuck after an update is installed.

In localPackage.js in LocalPackage.getPackage():
FileUtil.readDataFile(LocalPackage.RootDir, packageFile, function (error, content) {

The readDataFile method never returns.

LocalPackage.RootDir = 'codepush'
packageFile = 'currentPackage.json'

Following the code through takes me into the readFileEntry() method in fileUtil.js:

    FileUtil.readFileEntry = function (fileEntry, callback) {
        fileEntry.file(function (file) {
            var fileReader = new FileReader();
            fileReader.onloadend = function (ev) {
                callback(null, ev.target.result);
            };
            fileReader.onerror = function (ev) {
                callback(new Error("Could not get file. Error: " + ev.error), null);
            };
            fileReader.readAsText(file);
        }, function (error) {
            callback(new Error("Could not get file. Error code: " + error.code), null);
        });
    };

The file object looks as follows:

end: 390
lastModified: 1459493077000
lastModifiedDate: 1459493077000
localURL: "cdvfile://localhost/files/codepush/currentPackage.json"
name: "currentPackage.json"
size: 390
start: 0
type: null

Is that localURL right? The FileReader's onloadend and onerror callbacks do not fire.

After the update the new package is definitely running as seen below:

[geof90]

Thanks for the info @dylanvdmerwe. The URL is definitely correct, the metadata file currentpackage.json contains information about where the current update is stored on disk, and seeing that it has a size of 390 it definitely exists and is not empty.

It's really bizarre that both onloadend and onerror are both not firing, either one should be guaranteed to fire. You said you are sure that this froze both with Crosswalk as well as the normal webview? I am wondering if there is a bug with that implementation of the FileReader API in the webview.

Just a random stab, could u try modifying the code and change onloadend to onload and see if it fixes it? I'll also set up Crosswalk and giving it a try.

// fileReader.onloadend = function (ev) {
fileReader.onload = function (ev) {
    callback(null, ev.target.result);
};

[dylanvdmerwe]

1. I added in my own onload just to check and it also did not fire.
2. Tried with crosswalk and without crosswalk - still get's stuck.
3. Could this not be an Android 6 issue?

[geof90]

I was unable to reproduce this error with a Nexus 5, android 6 emulator though. Do you ever get this same problem in a different device?

[dylanvdmerwe]

I don't have any other Android devices with me at this point in time. Going to set some emulators up to test shortly.

[dylanvdmerwe]

What could be causing this though? How can we further debug this? Is there not a problem with the installation?

I have just tried the app on Samsung S6 5.1.0 (w Crosswalk) emulator and Samsung S3 4.2.2 (w Crosswalk) emulator and after the update is installed the app hangs again.

I also tried multiple versions of Crosswalk which didn't change anything.

[dylanvdmerwe]

Digging into the FileReader.

// Read file
    exec(
        // Success callback
        function(r) {
            // If DONE (cancelled), then don't do anything
            if (me._readyState === FileReader.DONE) {
                return;
            }

            // DONE state
            me._readyState = FileReader.DONE;

            // Save result
            me._result = r;

            // If onload callback
            if (typeof me.onload === "function") {
                me.onload(new ProgressEvent("load", {target:me}));
            }

            // If onloadend callback
            if (typeof me.onloadend === "function") {
                me.onloadend(new ProgressEvent("loadend", {target:me}));
            }
        },
        // Error callback
        function(e) {
            // If DONE (cancelled), then don't do anything
            if (me._readyState === FileReader.DONE) {
                return;
            }

            // DONE state
            me._readyState = FileReader.DONE;

            // null result
            me._result = null;

            // Save error
            me._error = new FileError(e);

            // If onerror callback
            if (typeof me.onerror === "function") {
                me.onerror(new ProgressEvent("error", {target:me}));
            }

            // If onloadend callback
            if (typeof me.onloadend === "function") {
                me.onloadend(new ProgressEvent("loadend", {target:me}));
            }
        }, "File", "readAsText", execArgs);

The line that does not execute is:

// If onloadend callback
if (typeof me.onloadend === "function") {

typeof me.onloadend = null

[geof90]

Thats weird.. I wonder how typeof me.onloadend became null, typeof null should return "object", and typeof undefined returns "undefined". Does onerror execute then?

Also, I wonder if your other issue #92 is related to your problem. The fact that the checkForUpdate only fails after the first update leads me to believe that there is somehow something wrong with the update contents. If you are comfortable with letting us look at your update contents, could you email your deployment key to us at [email protected]? That would help us to diagnose this issue further.

Finally, are you ever seeing this problem with a blank Cordova app with CodePush added to it? I want to rule out the possibility of a conflicting plugin.

[geof90]

@dylanvdmerwe I think I may have found the problem. It appears to be an Angular2/zone.js bug: look at angular/angular#2533 and angular/zone.js#137

I think the angular version shipped with ionic 2.0 does not include the fix. To verify that this is indeed the cause of the issue, could you try changing our plugin code:

/* old code
fileReader.onloadend = function (ev) {
    callback(null, ev.target.result);
};
fileReader.onerror = function (ev) {
    callback(new Error("Could not get file. Error: " + ev.error), null);
};
*/
// new code
fileReader.addEventListener('loadend', function(ev) {
    callback(null, ev.target.result);
});
fileReader.addEventListener('error', function(ev) {
    callback(new Error("Could not get file. Error: " + ev.error), null);
});

If this fix works, I will send out a PR including this fix.

Also, could you let me know the version of angular2 and zone.js in your package.json?

  "dependencies": {
    "angular2": "2.0.0-beta.6",
    "zone.js": "0.5.14"
  },

[dylanvdmerwe]

I had a feeling that would work, however I get the following error:

Uncaught TypeError: fileReader.addEventListener is not a function

 "dependencies": {
    "angular2": "2.0.0-beta.6",
    "ionic-angular": "2.0.0-beta.3",
    "zone.js": "0.5.14"

[geof90]

@dylanvdmerwe FYI, I still can't repro this error with a newly created a new ionic v2 project. Could you give it a try? I don't know if your project was created under an older ionic version. Perhaps simply recreating the project and moving all your code there will solve the problem.

[dylanvdmerwe]

@geof90 that was a good suggestion. I created a new blank ionic 2 project and copied everything across. Works like a charm on the device now. Weird.

[geof90]

@dylanvdmerwe I'm really glad that worked! We will be doing more validation of our plugin with Ionic 2 moving forward.