Plugin Installation Failed


#1

I’ve created a fresh plugin sample from scratch using:

atlas-create-confluence-plugin

Then the confluence version was changed to exact what is used in test, Confluence 6.11.0. After that I created the package:

atlas-package

and installed the jar manually using the UPM file upload. Immediately UPM throws following exception:

After refreshing the page, the plugin was installed successfully. I have the same error for a more complex custom plugin, where this error is thrown, but UPM installs the plugin.

The logs do not show anything suspicious

2018-12-07 12:50:25,668 WARN [Caesium-1-1] [impl.schedule.caesium.JobRunnerWrapper] runJob Scheduled job LaasPerformanceLoggingJob#LaasPerformanceLoggingJob completed unsuccessfully with response JobRunnerResponse[runOutcome=ABORTED,message='LaaS performance logging is turned off']
2018-12-07 12:50:30,618 DEBUG [ThreadPoolAsyncTaskExecutor::Thread 54] [com.example.test.spring] printBundleDebugInfo
	Bundle Id : 266
	Bundle Name : com.example.test
	Bundle Location : file:/opt/atlassian/application-data/confluence/plugins-cache/1544183430550plugin_9019756578600465682_test-1.0.0-SNAPSHOT.jar
	Bundle Version : 1.0.0.SNAPSHOT
	Bundle Headers :
		Archiver-Version: Plexus Archiver
		Atlassian-Build-Date: 2018-12-07T12:48:54+0100
		Atlassian-Plugin-Key: com.example.test
		Bnd-LastModified: 1544183335421
		Build-Jdk: 1.8.0_121
		Built-By: david
		Bundle-Description: This is the com.example:test plugin for Atlassian Confluence.
		Bundle-DocURL: http://www.example.com/
		Bundle-ManifestVersion: 2
		Bundle-Name: test
		Bundle-SymbolicName: com.example.test
		Bundle-Vendor: Example Company
		Bundle-Version: 1.0.0.SNAPSHOT
		Created-By: Apache Maven Bundle Plugin
		Export-Package: com.example.test.api;version="1.0.0"
		Import-Package: org.springframework.osgi.context;resolution:=optional,org.springframework.osgi.service.exporter.support;resolution:=optional,org.springframework.osgi.service.importer.support;resolution:=optional,org.eclipse.gemini.blueprint.context;resolution:=optional,org.eclipse.gemini.blueprint.service.exporter;resolution:=optional,org.eclipse.gemini.blueprint.service.exporter.support;resolution:=optional,org.eclipse.gemini.blueprint.service.importer.support;resolution:=optional,com.atlassian.plugin.osgi.factory,com.atlassian.sal.api,com.example.test.api;version="[1.0,2)",com.google.common.base,com.google.common.collect,javax.annotation,javax.inject,org.apache.commons.lang,org.apache.commons.logging,org.osgi.framework,org.springframework.aop.support,org.springframework.beans,org.springframework.beans.factory,org.springframework.beans.factory.annotation,org.springframework.beans.factory.config,org.springframework.beans.factory.parsing,org.springframework.beans.factory.support,org.springframework.beans.factory.xml,org.springframework.context.annotation,org.springframework.core.io,org.springframework.stereotype,org.springframework.util,org.w3c.dom
		Manifest-Version: 1.0
		Originally-Created-By: Apache Maven Bundle Plugin
		Require-Capability: osgi.ee;filter:="(&(osgi.ee=JavaSE)(version=1.8))"
		Spring-Context: *
		Tool: Bnd-3.5.0.201709291849


