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