Rename/move job sometimes crashes and blocks other jobs - probably JRE encoding problem

When renaming (moving) a page that has couple of subpages I encounter a problem that makes impossible for any other similar jobs to be executed. Trying to move it again results with blank “loading screen” (see screenshot below): Restarting Tomcat allows to perform this action.

image

I’d like to investigate it in more detail as I presume that after successful migration of our previous wiki to XWiki many users are going to move and rename various pages. I’d be grateful for the guidance on which loggers should I enable if it’s necessary.

In the catalina.out I can see some exceptions related to encoding in JRE. Please take a look at the snippet from the moment when I was trying to move one of the pages from Sport to Sport2 (numbers can be different though).

28-Aug-2018 11:52:37.890 WARNING [http://XX.XX.XX.XX:8080/download/FlamingoThemes/Iceberg/logo_wiki.svg] org.apache.catalina.connector.Response.setCharacterEncoding The encoding [] is not recognised by the JRE
 java.io.UnsupportedEncodingException: The character encoding [] is not supported
	at org.apache.tomcat.util.buf.B2CConverter.getCharset(B2CConverter.java:79)
	at org.apache.coyote.Response.setCharacterEncoding(Response.java:496)
	at org.apache.catalina.connector.Response.setCharacterEncoding(Response.java:802)
	at org.apache.catalina.connector.ResponseFacade.setCharacterEncoding(ResponseFacade.java:623)
	at javax.servlet.ServletResponseWrapper.setCharacterEncoding(ServletResponseWrapper.java:82)
	at javax.servlet.ServletResponseWrapper.setCharacterEncoding(ServletResponseWrapper.java:82)
	at com.xpn.xwiki.web.XWikiServletResponse.setCharacterEncoding(XWikiServletResponse.java:154)
	at com.xpn.xwiki.web.DownloadAction.setCommonHeaders(DownloadAction.java:446)
	at com.xpn.xwiki.web.DownloadAction.sendContent(DownloadAction.java:301)
	at com.xpn.xwiki.web.DownloadAction.render(DownloadAction.java:183)
	at com.xpn.xwiki.web.XWikiAction.execute(XWikiAction.java:459)
	at com.xpn.xwiki.web.XWikiAction.execute(XWikiAction.java:209)
	at org.apache.struts.action.RequestProcessor.processActionPerform(RequestProcessor.java:425)
	at org.apache.struts.action.RequestProcessor.process(RequestProcessor.java:228)
	at org.apache.struts.action.ActionServlet.process(ActionServlet.java:1913)
	at org.apache.struts.action.ActionServlet.doGet(ActionServlet.java:449)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:634)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:741)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at com.xpn.xwiki.web.ActionFilter.doFilter(ActionFilter.java:112)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.xwiki.wysiwyg.filter.ConversionFilter.doFilter(ConversionFilter.java:127)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.xwiki.container.servlet.filters.internal.SavedRequestRestorerFilter.doFilter(SavedRequestRestorerFilter.java:208)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.xwiki.container.servlet.filters.internal.SetCharacterEncodingFilter.doFilter(SetCharacterEncodingFilter.java:111)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.tuckey.web.filters.urlrewrite.RuleChain.handleRewrite(RuleChain.java:176)
	at org.tuckey.web.filters.urlrewrite.RuleChain.doRules(RuleChain.java:145)
	at org.tuckey.web.filters.urlrewrite.UrlRewriter.processRequest(UrlRewriter.java:92)
	at org.tuckey.web.filters.urlrewrite.UrlRewriteFilter.doFilter(UrlRewriteFilter.java:394)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:712)
	at org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:459)
	at org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:384)
	at org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:312)
	at org.tuckey.web.filters.urlrewrite.NormalRewrittenUrl.doRewrite(NormalRewrittenUrl.java:213)
	at org.tuckey.web.filters.urlrewrite.RuleChain.handleRewrite(RuleChain.java:171)
	at org.tuckey.web.filters.urlrewrite.RuleChain.doRules(RuleChain.java:145)
	at org.tuckey.web.filters.urlrewrite.UrlRewriter.processRequest(UrlRewriter.java:92)
	at org.tuckey.web.filters.urlrewrite.UrlRewriteFilter.doFilter(UrlRewriteFilter.java:394)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:199)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:491)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:139)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
	at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:668)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343)
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:408)
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:764)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1388)
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:748)

