Collabora stopped working on two of my instances, failed to load document

jacotec · July 26, 2021, 6:29pm

Hi,

I have a serious issue with two of my NC instances. On both Collabora suddenly stopped working, it hangs for ages in “Initializing…” and then errors with “Failed to load document”.

Collabora is running in a separate VM via my HAPROXY which handles SSL etc. I have a third, external NC instance which also uses this server and that works. Also my two instances here are showing the same issue when I change from my external VM to the local Collabora app.

All NC logs, including the Apache logs are fine. Apache shows the requests for the document with code 200 and the correct size in the access log.

The only evidence is the log of the Collabora server. It waits for 30 seconds and then shows a timeout when requesting the document, then the request seems to work but results in an error further down.

I’ve spent many hours in getting behind this, but I’m fully puzzles and ran out of ideas. I hope someone has an idea as we heavily rely on Collabora.

Collabora log is below:
17:46:58.692511 - The timeout
17:46:58.790693 - Final Error “Failed to load file”

Jul 26 17:46:28 collabora loolwsd[6568]: wsd-06568-150807 2021-07-26 17:46:28.660354 [ docbroker_0a2 ] INF  WOPI::GetFile using default URI: https://cloud.*****.de/index.php/apps/richdocuments/wopi/files/5773_ocv8mixtor6x/contents?access_token=&access_token_ttl=0| wsd/Storage.cpp:1037
Jul 26 17:46:28 collabora loolwsd[6568]: wsd-06568-150807 2021-07-26 17:46:28.662608 [ docbroker_0a2 ] DBG  Connecting to cloud.*****.de:443 (SSL)| net/NetUtil.cpp:92
Jul 26 17:46:28 collabora loolwsd[6568]: wsd-06568-150807 2021-07-26 17:46:28.663953 [ docbroker_0a2 ] DBG  #37 Created socket. Thread affinity set to 0x7fb828ff9700| ./net/Socket.hpp:356
Jul 26 17:46:28 collabora loolwsd[6568]: wsd-06568-150807 2021-07-26 17:46:28.663979 [ docbroker_0a2 ] DBG  StreamSocket ctor #37| ./net/Socket.hpp:869
Jul 26 17:46:28 collabora loolwsd[6568]: wsd-06568-150807 2021-07-26 17:46:28.663990 [ docbroker_0a2 ] DBG  SslStreamSocket ctor #37| ./net/SslSocket.hpp:28
Jul 26 17:46:28 collabora loolwsd[6568]: wsd-06568-150807 2021-07-26 17:46:28.664902 [ docbroker_0a2 ] DBG  Inserting socket #37 into HttpSynReqPoll| ./net/Socket.hpp:697
Jul 26 17:46:28 collabora loolwsd[6568]: wsd-06568-150807 2021-07-26 17:46:28.664925 [ docbroker_0a2 ] DBG  #37 Thread affinity set to 0 (was 0x7fb828ff9700).| ./net/Socket.hpp:307
Jul 26 17:46:28 collabora loolwsd[6568]: wsd-06568-150807 2021-07-26 17:46:28.664939 [ docbroker_0a2 ] WRN  Waking up dead poll thread [HttpSynReqPoll], started: false, finished: false| ./net/Socket.hpp:680
Jul 26 17:46:28 collabora loolwsd[6568]: wsd-06568-150807 2021-07-26 17:46:28.664963 [ docbroker_0a2 ] DBG  #37 Thread affinity set to 0x7fb828ff9700 (was 0).| ./net/Socket.hpp:307
Jul 26 17:46:45 collabora kernel: [163090.686645] device ens160 left promiscuous mode
Jul 26 17:46:58 collabora loolwsd[6568]: wsd-06568-150807 2021-07-26 17:46:58.692511 [ docbroker_0a2 ] WRN  Socket #37 has timed out while requesting [GET cloud.*****.de/index.php/apps/richdocuments/wopi/files/5773_ocv8mixtor6x/contents?access_token=7IwKJRaBJxLvrZE3VEQkz9c5FomRmfnH&access_token_ttl=0] after 30029ms| net/HttpRequest.hpp:1294
Jul 26 17:46:58 collabora loolwsd[6568]: wsd-06568-150807 2021-07-26 17:46:58.692601 [ docbroker_0a2 ] DBG  SslStreamSocket::closeConnection() #37| ./net/SslSocket.hpp:76
Jul 26 17:46:58 collabora loolwsd[6568]: wsd-06568-150807 2021-07-26 17:46:58.692738 [ docbroker_0a2 ] DBG  SslStreamSocket dtor #37| ./net/SslSocket.hpp:62
Jul 26 17:46:58 collabora loolwsd[6568]: wsd-06568-150807 2021-07-26 17:46:58.692814 [ docbroker_0a2 ] DBG  StreamSocket dtor #37 with pending write: 0, read: 0| ./net/Socket.hpp:878
Jul 26 17:46:58 collabora loolwsd[6568]: wsd-06568-150807 2021-07-26 17:46:58.692872 [ docbroker_0a2 ] INF  WOPI::GetFile downloaded 41711 bytes from [https://cloud.*****.de/index.php/apps/richdocuments/wopi/files/5773_ocv8mixtor6x/contents?access_token=&access_token_ttl=0] -> /opt/lool/child-roots/lnONgqTOdMr4qObn/tmp/user/docs/lnONgqTOdMr4qObn/Eintrittserklärung SEPA.docx in 30032ms| wsd/Storage.cpp:1122
Jul 26 17:46:58 collabora loolwsd[6568]: wsd-06568-150807 2021-07-26 17:46:58.693413 [ docbroker_0a2 ] INF  SHA1 for DocKey [/index.php/apps/richdocuments/wopi/files/5773_ocv8mixtor6x] of [/tmp/user/docs/lnONgqTOdMr4qObn/Eintrittserklärung SEPA.docx]: 1c8d6e49f5f02735346666670e3419c1ba2c7330| wsd/DocumentBroker.cpp:955
Jul 26 17:46:58 collabora loolwsd[6568]: wsd-06568-150807 2021-07-26 17:46:58.693466 [ docbroker_0a2 ] INF  TileCache ctor for uri [https://cloud.*****.de/index.php/apps/richdocuments/wopi/files/5773_ocv8mixtor6x?access_token=&access_token_ttl=0], modifiedTime=1627321588], dontCache=false| wsd/TileCache.cpp:41
Jul 26 17:46:58 collabora loolwsd[6568]: wsd-06568-150807 2021-07-26 17:46:58.693541 [ docbroker_0a2 ] INF  Filesystem [/opt/lool/child-roots/.] has 227329 MB free (90.5855%).| common/FileUtil.cpp:477
Jul 26 17:46:58 collabora loolwsd[6568]: wsd-06568-150807 2021-07-26 17:46:58.693594 [ docbroker_0a2 ] DBG  #25 Thread affinity set to 0x7fb828ff9700 (was 0).| ./net/Socket.hpp:307
Jul 26 17:46:58 collabora loolwsd[6568]: wsd-06568-150807 2021-07-26 17:46:58.693660 [ docbroker_0a2 ] INF  Client timestamps: Date.now():1627321556871, performance.now():405.2 => 1627321556465801| wsd/ClientSession.cpp:504
Jul 26 17:46:58 collabora loolwsd[6568]: wsd-06568-150807 2021-07-26 17:46:58.693818 [ docbroker_0a2 ] INF  Requesting document load from child.| wsd/ClientSession.cpp:1029
Jul 26 17:46:58 collabora loolwsd[6568]: wsd-06568-06591 2021-07-26 17:46:58.694049 [ admin ] DBG  Added admin document [/index.php/apps/richdocuments/wopi/files/5773_ocv8mixtor6x].| wsd/AdminModel.cpp:516
Jul 26 17:46:58 collabora loolwsd[150529]: kit-150529-06586 2021-07-26 17:46:58.694186 [ kit_spare_0a2 ] DBG  child_ws: recv [session 17a /index.php/apps/richdocuments/wopi/files/5773_ocv8mixtor6x 0a2 0 | kit/Kit.cpp:2108
Jul 26 17:46:58 collabora loolwsd[150529]: kit-150529-06586 2021-07-26 17:46:58.694264 [ kit_spare_0a2 ] INF  New session [17a] request on url [/index.php/apps/richdocuments/wopi/files/5773_ocv8mixtor6x] with viewId 0| kit/Kit.cpp:2127
Jul 26 17:46:58 collabora loolwsd[150529]: kit-150529-06586 2021-07-26 17:46:58.694298 [ kitbroker_0a2 ] INF  Thread 6586 (7f867e4bcbc0) of process 150529 formerly known as [kit_spare_0a2] is now called [kitbroker_0a2].| common/Util.cpp:594
Jul 26 17:46:58 collabora loolwsd[150529]: kit-150529-06586 2021-07-26 17:46:58.694595 [ kitbroker_0a2 ] INF  Document ctor for [/index.php/apps/richdocuments/wopi/files/5773_ocv8mixtor6x] url [/index.php/apps/richdocuments/wopi/files/5773_ocv8mixtor6x] on child [lnONgqTOdMr4qObn] and id [0a2].| kit/Kit.cpp:543
Jul 26 17:46:58 collabora loolwsd[150529]: kit-150529-06586 2021-07-26 17:46:58.694664 [ kitbroker_0a2 ] INF  Creating first session for url: /index.php/apps/richdocuments/wopi/files/5773_ocv8mixtor6x for sessionId: 17a on jailId: lnONgqTOdMr4qObn| kit/Kit.cpp:603
Jul 26 17:46:58 collabora loolwsd[150529]: kit-150529-06586 2021-07-26 17:46:58.694686 [ kitbroker_0a2 ] INF  ChildSession ctor [ToMaster-17a]. JailRoot: [].| kit/ChildSession.cpp:86
Jul 26 17:46:58 collabora loolwsd[150529]: kit-150529-06586 2021-07-26 17:46:58.694755 [ kitbroker_0a2 ] DBG  Sessions: 1| kit/Kit.cpp:617
Jul 26 17:46:58 collabora loolwsd[150529]: kit-150529-06586 2021-07-26 17:46:58.694808 [ kitbroker_0a2 ] DBG  child_ws: recv [child-17a load xjail=file:///tmp/user/docs/lnONgqTOdMr4qObn/Eintrittserkl%C3%A4rung%20SEPA.docx xauthorid=marco xauthor=Marco%20Jakobs readonly=0 lang=de deviceFormFactor=desktop | kit/Kit.cpp:2108
Jul 26 17:46:58 collabora loolwsd[150529]: kit-150529-06586 2021-07-26 17:46:58.694963 [ kitbroker_0a2 ] INF  Loading url [file:///tmp/user/docs/lnONgqTOdMr4qObn/Eintrittserkl%C3%A4rung%20SEPA.docx] for session [17a] which has 0 sessions. Another load in progress: 0| kit/Kit.cpp:975
Jul 26 17:46:58 collabora loolwsd[150529]: kit-150529-06586 2021-07-26 17:46:58.694986 [ kitbroker_0a2 ] INF  Loading new document from URI: [file:///tmp/user/docs/lnONgqTOdMr4qObn/Eintrittserkl%C3%A4rung%20SEPA.docx] for session [17a].| kit/Kit.cpp:1282
Jul 26 17:46:58 collabora loolwsd[150529]: kit-150529-06586 2021-07-26 17:46:58.695049 [ kitbroker_0a2 ] DBG  Calling lokit::documentLoad(file:///tmp/user/docs/lnONgqTOdMr4qObn/Eintrittserkl%C3%A4rung%20SEPA.docx, "Language=de,DeviceFormFactor=desktop").| kit/Kit.cpp:1301
Jul 26 17:46:58 collabora loolwsd[150529]: kit-150529-06586 2021-07-26 17:46:58.790630 [ kitbroker_0a2 ] DBG  Returned lokit::documentLoad(file:///tmp/user/docs/lnONgqTOdMr4qObn/Eintrittserkl%C3%A4rung%20SEPA.docx) in 95ms| kit/Kit.cpp:1309
Jul 26 17:46:58 collabora loolwsd[150529]: kit-150529-06586 2021-07-26 17:46:58.790693 [ kitbroker_0a2 ] ERR  Failed to load: file:///tmp/user/docs/lnONgqTOdMr4qObn/Eintrittserkl%C3%A4rung%20SEPA.docx, error: loadComponentFromURL returned an empty reference| kit/Kit.cpp:1316
Jul 26 17:46:58 collabora loolwsd[150529]: kit-150529-06586 2021-07-26 17:46:58.790721 [ kitbroker_0a2 ] ERR  error: cmd=load kind=faileddocloading| ./common/Session.hpp:136
Jul 26 17:46:58 collabora loolwsd[150529]: kit-150529-06586 2021-07-26 17:46:58.790767 [ kitbroker_0a2 ] ERR  Failed to get LoKitDocument instance for [file:///tmp/user/docs/lnONgqTOdMr4qObn/Eintrittserkl%C3%A4rung%20SEPA.docx].| kit/ChildSession.cpp:684

factor3 · August 15, 2021, 9:20pm

Actually:

It seems that the latest Collabora simply does not work. I have had similar problems with it.

It seems that you cannot really enable it. Both Collabora Online and the CODE Server generate failures when they are enabled. The failure message says that they cannot be enabled, though the little button says that they are. Once enabled, Collabora will not load documents. In fact, Nextcloud cannot load Collabora.

The current version of the Collabora app is simply unusable on Nextcloud. While some folks have suggested using an earlier version of Collabora and the CODE server, earlier versions are apparently incompatible with the current Nextcloud version. And the fact that after 20 days you have received no help with this issue indicates that this “featured” app may never be fixed.

I would find some alternative if you want to look at Office documents – either for Collabora or for Nextcloud itself.

wwe · August 20, 2021, 8:13pm

I had an long time issue with collabora/code but now it looks good!

jacotec · August 24, 2021, 1:44pm

Negative here. Updated my Collabora server via apt to 6.4.10-10 and no change. It still does not work.

Failed to load: file:///tmp/user/docs/JRavkXQKYiptrYBj/Testdic.docx, error: loadComponentFromURL returned an empty reference| kit/Kit.cpp:1316

wwe · August 24, 2021, 8:39pm

while troubleshooting I added this option to collabora extra_params --o:net.proto=IPv4 (could be done in loolwsd.xml as well). Specially with docker it’s hard to make IPv6 working…

jacotec · August 24, 2021, 8:54pm

This is already set in my loolwsd.xml … does not help.

harley-peter · August 31, 2021, 8:00am

Tried the Server 6.4.10.10 with the actual Nextcloud 21.04 but it does not work. Apparantly Collabora is not interested to solve the problem.
Any ideas or workarounds?

wwe · August 31, 2021, 8:27pm

I don’t agree - there are bug reports and the problem receives attention - please follow the threads I referenced. Please get in touch with the folks from Collabora and help them to nail it down.

jacotec · September 7, 2021, 12:43pm

I’ve spent some more hours by trying around, especially as I have - or better had - one working NC instance. Tracking the differences I’ve found that the only one was that the working NC instance was sitting behind an older HAPROXY version than the other ones.

I’ve updated that HAPROXY and it stopped working here as well

So Collabora introduced an issue with 6.4.10.x in case the Nexcloud instance is handled by HAPROXY >=2.x.

I’ve opened an issue: https://github.com/CollaboraOnline/online/issues/3199