search

element-hq / element-web

A glossy Matrix collaboration client for the web.
https://element.io
Apache License 2.0
10.74k stars 1.89k forks source link

macOS desktop app doesn't restart after updating #12433

Closed kegsay closed 1 year ago

kegsay commented 4 years ago

OS: Mac Catalina

Basically what it says in the title. Yes, I've waited a while.

jryans commented 4 years ago

What version did you update from, in case you recall?

kegsay commented 4 years ago

A recent version, I think one that was released a few days ago?

dr-waterstorm commented 4 years ago

Can confirm this issue on Catalina with the latest stable Riot version. This does not happen on older Mac OS. We've also tested this on another Mac laptop with older OS.

Rolling back on Catalina does not help, then the old riot still does not show up. Only notifications work, the main view does not open.

Update: We upgraded another Catalina Mac, worked on that laptop, so I'm not sure what the problem is.

dbkr commented 4 years ago

https://github.com/Squirrel/Squirrel.Mac/issues/204 looks like the closest approximation of an upstream bug to track this

benparsons commented 4 years ago

I see this problem on macOS 10.14.4, don't think it's related to Catalina.

kegsay commented 4 years ago

I'm really wondering why we have this problem but Slack and VSCode, both of which afaik run on Electron, don't. I'm sure the fix is somewhere buried in https://github.com/microsoft/vscode ...

https://github.com/microsoft/vscode/blob/master/build/lib/electron.ts#L116 maybe?

jryans commented 4 years ago

I would guess at least VS Code uses a custom updater pipeline instead of Squirrel...?

loa commented 4 years ago

Main window is gone, "Show All Windows" shows nothing.

macOS Catalina 10.15.4

$ /Applications/Riot.app/Contents/MacOS/Riot
Starting auto update with base URL: https://packages.riot.im/desktop/update/
(electron) The default value of app.allowRendererProcessReuse is deprecated, it is currently "false".  It will change to be "true" in Electron 9.  For more information please check https://github.com/electron/electron/issues/18397
GVA encoder info: AMD performance mode : 2
GVA encoder info: deleteSCDMetalContext : texture cache hits: 0, misses: 0

update 1:

Main window shows when specifying empty dir as profile-dir.

$ /Applications/Riot.app/Contents/MacOS/Riot  --profile-dir $PWD
Starting auto update with base URL: https://packages.riot.im/desktop/update/
(electron) The default value of app.allowRendererProcessReuse is deprecated, it is currently "false".  It will change to be "true" in Electron 9.  For more information please check https://github.com/electron/electron/issues/18397
GVA encoder info: AMD performance mode : 2
GVA encoder info: deleteSCDMetalContext : texture cache hits: 0, misses: 0

This resolved the issue for me:

rm ~/Library/Application\ Support/Riot/window-state.json
kegsay commented 3 years ago

This now works for me since a few days/weeks ago, without any modifications/hacks.

benparsons commented 3 years ago

This failed for me this morning

jryans commented 3 years ago

@Kegsay @benparsons Are you using nightly or release?

benparsons commented 3 years ago

Nightly

benparsons commented 3 years ago

FYI of two prompted restarts today, the first failed, the second succeeded.

jryans commented 3 years ago

Okay, sounds like something's still racing / wrong here.

benparsons commented 3 years ago

@jryans are there logs or anything else I can offer as help? I (obsessively 😅) pay attention to whether it succeeds or not but don't see any pattern...

kegsay commented 3 years ago

Release.

jryans commented 3 years ago

@benparsons Not sure yet, but we're discussing as a team, we'll try to work out a next step here.

kegsay commented 3 years ago

Didn't reopen after my last update :(

t3chguy commented 3 years ago

Related https://github.com/vector-im/riot-web/issues/12402 https://github.com/vector-im/riot-web/issues/6252 (based on https://github.com/vector-im/riot-web/issues/12433#issuecomment-631043711)

ara4n commented 3 years ago

empirically this seems to have inexplicably started working at last, in the last week or so, presumably due to something in electron or squirrel having fixed itself.

folks: please yell if you see it recur; otherwise let's close this in a bit.

ara4n commented 3 years ago

...or i could just press the wrong button and close it now, i guess.

ara4n commented 3 years ago

...and today's update didn't relaunch after hitting the restart button.

fokkahontas commented 3 years ago

I'm still experiencing this problem on Catalina 10.15.7; Element version: 1.7.12; olm version: 3.2.1

The fullscreen toggle seems to help at least though.

bwinton commented 3 years ago

I'm seeing this too, although I notice that it opens (seemingly randomly?) 9-12 hours later


benparsons commented 3 years ago

Just experienced this updating to Element Nightly version: 2020122201

RCheesley commented 3 years ago

I am only able to run the application in full screen at present on mac - it remains running but is not visible regardless of which display it is on or tiling (which breaks it completely).

jryans commented 3 years ago

I am only able to run the application in full screen at present on mac - it remains running but is not visible regardless of which display it is on or tiling (which breaks it completely).

Please file a new issue, that seems unrelated to updating.

TheButterZone commented 3 years ago

Same on OSX 10.13.6, Version 1.7.20. I manually relaunched, but I didn't wait anywhere near 9-12 hours after hitting update LOL

ara4n commented 3 years ago

okay, for the last 4-5 days it's been autoupgrading correctly for once (on 10.15.7), so i'm going to have another go at speculatively closing this.

I have a pet theory that it's possible for the app to refuse to shut down if there is an indexeddb transaction in progress (and certain other e2ee bugs can cause transactions to hang around for ages), but this is almost entirely unsubstantiated other than when debugging https://github.com/vector-im/element-web/issues/16194 i noticed the app never shut down when that failure mode was in play.

ara4n commented 3 years ago

