Details
-
Bug
-
Resolution: Unresolved
-
Medium
-
None
-
7.4.8, 7.4.11
-
25
-
Severity 3 - Minor
-
20
-
Description
Issue Summary
Using REST API to update large pages after restart of Collaborative editing will throw 501 errors and fail to update. Keep in mind that all pages will have contentpropertyes "sync-rev-source" set to "restored".
Steps to Reproduce
- Create 2 pages. Page A with few lines of text, and Page B with 1MB of text.
- Inspect contentproperties table for these 2 pages and we will see that contentpropertyes "sync-rev-source" is set to "synchrony".
- Turn off Collaborative Editing. Then turn it on. Or set the contentpropertyes "sync-rev-source" to "restored" for both pages, and then flush the cache in Confluence Administration > Manage cache.
- Open the page in a view mode.
- Run REST API put a call to update them. For page A use small content and for page B use the same amount of content, but with small changes in the content.
Expected Results
Both pages will be updated without any problem.
Actual Results
Page A is updated without problem, but page B will fail with an error:
{ "statusCode": 501, "message": "Unable to save changes to unreconciled page ContentId{id=8093727}", "reason": "Not Implemented" }
The below exception is thrown in the atlassian-confluence.log file:
2021-09-09 17:29:16,107 WARN [http-nio-6743-exec-6] [synchrony.service.http.SynchronyResponseHandler] failed Synchrony external changes API call returned 500: {"id":"YhhX2gNq3bXjDMSgtt68JQ","message":"Internal Server Error"} content-id: 8093727 rev: null ancestor: null merges: {"confVersion":"7","trigger":"restored","type":"external"} generate-rev: true generate-reset: true -- space: 4423681 | url: /c743/plugins/editor-loader/editor.action | page: 8093727 | traceId: bc1dac72dde6db44 | userName: admin | referer: http://localhost:6743/c743/pages/viewpage.action?pageId=8093727 | action: editor 2021-09-09 17:29:16,118 WARN [http-nio-6743-exec-6] [plugins.synchrony.service.SynchronyContentService] runRecoveryInTransaction Could not reconcile content for restored. ID: 8093727 Caused by: java.lang.RuntimeException: Synchrony error: cannot reset page ContentId{id=8093727} -- space: 4423681 | url: /c743/plugins/editor-loader/editor.action | page: 8093727 | traceId: bc1dac72dde6db44 | userName: admin | referer: http://localhost:6743/c743/pages/viewpage.action?pageId=8093727 | action: editor 2021-09-09 17:29:16,119 WARN [http-nio-6743-exec-6] [confluence.util.profiling.DurationThresholdWarningTimingHelperFactory] logMessage Execution time for publishing event com.atlassian.confluence.event.events.content.page.synchrony.SynchronyRecoveryEvent@69ef4a8c took 15647 ms (warning threshold is 5000 ms) -- space: 4423681 | url: /c743/plugins/editor-loader/editor.action | page: 8093727 | traceId: bc1dac72dde6db44 | userName: admin | referer: http://localhost:6743/c743/pages/viewpage.action?pageId=8093727 | action: editor 2021-09-09 17:29:16,120 WARN [http-nio-6743-exec-6] [confluence.impl.hibernate.ConfluenceHibernateTransactionManager] doRollback Performing rollback. Transactions: ->[null]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT (Session #1368676878) [SALSpringTx]: PROPAGATION_REQUIRES_NEW,ISOLATION_DEFAULT,readOnly (Session #1267779669) -- space: 4423681 | url: /c743/plugins/editor-loader/editor.action | page: 8093727 | traceId: bc1dac72dde6db44 | userName: admin | referer: http://localhost:6743/c743/pages/viewpage.action?pageId=8093727 | action: editor 2021-09-09 17:29:16,234 INFO [http-nio-6743-exec-3] [synchrony.service.http.SynchronyRequestExecutor] execute Initiating request PUT http://127.0.0.1:5743/synchrony/v1/data/Synchrony-e7709fa5-5f9a-3039-bb8b-ca8ec9737c23/confluence-8093727 HTTP/1.1 for 8093727 2021-09-09 17:29:37,469 WARN [http-nio-6743-exec-3] [synchrony.service.http.SynchronyResponseHandler] failed Synchrony external changes API call returned 500: {"id":"Kxf9Wacjpn8Fvc3JH6ppBA","message":"Internal Server Error"} content-id: 8093727 rev: null ancestor: null merges: {"confVersion":"7","trigger":"restored","type":"external"} generate-rev: true generate-reset: true -- url: /c743/rest/api/content/8093727 | traceId: a43e477b4e93cbda | userName: admin 2021-09-09 17:29:37,471 WARN [http-nio-6743-exec-3] [plugins.synchrony.service.SynchronyContentService] runRecoveryInTransaction Could not reconcile content for restored. ID: 8093727 Caused by: java.lang.RuntimeException: Synchrony error: cannot reset page ContentId{id=8093727} -- url: /c743/rest/api/content/8093727 | traceId: a43e477b4e93cbda | userName: admin 2021-09-09 17:29:37,472 WARN [http-nio-6743-exec-3] [confluence.util.profiling.DurationThresholdWarningTimingHelperFactory] logMessage Execution time for publishing event com.atlassian.confluence.event.events.content.page.synchrony.SynchronyRecoveryEvent@4a0a77d5 took 24670 ms (warning threshold is 5000 ms) -- url: /c743/rest/api/content/8093727 | traceId: a43e477b4e93cbda | userName: admin 2021-09-09 17:29:37,473 WARN [http-nio-6743-exec-3] [confluence.impl.hibernate.ConfluenceHibernateTransactionManager] doRollback Performing rollback. Transactions: ->[com.atlassian.confluence.api.impl.service.content.ContentServiceImpl.update]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT (Session #1725687175) [SALSpringTx]: PROPAGATION_REQUIRES_NEW,ISOLATION_DEFAULT,readOnly (Session #933445248) -- url: /c743/rest/api/content/8093727 | traceId: a43e477b4e93cbda | userName: admin 2021-09-09 17:30:39,787 INFO [http-nio-6743-exec-9] [synchrony.service.http.SynchronyRequestExecutor] execute Initiating request PUT http://127.0.0.1:5743/synchrony/v1/data/Synchrony-e7709fa5-5f9a-3039-bb8b-ca8ec9737c23/confluence-8093727 HTTP/1.1 for 8093727 2021-09-09 17:31:00,987 WARN [http-nio-6743-exec-9] [synchrony.service.http.SynchronyResponseHandler] failed Synchrony external changes API call returned 500: {"id":"ljlTszkh8C7mMMHHkKEWeQ","message":"Internal Server Error"} content-id: 8093727 rev: null ancestor: null merges: {"confVersion":"7","trigger":"restored","type":"external"} generate-rev: true generate-reset: true -- url: /c743/rest/api/content/8093727 | traceId: 410d7bba06f997bd | userName: admin 2021-09-09 17:31:00,989 WARN [http-nio-6743-exec-9] [plugins.synchrony.service.SynchronyContentService] runRecoveryInTransaction Could not reconcile content for restored. ID: 8093727 Caused by: java.lang.RuntimeException: Synchrony error: cannot reset page ContentId{id=8093727} -- url: /c743/rest/api/content/8093727 | traceId: 410d7bba06f997bd | userName: admin 2021-09-09 17:31:00,990 WARN [http-nio-6743-exec-9] [confluence.util.profiling.DurationThresholdWarningTimingHelperFactory] logMessage Execution time for publishing event com.atlassian.confluence.event.events.content.page.synchrony.SynchronyRecoveryEvent@783aa1e took 22991 ms (warning threshold is 5000 ms) -- url: /c743/rest/api/content/8093727 | traceId: 410d7bba06f997bd | userName: admin 2021-09-09 17:31:00,991 WARN [http-nio-6743-exec-9] [confluence.impl.hibernate.ConfluenceHibernateTransactionManager] doRollback Performing rollback. Transactions: ->[com.atlassian.confluence.api.impl.service.content.ContentServiceImpl.update]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT (Session #1247324562) [SALSpringTx]: PROPAGATION_REQUIRES_NEW,ISOLATION_DEFAULT,readOnly (Session #24364497) -- url: /c743/rest/api/content/8093727 | traceId: 410d7bba06f997bd | userName: admin
Synchrony logs:
2021-09-09 17:30:40,416 DEBUG [395:StdOutHandler [/Library/Java/JavaVirtualMachines/adoptopenjdk-11.jdk/Contents/Home/bin/java]] 2021-09-09 15:30:40,416 INFO [async-dispatch-6] [synchrony.sync.hubs] create-entity {:event :entity.created, :entity "/Synchrony-e7709fa5-5f9a-3039-bb8b-ca8ec9737c23/confluence-8093727"} 2021-09-09 17:30:46,129 DEBUG [395:StdOutHandler [/Library/Java/JavaVirtualMachines/adoptopenjdk-11.jdk/Contents/Home/bin/java]] 2021-09-09 15:30:46,128 INFO [async-dispatch-5] [synchrony.middleware.logging] {:request {:remote-addr "127.0.0.1", :uri "/synchrony/heartbeat", :request-method :get, :query-string nil}, :response {:status 200}} 2021-09-09 17:31:00,544 DEBUG [395:StdOutHandler [/Library/Java/JavaVirtualMachines/adoptopenjdk-11.jdk/Contents/Home/bin/java]] 2021-09-09 15:31:00,544 INFO [hz._hzInstance_1_gojko-Synchrony.HealthMonitor] [hazelcast.internal.diagnostics.HealthMonitor] [172.16.0.32]:5701 [gojko-Synchrony] [3.11.4] processors=12, physical.memory.total=0, physical.memory.free=0, swap.space.total=0, swap.space.free=0, heap.memory.used=720.8M, heap.memory.free=303.2M, heap.memory.total=1024.0M, heap.memory.max=1024.0M, heap.memory.used/total=70.32%, heap.memory.used/max=70.32%, minor.gc.count=451, minor.gc.time=7405ms, major.gc.count=0, major.gc.time=0ms, load.process=0.00%, load.system=0.00%, load.systemAverage=5.61, thread.count=93, thread.peakCount=95, cluster.timeDiff=0, event.q.size=0, executor.q.async.size=0, executor.q.client.size=0, executor.q.client.query.size=0, executor.q.client.blocking.size=0, executor.q.query.size=0, executor.q.scheduled.size=0, executor.q.io.size=0, executor.q.system.size=0, executor.q.operations.size=0, executor.q.priorityOperation.size=0, operations.completed.count=44, executor.q.mapLoad.size=0, executor.q.mapLoadAllKeys.size=0, executor.q.cluster.size=0, executor.q.response.size=0, operations.running.count=0, operations.pending.invocations.percentage=0.00%, operations.pending.invocations.count=0, proxy.count=0, clientEndpoint.count=0, connection.active.count=1, client.connection.count=0, connection.count=1 2021-09-09 17:31:00,986 DEBUG [395:StdOutHandler [/Library/Java/JavaVirtualMachines/adoptopenjdk-11.jdk/Contents/Home/bin/java]] 2021-09-09 15:31:00,985 WARN [async-dispatch-8] [synchrony.http.entity-api] Error in put-entity {:entity "/Synchrony-e7709fa5-5f9a-3039-bb8b-ca8ec9737c23/confluence-8093727", :id "ljlTszkh8C7mMMHHkKEWeQ", :throwable #error { 2021-09-09 17:31:00,986 DEBUG [395:StdOutHandler [/Library/Java/JavaVirtualMachines/adoptopenjdk-11.jdk/Contents/Home/bin/java]] :cause "request closed prematurely" 2021-09-09 17:31:00,986 DEBUG [395:StdOutHandler [/Library/Java/JavaVirtualMachines/adoptopenjdk-11.jdk/Contents/Home/bin/java]] :data {} 2021-09-09 17:31:00,986 DEBUG [395:StdOutHandler [/Library/Java/JavaVirtualMachines/adoptopenjdk-11.jdk/Contents/Home/bin/java]] :via 2021-09-09 17:31:00,986 DEBUG [395:StdOutHandler [/Library/Java/JavaVirtualMachines/adoptopenjdk-11.jdk/Contents/Home/bin/java]] [{:type clojure.lang.ExceptionInfo 2021-09-09 17:31:00,986 DEBUG [395:StdOutHandler [/Library/Java/JavaVirtualMachines/adoptopenjdk-11.jdk/Contents/Home/bin/java]] :message "Request aborted" 2021-09-09 17:31:00,986 DEBUG [395:StdOutHandler [/Library/Java/JavaVirtualMachines/adoptopenjdk-11.jdk/Contents/Home/bin/java]] :data {:level :warn} 2021-09-09 17:31:00,986 DEBUG [395:StdOutHandler [/Library/Java/JavaVirtualMachines/adoptopenjdk-11.jdk/Contents/Home/bin/java]] :at [synchrony.sync.connection$request_BANG_$fn__33384 invoke "connection.cljc" 88]} 2021-09-09 17:31:00,986 DEBUG [395:StdOutHandler [/Library/Java/JavaVirtualMachines/adoptopenjdk-11.jdk/Contents/Home/bin/java]] {:type clojure.lang.ExceptionInfo 2021-09-09 17:31:00,986 DEBUG [395:StdOutHandler [/Library/Java/JavaVirtualMachines/adoptopenjdk-11.jdk/Contents/Home/bin/java]] :message "request closed prematurely" 2021-09-09 17:31:00,986 DEBUG [395:StdOutHandler [/Library/Java/JavaVirtualMachines/adoptopenjdk-11.jdk/Contents/Home/bin/java]] :data {} 2021-09-09 17:31:00,986 DEBUG [395:StdOutHandler [/Library/Java/JavaVirtualMachines/adoptopenjdk-11.jdk/Contents/Home/bin/java]] :at [ginga.core$raise invokeStatic "core.cljc" 607]}] 2021-09-09 17:31:00,986 DEBUG [395:StdOutHandler [/Library/Java/JavaVirtualMachines/adoptopenjdk-11.jdk/Contents/Home/bin/java]] :trace 2021-09-09 17:31:00,986 DEBUG [395:StdOutHandler [/Library/Java/JavaVirtualMachines/adoptopenjdk-11.jdk/Contents/Home/bin/java]] [[ginga.core$raise invokeStatic "core.cljc" 607] 2021-09-09 17:31:00,986 DEBUG [395:StdOutHandler [/Library/Java/JavaVirtualMachines/adoptopenjdk-11.jdk/Contents/Home/bin/java]] [clojure.lang.RestFn invoke "RestFn.java" 408] 2021-09-09 17:31:00,986 DEBUG [395:StdOutHandler [/Library/Java/JavaVirtualMachines/adoptopenjdk-11.jdk/Contents/Home/bin/java]] [ginga.async$expect_BANG_$fn__9221 invoke "async.cljc" 332] 2021-09-09 17:31:00,986 DEBUG [395:StdOutHandler [/Library/Java/JavaVirtualMachines/adoptopenjdk-11.jdk/Contents/Home/bin/java]] [clojure.core.async$ioc_alts_BANG_$fn__5658 invoke "async.clj" 385] 2021-09-09 17:31:00,986 DEBUG [395:StdOutHandler [/Library/Java/JavaVirtualMachines/adoptopenjdk-11.jdk/Contents/Home/bin/java]] [clojure.core.async$do_alts$fn__5598$fn__5601 invoke "async.clj" 254] 2021-09-09 17:31:00,986 DEBUG [395:StdOutHandler [/Library/Java/JavaVirtualMachines/adoptopenjdk-11.jdk/Contents/Home/bin/java]] [ginga.async (take?) "async.cljc" 353] 2021-09-09 17:31:00,986 DEBUG [395:StdOutHandler [/Library/Java/JavaVirtualMachines/adoptopenjdk-11.jdk/Contents/Home/bin/java]] [ginga.async$request_BANG_$fn__9390 invoke "async.cljc" 351] 2021-09-09 17:31:00,986 DEBUG [395:StdOutHandler [/Library/Java/JavaVirtualMachines/adoptopenjdk-11.jdk/Contents/Home/bin/java]] [clojure.lang.AFn run "AFn.java" 22] 2021-09-09 17:31:00,986 DEBUG [395:StdOutHandler [/Library/Java/JavaVirtualMachines/adoptopenjdk-11.jdk/Contents/Home/bin/java]] [java.util.concurrent.ThreadPoolExecutor runWorker "ThreadPoolExecutor.java" 1128] 2021-09-09 17:31:00,986 DEBUG [395:StdOutHandler [/Library/Java/JavaVirtualMachines/adoptopenjdk-11.jdk/Contents/Home/bin/java]] [java.util.concurrent.ThreadPoolExecutor$Worker run "ThreadPoolExecutor.java" 628] 2021-09-09 17:31:00,986 DEBUG [395:StdOutHandler [/Library/Java/JavaVirtualMachines/adoptopenjdk-11.jdk/Contents/Home/bin/java]] [java.lang.Thread run "Thread.java" 834]]}} 2021-09-09 17:31:00,986 DEBUG [395:StdOutHandler [/Library/Java/JavaVirtualMachines/adoptopenjdk-11.jdk/Contents/Home/bin/java]] 2021-09-09 15:31:00,986 INFO [async-dispatch-8] [synchrony.middleware.logging] {:request {:remote-addr "127.0.0.1", :uri "/synchrony/v1/data/Synchrony-e7709fa5-5f9a-3039-bb8b-ca8ec9737c23/confluence-8093727", :request-method :put, :query-string nil}, :response {:status 500}} 2021-09-09 17:31:03,174 DEBUG [395:StdOutHandler [/Library/Java/JavaVirtualMachines/adoptopenjdk-11.jdk/Contents/Home/bin/java]] 2021-09-09 15:31:03,174 WARN [async-dispatch-7] [synchrony.sync.hubs] processing incoming message exceeded time threshold {:threshold 1000, :delta 12191, :entity "/Synchrony-e7709fa5-5f9a-3039-bb8b-ca8ec9737c23/confluence-8093727"}
Notes
This issue can not be replicated always and for this large page, it took me 5 tries before I managed to replicate it. What is noticed is that the more changes across the page we have before the update the better the chances for the issue. Refreshing the original big page while running updates helps aswell. If we repeat the request few more times with the same request, eventually the page will update.
Workaround
Currently, there is no known workaround for this behavior. A workaround will be added here when available