Some Alfresco Share proxy requests fail with 500 http status code, although Alfresco repository returns successfull http response (200)

[jego]

I have upgraded a customer from 5.1.4 to 5.2.4 Alfresco Enterprise.

After migrating the source code and installing the new Alfresco installation via installer, we have 

Alfresco Share itself is running, but certain requests to the alfresco repository via Share proxy SOMETIMES work and SOMETIMES fail.

We have two requests which are failing:

• request to https://<host>/share/proxy/alfresco/slingshot/doclib2/node/workspace/SpacesStore/5cdee94b-8352-403e-a0cc-958942965ebf fails with 500 http status code and NO error response, but direct call to https://<host>/alfresco/slingshot/doclib2/node/workspace/SpacesStore/5cdee94b-8352-403e-a0cc-958942965ebf works (200 response code and valid json)
• direct request to http://localhost:8080/alfresco/wcs/api/sites/test/memberships/userxy works, but call via share proxy does not work  https://<host>/share/proxy/alfresco/... does not work (500 response code)

This is the debug log of share after setting DEBUG loglevel to Apache HTTP Client (org.apache.http.wire) and Share RemoteClient (org.springframework.extensions.websripts.connector.RemoteClient). It shows the flow of a request to the doclib2/node endpoint...

2019-01-31 08:17:16,894 DEBUG [org.springframework.extensions.webscripts.connector.RemoteClient] [http-apr-8080-exec-1] Executing (GET) http://localhost:8080/alfresco/wcs/slingshot/doclib2/node/workspace/SpacesStore/5cdee94b-8352-403e-a0cc-958942965ebf
2019-01-31 08:17:16,894 DEBUG [org.springframework.extensions.webscripts.connector.RemoteClient] [http-apr-8080-exec-1]  - OutputStream supplied - will stream response...
2019-01-31 08:17:16,894 DEBUG [org.springframework.extensions.webscripts.connector.RemoteClient] [http-apr-8080-exec-1]  - Full Proxy mode between servlet request and response...
2019-01-31 08:17:16,894 TRACE [org.springframework.extensions.webscripts.connector.RemoteClient] [http-apr-8080-exec-1] Proxy request header: user-agent=Mozilla/5.0 (Windows NT 10.0; WOW64; rv:60.0) Gecko/20100101 Firefox/60.0
2019-01-31 08:17:16,894 TRACE [org.springframework.extensions.webscripts.connector.RemoteClient] [http-apr-8080-exec-1] Proxy request header: accept=text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
2019-01-31 08:17:16,894 TRACE [org.springframework.extensions.webscripts.connector.RemoteClient] [http-apr-8080-exec-1] Proxy request header: accept-language=en,en-US;q=0.7,de;q=0.3
2019-01-31 08:17:16,894 TRACE [org.springframework.extensions.webscripts.connector.RemoteClient] [http-apr-8080-exec-1] Proxy request header: accept-encoding=gzip, deflate, br
2019-01-31 08:17:16,894 TRACE [org.springframework.extensions.webscripts.connector.RemoteClient] [http-apr-8080-exec-1] Proxy request header: dnt=1
2019-01-31 08:17:16,894 TRACE [org.springframework.extensions.webscripts.connector.RemoteClient] [http-apr-8080-exec-1] Proxy request header: upgrade-insecure-requests=1
2019-01-31 08:17:16,894 TRACE [org.springframework.extensions.webscripts.connector.RemoteClient] [http-apr-8080-exec-1] Proxy request header: x-forwarded-for=10.137.24.86
2019-01-31 08:17:16,894 TRACE [org.springframework.extensions.webscripts.connector.RemoteClient] [http-apr-8080-exec-1] Proxy request header: x-forwarded-host=<host>
2019-01-31 08:17:16,894 TRACE [org.springframework.extensions.webscripts.connector.RemoteClient] [http-apr-8080-exec-1] Proxy request header: x-forwarded-server=<host>
2019-01-31 08:17:16,895 TRACE [org.springframework.extensions.webscripts.connector.RemoteClient] [http-apr-8080-exec-1] Proxy request header: connection=Keep-Alive
2019-01-31 08:17:16,895 TRACE [org.springframework.extensions.webscripts.connector.RemoteClient] [http-apr-8080-exec-1] Set request header: authorization=null
2019-01-31 08:17:16,895 DEBUG [org.springframework.extensions.webscripts.connector.RemoteClient] [http-apr-8080-exec-1] Setting Cookie header: JSESSIONID=XXX
2019-01-31 08:17:16,895 DEBUG [org.apache.http.client.protocol.RequestAddCookies] [http-apr-8080-exec-1] CookieSpec selected: default
2019-01-31 08:17:16,895 DEBUG [org.apache.http.client.protocol.RequestAuthCache] [http-apr-8080-exec-1] Auth cache not set in the context
2019-01-31 08:17:16,895 DEBUG [org.apache.http.impl.conn.PoolingHttpClientConnectionManager] [http-apr-8080-exec-1] Connection request: [route: {}->http://localhost:8080][total kept alive: 1; route allocated: 1 of 200; total allocated: 1 of 200]
2019-01-31 08:17:16,895 DEBUG [org.apache.http.impl.conn.PoolingHttpClientConnectionManager] [http-apr-8080-exec-1] Connection leased: [id: 30][route: {}->http://localhost:8080][total kept alive: 0; route allocated: 1 of 200; total allocated: 1 of 200]
2019-01-31 08:17:16,895 DEBUG [org.apache.http.impl.execchain.MainClientExec] [http-apr-8080-exec-1] Stale connection check
2019-01-31 08:17:16,897 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "[read] I/O error: Read timed out"
2019-01-31 08:17:16,897 DEBUG [org.apache.http.impl.conn.DefaultManagedHttpClientConnection] [http-apr-8080-exec-1] http-outgoing-30: set socket timeout to 120000
2019-01-31 08:17:16,897 DEBUG [org.apache.http.impl.execchain.MainClientExec] [http-apr-8080-exec-1] Executing request GET /alfresco/wcs/slingshot/doclib2/node/workspace/SpacesStore/5cdee94b-8352-403e-a0cc-958942965ebf HTTP/1.1
2019-01-31 08:17:16,897 DEBUG [org.apache.http.impl.execchain.MainClientExec] [http-apr-8080-exec-1] Target auth state: UNCHALLENGED
2019-01-31 08:17:16,897 DEBUG [org.apache.http.impl.execchain.MainClientExec] [http-apr-8080-exec-1] Proxy auth state: UNCHALLENGED
2019-01-31 08:17:16,897 DEBUG [org.apache.http.headers] [http-apr-8080-exec-1] http-outgoing-30 >> GET /alfresco/wcs/slingshot/doclib2/node/workspace/SpacesStore/5cdee94b-8352-403e-a0cc-958942965ebf HTTP/1.1
2019-01-31 08:17:16,897 DEBUG [org.apache.http.headers] [http-apr-8080-exec-1] http-outgoing-30 >> user-agent: Mozilla/5.0 (Windows NT 10.0; WOW64; rv:60.0) Gecko/20100101 Firefox/60.0
2019-01-31 08:17:16,897 DEBUG [org.apache.http.headers] [http-apr-8080-exec-1] http-outgoing-30 >> accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
2019-01-31 08:17:16,897 DEBUG [org.apache.http.headers] [http-apr-8080-exec-1] http-outgoing-30 >> accept-language: en,en-US;q=0.7,de;q=0.3
2019-01-31 08:17:16,898 DEBUG [org.apache.http.headers] [http-apr-8080-exec-1] http-outgoing-30 >> accept-encoding: gzip, deflate, br
2019-01-31 08:17:16,898 DEBUG [org.apache.http.headers] [http-apr-8080-exec-1] http-outgoing-30 >> dnt: 1
2019-01-31 08:17:16,898 DEBUG [org.apache.http.headers] [http-apr-8080-exec-1] http-outgoing-30 >> upgrade-insecure-requests: 1
2019-01-31 08:17:16,898 DEBUG [org.apache.http.headers] [http-apr-8080-exec-1] http-outgoing-30 >> x-forwarded-for: 10.137.24.86
2019-01-31 08:17:16,898 DEBUG [org.apache.http.headers] [http-apr-8080-exec-1] http-outgoing-30 >> x-forwarded-host: YYYY
2019-01-31 08:17:16,898 DEBUG [org.apache.http.headers] [http-apr-8080-exec-1] http-outgoing-30 >> x-forwarded-server: YYYY
2019-01-31 08:17:16,898 DEBUG [org.apache.http.headers] [http-apr-8080-exec-1] http-outgoing-30 >> connection: Keep-Alive
2019-01-31 08:17:16,898 DEBUG [org.apache.http.headers] [http-apr-8080-exec-1] http-outgoing-30 >> Cookie: JSESSIONID=XXX
2019-01-31 08:17:16,898 DEBUG [org.apache.http.headers] [http-apr-8080-exec-1] http-outgoing-30 >> Host: localhost:8080
2019-01-31 08:17:16,898 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 >> "GET /alfresco/wcs/slingshot/doclib2/node/workspace/SpacesStore/5cdee94b-8352-403e-a0cc-958942965ebf HTTP/1.1[\r][\n]"
2019-01-31 08:17:16,898 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 >> "user-agent: Mozilla/5.0 (Windows NT 10.0; WOW64; rv:60.0) Gecko/20100101 Firefox/60.0[\r][\n]"
2019-01-31 08:17:16,898 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 >> "accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8[\r][\n]"
2019-01-31 08:17:16,898 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 >> "accept-language: en,en-US;q=0.7,de;q=0.3[\r][\n]"
2019-01-31 08:17:16,898 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 >> "accept-encoding: gzip, deflate, br[\r][\n]"
2019-01-31 08:17:16,898 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 >> "dnt: 1[\r][\n]"
2019-01-31 08:17:16,898 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 >> "upgrade-insecure-requests: 1[\r][\n]"
2019-01-31 08:17:16,898 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 >> "x-forwarded-for: 10.137.24.86[\r][\n]"
2019-01-31 08:17:16,898 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 >> "x-forwarded-host: YYYY[\r][\n]"
2019-01-31 08:17:16,898 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 >> "x-forwarded-server: YYYY[\r][\n]"
2019-01-31 08:17:16,898 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 >> "connection: Keep-Alive[\r][\n]"
2019-01-31 08:17:16,898 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 >> "Cookie: JSESSIONID=XXX[\r][\n]"
2019-01-31 08:17:16,898 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 >> "Host: localhost:8080[\r][\n]"
2019-01-31 08:17:16,898 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 >> "[\r][\n]"
2019-01-31 08:17:17,011 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "HTTP/1.1 200 OK[\r][\n]"
2019-01-31 08:17:17,012 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "Server: Apache-Coyote/1.1[\r][\n]"
2019-01-31 08:17:17,012 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "Cache-Control: no-cache[\r][\n]"
2019-01-31 08:17:17,012 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "Expires: Thu, 01 Jan 1970 00:00:00 GMT[\r][\n]"
2019-01-31 08:17:17,012 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "Pragma: no-cache[\r][\n]"
2019-01-31 08:17:17,012 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "Content-Type: application/json;charset=UTF-8[\r][\n]"
2019-01-31 08:17:17,012 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "Transfer-Encoding: chunked[\r][\n]"
2019-01-31 08:17:17,012 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "Date: Thu, 31 Jan 2019 07:17:16 GMT[\r][\n]"
2019-01-31 08:17:17,012 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "[\r][\n]"
2019-01-31 08:17:17,012 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "12d0[\r][\n]"
2019-01-31 08:17:17,012 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "{[\n]"
2019-01-31 08:17:17,012 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "   "metadata":[\n]"
2019-01-31 08:17:17,012 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "   {[\n]"
2019-01-31 08:17:17,012 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "      "repositoryId": "19cc135d-8823-4d83-a5ba-c724d94ac042",[\n]"
2019-01-31 08:17:17,012 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "      [\n]"
2019-01-31 08:17:17,012 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "      "custom": {"aos":{"baseUrl":"https://<host>/alfresco/aos"},"vtiServer":null},[\n]"
2019-01-31 08:17:17,012 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "      "onlineEditing": false,[\n]"
2019-01-31 08:17:17,012 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "      "workingCopyLabel": " (Working Copy)",[\n]"
2019-01-31 08:17:17,012 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "      "shareURL": "https:\/\/<host>\/share",[\n]"
2019-01-31 08:17:17,012 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "      "serverURL": "http:\/\/localhost:8080"[\n]"
2019-01-31 08:17:17,012 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "   },[\n]"
2019-01-31 08:17:17,012 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "   [\n]"
2019-01-31 08:17:17,012 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "   "item":[\n]"
2019-01-31 08:17:17,012 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "   {[\n]"
2019-01-31 08:17:17,012 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "   [\n]"
2019-01-31 08:17:17,012 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "      "node": {"isLink":false,"aspects":["rn:renditioned","cm:versionable","cm:copiedfrom","cm:ownable","cm:titled","cm:auditable","sys:referenceable","cm:taggable","sys:localized","cm:author"],"isContainer":false,"type":"cm:content","encoding":"UTF-8","contentURL":"\/slingshot\/node\/content\/workspace\/SpacesStore\/5cdee94b-8352-403e-a0cc-958942965ebf\Dokument.docx","size":15577,"nodeRef":"workspace:\/\/SpacesStore\/5cdee94b-8352-403e-a0cc-958942965ebf","permissions":{"inherited":true,"roles":["ALLOWED;bjoern.Nustermann;SiteCollaborator;INHERITED","ALLOWED;marco.langer;SiteCollaborator;INHERITED","ALLOWED;anja.schnelle;SiteCollaborator;INHERITED","ALLOWED;nadine.moehle;SiteCollaborator;INHERITED","ALLOWED;GROUP_site_R30_SiteManager;SiteManager;INHERITED"],"user":{"Delete":true,"Write":true,"CancelCheckOut":false,"ChangePermissions":true,"CreateChildren":true,"Unlock":false}},"isLocked":false,"mimetype":"application\/vnd.openxmlformats-officedocument.wordprocessingml.document","properties":{"cm:creator":{"firstName":"Max","lastName":"Mustermann","displayName":"Max Mustermann","userName":"Max.Mustermann"},"cm:autoVersion":"false","cm:title":"","cm:modifier":{"firstName":"Hans-Peter","lastName":"Vollbach","displayName":"Hans-Peter Vollbach","userName":"hans-peter.vollbach"},"cm:created":{"iso8601":"2013-08-08T12:50:05.162Z","value":"Thu Aug 08 14:50:05 CEST 2013"},"cm:versionLabel":"0.1","cm:autoVersionOnUpdateProps":"false","sys:store-protocol":null,"sys:store-identifier":null,"cm:owner":{"firstName":"System","lastName":"","displayName":"System","userName":"System"},"cm:content":null,"cm:description":"","sys:node-uuid":null,"cm:taggable":null,"cm:name":"Dokument.docx","cm:author":"Max.Mustermann","sys:node-dbid":null,"cm:initialVersion":"true","sys:locale":null,"cm:modified":{"iso8601":"2013-08-08T14:33:47.826Z","value":"Thu Aug 08 16:33:47 CEST 2013"}},"mimetypeDisplayName":"Microsoft Word 2007"},[\n]"
2019-01-31 08:17:17,013 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "      "parent": {"isLink":false,"nodeRef":"workspace:\/\/SpacesStore\/e5b3f7fd-9ef5-4261-ad5d-8825e6d54685","permissions":{"inherited":false,"roles":["ALLOWED;bjoern.Nustermann;SiteCollaborator;DIRECT","ALLOWED;marco.langer;SiteCollaborator;DIRECT","ALLOWED;anja.schnelle;SiteCollaborator;DIRECT","ALLOWED;nadine.moehle;SiteCollaborator;DIRECT","ALLOWED;GROUP_site_R30_SiteManager;SiteManager;DIRECT"],"user":{"Delete":true,"Write":true,"CancelCheckOut":false,"ChangePermissions":true,"CreateChildren":true,"Unlock":false}},"isLocked":false,"aspects":["cm:versionable","cm:ownable","cm:titled","cm:auditable","sys:referenceable","cm:taggable","sys:localized"],"isContainer":true,"type":"cm:folder","properties":{"cm:creator":{"firstName":"Administrator","lastName":"","displayName":"Administrator","userName":"admin"},"cm:autoVersion":"true","cm:title":"","cm:modifier":{"firstName":"Max","lastName":"Nustermann","displayName":"Max Nustermann","userName":"max.Nustermann"},"cm:created":{"iso8601":"2012-04-30T11:27:08.303Z","value":"Mon Apr 30 13:27:08 CEST 2012"},"cm:versionLabel":"0.6","cm:autoVersionOnUpdateProps":"true","sys:store-protocol":null,"sys:store-identifier":null,"cm:owner":{"firstName":"System","lastName":"","displayName":"System","userName":"System"},"cm:description":"","sys:node-uuid":null,"cm:taggable":null,"cm:name":"Versicherungen_R30","sys:node-dbid":null,"cm:initialVersion":"true","sys:locale":null,"cm:modified":{"iso8601":"2019-01-07T10:46:20.096Z","value":"Mon Jan 07 11:46:20 CET 2019"}}},[\n]"
2019-01-31 08:17:17,013 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "   "version": "0.1",[\n]"
2019-01-31 08:17:17,013 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "   "webdavUrl": "\/webdav\/Sites\/R30\/documentLibrary\/Versicherungen_R30\/Dokument.docx",[\n]"
2019-01-31 08:17:17,013 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "   [\n]"
2019-01-31 08:17:17,013 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "   "isFavourite": false,[\n]"
2019-01-31 08:17:17,013 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "   [\n]"
2019-01-31 08:17:17,013 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "   "likes":[\n]"
2019-01-31 08:17:17,013 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "   {[\n]"
2019-01-31 08:17:17,013 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "      "isLiked": false,[\n]"
2019-01-31 08:17:17,013 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "      "totalLikes": 0[\n]"
2019-01-31 08:17:17,013 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "   },[\n]"
2019-01-31 08:17:17,013 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "   "location":[\n]"
2019-01-31 08:17:17,013 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "   {[\n]"
2019-01-31 08:17:17,013 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "      "repositoryId": "19cc135d-8823-4d83-a5ba-c724d94ac042",[\n]"
2019-01-31 08:17:17,013 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "      "site":[\n]"
2019-01-31 08:17:17,013 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "      {[\n]"
2019-01-31 08:17:17,013 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "         "name": "R30",[\n]"
2019-01-31 08:17:17,013 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "         "title": "Referat 30",[\n]"
2019-01-31 08:17:17,013 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "         "preset": "site-dashboard"[\n]"
2019-01-31 08:17:17,013 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "      },[\n]"
2019-01-31 08:17:17,013 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "      "container":[\n]"
2019-01-31 08:17:17,013 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "      {[\n]"
2019-01-31 08:17:17,013 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "         "name": "documentLibrary",[\n]"
2019-01-31 08:17:17,013 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "         "type": "cm:folder",[\n]"
2019-01-31 08:17:17,013 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "         "nodeRef": ""[\n]"
2019-01-31 08:17:17,013 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "      },[\n]"
2019-01-31 08:17:17,013 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "      "path": "\/Versicherungen_R30",[\n]"
2019-01-31 08:17:17,013 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "      "repoPath": "\/Sites\/R30\/documentLibrary\/Versicherungen_R30",[\n]"
2019-01-31 08:17:17,013 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "      "file": "Dokument.docx",[\n]"
2019-01-31 08:17:17,014 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "      "parent":[\n]"
2019-01-31 08:17:17,014 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "      {[\n]"
2019-01-31 08:17:17,014 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "      }[\n]"
2019-01-31 08:17:17,014 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "   }[\n]"
2019-01-31 08:17:17,014 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "   }[\n]"
2019-01-31 08:17:17,014 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "}[\n]"
2019-01-31 08:17:17,014 DEBUG [org.apache.http.wire] [http-apr-8080-exec-1] http-outgoing-30 << "[\r][\n]"
2019-01-31 08:17:17,014 DEBUG [org.apache.http.headers] [http-apr-8080-exec-1] http-outgoing-30 << HTTP/1.1 200 OK
2019-01-31 08:17:17,014 DEBUG [org.apache.http.headers] [http-apr-8080-exec-1] http-outgoing-30 << Server: Apache-Coyote/1.1
2019-01-31 08:17:17,014 DEBUG [org.apache.http.headers] [http-apr-8080-exec-1] http-outgoing-30 << Cache-Control: no-cache
2019-01-31 08:17:17,014 DEBUG [org.apache.http.headers] [http-apr-8080-exec-1] http-outgoing-30 << Expires: Thu, 01 Jan 1970 00:00:00 GMT
2019-01-31 08:17:17,014 DEBUG [org.apache.http.headers] [http-apr-8080-exec-1] http-outgoing-30 << Pragma: no-cache
2019-01-31 08:17:17,014 DEBUG [org.apache.http.headers] [http-apr-8080-exec-1] http-outgoing-30 << Content-Type: application/json;charset=UTF-8
2019-01-31 08:17:17,014 DEBUG [org.apache.http.headers] [http-apr-8080-exec-1] http-outgoing-30 << Transfer-Encoding: chunked
2019-01-31 08:17:17,014 DEBUG [org.apache.http.headers] [http-apr-8080-exec-1] http-outgoing-30 << Date: Thu, 31 Jan 2019 07:17:16 GMT
2019-01-31 08:17:17,014 DEBUG [org.apache.http.impl.execchain.MainClientExec] [http-apr-8080-exec-1] Connection can be kept alive indefinitely
2019-01-31 08:17:17,014 DEBUG [org.springframework.extensions.webscripts.connector.RemoteClient] [http-apr-8080-exec-1] Response status code: 200
2019-01-31 08:17:17,014 TRACE [org.springframework.extensions.webscripts.connector.RemoteClient] [http-apr-8080-exec-1] Response header: Cache-Control=no-cache
2019-01-31 08:17:17,014 TRACE [org.springframework.extensions.webscripts.connector.RemoteClient] [http-apr-8080-exec-1] Response header: Expires=Thu, 01 Jan 1970 00:00:00 GMT
2019-01-31 08:17:17,014 TRACE [org.springframework.extensions.webscripts.connector.RemoteClient] [http-apr-8080-exec-1] Response header: Pragma=no-cache
2019-01-31 08:17:17,014 TRACE [org.springframework.extensions.webscripts.connector.RemoteClient] [http-apr-8080-exec-1] Response header: Content-Type=application/json;charset=UTF-8
2019-01-31 08:17:17,014 TRACE [org.springframework.extensions.webscripts.connector.RemoteClient] [http-apr-8080-exec-1] Response header: Date=Thu, 31 Jan 2019 07:17:16 GMT
2019-01-31 08:17:17,014 DEBUG [org.springframework.extensions.webscripts.connector.RemoteClient] [http-apr-8080-exec-1] Response charset: UTF-8
2019-01-31 08:17:17,014 DEBUG [org.springframework.extensions.webscripts.connector.RemoteClient] [http-apr-8080-exec-1] Response encoding: Content-Type: application/json;charset=UTF-8
2019-01-31 08:17:17,015 DEBUG [org.springframework.extensions.webscripts.connector.RemoteClient] [http-apr-8080-exec-1] Exception calling (GET) http://localhost:8080/alfresco/wcs/slingshot/doclib2/node/workspace/SpacesStore/5cdee94b-8352-403e-a0cc-958942965ebf
2019-01-31 08:17:17,015 DEBUG [org.apache.http.impl.execchain.MainClientExec] [http-apr-8080-exec-1] Cancelling request execution
2019-01-31 08:17:17,015 DEBUG [org.apache.http.impl.conn.DefaultManagedHttpClientConnection] [http-apr-8080-exec-1] http-outgoing-30: Shutdown connection
2019-01-31 08:17:17,015 DEBUG [org.apache.http.impl.execchain.MainClientExec] [http-apr-8080-exec-1] Connection discarded
2019-01-31 08:17:17,015 DEBUG [org.apache.http.impl.conn.PoolingHttpClientConnectionManager] [http-apr-8080-exec-1] Connection released: [id: 30][route: {}->http://localhost:8080][total kept alive: 0; route allocated: 0 of 200; total allocated: 0 of 200]‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

In line 132 you will notice the output

2019-01-31 08:17:17,015 DEBUG [org.springframework.extensions.webscripts.connector.RemoteClient] [http-apr-8080-exec-1] Exception calling (GET) http://localhost:8080/alfresco/wcs/slingshot/doclib2/node/workspace/SpacesStore/5cdee94b-8352-403e-a0cc-958942965ebf

This is very strange because the https response from alfresco was successfull and we even see the valid json in the debug log...

2019-01-31 08:17:17,014 DEBUG [org.springframework.extensions.webscripts.connector.RemoteClient] [http-apr-8080-exec-1] Response status code: 200

2019-01-31 08:17:17,014 TRACE [org.springframework.extensions.webscripts.connector.RemoteClient] [http-apr-8080-exec-1] Response header: Cache-Control=no-cache

2019-01-31 08:17:17,014 TRACE [org.springframework.extensions.webscripts.connector.RemoteClient] [http-apr-8080-exec-1] Response header: Expires=Thu, 01 Jan 1970 00:00:00 GMT

2019-01-31 08:17:17,014 TRACE [org.springframework.extensions.webscripts.connector.RemoteClient] [http-apr-8080-exec-1] Response header: Pragma=no-cache

2019-01-31 08:17:17,014 TRACE [org.springframework.extensions.webscripts.connector.RemoteClient] [http-apr-8080-exec-1] Response header: Content-Type=application/json;charset=UTF-8

2019-01-31 08:17:17,014 TRACE [org.springframework.extensions.webscripts.connector.RemoteClient] [http-apr-8080-exec-1] Response header: Date=Thu, 31 Jan 2019 07:17:16 GMT

2019-01-31 08:17:17,014 DEBUG [org.springframework.extensions.webscripts.connector.RemoteClient] [http-apr-8080-exec-1] Response charset: UTF-8

2019-01-31 08:17:17,014 DEBUG [org.springframework.extensions.webscripts.connector.RemoteClient] [http-apr-8080-exec-1] Response encoding: Content-Type: application/json;charset=UTF-8

The RemoteClient class from spring webscripts and SlingshotRemoteClient from alfresco share are responsible for handling the communication with Alfresco Repository.

The last debug output "Response encoding..." is in org/alfresco/surf/spring-webscripts/6.13/spring-webscripts-6.13-sources.jar!/org/springframework/extensions/webscripts/connector/RemoteClient.java:1245

Afterwards the http response from Alfresco should be copied to the http response from the browser to Share, but this fails resulting in the message "Exception calling..." with status code 500.

Only 2 cases set this http code - runtime exception and ioexception. 

catch (IOException ioErr)
{
    // caught a general IO exception - apply generic error code so one gets returned
    logger.info("Exception calling (" + requestMethod + ") " + url.toString());
    status.setCode(HttpServletResponse.SC_INTERNAL_SERVER_ERROR);
    status.setException(ioErr);
    status.setMessage(ioErr.getMessage());
    if (res != null)
    {
        res.setStatus(HttpServletResponse.SC_INTERNAL_SERVER_ERROR, ioErr.getMessage());
    }
    
    throw ioErr;
}
catch (RuntimeException e)
{
    // caught an exception - apply generic error code so one gets returned
    logger.debug("Exception calling (" + requestMethod + ") " + url.toString());
    status.setCode(HttpServletResponse.SC_INTERNAL_SERVER_ERROR);
    status.setException(e);
    status.setMessage(e.getMessage());
    if (res != null)
    {
        res.setStatus(HttpServletResponse.SC_INTERNAL_SERVER_ERROR, e.getMessage());
    }
    return null;
}

In case of the runtimeexception the method returns null and throws no exception.

So the method returns and the following code is executed. The error is not logged because the runtime exception was not rethrown  (a bug in my eyes) which leads the situation that I am not able to see the underlying issue.

Even newer versions of the org.alfresco.surf.surf-webscripts dependency have this code, altough this version of the class rethrows the exception in the catch block...

surf-webscripts/RemoteClient.java at master · Kast0rTr0y/surf-webscripts · GitHub 

public Response call(String uri, HttpServletRequest req, HttpServletResponse res)
{
    Response result;
    ResponseStatus status = new ResponseStatus();
    try
    {
        boolean isPush = (requestMethod == HttpMethod.POST || requestMethod == HttpMethod.PUT);
        String encoding = service(
                buildURL(uri),
                isPush ? req.getInputStream() : null,
                res != null ? res.getOutputStream() : null,
                req, res, status);
        result = new Response(status);
        result.setEncoding(encoding);
    }
    catch (IOException ioErr)
    {
        if (logger.isInfoEnabled())
            logger.info("Error status " + status.getCode() + " " + status.getMessage(), ioErr);
        
        // error information already applied to Status object during service() call
        result = new Response(status);
    }
    catch (Throwable e)
    {
        if (logger.isErrorEnabled())
            logger.error("Error status " + status.getCode() + " " + status.getMessage(), e);
        
        // error information already applied to Status object during service() call
        result = new Response(status);
    }
    
    return result;
}

The call method of the RemoteClient handles the null return as normal process flow, so in the end no error is returned to the client.

Besides this bug in Alfresco Surf webscripts- has anybody encountered this situation before? 

What could be the reason that for 2 webscripts over Alfresco Share sometimes break?

CC: Axel Faust‌

Environment:

• Alfresco 5.2.4
• Kerberos Authentication in Share and Alfresco

[anghelutar]

I believe we might have hit the same problem, using external authentication.

Works fine on another environment - same version - with saml module enabled.

roxana

[afaust]

I finally have some time after DevCon to look through the longer questions / posts on this plattform again (and Roxana also had contacted me about this issue this week).

I have not seen similar behaviour before myself. I too consider the missing rethrow of the RuntimeException case a programming mistake, though the only consequence of this is a missing "error" log entry and missing stacktrace information about the real exception - the response to the client will look exactly the same as for the other catch-clauses.

I'd personally patch that rethrow into the specific version of webscripts used in 5.2.4, run with that and then check the stacktrace. Alternative - in a dirtier approach - I'd use remote debugging with a breakpoint in that catch clause.

Since I don't see any TRACE output from the copyResponseStreamOutput method, I expect the RuntimeException to be triggered in that method, though I can see no readily apparent errors / relevant corner cases in that code.

[afaust · Accepted solution]

Ok - the cause is a stupid NullPointerException that Alfresco has introduced in Share code for one of the 5.2 Service Packs. The bug did not exist in the latest 5.2 Community code. The bug only affects any proxy URLs that do not include a URL query (so no ? in the URL). The bug is located in line 85 of SlingshotRemoteClient. Whenever the url.getQuery() returns null, the proxy request will fail.

[afaust]

It is actually a known issue and already fixed for the next 5.2.X service pack: MNT-19933

Still unclear though how this was not caught in testing with dozens of requests issued by the browser failing and access logs showing 500er errors...

[afaust]

One reason it may not have been caught in testing is that SSO was not being used. When SSO is not enabled, the proxy should actually append an "alf_ticket=sdfghj" query fragment to the URL, so the specific condition for the NullPointerException does not trigger.

[jego]

Axel, you are great. Thanks for finding the root cause of the issue. I owe you a beer!!

I had patched the class with my own version to log the error correctly, but in this case the error was not happening anymore, so I was not sure what really happened...

Thank you!

[anghelutar]

Possible solution until the hotfix is out (tested): go back to 5.2.3.