...but then today it failed to autoupgrade (the app quit successfully, but then didn't relaunch).

kegsay commented 3 years ago

Definitely feels like a race condition due to how it sometimes does and sometimes doesn't. I have the same behaviour.

TheButterZone commented 3 years ago

1.7.27 update on OSX didn't automatically relaunch after completion

hughns commented 2 years ago

I've been encountering this too. I don't know how ShipIt works, but I found ~/Library/Caches/im.riot.nightly.ShipIt/ShipIt_stderr.log and see entries for successful and failed updates.

n.b. I think the The file doesn’t exist error in below is unrelated to this issue.

A successful update:

2022-01-11 09:46:46.581 ShipIt[90394:5215578] Beginning installation
2022-01-11 09:46:46.847 ShipIt[90394:5215578] Moved bundle from file:///Applications/Element%20Nightly.app/ to file:///var/folders/4d/46zf3gf50dz26r9fq7791k000000gn/T/im.riot.nightly.ShipIt.f5FNudpv/Element%20Nightly.app
2022-01-11 09:46:46.847 ShipIt[90394:5215578] Moved bundle from file:///var/folders/4d/46zf3gf50dz26r9fq7791k000000gn/T/im.riot.nightly.ShipIt.L5EmG2XJ/Element%20Nightly.app to file:///Applications/Element%20Nightly.app/
2022-01-11 09:46:46.861 ShipIt[90394:5215578] Couldn't remove owned bundle at location file:///var/folders/4d/46zf3gf50dz26r9fq7791k000000gn/T/im.riot.nightly.ShipIt.L5EmG2XJ/Element%20Nightly.app, error NSError { domain: NSCocoaErrorDomain, code: 4, description: "“Element Nightly.app” couldn’t be removed.", failureReason: "The file doesn’t exist.", underlying error: NSError { domain: NSPOSIXErrorDomain, code: 2, description: "The operation couldn’t be completed. No such file or directory" }, userInfo: {
    NSFilePath = "/var/folders/4d/46zf3gf50dz26r9fq7791k000000gn/T/im.riot.nightly.ShipIt.L5EmG2XJ/Element Nightly.app";
    NSUserStringVariant =     (
        Remove
    );
} }
2022-01-11 09:46:46.893 ShipIt[90394:5231825] On main thread and launching: file:///Applications/Element%20Nightly.app/
2022-01-11 09:46:46.893 ShipIt[90394:5231825] Bundle URL is valid
2022-01-11 09:46:46.893 ShipIt[90394:5231825] Attempting to launch app on 11.0 or higher
2022-01-11 09:46:46.894 ShipIt[90394:5231825] Launching new ShipIt at /Applications/Element Nightly.app/Contents/Frameworks/Squirrel.framework/Resources/ShipIt with instructions to launch file:///Applications/Element%20Nightly.app/
2022-01-11 09:46:46.894 ShipIt[90394:5215578] Installation completed successfully
2022-01-11 09:46:49.153 ShipIt[42345:5231836] Detected this as a launch request
2022-01-11 09:46:49.276 ShipIt[42345:5231836] Successfully launched application at file:///Applications/Element%20Nightly.app/
2022-01-11 09:46:49.276 ShipIt[42345:5231836] ShipIt quitting
2022-01-11 09:46:49.276 ShipIt[90394:5231825] New ShipIt exited
2022-01-11 09:46:49.277 ShipIt[90394:5231825] ShipIt quitting

A failed update:

2022-01-18 12:32:38.109 ShipIt[50590:11045163] Beginning installation
2022-01-18 12:32:38.361 ShipIt[50590:11127841] Moved bundle from file:///Applications/Element%20Nightly.app/ to file:///var/folders/4d/46zf3gf50dz26r9fq7791k000000gn/T/im.riot.nightly.ShipIt.J3X9hwUY/Element%20Nightly.app
2022-01-18 12:32:38.361 ShipIt[50590:11127841] Moved bundle from file:///var/folders/4d/46zf3gf50dz26r9fq7791k000000gn/T/im.riot.nightly.ShipIt.B9hkNTak/Element%20Nightly.app to file:///Applications/Element%20Nightly.app/
2022-01-18 12:32:38.382 ShipIt[50590:11127841] Couldn't remove owned bundle at location file:///var/folders/4d/46zf3gf50dz26r9fq7791k000000gn/T/im.riot.nightly.ShipIt.B9hkNTak/Element%20Nightly.app, error NSError { domain: NSCocoaErrorDomain, code: 4, description: "“Element Nightly.app” couldn’t be removed.", failureReason: "The file doesn’t exist.", underlying error: NSError { domain: NSPOSIXErrorDomain, code: 2, description: "The operation couldn’t be completed. No such file or directory" }, userInfo: {
    NSFilePath = "/var/folders/4d/46zf3gf50dz26r9fq7791k000000gn/T/im.riot.nightly.ShipIt.B9hkNTak/Element Nightly.app";
    NSUserStringVariant =     (
        Remove
    );
} }
2022-01-18 12:32:38.410 ShipIt[50590:11127841] Installation completed successfully
2022-01-18 12:32:38.410 ShipIt[50590:11127841] ShipIt quitting
ara4n commented 2 years ago

this affects almost every update for me; the only time it manages to successfully update is if the upgrade is <24h since the last upgrade. i assume it also affects updates for stable as well as nightly.

surely this should be higher priority?

ara4n commented 1 year ago

I just took a look into a typical failed update:

2022-07-02 09:37:56.087 ShipIt[15329:325960] Detected this as an install request
2022-07-02 17:31:27.746 ShipIt[15329:325962] Beginning installation
2022-07-02 17:31:27.848 ShipIt[15329:367865] Attempting to add timer to main runloop, but the main thread as exited. This message will only log once. Break on _CFRunLoopError_MainThreadHasExited to debug.
2022-07-02 17:31:33.341 ShipIt[15329:367865] Moving bundle from file:///Applications/Element%20Nightly.app/ to file:///var/folders/1n/7qxltb4x00xgpv8q0g3syvxh0000gn/T/im.riot.nightly.ShipIt.jGPAkAnf/Element%20Nightly.app
2022-07-02 17:31:33.341 ShipIt[15329:367865] Moving bundles directly as SquirrelMacEnableDirectContentsWrite is disabled for app: im.riot.nightly.ShipIt
2022-07-02 17:31:33.341 ShipIt[15329:367865] Moved bundle contents from file:///Applications/Element%20Nightly.app/ to file:///var/folders/1n/7qxltb4x00xgpv8q0g3syvxh0000gn/T/im.riot.nightly.ShipIt.jGPAkAnf/Element%20Nightly.app
2022-07-02 17:31:33.341 ShipIt[15329:367865] Moving bundle from file:///var/folders/1n/7qxltb4x00xgpv8q0g3syvxh0000gn/T/im.riot.nightly.ShipIt.ECa2oUGG/Element%20Nightly.app to file:///Applications/Element%20Nightly.app/
2022-07-02 17:31:33.342 ShipIt[15329:367865] Moving bundles directly as SquirrelMacEnableDirectContentsWrite is disabled for app: im.riot.nightly.ShipIt
2022-07-02 17:31:33.342 ShipIt[15329:367865] Moved bundle contents from file:///var/folders/1n/7qxltb4x00xgpv8q0g3syvxh0000gn/T/im.riot.nightly.ShipIt.ECa2oUGG/Element%20Nightly.app to file:///Applications/Element%20Nightly.app/
2022-07-02 17:31:33.368 ShipIt[15329:367865] Couldn't remove owned bundle at location file:///var/folders/1n/7qxltb4x00xgpv8q0g3syvxh0000gn/T/im.riot.nightly.ShipIt.ECa2oUGG/Element%20Nightly.app, error NSError { domain: NSCocoaErrorDomain, code: 4, description: "“Element Nightly.app” couldn’t be removed.", failureReason: "The file doesn’t exist.", underlying error: NSError { domain: NSPOSIXErrorDomain, code: 2, description: "The operation couldn’t be completed. No such file or directory" }, userInfo: {
    NSFilePath = "/var/folders/1n/7qxltb4x00xgpv8q0g3syvxh0000gn/T/im.riot.nightly.ShipIt.ECa2oUGG/Element Nightly.app";
    NSUserStringVariant =     (
        Remove
    );
} }
2022-07-02 17:31:33.387 ShipIt[15329:367865] Installation completed successfully
2022-07-02 17:31:33.387 ShipIt[15329:367865] ShipIt quitting

Interesting things to note:

matthew@shadowfax im.riot.nightly.ShipIt % GetFileInfo ShipItState.plist 
file: "/Users/matthew/Library/Caches/im.riot.nightly.ShipIt/ShipItState.plist"
type: "\0\0\0\0"
creator: "\0\0\0\0"
attributes: avbstclinmedz
created: 07/02/2022 09:37:56
modified: 07/02/2022 09:37:56

matthew@shadowfax im.riot.nightly.ShipIt % cat ShipItState.plist| jq .
{
  "launchAfterInstallation": false,
  "updateBundleURL": "file:///Users/matthew/Library/Caches/im.riot.nightly.ShipIt/update.PymyXlW/Element%20Nightly.app/",
  "useUpdateBundleName": true,
  "bundleIdentifier": "im.riot.nightly",
  "targetBundleURL": "file:///Applications/Element%20Nightly.app/"
}