2018-08-28 11:52:37,925 [http://XX.XX.XX.XX:8080/jsx/XWiki/Xuake?language=pl&docVersion=1.1] WARN  c.x.x.w.s.JsExtension          - Error at line 47, column 14: invalid property id. Caused by: [      , class: "xuake-console hidden"] 
2018-08-28 11:52:37,925 [http://XX.XX.XX.XX:8080/jsx/XWiki/Xuake?language=pl&docVersion=1.1] WARN  c.x.x.w.s.JsExtension          - Error at line 48, column 6: syntax error. Caused by: [    });] 
2018-08-28 11:52:37,926 [http://XX.XX.XX.XX:8080/jsx/XWiki/Xuake?language=pl&docVersion=1.1] WARN  c.x.x.w.s.JsExtension          - Error at line 51, column 14: invalid property id. Caused by: [      , class: "consoleInput"] 
2018-08-28 11:52:37,926 [http://XX.XX.XX.XX:8080/jsx/XWiki/Xuake?language=pl&docVersion=1.1] WARN  c.x.x.w.s.JsExtension          - Error at line 52, column 6: syntax error. Caused by: [    })] 
2018-08-28 11:52:37,926 [http://XX.XX.XX.XX:8080/jsx/XWiki/Xuake?language=pl&docVersion=1.1] WARN  c.x.x.w.s.JsExtension          - Error at line 53, column 10: syntax error. Caused by: [    this.executeButton = new Element("input", {] 
2018-08-28 11:52:37,926 [http://XX.XX.XX.XX:8080/jsx/XWiki/Xuake?language=pl&docVersion=1.1] WARN  c.x.x.w.s.JsExtension          - Error at line 54, column 12: syntax error. Caused by: [        id: "xuake-execute-button"] 
2018-08-28 11:52:37,926 [http://XX.XX.XX.XX:8080/jsx/XWiki/Xuake?language=pl&docVersion=1.1] WARN  c.x.x.w.s.JsExtension          - Error at line 55, column 14: identifier is a reserved word. Caused by: [      , class: "btn btn-info button"] 
2018-08-28 11:52:37,926 [http://XX.XX.XX.XX:8080/jsx/XWiki/Xuake?language=pl&docVersion=1.1] WARN  c.x.x.w.s.JsExtension          - Error at line 57, column 15: missing ; before statement. Caused by: [      , value: "Execute (CTRL + E)" ] 
2018-08-28 11:52:37,927 [http://XX.XX.XX.XX:8080/jsx/XWiki/Xuake?language=pl&docVersion=1.1] WARN  c.x.x.w.s.JsExtension          - Error at line 58, column 6: syntax error. Caused by: [    })] 
2018-08-28 11:52:37,927 [http://XX.XX.XX.XX:8080/jsx/XWiki/Xuake?language=pl&docVersion=1.1] WARN  c.x.x.w.s.JsExtension          - Error at line 59, column 10: syntax error. Caused by: [    this.console.insert(this.input);] 
2018-08-28 11:52:37,927 [http://XX.XX.XX.XX:8080/jsx/XWiki/Xuake?language=pl&docVersion=1.1] ERROR c.x.x.w.s.JsExtension          - Runtime error minimizing JSX object: Compilation produced 10 syntax errors. 
2018-08-28 11:52:37,927 [http://XX.XX.XX.XX:8080/jsx/XWiki/Xuake?language=pl&docVersion=1.1] WARN  c.x.x.w.s.JsExtension          - Failed to compress JS extension: null 
28-Aug-2018 11:52:38.170 WARNING [http://XX.XX.XX.XX:8080/download/XWiki/Ace/ace.zip/ace.js] org.apache.catalina.connector.Response.setCharacterEncoding The encoding [] is not recognised by the JRE
 java.io.UnsupportedEncodingException: The character encoding [] is not supported
	at org.apache.tomcat.util.buf.B2CConverter.getCharset(B2CConverter.java:79)
	at org.apache.coyote.Response.setCharacterEncoding(Response.java:496)
	at org.apache.catalina.connector.Response.setCharacterEncoding(Response.java:802)
	at org.apache.catalina.connector.ResponseFacade.setCharacterEncoding(ResponseFacade.java:623)
	at javax.servlet.ServletResponseWrapper.setCharacterEncoding(ServletResponseWrapper.java:82)
	at javax.servlet.ServletResponseWrapper.setCharacterEncoding(ServletResponseWrapper.java:82)
	at com.xpn.xwiki.web.XWikiServletResponse.setCharacterEncoding(XWikiServletResponse.java:154)
	at com.xpn.xwiki.web.DownloadAction.setCommonHeaders(DownloadAction.java:446)
	at com.xpn.xwiki.web.DownloadAction.sendContent(DownloadAction.java:301)
	at com.xpn.xwiki.web.DownloadAction.render(DownloadAction.java:183)
	at com.xpn.xwiki.web.XWikiAction.execute(XWikiAction.java:459)
	at com.xpn.xwiki.web.XWikiAction.execute(XWikiAction.java:209)
	at org.apache.struts.action.RequestProcessor.processActionPerform(RequestProcessor.java:425)
	at org.apache.struts.action.RequestProcessor.process(RequestProcessor.java:228)
	at org.apache.struts.action.ActionServlet.process(ActionServlet.java:1913)
	at org.apache.struts.action.ActionServlet.doGet(ActionServlet.java:449)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:634)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:741)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at com.xpn.xwiki.web.ActionFilter.doFilter(ActionFilter.java:112)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.xwiki.wysiwyg.filter.ConversionFilter.doFilter(ConversionFilter.java:127)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.xwiki.container.servlet.filters.internal.SavedRequestRestorerFilter.doFilter(SavedRequestRestorerFilter.java:208)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.xwiki.container.servlet.filters.internal.SetCharacterEncodingFilter.doFilter(SetCharacterEncodingFilter.java:111)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.tuckey.web.filters.urlrewrite.RuleChain.handleRewrite(RuleChain.java:176)
	at org.tuckey.web.filters.urlrewrite.RuleChain.doRules(RuleChain.java:145)
	at org.tuckey.web.filters.urlrewrite.UrlRewriter.processRequest(UrlRewriter.java:92)
	at org.tuckey.web.filters.urlrewrite.UrlRewriteFilter.doFilter(UrlRewriteFilter.java:394)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:712)
	at org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:459)
	at org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:384)
	at org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:312)
	at org.tuckey.web.filters.urlrewrite.NormalRewrittenUrl.doRewrite(NormalRewrittenUrl.java:213)
	at org.tuckey.web.filters.urlrewrite.RuleChain.handleRewrite(RuleChain.java:171)
	at org.tuckey.web.filters.urlrewrite.RuleChain.doRules(RuleChain.java:145)
	at org.tuckey.web.filters.urlrewrite.UrlRewriter.processRequest(UrlRewriter.java:92)
	at org.tuckey.web.filters.urlrewrite.UrlRewriteFilter.doFilter(UrlRewriteFilter.java:394)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:199)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:491)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:139)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
	at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:668)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343)
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:408)
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:764)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1388)
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:748)

