typo

this happens because we have some bug in sftp container causing uninstall(s) to
fail. the database of those apps are gone but the export logic then tries to export
them and it all fails.

CHANGES

@@ -2217,3 +2217,14 @@
 * rsync: preserve and restore symlinks
 * Clean up backups function now removes missing backups
 
+[6.2.1]
+* Avoid updown notifications on full restore
+* Add retries to downloader logic in installer
+
+[6.2.2]
+* Fix ENOBUFS issue with backups when collecting fs metadata
+
+[6.2.3]
+* Fix addon crashes with missing databases
+* Update mail container for LMTP cert fix
+* Fix services view showing yellow icon

migrations/20210204181904-settings-change-ovh-url.js

@@ -1,16 +1,8 @@
 'use strict';
 
 exports.up = function(db, callback) {
-    db.all('SELECT value FROM settings WHERE name="backup_config"', function (error, results) {
-        if (error || results.length === 0) return callback(error);
-
-        var backupConfig = JSON.parse(results[0].value);
-        if (backupConfig.provider !== 'ovh-objectstorage') return callback();
-
-        backupConfig.endpoint = backupConfig.endpoint.replace('https://s3.', 'https://storage.');
-
-        db.runSql('UPDATE settings SET value=? WHERE name="backup_config"', [ JSON.stringify(backupConfig) ], callback);
-    });
+    /* this contained an invalid migration of OVH URLs from s3 subdomain to storage subdomain. See https://forum.cloudron.io/topic/4584/issue-with-backups-listings-and-saving-backup-config-in-6-2  */
+    callback();
 };
 
 exports.down = function(db, callback) {

scripts/cloudron-setup

@@ -107,7 +107,7 @@ printf "**********************************************************************\n
 printf "\t\t\tWELCOME TO CLOUDRON\n"
 printf "\t\t\t-------------------\n"
 
-printf '\n\e[1;32m%-6s\e[m\n\n' "Cloudron is installing. Run 'tail -f /var/log/cloudron-setup.log' to view progress.
+printf '\n\e[1;32m%-6s\e[m\n\n' "Cloudron is installing. Run 'tail -f /var/log/cloudron-setup.log' to view progress."
 
 printf "Cloudron overview - https://docs.cloudron.io/ \n"
 printf "Cloudron setup - https://docs.cloudron.io/installation/#setup \n"

scripts/installer.sh

@@ -25,7 +25,7 @@ readonly box_src_tmp_dir="$(realpath ${script_dir}/..)"
 readonly ubuntu_version=$(lsb_release -rs)
 readonly ubuntu_codename=$(lsb_release -cs)
 
-readonly is_update=$(systemctl is-active box && echo "yes" || echo "no")
+readonly is_update=$(systemctl is-active -q box && echo "yes" || echo "no")
 
 log "Updating from $(cat $box_src_dir/VERSION) to $(cat $box_src_tmp_dir/VERSION)"
 
@@ -34,9 +34,9 @@ log "updating docker"
 readonly docker_version=20.10.3
 if [[ $(docker version --format {{.Client.Version}}) != "${docker_version}" ]]; then
     # there are 3 packages for docker - containerd, CLI and the daemon
-    curl -sL "https://download.docker.com/linux/ubuntu/dists/${ubuntu_codename}/pool/stable/amd64/containerd.io_1.4.3-1_amd64.deb" -o /tmp/containerd.deb
-    curl -sL "https://download.docker.com/linux/ubuntu/dists/${ubuntu_codename}/pool/stable/amd64/docker-ce-cli_${docker_version}~3-0~ubuntu-${ubuntu_codename}_amd64.deb" -o /tmp/docker-ce-cli.deb
-    curl -sL "https://download.docker.com/linux/ubuntu/dists/${ubuntu_codename}/pool/stable/amd64/docker-ce_${docker_version}~3-0~ubuntu-${ubuntu_codename}_amd64.deb" -o /tmp/docker.deb
+    $curl -sL "https://download.docker.com/linux/ubuntu/dists/${ubuntu_codename}/pool/stable/amd64/containerd.io_1.4.3-1_amd64.deb" -o /tmp/containerd.deb
+    $curl -sL "https://download.docker.com/linux/ubuntu/dists/${ubuntu_codename}/pool/stable/amd64/docker-ce-cli_${docker_version}~3-0~ubuntu-${ubuntu_codename}_amd64.deb" -o /tmp/docker-ce-cli.deb
+    $curl -sL "https://download.docker.com/linux/ubuntu/dists/${ubuntu_codename}/pool/stable/amd64/docker-ce_${docker_version}~3-0~ubuntu-${ubuntu_codename}_amd64.deb" -o /tmp/docker.deb
 
     log "Waiting for all dpkg tasks to finish..."
     while fuser /var/lib/dpkg/lock; do
@@ -65,7 +65,7 @@ fi
 readonly nginx_version=$(nginx -v 2>&1)
 if [[ "${nginx_version}" != *"1.18."* ]]; then
     log "installing nginx 1.18"
-    curl -sL http://nginx.org/packages/ubuntu/pool/nginx/n/nginx/nginx_1.18.0-2~${ubuntu_codename}_amd64.deb -o /tmp/nginx.deb
+    $curl -sL http://nginx.org/packages/ubuntu/pool/nginx/n/nginx/nginx_1.18.0-2~${ubuntu_codename}_amd64.deb -o /tmp/nginx.deb
     # apt install with install deps (as opposed to dpkg -i)
     apt install -y -o Dpkg::Options::="--force-confdef" -o Dpkg::Options::="--force-confold" --force-yes /tmp/nginx.deb
     rm /tmp/nginx.deb
@@ -103,14 +103,14 @@ images=$(node -e "var i = require('${box_src_tmp_dir}/src/infra_version.js'); co
 
 log "\tPulling docker images: ${images}"
 for image in ${images}; do
-    if ! docker pull "${image}"; then           # this pulls the image using the sha256
+    while ! docker pull "${image}"; do           # this pulls the image using the sha256
         log "Could not pull ${image}"
-        exit 5
-    fi
-    if ! docker pull "${image%@sha256:*}"; then  # this will tag the image for readability
+        sleep 5
+    done
+    while ! docker pull "${image%@sha256:*}"; do  # this will tag the image for readability
         log "Could not pull ${image%@sha256:*}"
-        exit 6
-   fi
+        sleep 5
+   done
 done
 
 log "update cloudron-syslog"

setup/start/systemd/box.service

@@ -1,8 +1,6 @@
 [Unit]
 Description=Cloudron Admin
 OnFailure=crashnotifier@%n.service
-; journald crashes result in a EPIPE in node. Cannot ignore it as it results in loss of logs.
-BindsTo=systemd-journald.service
 After=mysql.service nginx.service
 ; As cloudron-resize-fs is a one-shot, the Wants= automatically ensures that the service *finishes*
 Wants=cloudron-resize-fs.service

src/apphealthmonitor.js

@@ -10,51 +10,48 @@ var appdb = require('./appdb.js'),
     docker = require('./docker.js'),
     eventlog = require('./eventlog.js'),
     safe = require('safetydance'),
-    superagent = require('superagent'),
-    util = require('util');
+    superagent = require('superagent');
 
 exports = module.exports = {
     run
 };
 
 const HEALTHCHECK_INTERVAL = 10 * 1000; // every 10 seconds. this needs to be small since the UI makes only healthy apps clickable
-const UNHEALTHY_THRESHOLD = 10 * 60 * 1000; // 10 minutes
+const UNHEALTHY_THRESHOLD = 20 * 60 * 1000; // 20 minutes
 
 const OOM_EVENT_LIMIT = 60 * 60 * 1000; // 60 minutes
-const gStartTime = new Date(); // time when apphealthmonitor was started
+let gStartTime = null; // time when apphealthmonitor was started
 let gLastOomMailTime = Date.now() - (5 * 60 * 1000); // pretend we sent email 5 minutes ago
 
-function debugApp(app) {
-    assert(typeof app === 'object');
-
-    debug(app.fqdn + ' ' + util.format.apply(util, Array.prototype.slice.call(arguments, 1)) + ' - ' + app.id);
-}
-
 function setHealth(app, health, callback) {
     assert.strictEqual(typeof app, 'object');
     assert.strictEqual(typeof health, 'string');
     assert.strictEqual(typeof callback, 'function');
 
-    let now = new Date(), curHealth = app.health;
+    // app starts out with null health
+    // if it became healthy, we update immediately. this is required for ui to say "running" etc
+    // if it became unhealthy/error/dead, wait for a threshold before updating db
+
+    const now = new Date(), lastHealth = app.health;
     let healthTime = gStartTime > app.healthTime ? gStartTime : app.healthTime; // on box restart, clamp value to start time
 
     if (health === apps.HEALTH_HEALTHY) {
         healthTime = now;
-        if (curHealth && curHealth !== apps.HEALTH_HEALTHY) { // app starts out with null health
-            debugApp(app, 'app switched from %s to healthy', curHealth);
+        if (lastHealth && lastHealth !== apps.HEALTH_HEALTHY) { // app starts out with null health
+            debug(`setHealth: ${app.id} (${app.fqdn}) switched from ${lastHealth} to healthy`);
 
             // do not send mails for dev apps
             if (!app.debugMode) eventlog.add(eventlog.ACTION_APP_UP, auditSource.HEALTH_MONITOR, { app: app });
         }
     } else if (Math.abs(now - healthTime) > UNHEALTHY_THRESHOLD) {
-        if (curHealth === apps.HEALTH_HEALTHY) {
-            debugApp(app, 'marking as unhealthy since not seen for more than %s minutes', UNHEALTHY_THRESHOLD/(60 * 1000));
+        if (lastHealth === apps.HEALTH_HEALTHY) {
+            debug(`setHealth: marking ${app.id} (${app.fqdn}) as unhealthy since not seen for more than ${UNHEALTHY_THRESHOLD/(60 * 1000)} minutes`);
 
             // do not send mails for dev apps
             if (!app.debugMode) eventlog.add(eventlog.ACTION_APP_DOWN, auditSource.HEALTH_MONITOR, { app: app });
         }
     } else {
-        debugApp(app, 'waiting for %s seconds to update the app health', (UNHEALTHY_THRESHOLD - Math.abs(now - healthTime))/1000);
+        debug(`setHealth: ${app.id} (${app.fqdn}) waiting for ${(UNHEALTHY_THRESHOLD - Math.abs(now - healthTime))/1000} to update health`);
         return callback(null);
     }
 
@@ -63,6 +60,7 @@ function setHealth(app, health, callback) {
         if (error) return callback(error);
 
         app.health = health;
+        app.healthTime = healthTime;
 
         callback(null);
     });
@@ -189,6 +187,8 @@ function run(intervalSecs, callback) {
     assert.strictEqual(typeof intervalSecs, 'number');
     assert.strictEqual(typeof callback, 'function');
 
+    if (!gStartTime) gStartTime = new Date();
+
     async.series([
         processApp, // this is first because docker.getEvents seems to get 'stuck' sometimes
         processDockerEvents.bind(null, intervalSecs)

src/apps.js

@@ -1530,7 +1530,7 @@ function restore(app, backupId, auditSource, callback) {
             args: {
                 restoreConfig,
                 oldManifest: app.manifest,
-                skipDnsSetup: false,
+                skipDnsSetup: !!backupId, // if this is a restore, just skip dns setup. only re-installs should setup dns
                 overwriteDns: true
             },
             values

src/backups.js

@@ -554,16 +554,17 @@ function saveFsMetadata(dataLayout, metadataFile, callback) {
         symlinks: []
     };
 
+    // we assume small number of files. spawnSync will raise a ENOBUFS error after maxBuffer
     for (let lp of dataLayout.localPaths()) {
-        const emptyDirs = safe.child_process.execSync(`find ${lp} -type d -empty\n`, { encoding: 'utf8' });
+        const emptyDirs = safe.child_process.execSync(`find ${lp} -type d -empty`, { encoding: 'utf8', maxBuffer: 1024 * 1024 * 30 });
         if (emptyDirs === null) return callback(new BoxError(BoxError.FS_ERROR, `Error finding empty dirs: ${safe.error.message}`));
         if (emptyDirs.length) metadata.emptyDirs = metadata.emptyDirs.concat(emptyDirs.trim().split('\n').map((ed) => dataLayout.toRemotePath(ed)));
 
-        const execFiles = safe.child_process.execSync(`find ${lp} -type f -executable\n`, { encoding: 'utf8' });
+        const execFiles = safe.child_process.execSync(`find ${lp} -type f -executable`, { encoding: 'utf8', maxBuffer: 1024 * 1024 * 30 });
         if (execFiles === null) return callback(new BoxError(BoxError.FS_ERROR, `Error finding executables: ${safe.error.message}`));
         if (execFiles.length) metadata.execFiles = metadata.execFiles.concat(execFiles.trim().split('\n').map((ef) => dataLayout.toRemotePath(ef)));
 
-        const symlinks = safe.child_process.execSync(`find ${lp} -type l\n`, { encoding: 'utf8' });
+        const symlinks = safe.child_process.execSync(`find ${lp} -type l`, { encoding: 'utf8', maxBuffer: 1024 * 1024 * 30 });
         if (symlinks === null) return callback(new BoxError(BoxError.FS_ERROR, `Error finding symlinks: ${safe.error.message}`));
         if (symlinks.length) metadata.symlinks = metadata.symlinks.concat(symlinks.trim().split('\n').map((sl) => {
             const target = safe.fs.readlinkSync(sl);

src/infra_version.js

@@ -16,11 +16,11 @@ exports = module.exports = {
     // docker inspect --format='{{index .RepoDigests 0}}' $IMAGE to get the sha256
     'images': {
         'turn': { repo: 'cloudron/turn', tag: 'cloudron/turn:1.3.0@sha256:386fb755fc41edd7086f7bcb230f7f28078936f9ae4ead6d97c741df1cc194ae' },
-        'mysql': { repo: 'cloudron/mysql', tag: 'cloudron/mysql:3.0.3@sha256:dde2522915a12bfb3c840771553ea8a670c7e0ef84d7ec619483b98b3dfec082' },
-        'postgresql': { repo: 'cloudron/postgresql', tag: 'cloudron/postgresql:4.0.1@sha256:279e66a20483f230e970078c7b51581e19017fb2436d1caa514969ff07a16464' },
+        'mysql': { repo: 'cloudron/mysql', tag: 'cloudron/mysql:3.0.4@sha256:4d688c746f27b195d98f35a7d24ec01f3f754e0ca61e9de0b0bc9793553880f1' },
+        'postgresql': { repo: 'cloudron/postgresql', tag: 'cloudron/postgresql:4.0.2@sha256:424081fd38ebd35f3606c64f8f99138570e5f4d5066f12cfb4142447d249d3e7' },
         'mongodb': { repo: 'cloudron/mongodb', tag: 'cloudron/mongodb:4.0.1@sha256:ad20a9a5dcb2ab132374a7c8d44b89af0ec37651cf889e570f7625b02ee85fdf' },
-        'redis': { repo: 'cloudron/redis', tag: 'cloudron/redis:3.0.1@sha256:9f8de95b88ce64650c08d5af7b0c2cd24465dd4e24cb0537a0d0f84e78da9840' },
-        'mail': { repo: 'cloudron/mail', tag: 'cloudron/mail:3.2.2@sha256:ae7647ec5d32478f22c056d65700e458a089bb45667aa3c67a1b3dd049754cee' },
+        'redis': { repo: 'cloudron/redis', tag: 'cloudron/redis:3.0.2@sha256:caaa1f7f4055ae8990d8ec65bd100567496df7e4ed5eb427867f3717a8dcbf92' },
+        'mail': { repo: 'cloudron/mail', tag: 'cloudron/mail:3.2.3@sha256:fdc4aa6d2c85aeafe65eaa4243aada0cc2e57b94f6eaee02c9b1a8fb89b01dd7' },
         'graphite': { repo: 'cloudron/graphite', tag: 'cloudron/graphite:2.4.0@sha256:953bbd8b72a9108a8526d2c0bdbba67e1e1563ff59d0a117f0884dba1576f3dd' },
         'sftp': { repo: 'cloudron/sftp', tag: 'cloudron/sftp:3.2.0@sha256:61e8247ded1e07cf882ca478dab180960357c614472e80b938f1f690a46788c2' }
     }

src/services.js

@@ -301,7 +301,7 @@ function containerStatus(containerName, tokenEnvName, callback) {
         if (error && (error.reason === BoxError.NOT_FOUND || error.reason === BoxError.INACTIVE)) return callback(null, { status: exports.SERVICE_STATUS_STOPPED });
         if (error) return callback(error);
 
-        request.get(`https://${addonDetails.ip}:3000/healthcheck?access_token=${addonDetails.token}`, { json: true, rejectUnauthorized: false, timeout: 3000 }, function (error, response) {
+        request.get(`https://${addonDetails.ip}:3000/healthcheck?access_token=${addonDetails.token}`, { json: true, rejectUnauthorized: false, timeout: 20000 }, function (error, response) {
             if (error) return callback(null, { status: exports.SERVICE_STATUS_STARTING, error: `Error waiting for ${containerName}: ${error.message}` });
             if (response.statusCode !== 200 || !response.body.status) return callback(null, { status: exports.SERVICE_STATUS_STARTING, error: `Error waiting for ${containerName}. Status code: ${response.statusCode} message: ${response.body.message}` });
 
@@ -614,7 +614,7 @@ function waitForContainer(containerName, tokenEnvName, callback) {
         if (error) return callback(error);
 
         async.retry({ times: 10, interval: 15000 }, function (retryCallback) {
-            request.get(`https://${result.ip}:3000/healthcheck?access_token=${result.token}`, { json: true, rejectUnauthorized: false, timeout: 3000 }, function (error, response) {
+            request.get(`https://${result.ip}:3000/healthcheck?access_token=${result.token}`, { json: true, rejectUnauthorized: false, timeout: 5000 }, function (error, response) {
                 if (error) return retryCallback(new BoxError(BoxError.ADDONS_ERROR, `Network error waiting for ${containerName}: ${error.message}`));
                 if (response.statusCode !== 200 || !response.body.status) return retryCallback(new BoxError(BoxError.ADDONS_ERROR, `Error waiting for ${containerName}. Status code: ${response.statusCode} message: ${response.body.message}`));
 
@@ -769,10 +769,10 @@ function exportDatabase(addon, callback) {
         return callback(null);
     }
 
-    appdb.getAll(function (error, apps) {
+    appdb.getAll(function (error, allApps) {
         if (error) return callback(error);
 
-        async.eachSeries(apps, function iterator (app, iteratorCallback) {
+        async.eachSeries(allApps, function iterator (app, iteratorCallback) {
             if (!app.manifest.addons || !(addon in app.manifest.addons)) return iteratorCallback(); // app doesn't use the addon
 
             debug(`exportDatabase: Exporting addon ${addon} of app ${app.id}`);
@@ -780,7 +780,8 @@ function exportDatabase(addon, callback) {
             ADDONS[addon].backup(app, app.manifest.addons[addon], function (error) {
                 if (error) {
                     debug(`exportDatabase: Error exporting ${addon} of app ${app.id}.`, error);
-                    return iteratorCallback(error);
+                    // for errored apps, we can ignore if export had an error
+                    return iteratorCallback(app.installationState === apps.ISTATE_ERROR ? null : error);
                 }
 
                 iteratorCallback();
@@ -837,6 +838,7 @@ function startServices(existingInfra, callback) {
         if (existingInfra.version !== infra.version) {
             debug(`startServices: ${existingInfra.version} -> ${infra.version}. starting all services`);
             startFuncs.push(
+                mail.startMail, // start this first to reduce email downtime
                 startTurn.bind(null, existingInfra, servicesConfig['turn'] || {}),
                 startMysql.bind(null, existingInfra),
                 startPostgresql.bind(null, existingInfra),
@@ -844,15 +846,15 @@ function startServices(existingInfra, callback) {
                 startRedis.bind(null, existingInfra),
                 graphite.start.bind(null, existingInfra, servicesConfig['graphite'] || {}),
                 sftp.start.bind(null, existingInfra, servicesConfig['sftp'] || {}),
-                mail.startMail);
+            );
         } else {
             assert.strictEqual(typeof existingInfra.images, 'object');
 
+            if (infra.images.mail.tag !== existingInfra.images.mail.tag) startFuncs.push(mail.startMail);  // start this first to reduce email downtime
             if (infra.images.turn.tag !== existingInfra.images.turn.tag) startFuncs.push(startTurn.bind(null, existingInfra, servicesConfig['turn'] || {}));
             if (infra.images.mysql.tag !== existingInfra.images.mysql.tag) startFuncs.push(startMysql.bind(null, existingInfra));
             if (infra.images.postgresql.tag !== existingInfra.images.postgresql.tag) startFuncs.push(startPostgresql.bind(null, existingInfra));
             if (infra.images.mongodb.tag !== existingInfra.images.mongodb.tag) startFuncs.push(startMongodb.bind(null, existingInfra));
-            if (infra.images.mail.tag !== existingInfra.images.mail.tag) startFuncs.push(mail.startMail);
             if (infra.images.redis.tag !== existingInfra.images.redis.tag) startFuncs.push(startRedis.bind(null, existingInfra));
             if (infra.images.graphite.tag !== existingInfra.images.graphite.tag) startFuncs.push(graphite.start.bind(null, existingInfra, servicesConfig['graphite'] || {}));
             if (infra.images.sftp.tag !== existingInfra.images.sftp.tag) startFuncs.push(sftp.start.bind(null, existingInfra, servicesConfig['sftp'] || {}));
@@ -2082,7 +2084,7 @@ function statusGraphite(callback) {
         if (error && error.reason === BoxError.NOT_FOUND) return callback(null, { status: exports.SERVICE_STATUS_STOPPED });
         if (error) return callback(error);
 
-        request.get('http://127.0.0.1:8417/graphite-web/dashboard', { json: true, timeout: 3000 }, function (error, response) {
+        request.get('http://127.0.0.1:8417/graphite-web/dashboard', { json: true, timeout: 20000 }, function (error, response) {
             if (error) return callback(null, { status: exports.SERVICE_STATUS_STARTING, error: `Error waiting for graphite: ${error.message}` });
             if (response.statusCode !== 200) return callback(null, { status: exports.SERVICE_STATUS_STARTING, error: `Error waiting for graphite. Status code: ${response.statusCode} message: ${response.body.message}` });
 

src/storage/s3.js

@@ -65,7 +65,7 @@ function getS3Config(apiConfig, callback) {
         region: apiConfig.region || 'us-east-1',
         maxRetries: 10,
         retryDelayOptions: {
-            customBackoff: () => 20000 // constant backoff - https://docs.aws.amazon.com/AWSJavaScriptSDK/latest/AWS/Config.html#retryDelayOptions-property
+            customBackoff: (/* retryCount, error */) => 20000 // constant backoff - https://docs.aws.amazon.com/AWSJavaScriptSDK/latest/AWS/Config.html#retryDelayOptions-property
         },
         httpOptions: {
             connectTimeout: 60000, // https://github.com/aws/aws-sdk-js/pull/1446
@@ -146,7 +146,7 @@ function exists(apiConfig, backupFilePath, callback) {
     getS3Config(apiConfig, function (error, credentials) {
         if (error) return callback(error);
 
-        const s3 = new AWS.S3(credentials);
+        const s3 = new AWS.S3(_.omit(credentials, 'retryDelayOptions', 'maxRetries'));
 
         if (!backupFilePath.endsWith('/')) { // check for file
             const params = {
@@ -155,6 +155,7 @@ function exists(apiConfig, backupFilePath, callback) {
             };
 
             s3.headObject(params, function (error) {
+                if (!Object.keys(this.httpResponse.headers).some(h => h.startsWith('x-amz'))) return callback(new BoxError(BoxError.EXTERNAL_ERROR, 'not a s3 endpoint'));
                 if (error && S3_NOT_FOUND(error)) return callback(null, false);
                 if (error) return callback(new BoxError(BoxError.EXTERNAL_ERROR, error.message || error.code));
 

src/updatechecker.js

@@ -35,7 +35,7 @@ function checkAppUpdates(options, callback) {
     assert.strictEqual(typeof options, 'object');
     assert.strictEqual(typeof callback, 'function');
 
-    debug('Checking App Updates');
+    debug('checkAppUpdates: checking for updates');
 
     let state = getUpdateInfo();
     let newState = { };  // create new state so that old app ids are removed
@@ -50,7 +50,7 @@ function checkAppUpdates(options, callback) {
 
             appstore.getAppUpdate(app, options, function (error, updateInfo) {
                 if (error) {
-                    debug('Error getting app update info for %s', app.id, error);
+                    debug('checkAppUpdates: Error getting app update info for %s', app.id, error);
                     return iteratorDone();  // continue to next
                 }
 
@@ -59,10 +59,12 @@ function checkAppUpdates(options, callback) {
                 newState[app.id] = updateInfo;
 
                 if (safe.query(state[app.id], 'manifest.version') === updateInfo.manifest.version) {
-                    debug(`Skipping app update notification of ${app.id} since user was already notified of ${updateInfo.manifest.version}`);
+                    debug(`checkAppUpdates: Skipping app update notification of ${app.id} since user was already notified of ${updateInfo.manifest.version}`);
                     return iteratorDone();
                 }
 
+                debug(`checkAppUpdates: ${app.id} can be updated to ${updateInfo.manifest.id}@${updateInfo.manifest.version}`);
+
                 pendingNotifications.push({ app, updateInfo });
                 iteratorDone();
             });
@@ -80,7 +82,7 @@ function checkBoxUpdates(options, callback) {
     assert.strictEqual(typeof options, 'object');
     assert.strictEqual(typeof callback, 'function');
 
-    debug('Checking Box Updates');
+    debug('checkBoxUpdates: checking for updates');
 
     appstore.getBoxUpdate(options, function (error, updateInfo) {
         if (error) return callback(error);
@@ -92,14 +94,17 @@ function checkBoxUpdates(options, callback) {
                 delete state.box;
                 setUpdateInfo(state);
             }
+            debug('checkBoxUpdates: no updates');
             return callback(null);
         }
 
         if (state.box && state.box.version === updateInfo.version) {
-            debug('Skipping notification of box update as user was already notified');
+            debug(`checkBoxUpdates: Skipping notification of box update ${updateInfo.version} as user was already notified`);
             return callback();
         }
 
+        debug(`checkBoxUpdates: ${updateInfo.version} is available`);
+
         const changelog = updateInfo.changelog.map((m) => `* ${m}\n`).join('');
 
         const message = `Changelog:\n${changelog}\n\nGo to the settings view to update.\n\n`;