2018-12-07 12:50:30,620 DEBUG [ThreadPoolAsyncTaskExecutor::Thread 54] [com.example.test.spring] logBeanDetail BeforeInstantiation [bean=myPluginComponent, type=com.example.test.impl.MyPluginComponentImpl]
2018-12-07 12:50:30,621 DEBUG [ThreadPoolAsyncTaskExecutor::Thread 54] [com.example.test.spring] logBeanDetail AfterInitialisation [bean=applicationProperties, type=com.sun.proxy.$Proxy2611]
2018-12-07 12:50:30,624 DEBUG [ThreadPoolAsyncTaskExecutor::Thread 54] [com.example.test.spring] logBeanDetail AfterInitialisation [bean=myPluginComponent_osgiService, type=org.eclipse.gemini.blueprint.service.exporter.support.internal.support.ServiceRegistrationWrapper]
2018-12-07 12:50:30,624 DEBUG [ThreadPoolAsyncTaskExecutor::Thread 54] [com.example.test.spring] logBeanDetail AfterInitialisation [bean=myPluginComponent, type=com.example.test.impl.MyPluginComponentImpl]
2018-12-07 12:50:30,624 DEBUG [ThreadPoolAsyncTaskExecutor::Thread 54] [com.example.test.spring] logBeanDetail BeforeInstantiation [bean=org.springframework.context.event.internalEventListenerProcessor, type=org.springframework.context.event.EventListenerMethodProcessor]
2018-12-07 12:50:30,625 DEBUG [ThreadPoolAsyncTaskExecutor::Thread 54] [com.example.test.spring] logBeanDetail AfterInitialisation [bean=org.springframework.context.event.internalEventListenerProcessor, type=org.springframework.context.event.EventListenerMethodProcessor]
2018-12-07 12:50:30,625 DEBUG [ThreadPoolAsyncTaskExecutor::Thread 54] [com.example.test.spring] logBeanDetail BeforeInstantiation [bean=org.springframework.context.event.internalEventListenerFactory, type=org.springframework.context.event.DefaultEventListenerFactory]
2018-12-07 12:50:30,625 DEBUG [ThreadPoolAsyncTaskExecutor::Thread 54] [com.example.test.spring] logBeanDetail AfterInitialisation [bean=org.springframework.context.event.internalEventListenerFactory, type=org.springframework.context.event.DefaultEventListenerFactory]
2018-12-07 12:50:33,151 WARN [UpmScheduler:thread-4] [atlassian.upm.pac.PacClientImpl] getUpdates Update check request may take longer because of the number of apps
 -- url: /confluence/rest/plugins/1.0/ | referer: https://ppm.bytesourcecloud.com/confluence/plugins/servlet/upm | traceId: 5aba18befd30966a | userName: david

The only error is about the update check:

2018-12-07 12:50:33,151 WARN [UpmScheduler:thread-4] [atlassian.upm.pac.PacClientImpl] getUpdates Update check request may take longer because of the number of apps

Any idea?


#2

I just tried what you described

  • run create-atlassian-confluence-plugin
  • changed version from 6.12.0 to 6.11.0 in the pom.xml
  • run atlas-clean
  • run atlas-package
  • installed the plugin via upm

This worked for me on the first try.

Which atlas-sdk version do you use? What was the original confluence version, when running create-plugin?


#3

My Confluence instance version is 6.11.0.

ATLAS Version:    6.3.12
ATLAS Home:       /usr/local/Cellar/atlassian-plugin-sdk/6.3.10/libexec
ATLAS Scripts:    /usr/local/Cellar/atlassian-plugin-sdk/6.3.10/libexec/bin
ATLAS Maven Home: /usr/local/Cellar/atlassian-plugin-sdk/6.3.10/libexec/apache-maven-3.2.1
AMPS Version:     6.3.21

What Confluence target version do you have in your case?


#4

Is your base URL set to the wrong one by any chance? UPM won’t work properly if it isn’t and this might happen.
In any case, you can use your browser’s inspect window to see where the requests are failing.


#5

Console shows following:

The only request fired after hitting the “upload” button on the “Upload app” dialog is this one:

The unexpected error message is shown in background and loading indicator spins forever:


#6

Forgot to mention that the base URL is also configured correctly.


#7

That’s a bit weird so far. Looks like UPM is getting something that it’s not expecting and trying to parse it as JSON. As a long shot: there wouldn’t be an update for UPM available, right?

In the Network tab, you’ll need to switch the filter to “All” to see all requests. The file upload is actually a form submit and not an XHR.
Also, please make sure to uninstall the app and reload the page before recording the Network traffic. The upm-token that’s in the request should ideally not be cached.

1st request is (I think) the web interface checking to see if there’s an operation running.
2nd request is the spinner gif, ignore that.
3rd request is the file upload with an old upm-token. This works here since the token is not expired.
4th request is a HEAD request for the /rest/plugins/1.0/ resource to get a upm-token in case the token had expired. I’m assuming requests 3 and 4 in this case are sent in parallel. In this case (token not expired) it wouldn’t be necessary. But in case the token had been expired, this would speed things up.
All subsequent requests after this are requesting the state of the installation and after that are just requests to update the UI (not displayed).

Below is an image of what it looks like with an expired token:

The upload request is being repeated with the new token in this case.

Here’s the content of the upload response for me:

<textarea>{
   "type":"INSTALL",
   "pingAfter":100,
   "status":{
      "done":false,
      "statusCode":200,
      "contentType":"application/vnd.atl.plugins.install.installing+json",
      "source":"myapp.obr",
      "name":"myapp.obr"
   },
   "links":{
      "self":"/jira/rest/plugins/1.0/pending/1bba4e5e-f527-4570-9ce1-9700dabc8c0d",
      "alternate":"/jira/rest/plugins/1.0/tasks/1bba4e5e-f527-4570-9ce1-9700dabc8c0d"
   },
   "timestamp":1544479748903,
   "userKey":"admin",
   "id":"1bba4e5e-f527-4570-9ce1-9700dabc8c0d"
}</textarea>

(I think Atlassian wraps this in a textarea as a countermeasure to either bypass something or protect from something, not sure)

This is what things look like for me. Could you maybe rerecord your upload and see if there’s anything funny going on with the upload request? Do you maybe have a reverse proxy that might do something funny to the response due to the weird wrapping?


#8

Here all requests:

During the endless spinner the “since” requests are performed periodically. The access logs of NGINX look also fine:

213.94.78.65 - - [11/Dec/2018:10:50:22 +0100] "GET /confluence/rest/plugins/1.0/pending?_=1544521845505 HTTP/2.0" 200 68 "https://ppm.bytesourcecloud.com/confluence/plugins/servlet/upm" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/70.0.3538.110 Safari/537.36"
213.94.78.65 - - [11/Dec/2018:10:50:22 +0100] "GET /confluence/s/en_GB/7801/0ac8ad8167063a2d16fb426a10b9044cf4bf1b17/2.22.18/_/download/resources/com.atlassian.upm.atlassian-universal-plugin-manager-plugin:upm-web-resources/images/in-progress.gif HTTP/2.0" 200 3208 "https://ppm.bytesourcecloud.com/confluence/plugins/servlet/upm" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/70.0.3538.110 Safari/537.36"
213.94.78.65 - - [11/Dec/2018:10:50:22 +0100] "POST /confluence/rest/plugins/1.0/?token=-9103088979935614679 HTTP/2.0" 202 336 "https://ppm.bytesourcecloud.com/confluence/plugins/servlet/upm" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/70.0.3538.110 Safari/537.36"
213.94.78.65 - - [11/Dec/2018:10:50:31 +0100] "GET /confluence/rest/quickreload/latest/0?since=1544521650787 HTTP/2.0" 200 102 "https://ppm.bytesourcecloud.com/confluence/admin/viewgeneralconfig.action" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/70.0.3538.110 Safari/537.36"
213.94.78.65 - - [11/Dec/2018:10:50:33 +0100] "GET /confluence/rest/mywork/latest/status/notification/count HTTP/2.0" 200 56 "https://ppm.bytesourcecloud.com/confluence/plugins/servlet/upm" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/70.0.3538.110 Safari/537.36"
213.94.78.65 - - [11/Dec/2018:10:50:33 +0100] "GET /confluence/rest/quickreload/latest/0?since=1544521801176 HTTP/2.0" 200 102 "https://ppm.bytesourcecloud.com/confluence/plugins/servlet/upm" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/70.0.3538.110 Safari/537.36"

The upload response, looks similar to yours:

<textarea>
{
   "type":"INSTALL",
   "pingAfter":100,
   "status":{
      "done":false,
      "statusCode":200,
      "contentType":"application/vnd.atl.plugins.install.installing+json",
      "source":"test-1.0.0-SNAPSHOT.jar",
      "name":"test-1.0.0-SNAPSHOT.jar"
   },
   "links":{
      "self":"/confluence/rest/plugins/1.0/pending/7968c2a6-20c8-4872-981f-d8aff0b9cfb4",
      "alternate":"/confluence/rest/plugins/1.0/tasks/7968c2a6-20c8-4872-981f-d8aff0b9cfb4"
   },
   "timestamp":1544521483593,
   "userKey":"393190b9673fb3dd016787847d6a0000",
   "id":"7968c2a6-20c8-4872-981f-d8aff0b9cfb4"
}
</textarea>

Should have done this earlier, in Firefox 63.0.1 the upload works as expected.

I guess it makes no sense to continue debugging this issue, unless you have more idea. Thanks in any case!