We’re running XWiki 10.6.1 on CentOs 7 in Tomcat. Should we update to 10.7?

Regarding Java we have:
openjdk version "1.8.0_171" \ OpenJDK Runtime Environment (build 1.8.0_171-b10) \ OpenJDK 64-Bit Server VM (build 25.171-b10, mixed mode)

What happens with the first job? The second job doesn’t progress because it waits for the first job to finish. I suppose the first job has some progress log. Does it finish successfully?

Note that if the affected paths don’t overlap then the jobs could run in parallel. See Loading... .

I restarted Tomcat and imported new page with several subpages again to perform the process from the beginning.

  1. Renaming Sport to Sport1 (After importing from Mindtouch the page Sport has a reference sport instead of Sport, thus I’m renaming it from Sport to Sport2 and then to Sport in order to have nicer URLs). Moving successful but the progress bar on the “status page” freezes as in the screenshot below. Nothing new in catalina.out.
    image

  2. After couple of minutes I started rename of Sport1 to Sport. Job stucks and the page is not moved. Nothing new in catalina.out apart from some Solr warnings. Progress bar also freezes.
    image

Could you guide me on what type of logger can be helpful here?

There’s an easier way to do this. Edit your user profile preferences and set the user type to Advanced. This enables a couple of useful features:

  • On the Move/Rename Page dialog you get a pencil icon on the New Location field that toggles two advanced fields, Parent and Name. Just replace “sport” with “Sport” in the value of the Parent field. This way you need only one step to get the desired nice URL.
  • On the job progress page you can see the entire progress log.

