Update fails silently

[krit0n]

I inherited a project, that is utilizing the Modularmind Updatemanager.

This projects build generates

• a zip file containing the deliverable product (as of now called the client)
• and a p2 repository containing all dependencies of the client.

Here is a sketch of the clients dependency tree:

client
├───klv-feature.feature.group  Version: 1.0.1.2
│   ├───klv-shared             Version: 1.0.1.2
│   ├───klv-ui                 Version: 1.0.1.2
│   └───...
├───...
└───com.modumind.updatemanager.feature.feature.group
                               Version: 1.0.0.202112082110

The Modularmind Updatemanager is invoked every time the client starts:

@Inject UpdateManager updateManager;
// ..

@PostContextCreate
void postContextCreate() {
  log.info("------------------------------");
  log.info("       Starting KLV 4.0       ");
  log.info("------------------------------");
  logSystemInformation();
  log.info("check for updates...");
  boolean updateDone = updateManager.performAutoUpdate();
  // ..
  // restart application if `updateDone` is true
}

As long as the contents of the p2 repository match the dependencies of the client no updates are made. As is expected.

Then I upgrade the contents of the p2 repository to a newer version (1.0.2.3):

repository
├───features
│   ├───klv-feature_1.0.2.3.jar
│   ├───com.modumind.updatemanager.feature_1.0.0.202112082110.jar
│   └───...
├───plugins
│   ├───com.evolit.klv.shared_1.0.2.3.jar
│   ├───klv-ui_1.0.2.3.jar
│   └───...
└───...

---

When I start the client at this point I expect the Modularmind Updatemanager to discover that some bundles can be updated, fetch these bundles from the repository and signal my application that it should restart (thus updateManager.performAutoUpdate should return true).

But no updates are fetched and the application starts without the updates.

Here is the relevant log:

14:23:10.254 [0cd862bd67] [DEBUG] c.e.k.s.extension.KlvApiObjectMapper   - Initialize new ObjectMapper.
14:23:10.349 [0cd862bd67] [INFO ] c.e.k.service.KLVUpdateManagerLogger   - Initialize new KLVUpdateManagerLogger
14:23:11.140 [      main] [INFO ] c.e.k.ui.state.ApplicationState        - ApplicationState init
14:23:11.376 [      main] [INFO ] c.e.k.ui.state.ApplicationState        - ClientId set to 88A4C24E7EA5
14:23:11.392 [      main] [INFO ] c.e.k.ui.login.LoginController         - LoginController init
14:23:11.392 [      main] [INFO ] c.e.k.ui.LifeCycleManager              - LifeCycleManager init
14:23:11.394 [      main] [INFO ] c.e.k.ui.LifeCycleManager              - ------------------------------
14:23:11.394 [      main] [INFO ] c.e.k.ui.LifeCycleManager              -        Starting KLV 4.0       
14:23:11.394 [      main] [INFO ] c.e.k.ui.LifeCycleManager              - ------------------------------
14:23:11.394 [      main] [INFO ] c.e.k.ui.LifeCycleManager              - java.version: 11.0.15
14:23:11.394 [      main] [INFO ] c.e.k.ui.LifeCycleManager              - java.class.version: 55.0
14:23:11.394 [      main] [INFO ] c.e.k.ui.LifeCycleManager              - java.home: C:\Users\cweber\test\klv-client-win32.x86_64-1.0.1.2\plugins\org.eclipse.justj.openjdk.hotspot.jre.full.win32.x86_64_11.0.15.v20220515-1236\jre
14:23:11.394 [      main] [INFO ] c.e.k.ui.LifeCycleManager              - java.class.path: C:\Users\cweber\test\klv-client-win32.x86_64-1.0.1.2\\plugins/org.eclipse.equinox.launcher_1.6.400.v20210924-0641.jar
14:23:11.394 [      main] [INFO ] c.e.k.ui.LifeCycleManager              - user.dir: C:\Users\cweber\test\klv-client-win32.x86_64-1.0.1.2
14:23:11.394 [      main] [INFO ] c.e.k.ui.LifeCycleManager              - user.home: C:\Users\cweber
14:23:11.394 [      main] [INFO ] c.e.k.ui.LifeCycleManager              - isTest: false
14:23:11.394 [      main] [INFO ] c.e.k.ui.LifeCycleManager              - repository URL: file:///Users/cweber/test/repository
14:23:11.394 [      main] [INFO ] c.e.k.ui.LifeCycleManager              - version: 1.0.1.2
14:23:11.394 [      main] [INFO ] c.e.k.ui.LifeCycleManager              - check for updates...
14:23:11.394 [      main] [INFO ] c.e.k.service.KLVUpdateManagerLogger   - ----------------------------------------------------------------
14:23:11.394 [      main] [INFO ] c.e.k.service.KLVUpdateManagerLogger   - Initializing P2 auto-update process
14:23:11.394 [      main] [INFO ] c.e.k.service.KLVUpdateManagerLogger   - ----------------------------------------------------------------
14:23:11.395 [      main] [INFO ] c.e.k.service.KLVUpdateManagerLogger   - Provisioning agent created
14:23:11.402 [      main] [INFO ] c.e.k.service.KLVUpdateManagerLogger   - Provisioning session created
14:23:11.402 [      main] [INFO ] c.e.k.service.KLVUpdateManagerLogger   - ----------------------------------------------------------------
14:23:11.402 [      main] [INFO ] c.e.k.service.KLVUpdateManagerLogger   - Processing updates
14:23:11.402 [      main] [INFO ] c.e.k.service.KLVUpdateManagerLogger   - ----------------------------------------------------------------
14:23:11.695 [      main] [INFO ] c.e.k.service.KLVUpdateManagerLogger   - Metadata repository loaded: file:///Users/cweber/test/repository
14:23:14.027 [      main] [INFO ] c.e.k.service.KLVUpdateManagerLogger   - Artifact repository loaded: file:///Users/cweber/test/repository
14:23:14.512 [      main] [INFO ] c.e.k.service.KLVUpdateManagerLogger   - Update operation resolved successfully
14:23:14.512 [      main] [INFO ] c.e.k.service.KLVUpdateManagerLogger   - Updates found:
14:23:14.513 [      main] [INFO ] c.e.k.service.KLVUpdateManagerLogger   -  - Update klv-feature.feature.group 1.0.1.2 ==> klv-feature.feature.group 1.0.2.3
14:23:14.513 [      main] [INFO ] c.e.k.service.KLVUpdateManagerLogger   - ----------------------------------------------------------------
14:23:14.513 [      main] [INFO ] c.e.k.service.KLVUpdateManagerLogger   - Process installs
14:23:14.513 [      main] [INFO ] c.e.k.service.KLVUpdateManagerLogger   - ----------------------------------------------------------------
14:23:14.516 [      main] [INFO ] c.e.k.service.KLVUpdateManagerLogger   - IUs to install (possibly 283):
14:23:14.517 [      main] [INFO ] c.e.k.service.KLVUpdateManagerLogger   - Nothing found to install
14:23:14.520 [      main] [INFO ] c.e.k.service.KLVUpdateManagerLogger   - ----------------------------------------------------------------
14:23:14.521 [      main] [INFO ] c.e.k.service.KLVUpdateManagerLogger   - Auto-update processing complete. Return restart flag: false
14:23:14.521 [      main] [INFO ] c.e.k.service.KLVUpdateManagerLogger   - ----------------------------------------------------------------
14:23:14.812 [      main] [INFO ] c.e.k.ui.LifeCycleManager              - no update necessary

[krit0n]

I made some experiments with different versioning schemes.

---

Sometimes it works:
e.g. client has version 1.0.24.202210181346, p2 repository has version 1.0.25.202210191307
==>