In other words, launchAfterInstallation looks to be false, on the state that presumably was used to launch ShipIt at 09:37:56. (Something less clear is the ID update.PymyXlW, which doesn't appear anywhere in ShipIt_stderr.log - instead it installs the download from update.ECa2oUGG :/

However, the fact that launchAfterInstallation is false there seems suspicious.

Next step: compare the state file with the next successful install+launch cycle, and see how it differs.

Alternative theory: if ShipIt is invoked while the laptop is off, perhaps the main thread times out somehow with some timeout while waiting for the user to hit 'update'.

ara4n commented 1 year ago

Another observation - Electron is applying a bunch of patches to the main squirrel.mac tree, especially stuff like https://github.com/electron/electron/blob/main/patches/squirrel.mac/feat_add_new_squirrel_mac_bundle_installation_method_behind_flag.patch, which explains why the logging doesn't match the squirrel.mac source tree, and might contribute to the problems here.

ara4n commented 1 year ago

Theory: electron's AutoUpdater::QuitAndInstall calls relaunchToInstallUpdate on Squirrel to install the app. This fairly unambiguously should set launchAfterInstallation: YES.

However, empirically, the state file isn't being written at the point that QuitAndInstall is called - we're seeing an earlier copy of the state file on disk.

Looking at:

- (RACSignal *)relaunchToInstallUpdate {
    return [[[[[[[[SQRLShipItRequest
        readUsingURL:self.shipItStateURL]
        map:^(SQRLShipItRequest *request) {
            return [[SQRLShipItRequest alloc] initWithUpdateBundleURL:request.updateBundleURL targetBundleURL:request.targetBundleURL bundleIdentifier:request.bundleIdentifier launchAfterInstallation:YES useUpdateBundleName:request.useUpdateBundleName];
        }]
        flattenMap:^(SQRLShipItRequest *request) {
            return [[request
                writeUsingURL:self.shipItStateURL]
                sqrl_addTransactionWithName:NSLocalizedString(@"Preparing to relaunch", nil) description:NSLocalizedString(@"%@ is preparing to relaunch to install an update. Interrupting the process could corrupt the application.", nil), NSRunningApplication.currentApplication.bundleIdentifier];
        }]
        deliverOn:RACScheduler.mainThreadScheduler]
        doCompleted:^{
            [NSApp terminate:self];
        }]
        // Never allow `completed` to escape this signal chain (in case
        // -terminate: is asynchronous or something crazy).
        concat:[RACSignal never]]
        replay]
        setNameWithFormat:@"%@ -relaunchToInstallUpdate", self];
}

I wonder whether the [request WriteUsingURL] is not completing before [NSApp terminate:self] is called - some kind of ARC lifetime problem like the one that https://github.com/electron/electron/blob/main/patches/squirrel.mac/fix_ensure_that_self_is_retained_until_the_racsignal_is_complete.patch is patching. Or alternatively perhaps the mainThreadScheduler is somehow dead by this point, causing the write to be lost.

ara4n commented 1 year ago

Another thought: https://github.com/vector-im/element-desktop/blob/develop/src/updater.ts has pollforupdates being triggered by both electron’s callback and from our timer. i wonder if we have a race between the two?

ara4n commented 1 year ago

I captured a successful upgrade just now. (The app hadn't spotted an upgrade overnight, for some reason; i had to manually click the check for upgrade button on opening it).

After having downloaded the update, the state file was:

{
  "launchAfterInstallation": false,
  "updateBundleURL": "file:///Users/matthew/Library/Caches/im.riot.nightly.ShipIt/update.J8xom8S/Element%20Nightly.app/",
  "useUpdateBundleName": true,
  "bundleIdentifier": "im.riot.nightly",
  "targetBundleURL": "file:///Applications/Element%20Nightly.app/"
}

but after installing the update successfully & reloaunching, the state file had been correctly updated to:

{
  "launchAfterInstallation": true,
  "updateBundleURL": "file:///Users/matthew/Library/Caches/im.riot.nightly.ShipIt/update.J8xom8S/Element%20Nightly.app/",
  "useUpdateBundleName": true,
  "bundleIdentifier": "im.riot.nightly",
  "targetBundleURL": "file:///Applications/Element%20Nightly.app/"
}

The logs from stderr.log were:

<click the check button>
2022-07-03 10:54:00.232 ShipIt[21213:505971] Detected this as an install request

<click the download button>
2022-07-03 10:55:10.046 ShipIt[21213:505978] Beginning installation
2022-07-03 10:55:15.264 ShipIt[21213:507037] Moving bundle from file:///Applications/Element%20Nightly.app/ to file:///var/folders/1n/7qxltb4x00xgpv8q0g3syvxh0000gn/T/im.riot.nightly.ShipIt.JFdrzhrw/Element%20Nightly.app
2022-07-03 10:55:15.265 ShipIt[21213:507037] Moving bundles directly as SquirrelMacEnableDirectContentsWrite is disabled for app: im.riot.nightly.ShipIt
2022-07-03 10:55:15.265 ShipIt[21213:507037] Moved bundle contents from file:///Applications/Element%20Nightly.app/ to file:///var/folders/1n/7qxltb4x00xgpv8q0g3syvxh0000gn/T/im.riot.nightly.ShipIt.JFdrzhrw/Element%20Nightly.app
2022-07-03 10:55:15.265 ShipIt[21213:507037] Moving bundle from file:///var/folders/1n/7qxltb4x00xgpv8q0g3syvxh0000gn/T/im.riot.nightly.ShipIt.cgwVERiV/Element%20Nightly.app to file:///Applications/Element%20Nightly.app/
2022-07-03 10:55:15.266 ShipIt[21213:507037] Moving bundles directly as SquirrelMacEnableDirectContentsWrite is disabled for app: im.riot.nightly.ShipIt
2022-07-03 10:55:15.266 ShipIt[21213:507037] Moved bundle contents from file:///var/folders/1n/7qxltb4x00xgpv8q0g3syvxh0000gn/T/im.riot.nightly.ShipIt.cgwVERiV/Element%20Nightly.app to file:///Applications/Element%20Nightly.app/
2022-07-03 10:55:15.287 ShipIt[21213:507037] Couldn't remove owned bundle at location file:///var/folders/1n/7qxltb4x00xgpv8q0g3syvxh0000gn/T/im.riot.nightly.ShipIt.cgwVERiV/Element%20Nightly.app, error NSError { domain: NSCocoaErrorDomain, code: 4, description: "“Element Nightly.app” couldn’t be removed.", failureReason: "The file doesn’t exist.", underlying error: NSError { domain: NSPOSIXErrorDomain, code: 2, description: "The operation couldn’t be completed. No such file or directory" }, userInfo: {
    NSFilePath = "/var/folders/1n/7qxltb4x00xgpv8q0g3syvxh0000gn/T/im.riot.nightly.ShipIt.cgwVERiV/Element Nightly.app";
    NSUserStringVariant =     (
        Remove
    );
} }
2022-07-03 10:55:15.310 ShipIt[21213:507061] On main thread and launching: file:///Applications/Element%20Nightly.app/
2022-07-03 10:55:15.310 ShipIt[21213:507061] Bundle URL is valid
2022-07-03 10:55:15.310 ShipIt[21213:507061] Attempting to launch app on 11.0 or higher
2022-07-03 10:55:15.310 ShipIt[21213:507061] Launching new ShipIt at /Applications/Element Nightly.app/Contents/Frameworks/Squirrel.framework/Resources/ShipIt with instructions to launch file:///Applications/Element%20Nightly.app/
2022-07-03 10:55:15.311 ShipIt[21213:507037] Installation completed successfully
2022-07-03 10:55:15.324 ShipIt[21213:507061] New ShipIt pid: 21267
2022-07-03 10:55:17.511 ShipIt[21267:507149] Detected this as a launch request
2022-07-03 10:55:17.636 ShipIt[21267:507149] Successfully launched application at file:///Applications/Element%20Nightly.app/
2022-07-03 10:55:17.636 ShipIt[21267:507149] ShipIt quitting
2022-07-03 10:55:17.636 ShipIt[21213:507061] ShipIt status 0
2022-07-03 10:55:17.636 ShipIt[21213:507061] New ShipIt exited
2022-07-03 10:55:17.636 ShipIt[21213:507061] ShipIt quitting

I wonder if there's a problem that the install request happens when it does the check and does the download, rather than when you actually hit the install button - which could be a long time apart?

Finally, for completeness, i left the Console running filtered on ShipIt, in case it captured anything else (and for a comparison with a bad run). Output was:

default 10:53:57.883320+0100    Element Nightly Download completed to: file:///Users/matthew/Library/Caches/im.riot.nightly.ShipIt/update.J8xom8S/Element%20Nightly-2022070301-universal-mac.zip
default 10:54:00.232748+0100    ShipIt  Detected this as an install request
default 10:54:00.241256+0100    ShipIt  Read options: 80000001 -- URL: <private> -- purposeID: 527B6F5A-7550-4199-A7F2-E3909E67B29A -- claimID: C994A181-419B-4019-85ED-456AD188D1DB
default 10:54:00.243324+0100    ShipIt  Claim C994A181-419B-4019-85ED-456AD188D1DB granted in client
default 10:54:00.243346+0100    ShipIt  Claim C994A181-419B-4019-85ED-456AD188D1DB invoked in client
default 10:54:00.247091+0100    ShipIt  Received configuration update from daemon (initial)
default 10:55:10.034003+0100    ShipIt  Read options: 1 -- URL: <private> -- purposeID: 3FA2B897-1B66-45F7-86EC-5CCE570BDF8A -- claimID: A2953812-FC78-49FB-BC39-C5D498AA6836
default 10:55:10.037559+0100    ShipIt  Claim A2953812-FC78-49FB-BC39-C5D498AA6836 granted in client
default 10:55:10.037584+0100    ShipIt  Claim A2953812-FC78-49FB-BC39-C5D498AA6836 invoked in client
default 10:55:10.045190+0100    powerd  Process ShipIt.21213 Created PreventSystemSleep "Updating" age:00:00:00  id:30064813873 [System: PrevIdle DeclUser kDisp]
default 10:55:10.045391+0100    powerd  Process ShipIt.21213 Created PreventSystemSleep "Updating" age:00:00:00  id:30064813874 [System: PrevIdle DeclUser kDisp]
default 10:55:10.045666+0100    ShipIt  Beginning installation
default 10:55:10.046031+0100    runningboardd   Resolved pid 21213 to [anon<ShipIt>(501):21213]
default 10:55:10.046252+0100    runningboardd   [anon<ShipIt>(501):21213] This process will not be managed.
default 10:55:10.046305+0100    runningboardd   Now tracking process: [anon<ShipIt>(501):21213]
default 10:55:10.046681+0100    runningboardd   Acquiring assertion targeting [anon<ShipIt>(501):21213] from originator [daemon<com.apple.powerd>:307] with description <RBSAssertionDescriptor| "App is holding power assertion" ID:385-307-404003 target:21213 attributes:[
    <RBSDomainAttribute| domain:"com.apple.appnap" name:"PowerAssertion" sourceEnvironment:"(null)">,
    <RBSAcquisitionCompletionAttribute| policy:AfterApplication>
    ]>
default 10:55:10.046771+0100    runningboardd   [anon<ShipIt>(501):21213] reported to RB as running
default 10:55:10.046797+0100    runningboardd   Assertion 385-307-404003 (target:[anon<ShipIt>(501):21213]) will be created as active
default 10:55:10.047224+0100    runningboardd   [anon<ShipIt>(501):21213] Ignoring jetsam update because this process is not memory-managed
default 10:55:10.047239+0100    runningboardd   [anon<ShipIt>(501):21213] Ignoring suspend because this process is not lifecycle managed
default 10:55:10.047312+0100    runningboardd   [anon<ShipIt>(501):21213] Ignoring role changes because this process is not role managed
default 10:55:10.047444+0100    runningboardd   [anon<ShipIt>(501):21213] Ignoring GPU update because this process is not GPU managed
default 10:55:10.138987+0100    ShipIt  TrustSettingsUseXPC is enabled (via feature flags)
default 10:55:15.264916+0100    ShipIt  Moving bundle from file:///Applications/Element%20Nightly.app/ to file:///var/folders/1n/7qxltb4x00xgpv8q0g3syvxh0000gn/T/im.riot.nightly.ShipIt.JFdrzhrw/Element%20Nightly.app
default 10:55:15.265655+0100    ShipIt  Moving bundles directly as SquirrelMacEnableDirectContentsWrite is disabled for app: im.riot.nightly.ShipIt
default 10:55:15.265847+0100    ShipIt  Moved bundle contents from file:///Applications/Element%20Nightly.app/ to file:///var/folders/1n/7qxltb4x00xgpv8q0g3syvxh0000gn/T/im.riot.nightly.ShipIt.JFdrzhrw/Element%20Nightly.app
default 10:55:15.265908+0100    ShipIt  Moving bundle from file:///var/folders/1n/7qxltb4x00xgpv8q0g3syvxh0000gn/T/im.riot.nightly.ShipIt.cgwVERiV/Element%20Nightly.app to file:///Applications/Element%20Nightly.app/
default 10:55:15.266074+0100    ShipIt  Moving bundles directly as SquirrelMacEnableDirectContentsWrite is disabled for app: im.riot.nightly.ShipIt
default 10:55:15.266237+0100    ShipIt  Moved bundle contents from file:///var/folders/1n/7qxltb4x00xgpv8q0g3syvxh0000gn/T/im.riot.nightly.ShipIt.cgwVERiV/Element%20Nightly.app to file:///Applications/Element%20Nightly.app/
default 10:55:15.287259+0100    ShipIt  Couldn't remove owned bundle at location file:///var/folders/1n/7qxltb4x00xgpv8q0g3syvxh0000gn/T/im.riot.nightly.ShipIt.cgwVERiV/Element%20Nightly.app, error NSError { domain: NSCocoaErrorDomain, code: 4, description: "“Element Nightly.app” couldn’t be removed.", failureReason: "The file doesn’t exist.", underlying error: NSError { domain: NSPOSIXErrorDomain, code: 2, description: "The operation couldn’t be completed. No such file or directory" }, userInfo: {
    NSFilePath = "/var/folders/1n/7qxltb4x00xgpv8q0g3syvxh0000gn/T/im.riot.nightly.ShipIt.cgwVERiV/Element Nightly.app";
    NSUserStringVariant =     (
        Remove
    );
} }
default 10:55:15.310698+0100    ShipIt  On main thread and launching: file:///Applications/Element%20Nightly.app/
default 10:55:15.310744+0100    ShipIt  Bundle URL is valid
default 10:55:15.310812+0100    ShipIt  Attempting to launch app on 11.0 or higher
default 10:55:15.311157+0100    powerd  Process ShipIt.21213 Released PreventSystemSleep "Updating" age:00:00:05  id:30064813874 [System: PrevIdle DeclUser kDisp]
default 10:55:15.311309+0100    powerd  Process ShipIt.21213 Released PreventSystemSleep "Updating" age:00:00:05  id:30064813873 [System: PrevIdle DeclUser kDisp]
default 10:55:15.310862+0100    ShipIt  Launching new ShipIt at /Applications/Element Nightly.app/Contents/Frameworks/Squirrel.framework/Resources/ShipIt with instructions to launch file:///Applications/Element%20Nightly.app/
default 10:55:15.311217+0100    ShipIt  Installation completed successfully
default 10:55:15.311460+0100    runningboardd   Invalidating assertion 385-307-404003 (target:[anon<ShipIt>(501):21213]) from originator [daemon<com.apple.powerd>:307]
default 10:55:15.324511+0100    ShipIt  New ShipIt pid: 21267
default 10:55:15.358983+0100    runningboardd   [anon<ShipIt>(501):21213] Ignoring jetsam update because this process is not memory-managed
default 10:55:15.358994+0100    runningboardd   [anon<ShipIt>(501):21213] Ignoring suspend because this process is not lifecycle managed
default 10:55:15.359005+0100    runningboardd   [anon<ShipIt>(501):21213] Ignoring role changes because this process is not role managed
default 10:55:15.359014+0100    runningboardd   [anon<ShipIt>(501):21213] Ignoring GPU update because this process is not GPU managed
default 10:55:17.510915+0100    ShipIt  Detected this as a launch request
default 10:55:17.514173+0100    ShipIt  Received configuration update from daemon (initial)
default 10:55:17.515922+0100    ShipIt  bundle 0xad48 mod date changed from Sat Jul  2 08:05:30 2022 to Sun Jul  3 08:05:20 2022
default 10:55:17.515964+0100    ShipIt  bundle 0xad48 node has changed
default 10:55:17.520204+0100    ShipIt  bundle 0xad48 mod date changed from Sat Jul  2 08:05:30 2022 to Sun Jul  3 08:05:20 2022
default 10:55:17.520230+0100    ShipIt  bundle 0xad48 node has changed
default 10:55:17.578988+0100    ShipIt  Initializing connection
default 10:55:17.579020+0100    ShipIt  Removing all cached process handles
default 10:55:17.579046+0100    ShipIt  Sending handshake request attempt #1 to server
default 10:55:17.579066+0100    ShipIt  Creating connection to com.apple.runningboard
default 10:55:17.579315+0100    runningboardd   Resolved pid 21267 to [anon<ShipIt>(501):21267]
default 10:55:17.579464+0100    runningboardd   [anon<ShipIt>(501):21267] This process will not be managed.
default 10:55:17.579488+0100    runningboardd   Now tracking process: [anon<ShipIt>(501):21267]
default 10:55:17.579785+0100    runningboardd   Setting client for [anon<ShipIt>(501):21267] as ready
default 10:55:17.580108+0100    ShipIt  Handshake succeeded
default 10:55:17.580126+0100    ShipIt  Identity resolved as anon<ShipIt>(501)
default 10:55:17.580348+0100    runningboardd   Acquiring assertion targeting app<application.im.riot.nightly.47828676.47828682(501)> from originator [anon<ShipIt>(501):21267] with description <RBSAssertionDescriptor| "LS launch im.riot.nightly" ID:385-21267-404012 target:app<application.im.riot.nightly.47828676.47828682(501)> attributes:[
    <RBSDomainAttribute| domain:"com.apple.launchservicesd" name:"LaunchRoleUserInteractive" sourceEnvironment:"(null)">
    ]>