Now back to your problem. You should focus on the first job. The second job is most probably waiting for the first job to finish so starting the second job doesn’t help us. On the progress page for the first job, when you feel the progress freezes:

  • open the JavaScript console using the browser’s built-in developer tools and check if there is any JavaScript exception.
  • Check also the Network tab to see if there are HTTP requests made regularly for the job status update.
  • Reload the page and see if there is any progress

Note that the current page URL contains the ID of the rename job which you can use to find its log on the file system inside <permanentDirectory>/jobs/status/refactoring/rename .

Thanks, this is really helpful feature!


This time I’m going to use the method provided by you i.e. renaming it as an advanced user. I restarted the Tomcat and tried to rename the page sport to Sport.

This is the output after executing the action (text log attached as XX.XX.XX.XX-1535461435084.log (8.5 KB)):

Finished with errors there are 2 requests:

Request URL: http://XX.XX.XX.XX:8080/sport/text.js
Request Method: GET
Status Code: 404 
Remote Address: XX.XX.XX.XX:8080
Referrer Policy: no-referrer-when-downgrade

Request URL: http://XX.XX.XX.XX:8080/job/wiki/xwiki/question/refactoring/rename/1535461209449-662
Request Method: GET
Status Code: 404 
Remote Address: XX.XX.XX.XX:8080
Referrer Policy: no-referrer-when-downgrade

Same situation, no progress. Stuck at Starting job of type [refactoring/rename] with identifier [refactoring/rename/1535461209449-662]. I checked the jobs folder (/var/local/xwiki/jobs/status/refactoring/rename) and there is no such folder 1535461209449-662. However there are some other job folders.
image

You have some errors related to the ACE editor, I think, which must be an extension that you installed on top of XWiki, because it’s not available in XWiki Standard. This shouldn’t affect the rename normally.

That’s normal. It means the rename job hasn’t asked any question. If the job asks a question (i.e. needs some input from the user) then that URL returns the question to display to the user.

Well, it’s different. You used to have some progress. This time the job doesn’t even start. Are you the only user that performs refactoring operation on the wiki? Could it be that some other user started a job?

That’s probably because the job log is saved on the file system when the job is done (with or without success).

In any case, what I don’t understand is why the job doesn’t start even though you restarted Tomcat. Last time the job log was stuck at “Document […] has been copied to […]” so the job managed to do something.

Yes, that’s a different situation. I’m the only one working on the XWiki right now.

I tried to rename a different page and the result was as previously i.e. the page was successfully renamed from Technologia to Technologie (there was a green Done message after refreshing the page and the page was visible) but then new job stucked again on renaming it back to Technologia (Starting job of type [refactoring/rename] with identifier [refactoring/rename/1535464504252-263]).

So, I restarted Tomcat after couple of minutes and tried again to rename it back to Technologia. It didn’t start and stucked at Starting job of type [refactoring/rename] with identifier [refactoring/rename/1535464944832-738].

So, I restarted Tomcat again and tried to rename Technologie to Technologie1. It worked.

It seems that the problem is related to renaming the same page back and forth.


This is the recent history of the extensions (two newest are result of clicking the Update in the Updater).

Yes… so here’s what I believe it happens:

  • you rename using the “Create an automatic redirect” option checked (the default). As a result the original page is not completely removed. It is actually replaced with a hidden “placeholder” page that performs the automatic redirect to the new page. And in case you’re wondering Loading...
  • when you try to rename back the rename job detects that the page exists (although it’s just a redirect placeholder) and asks whether you want to overwrite it or not. The job then waits for the answer.

In my XWiki 10.8-SNAPSHOT instance I get this:

So the issue seems to be that the request for the confirmation question

doesn’t return anything in your case… Looks like a bug. @tmortagne any idea?

1 Like

As far as I can see QuestionJobResourceReferenceHandler never return 404 (which should probably be improved since it would make more sense for not existing Job for example) so 404 here means that the resource handler itself cannot be found. That would suggest that the xwiki-platform-job-handler jar is not there.

I just checked the lib folder and this jar is present
image

Note that I reported and fixed Loading... and Loading... .

1 Like