15:10:31.859 [      main] [INFO ] c.e.klv.ui.LifeCycleManager              - version: 1.0.24.202210181346
15:10:31.859 [      main] [INFO ] c.e.klv.ui.LifeCycleManager              - check for updates...
15:10:31.859 [      main] [INFO ] c.e.klv.service.KLVUpdateManagerLogger   - ----------------------------------------------------------------
15:10:31.859 [      main] [INFO ] c.e.klv.service.KLVUpdateManagerLogger   - Initializing P2 auto-update process
15:10:31.859 [      main] [INFO ] c.e.klv.service.KLVUpdateManagerLogger   - ----------------------------------------------------------------
15:10:31.860 [      main] [INFO ] c.e.klv.service.KLVUpdateManagerLogger   - Provisioning agent created
15:10:31.867 [      main] [INFO ] c.e.klv.service.KLVUpdateManagerLogger   - Provisioning session created
15:10:31.867 [      main] [INFO ] c.e.klv.service.KLVUpdateManagerLogger   - ----------------------------------------------------------------
15:10:31.867 [      main] [INFO ] c.e.klv.service.KLVUpdateManagerLogger   - Processing updates
15:10:31.867 [      main] [INFO ] c.e.klv.service.KLVUpdateManagerLogger   - ----------------------------------------------------------------
15:10:32.545 [      main] [INFO ] c.e.klv.service.KLVUpdateManagerLogger   - Metadata repository loaded: http://some.url.at/klv/p2/
15:10:32.654 [      main] [INFO ] c.e.klv.service.KLVUpdateManagerLogger   - Artifact repository loaded: http://some.url.at/klv/p2/
15:10:33.709 [      main] [INFO ] c.e.klv.service.KLVUpdateManagerLogger   - Update operation resolved successfully
15:10:33.710 [      main] [INFO ] c.e.klv.service.KLVUpdateManagerLogger   - Updates found:
15:10:33.710 [      main] [INFO ] c.e.klv.service.KLVUpdateManagerLogger   -  - Update klv-feature.feature.group 1.0.24.202210181346 ==> klv-feature.feature.group 1.0.25.202210191307
15:10:35.003 [dalContext] [INFO ] c.e.klv.service.KLVUpdateManagerLogger   - Provisioning job completed succesfully. Setting restart flag to true
15:10:35.044 [      main] [INFO ] c.e.klv.service.KLVUpdateManagerLogger   - ----------------------------------------------------------------
15:10:35.045 [      main] [INFO ] c.e.klv.service.KLVUpdateManagerLogger   - Process installs
15:10:35.045 [      main] [INFO ] c.e.klv.service.KLVUpdateManagerLogger   - ----------------------------------------------------------------
15:10:35.048 [      main] [INFO ] c.e.klv.service.KLVUpdateManagerLogger   - IUs to install (possibly 283):
15:10:35.048 [      main] [INFO ] c.e.klv.service.KLVUpdateManagerLogger   - Nothing found to install
15:10:35.051 [      main] [INFO ] c.e.klv.service.KLVUpdateManagerLogger   - ----------------------------------------------------------------
15:10:35.051 [      main] [INFO ] c.e.klv.service.KLVUpdateManagerLogger   - Auto-update processing complete. Return restart flag: true
15:10:35.051 [      main] [INFO ] c.e.klv.service.KLVUpdateManagerLogger   - ----------------------------------------------------------------
15:10:35.313 [      main] [INFO ] c.e.klv.ui.LifeCycleManager              - update was performed

---

Sometimes it fails:
e.g. client has version 1.0.1.rc-3, p2 repository has version 1.0.20.202210190736
==>

