Skip to content

Commit d8ca88d

Browse files
perNyfeltperNyfelt
authored
Merge pull request #81 from Alipsa/codex/updater-logging
[codex] Förbättra updaterloggning
2 parents 9cfa812 + e020ce3 commit d8ca88d

6 files changed

Lines changed: 299 additions & 49 deletions

File tree

‎app/build.gradle‎

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -137,6 +137,12 @@ def buildJpackageArgs = { String platform, String type, File destinationDir, Lis
137137
'--java-options',
138138
'-Dfile.encoding=UTF-8'
139139
]
140+
if (platform == 'linux') {
141+
args += [
142+
'--java-options',
143+
'-Djdk.lang.Process.launchMechanism=VFORK'
144+
]
145+
}
140146
if (type != 'app-image') {
141147
args += [
142148
'--license-file',

‎app/src/main/groovy/se/alipsa/accounting/AlipsaAccounting.groovy‎

Lines changed: 12 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -28,11 +28,13 @@ final class AlipsaAccounting {
2828
private static final String VERSION_ARGUMENT = '--version'
2929
private static final String HOME_ARGUMENT_PREFIX = '--home='
3030
private static final String MODE_ARGUMENT_PREFIX = '--mode='
31+
private static final String PROCESS_LAUNCH_MECHANISM_PROPERTY = 'jdk.lang.Process.launchMechanism'
3132

3233
private AlipsaAccounting() {
3334
}
3435

3536
static void main(String[] args) {
37+
configureProcessLaunchMechanism()
3638
StartupOptions options = StartupOptions.parse(args ?: new String[0])
3739
if (options.applicationHomeOverride != null) {
3840
System.setProperty(AppPaths.HOME_OVERRIDE_PROPERTY, options.applicationHomeOverride)
@@ -104,6 +106,16 @@ final class AlipsaAccounting {
104106
}
105107
}
106108

109+
private static void configureProcessLaunchMechanism() {
110+
if (System.getProperty(PROCESS_LAUNCH_MECHANISM_PROPERTY) != null) {
111+
return
112+
}
113+
String osName = System.getProperty('os.name', '').toLowerCase(Locale.ROOT)
114+
if (osName.contains('linux')) {
115+
System.setProperty(PROCESS_LAUNCH_MECHANISM_PROPERTY, 'VFORK')
116+
}
117+
}
118+
107119
private static void failOnStartupErrors(StartupVerificationReport report) {
108120
if (report.ok) {
109121
return

‎app/src/main/groovy/se/alipsa/accounting/service/UpdateService.groovy‎

Lines changed: 171 additions & 36 deletions
Original file line numberDiff line numberDiff line change
@@ -13,6 +13,7 @@ import java.nio.file.Files
1313
import java.nio.file.Path
1414
import java.nio.file.StandardCopyOption
1515
import java.security.MessageDigest
16+
import java.util.logging.Logger
1617
import java.util.regex.Matcher
1718
import java.util.zip.ZipEntry
1819
import java.util.zip.ZipInputStream
@@ -24,6 +25,7 @@ import java.util.zip.ZipInputStream
2425
*/
2526
final class UpdateService {
2627

28+
private static final Logger log = Logger.getLogger(UpdateService.name)
2729
private static final String REPO = 'Alipsa/accounting'
2830
private static final String LATEST_RELEASE_URL = "https://api.github.com/repos/${REPO}/releases/latest"
2931
private static final String DIST_ASSET_PREFIX = 'app-'
@@ -83,6 +85,7 @@ final class UpdateService {
8385
throw new IllegalStateException('No download URL available for the update.')
8486
}
8587

88+
log.info("Downloading update ${info.availableVersion} from ${info.downloadUrl}")
8689
Path stagingDir = stagingDirectory()
8790
Files.createDirectories(stagingDir)
8891
Path targetFile = stagingDir.resolve("app-${info.availableVersion}.zip")
@@ -115,9 +118,11 @@ final class UpdateService {
115118
}
116119

117120
if (info.checksumUrl != null) {
121+
log.info("Verifying checksum for ${targetFile}")
118122
verifyChecksum(targetFile, info.checksumUrl, client)
119123
}
120124

125+
log.info("Downloaded update archive to ${targetFile}")
121126
targetFile
122127
}
123128

@@ -153,21 +158,36 @@ final class UpdateService {
153158
}
154159

155160
void applyUpdateAndRestart(Path downloadedZip) {
161+
applyUpdateAndRestart(downloadedZip, null)
162+
}
163+
164+
void applyUpdateAndRestart(Path downloadedZip, Closure<Void> phaseCallback) {
165+
log.info("Preparing to apply update from ${downloadedZip}")
156166
Path stagingDir = stagingDirectory()
157167
Path extractedDir = stagingDir.resolve('extracted')
168+
notifyApplyPhase(phaseCallback, ApplyPhase.EXTRACTING)
169+
log.info("Extracting update archive to ${extractedDir}")
158170
deleteDirectoryContents(extractedDir)
159171
Files.createDirectories(extractedDir)
160172

161173
extractJars(downloadedZip, extractedDir)
162174

175+
notifyApplyPhase(phaseCallback, ApplyPhase.STAGING)
176+
log.info('Staging updater script.')
163177
Path installDir = installationJarDirectory()
164178
if (installDir == null) {
165179
throw new IllegalStateException('Cannot determine installation JAR directory.')
166180
}
181+
Path updaterLog = updateLogPath()
182+
Files.createDirectories(updaterLog.parent)
167183

168-
Path updaterScript = writeUpdaterScript(stagingDir, extractedDir, installDir)
184+
Path updaterScript = writeUpdaterScript(stagingDir, extractedDir, installDir, updaterLog)
185+
log.info("Updater script written to ${updaterScript}; updater log will be ${updaterLog}")
186+
notifyApplyPhase(phaseCallback, ApplyPhase.LAUNCHING)
187+
log.info('Launching updater and exiting application.')
169188
LoggingConfigurer.shutdown()
170189
launchUpdaterAndExit(updaterScript)
190+
throw new IllegalStateException('Updater was launched, but the application did not exit.')
171191
}
172192

173193
Path installationJarDirectory() {
@@ -190,6 +210,10 @@ final class UpdateService {
190210
launcherPath(jarDir, System.getProperty('os.name', '').toLowerCase(Locale.ROOT))
191211
}
192212

213+
Path updateLogPath() {
214+
AppPaths.logDirectory().resolve('updater.log')
215+
}
216+
193217
static Path launcherPath(Path jarDir, String osName) {
194218
if (osName.contains('win')) {
195219
return appImageRoot(jarDir).resolve('AlipsaAccounting.exe')
@@ -225,65 +249,133 @@ final class UpdateService {
225249
}
226250
}
227251

228-
private Path writeUpdaterScript(Path stagingDir, Path extractedDir, Path installDir) {
252+
private Path writeUpdaterScript(Path stagingDir, Path extractedDir, Path installDir, Path updaterLog) {
229253
String osName = System.getProperty('os.name', '').toLowerCase(Locale.ROOT)
230254
boolean isWindows = osName.contains('win')
231255
Path launcher = launcherPath()
232256
String launcherCommand = launcher != null ? "\"${launcher}\"" : ''
233257
Path backupDir = installDir.resolve('.update-backup')
234258
String newMainJar = mainJarFileName(extractedDir) ?: ''
235259
String newVersion = versionFromMainJar(newMainJar) ?: ''
260+
UpdaterScriptContext context = new UpdaterScriptContext(
261+
stagingDir,
262+
extractedDir,
263+
installDir,
264+
updaterLog,
265+
backupDir,
266+
launcherCommand,
267+
newMainJar,
268+
newVersion
269+
)
236270

237271
Path script
238272
if (isWindows) {
239273
script = stagingDir.resolve('updater.bat')
240-
script.toFile().text = """\
274+
script.toFile().text = windowsUpdaterScript(context)
275+
} else {
276+
script = stagingDir.resolve('updater.sh')
277+
script.toFile().text = unixUpdaterScript(context)
278+
script.toFile().setExecutable(true)
279+
}
280+
script
281+
}
282+
283+
private static String windowsUpdaterScript(UpdaterScriptContext context) {
284+
"""\
241285
@echo off
286+
set "LOG_FILE=${context.updaterLog}"
287+
call :main >> "%LOG_FILE%" 2>&1
288+
exit /b %ERRORLEVEL%
289+
290+
:main
291+
echo [%DATE% %TIME%] Starting update.
292+
echo [%DATE% %TIME%] Install dir: ${context.installDir}
293+
echo [%DATE% %TIME%] Extracted dir: ${context.extractedDir}
242294
timeout /t 3 /nobreak >nul
243-
if exist "${backupDir}" rd /s /q "${backupDir}"
244-
mkdir "${backupDir}"
245-
for %%f in ("${installDir}\\*.jar") do move "%%f" "${backupDir}\\"
246-
for %%f in ("${extractedDir}\\*.jar") do copy /y "%%f" "${installDir}\\"
295+
echo [%DATE% %TIME%] Preparing backup directory: ${context.backupDir}
296+
if exist "${context.backupDir}" rd /s /q "${context.backupDir}"
297+
mkdir "${context.backupDir}"
298+
if errorlevel 1 (
299+
echo [%DATE% %TIME%] Failed to create backup directory.
300+
exit /b 1
301+
)
302+
echo [%DATE% %TIME%] Backing up current JAR files.
303+
for %%f in ("${context.installDir}\\*.jar") do move "%%f" "${context.backupDir}\\"
247304
if errorlevel 1 (
248-
echo Update failed, restoring backup...
249-
for %%f in ("${backupDir}\\*.jar") do move "%%f" "${installDir}\\"
250-
rd /s /q "${backupDir}"
251-
echo Update failed. Please try again.
305+
echo [%DATE% %TIME%] Failed to back up current JAR files.
306+
exit /b 1
307+
)
308+
echo [%DATE% %TIME%] Copying updated JAR files.
309+
for %%f in ("${context.extractedDir}\\*.jar") do copy /y "%%f" "${context.installDir}\\"
310+
if errorlevel 1 (
311+
echo [%DATE% %TIME%] Update failed while copying files, restoring backup...
312+
for %%f in ("${context.backupDir}\\*.jar") do move "%%f" "${context.installDir}\\"
313+
rd /s /q "${context.backupDir}"
314+
echo [%DATE% %TIME%] Update failed. Please try again.
252315
pause
253316
exit /b 1
254317
)
255-
${newMainJar.isEmpty() ? '' : windowsConfigUpdateCommand(installDir, newMainJar, newVersion)}
256-
rd /s /q "${backupDir}"
257-
rd /s /q "${extractedDir}"
258-
del "${stagingDir}\\*.zip"
259-
${launcherCommand.isEmpty() ? 'echo Update complete.' : "start \"\" ${launcherCommand}"}
318+
echo [%DATE% %TIME%] Updating launcher configuration.
319+
${context.newMainJar.isEmpty() ? '' : windowsConfigUpdateCommand(context.installDir, context.newMainJar, context.newVersion)}
320+
echo [%DATE% %TIME%] Cleaning update staging files.
321+
rd /s /q "${context.backupDir}"
322+
rd /s /q "${context.extractedDir}"
323+
del "${context.stagingDir}\\*.zip"
324+
echo [%DATE% %TIME%] Launching application.
325+
${context.launcherCommand.isEmpty() ? 'echo Update complete.' : "start \"\" ${context.launcherCommand}"}
326+
echo [%DATE% %TIME%] Update script finished.
260327
del "%~f0"
261328
""".stripIndent()
262-
} else {
263-
script = stagingDir.resolve('updater.sh')
264-
script.toFile().text = """\
329+
}
330+
331+
private static String unixUpdaterScript(UpdaterScriptContext context) {
332+
"""\
265333
#!/usr/bin/env bash
266-
sleep 3
267-
rm -rf "${backupDir}"
268-
mkdir -p "${backupDir}"
269-
mv "${installDir}/"*.jar "${backupDir}/"
270-
if ! cp "${extractedDir}/"*.jar "${installDir}/"; then
271-
echo "Update failed, restoring backup..."
272-
mv "${backupDir}/"*.jar "${installDir}/"
273-
rm -rf "${backupDir}"
274-
echo "Update failed. Please try again."
334+
LOG_FILE="${context.updaterLog}"
335+
exec >> "\$LOG_FILE" 2>&1
336+
337+
timestamp() {
338+
date -Is
339+
}
340+
341+
log() {
342+
echo "[\$(timestamp)] \$*"
343+
}
344+
345+
fail() {
346+
log "\$*"
275347
exit 1
348+
}
349+
350+
log "Starting update."
351+
log "Install dir: ${context.installDir}"
352+
log "Extracted dir: ${context.extractedDir}"
353+
sleep 3
354+
log "Preparing backup directory: ${context.backupDir}"
355+
rm -rf "${context.backupDir}"
356+
mkdir -p "${context.backupDir}" || fail "Failed to create backup directory."
357+
log "Backing up current JAR files."
358+
if ! mv "${context.installDir}/"*.jar "${context.backupDir}/"; then
359+
fail "Failed to back up current JAR files."
360+
fi
361+
log "Copying updated JAR files."
362+
if ! cp "${context.extractedDir}/"*.jar "${context.installDir}/"; then
363+
log "Update failed while copying files, restoring backup..."
364+
mv "${context.backupDir}/"*.jar "${context.installDir}/"
365+
rm -rf "${context.backupDir}"
366+
fail "Update failed. Please try again."
276367
fi
277-
${newMainJar.isEmpty() ? '' : unixConfigUpdateCommand(installDir, newMainJar, newVersion)}
278-
rm -rf "${backupDir}"
279-
rm -rf "${extractedDir}"
280-
rm -f "${stagingDir}/"*.zip
281-
${launcherCommand.isEmpty() ? 'echo "Update complete."' : "exec ${launcherCommand} &"}
368+
log "Updating launcher configuration."
369+
${context.newMainJar.isEmpty() ? '' : unixConfigUpdateCommand(context.installDir, context.newMainJar, context.newVersion)}
370+
log "Cleaning update staging files."
371+
rm -rf "${context.backupDir}"
372+
rm -rf "${context.extractedDir}"
373+
rm -f "${context.stagingDir}/"*.zip
374+
log "Launching application."
375+
${context.launcherCommand.isEmpty() ? 'echo "Update complete."' : "${context.launcherCommand} &"}
376+
log "Update script finished."
282377
rm -f "\$0"
283378
""".stripIndent()
284-
script.toFile().setExecutable(true)
285-
}
286-
script
287379
}
288380

289381
private static String mainJarFileName(Path directory) {
@@ -385,6 +477,49 @@ powershell -NoProfile -ExecutionPolicy Bypass -Command "Get-ChildItem -LiteralPa
385477
}
386478
}
387479

480+
private static void notifyApplyPhase(Closure<Void> callback, ApplyPhase phase) {
481+
if (callback != null) {
482+
callback.call(phase)
483+
}
484+
}
485+
486+
enum ApplyPhase {
487+
EXTRACTING,
488+
STAGING,
489+
LAUNCHING
490+
}
491+
492+
private static final class UpdaterScriptContext {
493+
494+
final Path stagingDir
495+
final Path extractedDir
496+
final Path installDir
497+
final Path updaterLog
498+
final Path backupDir
499+
final String launcherCommand
500+
final String newMainJar
501+
final String newVersion
502+
503+
private UpdaterScriptContext(
504+
Path stagingDir,
505+
Path extractedDir,
506+
Path installDir,
507+
Path updaterLog,
508+
Path backupDir,
509+
String launcherCommand,
510+
String newMainJar,
511+
String newVersion) {
512+
this.stagingDir = stagingDir
513+
this.extractedDir = extractedDir
514+
this.installDir = installDir
515+
this.updaterLog = updaterLog
516+
this.backupDir = backupDir
517+
this.launcherCommand = launcherCommand
518+
this.newMainJar = newMainJar
519+
this.newVersion = newVersion
520+
}
521+
}
522+
388523
static final class UpdateInfo {
389524

390525
String currentVersion

0 commit comments

Comments
 (0)