default 10:55:17.622551+0100    runningboardd   Invalidating assertion 385-21267-404012 (target:app<application.im.riot.nightly.47828676.47828682(501)>) from originator [anon<ShipIt>(501):21267]
default 10:55:17.634552+0100    ShipIt  -[SFLGenericList _insertItem:atIndex:error:]_block_invoke item: 09546786-8436-41A0-9DAA-99FCB43326AE at index: 0 list: com.apple.LSSharedFileList.RecentApplications
default 10:55:17.635159+0100    ShipIt  received: com.apple.LSSharedFileList.RecentApplications
default 10:55:17.636838+0100    ShipIt  ShipIt status 0
default 10:55:17.636869+0100    ShipIt  New ShipIt exited
default 10:55:17.636936+0100    ShipIt  Entering exit handler.
default 10:55:17.636945+0100    ShipIt  Exiting exit handler.
default 10:55:17.636951+0100    ShipIt  ShipIt quitting
default 10:55:17.638283+0100    runningboardd   [anon<ShipIt>(501):21267] termination reported by proc_exit
default 10:55:17.636254+0100    ShipIt  Successfully launched application at file:///Applications/Element%20Nightly.app/
default 10:55:17.636290+0100    ShipIt  Entering exit handler.
default 10:55:17.636300+0100    ShipIt  Exiting exit handler.
default 10:55:17.636307+0100    ShipIt  ShipIt quitting
default 10:55:17.641206+0100    runningboardd   [anon<ShipIt>(501):21213] termination reported by launchd (0, 0, 0)
default 10:55:17.641280+0100    runningboardd   Removing process: [anon<ShipIt>(501):21213]
default 10:55:17.641441+0100    runningboardd   removeJobWithInstance called for identity without existing job [anon<ShipIt>(501):21213]
default 10:55:17.641470+0100    runningboardd   Removing assertions for terminated process: [anon<ShipIt>(501):21213]
default 10:55:17.642231+0100    runningboardd   XPC connection invalidated: [anon<ShipIt>(501):21267]
default 10:55:17.746479+0100    runningboardd   Removing process: [anon<ShipIt>(501):21267]
default 10:55:17.746591+0100    runningboardd   removeJobWithInstance called for identity without existing job [anon<ShipIt>(501):21267]
default 10:55:17.746603+0100    runningboardd   Removing assertions for terminated process: [anon<ShipIt>(501):21267]
ara4n commented 1 year ago

https://github.com/vector-im/element-desktop/pull/386 is a stab at fixing this, by stopping autoUpdater.checkForUpdates(); being called if we've already downloaded an update. The assumption is that the update checks are somehow colliding with the queued download, and this will let the download install cleanly.

t3chguy commented 1 year ago

Closing as presumed fixed, if anyone sees this recur after 1.11.1 please shout

ara4n commented 1 year ago

I haven't had a failure since the fix landed, so yes, it looks speculatively fixed. Will reopen if needed.

For completeness, here's a ShipIt log from console of today's successful update:

default 10:27:01.079893+0100    ShipIt  Read options: 1 -- URL: <private> -- purposeID: 93A4C530-3DD2-4A5B-9A20-533793D28A6F -- claimID: B891F642-57F1-462E-A547-8CC6A912A977
default 10:27:01.083425+0100    ShipIt  Claim B891F642-57F1-462E-A547-8CC6A912A977 granted in client
default 10:27:01.083448+0100    ShipIt  Claim B891F642-57F1-462E-A547-8CC6A912A977 invoked in client
default 10:27:01.090940+0100    powerd  Process ShipIt.52251 Created PreventSystemSleep "Updating" age:00:00:00  id:30064808753 [System: PrevIdle DeclUser kDisp]
default 10:27:01.091500+0100    powerd  Process ShipIt.52251 Created PreventSystemSleep "Updating" age:00:00:00  id:30064808754 [System: PrevIdle DeclUser kDisp]
default 10:27:01.091713+0100    ShipIt  Beginning installation
default 10:27:01.107836+0100    runningboardd   Resolved pid 52251 to [anon<ShipIt>(501):52251]
default 10:27:01.108187+0100    runningboardd   [anon<ShipIt>(501):52251] This process will not be managed.
default 10:27:01.108371+0100    runningboardd   Now tracking process: [anon<ShipIt>(501):52251]
default 10:27:01.110378+0100    runningboardd   Acquiring assertion targeting [anon<ShipIt>(501):52251] from originator [daemon<com.apple.powerd>:307] with description <RBSAssertionDescriptor| "App is holding power assertion" ID:385-307-1214752 target:52251 attributes:[
    <RBSDomainAttribute| domain:"com.apple.appnap" name:"PowerAssertion" sourceEnvironment:"(null)">,
    <RBSAcquisitionCompletionAttribute| policy:AfterApplication>
    ]>
default 10:27:01.110490+0100    runningboardd   [anon<ShipIt>(501):52251] reported to RB as running
default 10:27:01.110476+0100    runningboardd   Assertion 385-307-1214752 (target:[anon<ShipIt>(501):52251]) will be created as active
default 10:27:01.111402+0100    runningboardd   [anon<ShipIt>(501):52251] Ignoring jetsam update because this process is not memory-managed
default 10:27:01.111464+0100    runningboardd   [anon<ShipIt>(501):52251] Ignoring suspend because this process is not lifecycle managed
default 10:27:01.111608+0100    runningboardd   [anon<ShipIt>(501):52251] Ignoring role changes because this process is not role managed
default 10:27:01.111660+0100    runningboardd   [anon<ShipIt>(501):52251] Ignoring GPU update because this process is not GPU managed
default 10:27:01.202482+0100    ShipIt  TrustSettingsUseXPC is enabled (via feature flags)
default 10:27:01.211086+0100    ShipIt  Received configuration update from daemon (initial)
default 10:27:06.243110+0100    ShipIt  Moving bundle from file:///Applications/Element%20Nightly.app/ to file:///var/folders/1n/7qxltb4x00xgpv8q0g3syvxh0000gn/T/im.riot.nightly.ShipIt.QxTSQD77/Element%20Nightly.app
default 10:27:06.243922+0100    ShipIt  Moving bundles directly as SquirrelMacEnableDirectContentsWrite is disabled for app: im.riot.nightly.ShipIt
default 10:27:06.244154+0100    ShipIt  Moved bundle contents from file:///Applications/Element%20Nightly.app/ to file:///var/folders/1n/7qxltb4x00xgpv8q0g3syvxh0000gn/T/im.riot.nightly.ShipIt.QxTSQD77/Element%20Nightly.app
default 10:27:06.244218+0100    ShipIt  Moving bundle from file:///var/folders/1n/7qxltb4x00xgpv8q0g3syvxh0000gn/T/im.riot.nightly.ShipIt.z1IaOTv8/Element%20Nightly.app to file:///Applications/Element%20Nightly.app/
default 10:27:06.244406+0100    ShipIt  Moving bundles directly as SquirrelMacEnableDirectContentsWrite is disabled for app: im.riot.nightly.ShipIt
default 10:27:06.244580+0100    ShipIt  Moved bundle contents from file:///var/folders/1n/7qxltb4x00xgpv8q0g3syvxh0000gn/T/im.riot.nightly.ShipIt.z1IaOTv8/Element%20Nightly.app to file:///Applications/Element%20Nightly.app/
default 10:27:06.271389+0100    ShipIt  Couldn't remove owned bundle at location file:///var/folders/1n/7qxltb4x00xgpv8q0g3syvxh0000gn/T/im.riot.nightly.ShipIt.z1IaOTv8/Element%20Nightly.app, error NSError { domain: NSCocoaErrorDomain, code: 4, description: "“Element Nightly.app” couldn’t be removed.", failureReason: "The file doesn’t exist.", underlying error: NSError { domain: NSPOSIXErrorDomain, code: 2, description: "The operation couldn’t be completed. No such file or directory" }, userInfo: {
    NSFilePath = "/var/folders/1n/7qxltb4x00xgpv8q0g3syvxh0000gn/T/im.riot.nightly.ShipIt.z1IaOTv8/Element Nightly.app";
    NSUserStringVariant =     (
        Remove
    );
} }
default 10:27:06.304574+0100    ShipIt  On main thread and launching: file:///Applications/Element%20Nightly.app/
default 10:27:06.304615+0100    ShipIt  Bundle URL is valid
default 10:27:06.304688+0100    ShipIt  Attempting to launch app on 11.0 or higher
default 10:27:06.304718+0100    ShipIt  Launching new ShipIt at /Applications/Element Nightly.app/Contents/Frameworks/Squirrel.framework/Resources/ShipIt with instructions to launch file:///Applications/Element%20Nightly.app/
default 10:27:06.305105+0100    powerd  Process ShipIt.52251 Released PreventSystemSleep "Updating" age:00:00:05  id:30064808753 [System: PrevIdle DeclUser kDisp]
default 10:27:06.305182+0100    ShipIt  Installation completed successfully
default 10:27:06.305294+0100    powerd  Process ShipIt.52251 Released PreventSystemSleep "Updating" age:00:00:05  id:30064808754 [System: PrevIdle DeclUser kDisp]
default 10:27:06.305469+0100    runningboardd   Invalidating assertion 385-307-1214752 (target:[anon<ShipIt>(501):52251]) from originator [daemon<com.apple.powerd>:307]
default 10:27:06.314944+0100    ShipIt  New ShipIt pid: 52722
default 10:27:06.409920+0100    runningboardd   [anon<ShipIt>(501):52251] Ignoring jetsam update because this process is not memory-managed
default 10:27:06.409946+0100    runningboardd   [anon<ShipIt>(501):52251] Ignoring suspend because this process is not lifecycle managed
default 10:27:06.409974+0100    runningboardd   [anon<ShipIt>(501):52251] Ignoring role changes because this process is not role managed
default 10:27:06.409998+0100    runningboardd   [anon<ShipIt>(501):52251] Ignoring GPU update because this process is not GPU managed
default 10:27:08.961090+0100    ShipIt  Detected this as a launch request
default 10:27:08.975132+0100    ShipIt  Initializing connection
default 10:27:08.975169+0100    ShipIt  Removing all cached process handles
default 10:27:08.975202+0100    ShipIt  Sending handshake request attempt #1 to server
default 10:27:08.975239+0100    ShipIt  Creating connection to com.apple.runningboard
default 10:27:08.975528+0100    runningboardd   Resolved pid 52722 to [anon<ShipIt>(501):52722]
default 10:27:08.975634+0100    runningboardd   [anon<ShipIt>(501):52722] This process will not be managed.
default 10:27:08.975651+0100    runningboardd   Now tracking process: [anon<ShipIt>(501):52722]
default 10:27:08.976733+0100    runningboardd   Setting client for [anon<ShipIt>(501):52722] as ready
default 10:27:08.977535+0100    runningboardd   Acquiring assertion targeting app<application.im.riot.nightly.48249699.48249705(501)> from originator [anon<ShipIt>(501):52722] with description <RBSAssertionDescriptor| "LS launch im.riot.nightly" ID:385-52722-1214761 target:app<application.im.riot.nightly.48249699.48249705(501)> attributes:[
    <RBSDomainAttribute| domain:"com.apple.launchservicesd" name:"LaunchRoleUserInteractive" sourceEnvironment:"(null)">
    ]>
