shinesolutions/puppet-aem-curator

Installing content package fails with missing multipart boundary

Opened this issue · 2 comments

    aem_curator::install_aem_package { "${aem_instance['aem_id']}: Install Sling mappings":
      tmp_dir         => $aem_instance['tmp_dir'],
      file_name       => "mappings.zip",
      package_group   => $mappings_config['package_group'],
      package_name    => $mappings_config['package_name'],
      package_version => $mappings_config['package_version'],
      artifacts_base  => $aem_instance['aem_artifacts_base'],
      aem_id          => $aem_instance['aem_id'],
      force           => true
    }

Fails with:

16.10.2019 13:58:47.659 *WARN* [qtp1899598146-1640] com.day.crx.packaging.impl.PackageManagerServlet PackageConsoleServlet requested with GET
16.10.2019 13:58:47.662 *ERROR* [qtp1899598146-1637] com.day.crx.packmgr.impl.support.HttpMultipartPost Error while processing multipart.
org.apache.commons.fileupload.FileUploadException: the request was rejected because no multipart boundary was found
	at org.apache.commons.fileupload.FileUploadBase$FileItemIteratorImpl.<init>(FileUploadBase.java:990)
	at org.apache.commons.fileupload.FileUploadBase.getItemIterator(FileUploadBase.java:310)
	at org.apache.commons.fileupload.servlet.ServletFileUpload.getItemIterator(ServletFileUpload.java:154) [org.apache.commons.fileupload:1.3.3]
	at com.day.crx.packmgr.impl.support.HttpMultipartPost.decodeMultipart(HttpMultipartPost.java:149) [com.adobe.granite.crx-packagemgr:1.2.74]
	at com.day.crx.packmgr.impl.support.HttpMultipartPost.<init>(HttpMultipartPost.java:217) [com.adobe.granite.crx-packagemgr:1.2.74]
	at com.day.crx.packaging.impl.RequestWrapper.<init>(RequestWrapper.java:40) [com.adobe.granite.crx-packagemgr:1.2.74]
	at com.day.crx.packaging.impl.PackageManagerServlet.doPost(PackageManagerServlet.java:100) [com.adobe.granite.crx-packagemgr:1.2.74]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:644) [org.apache.felix.http.servlet-api:1.1.2]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:725) [org.apache.felix.http.servlet-api:1.1.2]
	at org.apache.felix.http.base.internal.handler.ServletHandler.handle(ServletHandler.java:123) [org.apache.felix.http.jetty:4.0.8]
	at org.apache.felix.http.base.internal.dispatch.InvocationChain.doFilter(InvocationChain.java:86) [org.apache.felix.http.jetty:4.0.8]
	at com.adobe.granite.license.impl.LicenseCheckFilter.doFilter(LicenseCheckFilter.java:308) [com.adobe.granite.license:1.2.10]
	at org.apache.felix.http.base.internal.handler.FilterHandler.handle(FilterHandler.java:142) [org.apache.felix.http.jetty:4.0.8]
	at org.apache.felix.http.base.internal.dispatch.InvocationChain.doFilter(InvocationChain.java:81) [org.apache.felix.http.jetty:4.0.8]
	at org.apache.sling.i18n.impl.I18NFilter.doFilter(I18NFilter.java:131) [org.apache.sling.i18n:2.5.14]
	at org.apache.felix.http.base.internal.handler.FilterHandler.handle(FilterHandler.java:142) [org.apache.felix.http.jetty:4.0.8]
	at org.apache.felix.http.base.internal.dispatch.InvocationChain.doFilter(InvocationChain.java:81) [org.apache.felix.http.jetty:4.0.8]
	at org.apache.felix.http.base.internal.dispatch.Dispatcher$1.doFilter(Dispatcher.java:146) [org.apache.felix.http.jetty:4.0.8]
	at org.apache.felix.http.base.internal.whiteboard.WhiteboardManager$2.doFilter(WhiteboardManager.java:1002) [org.apache.felix.http.jetty:4.0.8]
	at org.apache.sling.security.impl.ReferrerFilter.doFilter(ReferrerFilter.java:326) [org.apache.sling.security:1.1.16]
	at org.apache.felix.http.base.internal.handler.PreprocessorHandler.handle(PreprocessorHandler.java:136) [org.apache.felix.http.jetty:4.0.8]
	at org.apache.felix.http.base.internal.whiteboard.WhiteboardManager$2.doFilter(WhiteboardManager.java:1008) [org.apache.felix.http.jetty:4.0.8]
	at org.apache.felix.http.sslfilter.internal.SslFilter.doFilter(SslFilter.java:97) [org.apache.felix.http.sslfilter:1.2.6]
	at org.apache.felix.http.base.internal.handler.PreprocessorHandler.handle(PreprocessorHandler.java:136) [org.apache.felix.http.jetty:4.0.8]
	at org.apache.felix.http.base.internal.whiteboard.WhiteboardManager$2.doFilter(WhiteboardManager.java:1008) [org.apache.felix.http.jetty:4.0.8]
	at org.apache.felix.http.base.internal.whiteboard.WhiteboardManager.invokePreprocessors(WhiteboardManager.java:1012) [org.apache.felix.http.jetty:4.0.8]
	at org.apache.felix.http.base.internal.dispatch.Dispatcher.dispatch(Dispatcher.java:91) [org.apache.felix.http.jetty:4.0.8]
	at org.apache.felix.http.base.internal.dispatch.DispatcherServlet.service(DispatcherServlet.java:49) [org.apache.felix.http.jetty:4.0.8]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:725) [org.apache.felix.http.servlet-api:1.1.2]
	at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:873) [org.apache.felix.http.jetty:4.0.8]
	at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:542) [org.apache.felix.http.jetty:4.0.8]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255) [org.apache.felix.http.jetty:4.0.8]
	at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1701) [org.apache.felix.http.jetty:4.0.8]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255) [org.apache.felix.http.jetty:4.0.8]
	at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1345) [org.apache.felix.http.jetty:4.0.8]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:203) [org.apache.felix.http.jetty:4.0.8]
	at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:480) [org.apache.felix.http.jetty:4.0.8]
	at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1668) [org.apache.felix.http.jetty:4.0.8]
	at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:201) [org.apache.felix.http.jetty:4.0.8]
	at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1247) [org.apache.felix.http.jetty:4.0.8]
	at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:144) [org.apache.felix.http.jetty:4.0.8]
	at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:220) [org.apache.felix.http.jetty:4.0.8]
	at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) [org.apache.felix.http.jetty:4.0.8]
	at org.eclipse.jetty.server.Server.handle(Server.java:502) [org.apache.felix.http.jetty:4.0.8]
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:370) [org.apache.felix.http.jetty:4.0.8]
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:267) [org.apache.felix.http.jetty:4.0.8]
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:305) [org.apache.felix.http.jetty:4.0.8]
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) [org.apache.felix.http.jetty:4.0.8]
	at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117) [org.apache.felix.http.jetty:4.0.8]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:333) [org.apache.felix.http.jetty:4.0.8]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:310) [org.apache.felix.http.jetty:4.0.8]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168) [org.apache.felix.http.jetty:4.0.8]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126) [org.apache.felix.http.jetty:4.0.8]
	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366) [org.apache.felix.http.jetty:4.0.8]
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:765) [org.apache.felix.http.jetty:4.0.8]
	at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:683) [org.apache.felix.http.jetty:4.0.8]
	at java.lang.Thread.run(Thread.java:748)

