AnsweredAssumed Answered

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

Question asked by jego on Jan 31, 2019
Latest reply on Feb 8, 2019 by anghelutar

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:

 

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

Outcomes