19.10.2022 09:42:49.359 [      main] [INFO ] c.e.klv.ui.LifeCycleManager              - check for updates...
19.10.2022 09:42:49.359 [      main] [INFO ] c.e.klv.service.KLVUpdateManagerLogger   - ----------------------------------------------------------------
19.10.2022 09:42:49.359 [      main] [INFO ] c.e.klv.service.KLVUpdateManagerLogger   - Initializing P2 auto-update process
09:42:49.359 [      main] [INFO ] c.e.klv.service.KLVUpdateManagerLogger   - ----------------------------------------------------------------
09:42:49.360 [      main] [INFO ] c.e.klv.service.KLVUpdateManagerLogger   - Provisioning agent created
09:42:49.367 [      main] [INFO ] c.e.klv.service.KLVUpdateManagerLogger   - Provisioning session created
09:42:49.367 [      main] [INFO ] c.e.klv.service.KLVUpdateManagerLogger   - ----------------------------------------------------------------
09:42:49.367 [      main] [INFO ] c.e.klv.service.KLVUpdateManagerLogger   - Processing updates
09:42:49.367 [      main] [INFO ] c.e.klv.service.KLVUpdateManagerLogger   - ----------------------------------------------------------------
09:42:49.629 [      main] [INFO ] c.e.klv.service.KLVUpdateManagerLogger   - Metadata repository loaded: file:///Users/cweber/Downloads/test/repository-1.0.20-SNAPSHOT
09:42:54.305 [      main] [INFO ] c.e.klv.service.KLVUpdateManagerLogger   - Artifact repository loaded: file:///Users/cweber/Downloads/test/repository-1.0.20-SNAPSHOT
09:42:54.938 [      main] [INFO ] c.e.klv.service.KLVUpdateManagerLogger   - Update operation resolved successfully
09:42:54.938 [      main] [INFO ] c.e.klv.service.KLVUpdateManagerLogger   - Updates found:
09:42:54.938 [      main] [INFO ] c.e.klv.service.KLVUpdateManagerLogger   -  - Update klv-feature.feature.group 1.0.1.rc-3 ==> klv-feature.feature.group 1.0.20.202210190736
09:42:55.207 [      main] [ERROR] c.e.klv.service.KLVUpdateManagerLogger   - Uncaught exception occurred during job execution
java.lang.reflect.InvocationTargetException: null
	at org.eclipse.jface.operation.ModalContext.run(ModalContext.java:395)
	at org.eclipse.jface.dialogs.ProgressMonitorDialog.run(ProgressMonitorDialog.java:470)
	at com.modumind.updatemanager.service.impl.UpdateManagerImpl.runProvisioningJob(UpdateManagerImpl.java:298)
	at com.modumind.updatemanager.service.impl.UpdateManagerImpl.performAutoUpdate(UpdateManagerImpl.java:136)
	at com.evolit.klv.ui.LifeCycleManager.postContextCreate(LifeCycleManager.java:63)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
	at org.eclipse.e4.core.internal.di.MethodRequestor.execute(MethodRequestor.java:58)
	at org.eclipse.e4.core.internal.di.InjectorImpl.invokeUsingClass(InjectorImpl.java:317)
	at org.eclipse.e4.core.internal.di.InjectorImpl.invoke(InjectorImpl.java:245)
	at org.eclipse.e4.core.contexts.ContextInjectionFactory.invoke(ContextInjectionFactory.java:147)
	at org.eclipse.e4.ui.internal.workbench.swt.E4Application.lambda$0(E4Application.java:233)
	at java.base/java.util.Optional.ifPresent(Optional.java:183)
	at org.eclipse.e4.ui.internal.workbench.swt.E4Application.createE4Workbench(E4Application.java:229)
	at org.eclipse.e4.ui.internal.workbench.swt.E4Application.start(E4Application.java:155)
	at org.eclipse.equinox.internal.app.EclipseAppHandle.run(EclipseAppHandle.java:203)
	at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.runApplication(EclipseAppLauncher.java:136)
	at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.start(EclipseAppLauncher.java:104)
	at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:401)
	at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:255)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
	at org.eclipse.equinox.launcher.Main.invokeFramework(Main.java:659)
	at org.eclipse.equinox.launcher.Main.basicRun(Main.java:596)
	at org.eclipse.equinox.launcher.Main.run(Main.java:1467)
Caused by: java.lang.NullPointerException: null
	at com.modumind.updatemanager.service.impl.UpdateManagerImpl$1.run(UpdateManagerImpl.java:306)
	at org.eclipse.jface.operation.ModalContext$ModalContextThread.run(ModalContext.java:122)