Log from Puppet installation:

Notice: /Stage[main]/Aemprovisioning::Aem::Configuration/Aemprovisioning::Aem::Sling_mappings[publish]/Aem_curator::Install_aem_package[publish: Install Sling mappings]/Archive[/var/tmp/publish/mappings-1.0.zip]/ensure: download archive from /vagrant/<customer>/files/mappings.zip to /var/tmp/publish/mappings-1.0.zip  without cleanup
Debug: /Stage[main]/Aemprovisioning::Aem::Configuration/Aemprovisioning::Aem::Sling_mappings[publish]/Aem_curator::Install_aem_package[publish: Install Sling mappings]/Archive[/var/tmp/publish/mappings-1.0.zip]: The container Aem_curator::Install_aem_package[publish: Install Sling mappings] will propagate my refresh event
Debug:  AEM username field is not specified, using default value from ruby_aem
Debug:  AEM password field is not specified, using default value from ruby_aem
Check CRX Package Manager service attempt #1: Package Manager active
Notice: /Stage[main]/Aemprovisioning::Aem::Configuration/Aemprovisioning::Aem::Sling_mappings[publish]/Aem_curator::Install_aem_package[publish: Install Sling mappings]/Aem_aem[publish: Wait until CRX Package Manager is ready before install mappings]/ensure: ensure changed 'present' to 'aem_package_manager_is_ready'
Debug: /Stage[main]/Aemprovisioning::Aem::Configuration/Aemprovisioning::Aem::Sling_mappings[publish]/Aem_curator::Install_aem_package[publish: Install Sling mappings]/Aem_aem[publish: Wait until CRX Package Manager is ready before install mappings]: The container Aem_curator::Install_aem_package[publish: Install Sling mappings] will propagate my refresh event
Debug:  AEM username field is not specified, using default value from ruby_aem
Debug:  AEM password field is not specified, using default value from ruby_aem
Debug:  AEM username field is not specified, using default value from ruby_aem
Debug:  AEM password field is not specified, using default value from ruby_aem
Check CRX Package Manager service attempt #1: Package Manager active
Upload check #1: true - Package my_packages/mappings-1.0 is uploaded
Debug:  AEM username field is not specified, using default value from ruby_aem
Debug:  AEM password field is not specified, using default value from ruby_aem
Check CRX Package Manager service attempt #1: Package Manager active
Install check #1: true - Package my_packages/mappings-1.0 is installed
Debug:  Response status code: 200
Debug:  Response body:
{"success":true,"msg":"Package uploaded","path":"/etc/packages/my_packages/mappings-1.0.zip"}
Debug:  Response headers:
{"Date"=>"Wed, 16 Oct 2019 13:58:47 GMT", "Content-Type"=>"application/json;charset=utf-8", "Content-Length"=>"93"}
Info:  Package uploaded
Debug:  Response status code: 200
Debug:  Response body:
{"success":true,"msg":"Package installed"}
Debug:  Response headers:
{"Date"=>"Wed, 16 Oct 2019 13:58:47 GMT", "Content-Type"=>"application/json;charset=utf-8", "Content-Length"=>"42"}
Info:  Package installed
Notice: /Stage[main]/Aemprovisioning::Aem::Configuration/Aemprovisioning::Aem::Sling_mappings[publish]/Aem_curator::Install_aem_package[publish: Install Sling mappings]/Aem_package[publish: Install mappings]/ensure: created
Debug: /Stage[main]/Aemprovisioning::Aem::Configuration/Aemprovisioning::Aem::Sling_mappings[publish]/Aem_curator::Install_aem_package[publish: Install Sling mappings]/Aem_package[publish: Install mappings]: The container Aem_curator::Install_aem_package[publish: Install Sling mappings] will propagate my refresh event
Debug: Exec[publish: Wait post install of mappings](provider=posix): Executing 'sleep 120'
Debug: Executing: 'sleep 120'
Notice: /Stage[main]/Aemprovisioning::Aem::Configuration/Aemprovisioning::Aem::Sling_mappings[publish]/Aem_curator::Install_aem_package[publish: Install Sling mappings]/Exec[publish: Wait post install of mappings]/returns: executed successfully
Debug: /Stage[main]/Aemprovisioning::Aem::Configuration/Aemprovisioning::Aem::Sling_mappings[publish]/Aem_curator::Install_aem_package[publish: Install Sling mappings]/Exec[publish: Wait post install of mappings]: The container Aem_curator::Install_aem_package[publish: Install Sling mappings] will propagate my refresh event
Debug:  AEM username field is not specified, using default value from ruby_aem
Debug:  AEM password field is not specified, using default value from ruby_aem
Retrieve login page attempt #1: Login page retrieved and ready
Notice: /Stage[main]/Aemprovisioning::Aem::Configuration/Aemprovisioning::Aem::Sling_mappings[publish]/Aem_curator::Install_aem_package[publish: Install Sling mappings]/Aem_aem[publish: Wait for login page post mappings]/ensure: ensure changed 'present' to 'login_page_is_ready'
Debug: /Stage[main]/Aemprovisioning::Aem::Configuration/Aemprovisioning::Aem::Sling_mappings[publish]/Aem_curator::Install_aem_package[publish: Install Sling mappings]/Aem_aem[publish: Wait for login page post mappings]: The container Aem_curator::Install_aem_package[publish: Install Sling mappings] will propagate my refresh event
Debug:  AEM username field is not specified, using default value from ruby_aem
Debug:  AEM password field is not specified, using default value from ruby_aem
Retrieve AEM Health Check attempt #1: AEM health check retrieved and ok
Notice: /Stage[main]/Aemprovisioning::Aem::Configuration/Aemprovisioning::Aem::Sling_mappings[publish]/Aem_curator::Install_aem_package[publish: Install Sling mappings]/Aem_aem[publish: Wait until aem health check is ok post mappings]/ensure: ensure changed 'present' to 'aem_health_check_is_ok'
Debug: /Stage[main]/Aemprovisioning::Aem::Configuration/Aemprovisioning::Aem::Sling_mappings[publish]/Aem_curator::Install_aem_package[publish: Install Sling mappings]/Aem_aem[publish: Wait until aem health check is ok post mappings]: The container Aem_curator::Install_aem_package[publish: Install Sling mappings] will propagate my refresh event
Debug: Exec[publish: Wait post login page for mappings](provider=posix): Executing 'sleep 0'
Debug: Executing: 'sleep 0'
Notice: /Stage[main]/Aemprovisioning::Aem::Configuration/Aemprovisioning::Aem::Sling_mappings[publish]/Aem_curator::Install_aem_package[publish: Install Sling mappings]/Exec[publish: Wait post login page for mappings]/returns: executed successfully

Hi @henrykuijpers,

is the package installation failing or does the package installation just throws an error in the error.log and the package still gets installed successfully ?

From the puppet log output you provided I can see that the package is installed

[...]
Upload check #1: true - Package my_packages/mappings-1.0 is uploaded
[...]
Install check #1: true - Package my_packages/mappings-1.0 is installed
[...]

From our experience, both messages are a very good indicator if the package got uploaded and installed, as they are contacting the package manager API to verify these

Upload API call:
https://github.com/shinesolutions/ruby_aem/blob/master/conf/spec.yaml#L654

Install API call:
https://github.com/shinesolutions/ruby_aem/blob/master/conf/spec.yaml#L609

The URL which gets called:
https://github.com/shinesolutions/swagger-aem/blob/master/conf/api.yml#L1083

We are experiencing this error message either but don't have time to investitage it/a proper explenation for it.

Cheers