default 10:27:09.030852+0100    runningboardd   Invalidating assertion 385-52722-1214761 (target:app<application.im.riot.nightly.48249699.48249705(501)>) from originator [anon<ShipIt>(501):52722]
default 10:27:09.037400+0100    ShipIt  -[SFLGenericList _insertItem:atIndex:error:]_block_invoke item: 76481219-42FB-4C87-8191-5355DB491DFD at index: 0 list: com.apple.LSSharedFileList.RecentApplications
default 10:27:09.038089+0100    ShipIt  received: com.apple.LSSharedFileList.RecentApplications
default 10:27:09.040425+0100    ShipIt  ShipIt status 0
default 10:27:09.040465+0100    ShipIt  New ShipIt exited
default 10:27:09.040543+0100    ShipIt  Entering exit handler.
default 10:27:09.040596+0100    ShipIt  Exiting exit handler.
default 10:27:09.040633+0100    ShipIt  ShipIt quitting
default 10:27:09.041713+0100    runningboardd   [anon<ShipIt>(501):52722] termination reported by proc_exit
default 10:27:09.046298+0100    runningboardd   [anon<ShipIt>(501):52251] termination reported by launchd (0, 0, 0)
default 10:27:09.046349+0100    runningboardd   Removing process: [anon<ShipIt>(501):52251]
default 10:27:09.046523+0100    runningboardd   removeJobWithInstance called for identity without existing job [anon<ShipIt>(501):52251]
default 10:27:09.047976+0100    runningboardd   XPC connection invalidated: [anon<ShipIt>(501):52722]
default 10:27:09.151052+0100    runningboardd   Removing process: [anon<ShipIt>(501):52722]
default 10:27:09.151323+0100    runningboardd   removeJobWithInstance called for identity without existing job [anon<ShipIt>(501):52722]
default 10:27:09.151352+0100    runningboardd   Removing assertions for terminated process: [anon<ShipIt>(501):52722]
hughns commented 1 year ago

FWIW, my install has also updated reliably and consistently every day since. Thank you!

seanmacisaac commented 1 year ago

@ara4n We're having the same issue, and the same work around fixes it. This is not great though as we have some users that don't auto update our app often, and so can end up many versions behind. When we then eventually force updates those users end up on the version they downloaded weeks or months ago, rather than on the most recent update.

Any chance you found a different solution to this that allowed a second version to be downloaded?

seanmacisaac commented 1 year ago

For anyone who finds this in the future.

I dug in more, and found that as long as the last call to autoUpdater.checkForUpdates led to an update things were fine, even if multiple updates had been released since the last install. Windows works fine in all cases, only Mac has the problem, so I wrote this wrapper around the call to autoUpdater.checkForUpdates which seems to resolve the issue. Note that we're using the json serverType. It does require some book keeping in the update-downloaded event handler to track latest version the client has downloaded.

private async safeCheckForUpdate() {
    if (process.platform === "darwin") {
      // On Mac if the user has already downloaded an update but not installed it and
      // we check again and no additional new update is available the app ends up in a
      // bad state and doesn't restart after installing any updates that are downloaded.
      // To avoid this we check manually whether an update is available and call the
      // autoUpdater.checkForUpdates() when something new is there.
      try {
        const { data } = await axios.get(this.feedURL);
        const { currentRelease } = data;
        logger.info(
          `Latest version from release download: ${currentRelease} (current: ${app.getVersion()}, most recent downloaded ${
            this.latestVersionDownloaded
          }})`
        );
        if (
          currentRelease === app.getVersion() ||
          currentRelease === this.latestVersionDownloaded
        ) {
          await this.onUpdateNotAvailable();
          return;
        }
      } catch (err) {
        logger.error(`Error checking for updates ${this.feedURL} ${getErrorMessage(err)}`);
        await this.onUpdateNotAvailable();
        return;
      }
    }
    autoUpdater.checkForUpdates();
  }
t3chguy commented 1 year ago

@seanmacisaac thanks for your feedback with the workaround. Do you know if there's any upstream issue? Have adopted a workaround based on your snippet in https://github.com/vector-im/element-desktop/pull/629

seanmacisaac commented 1 year ago

I don't, and I haven't spent the time needed to track down whether the problem is with Electron or its patching of Squirrel.Mac or Squirrel.Mac itself, or some lower layer than that. I did see the behavior noted here https://github.com/Squirrel/Squirrel.Mac/issues/204#issuecomment-1292361657, but I'm not sure that is really a Squirrel.Mac issue vs an Electron issue.