09:42:55.207 [      main] [INFO ] c.e.klv.service.KLVUpdateManagerLogger   - ----------------------------------------------------------------
09:42:55.207 [      main] [INFO ] c.e.klv.service.KLVUpdateManagerLogger   - Process installs
09:42:55.207 [      main] [INFO ] c.e.klv.service.KLVUpdateManagerLogger   - ----------------------------------------------------------------
09:42:55.210 [      main] [INFO ] c.e.klv.service.KLVUpdateManagerLogger   - IUs to install (possibly 283):
09:42:55.211 [      main] [INFO ] c.e.klv.service.KLVUpdateManagerLogger   - Nothing found to install
09:42:55.613 [      main] [INFO ] c.e.klv.service.KLVUpdateManagerLogger   - ----------------------------------------------------------------
09:42:55.613 [      main] [INFO ] c.e.klv.service.KLVUpdateManagerLogger   - Auto-update processing complete. Return restart flag: false
09:42:55.613 [      main] [INFO ] c.e.klv.service.KLVUpdateManagerLogger   - ----------------------------------------------------------------
09:42:55.736 [      main] [INFO ] c.e.klv.ui.LifeCycleManager              - no update necessary

I think this NPE is caused because IStatus can have an Severity equal to IStatus.ERROR and nevertheless have an Exception of null (For instance such an exception is generated in PlannerResolutionJob#84). In this line UpdateManagerImpl#306 this Status would cause a NPE.

Maybe IStatus#getMessage could be called instead of status.getException().getMessage().

[modular-mind]

@krit0n Thanks so much for the detailed issue report. I can fix the NPE of course and I'll look into the first error. It looks like the update is failing but the log doesn't record it for some reason.

Sorry for the delayed response btw, I've been traveling to EclipseCon this week and getting over jet lag. I should have some time soon to work on this.

[krit0n]

Hi @modular-mind - I already found the cause for my issue. The problem was in my project. There was a problem with the dependency resolution:

Status ERROR: org.eclipse.equinox.p2.director code=10053 Cannot complete the install because one or more required items could not be found. children=[
  Status ERROR: org.eclipse.equinox.p2.director code=0 Software being installed: Feature 1.0.2.3 (klv-feature.feature.group 1.0.2.3)
  Status ERROR: org.eclipse.equinox.p2.director code=0 Missing requirement: camco-api 1.0.0.SNAPSHOT (com.evolit.klv.camco-api 1.0.0.SNAPSHOT) requires 'java.package; com.fasterxml.jackson.annotation [2.13.0,3.0.0)' but it could not be found
  Status ERROR: org.eclipse.equinox.p2.director code=1 Cannot satisfy dependency: children=[
    Status ERROR: org.eclipse.equinox.p2.director code=0 From: Feature 1.0.2.3 (klv-feature.feature.group 1.0.2.3)
    Status ERROR: org.eclipse.equinox.p2.director code=0 To: org.eclipse.equinox.p2.iu; com.evolit.klv.camco-api [1.0.0.SNAPSHOT,1.0.0.SNAPSHOT]
  ]
]

(strangely this error only pops up if I make a p2 update. If I start a freshly build client without update it starts without complaints)

---

The only thing that could be made better in the Modularmind Updatemanager is the logging of this kind of problem:

In UpdateManagerImpl#226 the Method getProvisioningJob of ProfileChangeOperation is called.

This method may return null. (This is the case if the status that is returned in ProfileChangeOperation#getProvisioningJob(IProgressMonitor) by the method ProfileChangeOperation#getResolutionResult() is ERROR or CANCEL. In this case the error message that is contained in status is lost)

IMHO the solution should be - as is suggested in the documentation of ProfileChangeOperation#getProvisioningJob:

@return a job that can be used to perform the provisioning operation. This may be null
if the operation has not been resolved, or if a plan could not be obtained when attempting to
resolve. If the job is null and the operation has been resolved, then the resolution result
will explain the problem.

Therefore if the result of updateOperation.getProvisioningJob(null) (in this line) is null, the status should be retrieved by calling updateOperation.getResolutionResult() and passed to the logger.

[krit0n]

I haven't investigated further. But I guess that the same kind of issue with the logging happens in the install Job

[krit0n]

@krit0n Thanks so much for the detailed issue report. I can fix the NPE of course and I'll look into the first error. It looks like the update is failing but the log doesn't record it for some reason.

Sorry for the delayed response btw, I've been traveling to EclipseCon this week and getting over jet lag. I should have some time soon to work on this.

No hurry in fixing the issue. I have solved my critical problem now.
Thank you for your useful project 👍

---

I have just noticed that the other issues in this project seem to be from my ex colleague 😆