Strange Collabora "Connecting..." error/timeout unless I upload an image

Hi all!

I have a strange problem with latest Collabora + Nextcloud, when I try to open a document.

The following well-known message appears usually after 25 seconds of “Connecting…”:
“Well, this is embarrassing, we cannot connect to your document. Please try again.”

But now comes the strange behavior:
If I perform some collabora editor actions (like uploading an image) while connecting, it starts working immediately!
See also the debug log below, before and after uploading the image.
There are no JS errors in the browser, no nginx and no collabora errors at all.
It just gives collabora a kick.

I also tried many variations of /etc/resolve.conf, which resulted either in an immediate popup of this error message or no change at all.
I also read lots of other related posts, set up the whole server twice…

Thanks a lot!


My setup:

  • Ubuntu 16.04 LTS
  • kernel 4.4.0-62-generic with kernel extras
  • docker 1.13.1
  • aufs kernel support is available
  • latest collabora/code, loolwsd 2.0.3
  • wonderfall/nextcloud 11.0.1
  • jwilder/nginx-proxy
  • sameersbn/bind:9.9.5

docker info
Containers: 11
Running: 9
Paused: 0
Stopped: 2
Images: 11
Server Version: 1.13.1
Storage Driver: aufs
Root Dir: /var/lib/docker/aufs
Backing Filesystem: extfs
Dirs: 92
Dirperm1 Supported: true
Logging Driver: json-file
Cgroup Driver: cgroupfs
Plugins:
Volume: local
Network: bridge host macvlan null overlay
Swarm: inactive
Runtimes: runc
Default Runtime: runc
Init Binary: docker-init
containerd version: aa8187dbd3b7ad67d8e5e3a15115d3eef43a7ed1
runc version: 9df8b306d01f59d3a8029be411de015b7304dd8f
init version: 949e6fa
Security Options:
apparmor
seccomp
Profile: default
Kernel Version: 4.4.0-62-generic
Operating System: Ubuntu 16.04.2 LTS
OSType: linux
Architecture: x86_64
CPUs: 8
Total Memory: 23.48 GiB
Name: puck996
ID: RCWJ:F6MY:E4SS:WWPP:UYDC:E7DM:FDJP:RVLX:GZKJ:R7EK:7777:CVDM
Docker Root Dir: /var/lib/docker
Debug Mode (client): false
Debug Mode (server): false
Registry: https://index.docker.io/v1/
Experimental: false
Insecure Registries:
127.0.0.0/8
Live Restore Enabled: false


wsd-00033-0034 21:08:54.047549 [ client_req_hdl ] INF  Request from 172.18.0.5:44936: POST /loleaflet/2.0.3/loleaflet.html?WOPISrc=https%3A%2F%2Fcloud2.domain.at%2Fapps%2Frichdocuments%2Fwopi%2Ffiles%2F110_ocadc83b19e7&title=New%20Spreadsheet.ods&lang=en&closebutton=1&revisionhistory=1 HTTP/1.1 / Host: office.domain.at / Connection: close / X-Real-IP: 210.47.118.125 / X-Forwarded-For: 210.47.118.125 / X-Forwarded-Proto: https / X-Forwarded-Ssl: on / X-Forwarded-Port: 443 / Content-Length: 45 / Cache-Control: max-age=0 / Origin: null / Upgrade-Insecure-Requests: 1 / User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/56.0.2924.87 Safari/537.36 / Content-Type: application/x-www-form-urlencoded / Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8 / DNT: 1 / Accept-Encoding: gzip, deflate, br / Accept-Language: de-DE,de;q=0.8,en-US;q=0.6,en;q=0.4 / Cookie: cc2e6d07390afdb582b0d357eb22d1f5=i3mbijkhi2fvhs3j6nu9b3e6r6; _ga=GA1.2.145858230.1447332834; f7a8116916e4709f9034b00e655a9d92=us9v9bhat38kmun3p19etbb5k1
wsd-00033-0034 21:08:54.047719 [ client_req_hdl ] DBG  Preprocessing file: /usr/share/loolwsd//loleaflet/dist/loleaflet.html
wsd-00033-0034 21:08:54.047855 [ client_req_hdl ] WRN  WOPI host did not pass optional access_token_ttl| wsd/FileServer.cpp:255
wsd-00033-0035 21:08:54.526418 [ client_req_hdl ] INF  Request from 172.18.0.5:44938: GET /lool/https%3A%2F%2Fcloud2.domain.at%2Fapps%2Frichdocuments%2Fwopi%2Ffiles%2F110_ocadc83b19e7%3Faccess_token%3D9dtnk6HqTf1cSGxgH4J6QJcNtc22Ys0V%26access_token_ttl%3D0%26permission%3Dedit/ws HTTP/1.1 / Host: office.domain.at / Upgrade: websocket / Connection: upgrade / X-Real-IP: 210.47.118.125 / X-Forwarded-For: 210.47.118.125 / X-Forwarded-Proto: https / X-Forwarded-Ssl: on / X-Forwarded-Port: 443 / Pragma: no-cache / Cache-Control: no-cache / Origin: https://office.domain.at / Sec-WebSocket-Version: 13 / User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/56.0.2924.87 Safari/537.36 / DNT: 1 / Accept-Encoding: gzip, deflate, sdch, br / Accept-Language: de-DE,de;q=0.8,en-US;q=0.6,en;q=0.4 / Cookie: cc2e6d07390afdb582b0d357eb22d1f5=i3mbijkhi2fvhs3j6nu9b3e6r6; _ga=GA1.2.145858230.1447332834; f7a8116916e4709f9034b00e655a9d92=us9v9bhat38kmun3p19etbb5k1 / Sec-WebSocket-Key: ktYGyUfM6G1lyf0kBrhZuw== / Sec-WebSocket-Extensions: permessage-deflate; client_max_window_bits
wsd-00033-0035 21:08:54.526489 [ client_ws_001b ] DBG  Thread started.| wsd/LOOLWSD.cpp:1141
wsd-00033-0035 21:08:54.526514 [ client_ws_001b ] DBG  Handling: /lool/https%3A%2F%2Fcloud2.domain.at%2Fapps%2Frichdocuments%2Fwopi%2Ffiles%2F110_ocadc83b19e7%3Faccess_token%3D9dtnk6HqTf1cSGxgH4J6QJcNtc22Ys0V%26access_token_ttl%3D0%26permission%3Dedit/ws| wsd/LOOLWSD.cpp:1144
wsd-00033-0035 21:08:54.526659 [ client_ws_001b ] INF  Starting GET request handler for session [001b].| wsd/LOOLWSD.cpp:763
wsd-00033-0035 21:08:54.526753 [ client_ws_001b ] DBG  No DocumentBroker with docKey [/apps/richdocuments/wopi/files/110_ocadc83b19e7] found. New Child and Document.| wsd/LOOLWSD.cpp:853
wsd-00033-0035 21:08:54.526797 [ client_ws_001b ] DBG  getNewChild: Have 1 children, forking 1| wsd/LOOLWSD.cpp:430
wsd-00033-0035 21:08:54.526848 [ client_ws_001b ] DBG  MasterToForKit: spawn 1| wsd/LOOLWSD.cpp:310
wsd-00033-0035 21:08:54.526911 [ client_ws_001b ] DBG  getNewChild: Returning new child [2001].| wsd/LOOLWSD.cpp:442
wsd-00033-0035 21:08:54.526928 [ clifrk-00041-0041 21:08:54.527001 [ loolforkit ] INF  ForKit command: [spawn 1].| kit/ForKit.cpp:93
frk-00041-0041 21:08:54.527077 [ loolforkit ] INF  Spawning 1 child per request.| kit/ForKit.cpp:101
frk-00041-0041 21:08:54.527107 [ loolforkit ] INF  Creating 1 new child.| kit/ForKit.cpp:419
frk-00041-0041 21:08:54.527133 [ loolforkit ] DBG  Forking a loolkit process.| kit/ForKit.cpp:209
frk-00041-0041 21:08:54.531262 [ loolforkit ] INF  Forked kit [2066].| kit/ForKit.cpp:244
kit-02066-2066 21:08:54.531991 [ loolkit ] INF  Initializing kit
kit-02066-2066 21:08:54.532199 [ loolkit ] INF  Log level is [7].
kit-02066-2066 21:08:54.532260 [ loolkit ] DBG  Process started.| kit/Kit.cpp:1494
kit-02066-2066 21:08:54.532366 [ loolkit ] INF  Jail path: /opt/lool/child-roots/2066/| kit/Kit.cpp:1508
kit-02066-2066 21:08:54.532743 [ loolkit ] DBG  symlink("../lo","/opt/lool/child-roots/2066/opt/collaboraoffice5.1")| kit/Kit.cpp:265
ent_ws_001b ] DBG  New DocumentBroker for docKey [/apps/richdocuments/wopi/files/110_ocadc83b19e7].| wsd/LOOLWSD.cpp:885
wsd-00033-0035 21:08:54.527026 [ client_ws_001b ] INF  DocumentBroker [https://cloud2.domain.at/apps/richdocuments/wopi/files/110_ocadc83b19e7?access_token=9dtnk6HqTf1cSGxgH4J6QJcNtc22Ys0V&access_token_ttl=0&permission=edit] created. DocKey: [/apps/richdocuments/wopi/files/110_ocadc83b19e7]| wsd/DocumentBroker.cpp:172
wsd-00033-0035 21:08:54.527074 [ client_ws_001b ] DBG  Query param: access_token, value: 9dtnk6HqTf1cSGxgH4J6QJcNtc22Ys0V| wsd/LOOLWSD.cpp:908
wsd-00033-0035 21:08:54.527092 [ client_ws_001b ] DBG  Query param: access_token_ttl, value: 0| wsd/LOOLWSD.cpp:908
wsd-00033-0035 21:08:54.527108 [ client_ws_001b ] DBG  Query param: permission, value: edit| wsd/LOOLWSD.cpp:908
wsd-00033-0035 21:08:54.527126 [ client_ws_001b ] INF  ClientSession ctor [ToClient-001b].
wsd-00033-0035 21:08:54.527289 [ client_ws_001b ] INF  Loading [/apps/richdocuments/wopi/files/110_ocadc83b19e7] for session [001b] and jail [2001].| wsd/DocumentBroker.cpp:198
wsd-00033-0035 21:08:54.527314 [ client_ws_001b ] DBG  Loading from URI: https://cloud2.domain.at/apps/richdocuments/wopi/files/110_ocadc83b19e7?access_token=9dtnk6HqTf1cSGxgH4J6QJcNtc22Ys0V&access_token_ttl=0&permission=edit| wsd/DocumentBroker.cpp:214
wsd-00033-0035 21:08:54.527340 [ client_ws_001b ] INF  jailPath: /user/docs/2001, jailRoot: /opt/lool/child-roots/2001| wsd/DocumentBroker.cpp:229
wsd-00033-0035 21:08:54.527361 [ client_ws_001b ] DBG  Creating new storage instance for URI [https://cloud2.domain.at/apps/richdocuments/wopi/files/110_ocadc83b19e7?access_token=9dtnk6HqTf1cSGxgH4J6QJcNtc22Ys0V&access_token_ttl=0&permission=edit].| wsd/DocumentBroker.cpp:236
wsd-00033-0035 21:08:54.527382 [ client_ws_001b ] INF  Public URI [https://cloud2.domain.at/apps/richdocuments/wopi/files/110_ocadc83b19e7?access_token=9dtnk6HqTf1cSGxgH4J6QJcNtc22Ys0V&access_token_ttl=0&permission=edit] considered WOPI.| wsd/Storage.cpp:174
wsd-00033-0035 21:08:54.527424 [ client_ws_001b ] DBG  Storage ctor: https://cloud2.domain.at/apps/richdocuments/wopi/files/110_ocadc83b19e7?access_token=9dtnk6HqTf1cSGxgH4J6QJcNtc22Ys0V&access_token_ttl=0&permission=edit
wsd-00033-0035 21:08:54.527443 [ client_ws_001b ] INF  WopiStorage ctor with localStorePath: [/opt/lool/child-roots/2001], jailPath: [/user/docs/2001], uri: [https://cloud2.domain.at/apps/richdocuments/wopi/files/110_ocadc83b19e7?access_token=9dtnk6HqTf1cSGxgH4J6QJcNtc22Ys0V&access_token_ttl=0&permission=edit].
wsd-00033-0035 21:08:54.527461 [ client_ws_001b ] DBG  Getting info for wopi uri [https://cloud2.domain.at/apps/richdocuments/wopi/files/110_ocadc83b19e7?access_token=9dtnk6HqTf1cSGxgH4J6QJcNtc22Ys0V&access_token_ttl=0&permission=edit].
wsd-00033-2065 21:08:54.528436 [ client_ws_001b ] DBG  ToClient-001b SenderThread started| wsd/ClientSession.cpp:468
wsd-00033-0035 21:08:54.600830 [ client_ws_001b ] DBG  WOPI::CheckFileInfo returned: {"BaseFileName":"New Spreadsheet.ods","Size":7134,"Version":"0","UserId":"admin","OwnerId":"admin","UserFriendlyName":"admin","UserCanWrite":true,"PostMessageOrigin":"https:\/\/cloud2.domain.at\/"}. Call duration: 0.073348s
wsd-00033-0035 21:08:54.600959 [ client_ws_001b ] WRN  Missing JSON property [HidePrintOption]| wsd/Storage.cpp:353
wsd-00033-0035 21:08:54.600988 [ client_ws_001b ] WRN  Missing JSON property [HideSaveOption]| wsd/Storage.cpp:353
wsd-00033-0035 21:08:54.601012 [ client_ws_001b ] WRN  Missing JSON property [HideExportOption]| wsd/Storage.cpp:353
wsd-00033-0035 21:08:54.601043 [ client_ws_001b ] WRN  Missing JSON property [EnableOwnerTermination]| wsd/Storage.cpp:353
wsd-00033-0035 21:08:54.601064 [ client_ws_001b ] WRN  Missing JSON property [DisablePrint]| wsd/Storage.cpp:353
wsd-00033-0035 21:08:54.601085 [ client_ws_001b ] WRN  Missing JSON property [DisableExport]| wsd/Storage.cpp:353
wsd-00033-0035 21:08:54.601104 [ client_ws_001b ] WRN  Missing JSON property [DisableCopy]| wsd/Storage.cpp:353
wsd-00033-0035 21:08:54.601328 [ clienkit-02001-2001 21:08:54.685940 [ loolkit ] DBG  child_ws_2001: recv [session 001b /apps/richdocuments/wopi/files/110_ocadc83b19e7].| kit/Kit.cpp:1663
kit-02001-2001 21:08:54.685990 [ loolkit ] INF  New session [001b] request on url [/apps/richdocuments/wopi/files/110_ocadc83b19e7].| kit/Kit.cpp:1678
kit-02001-2001 21:08:54.686025 [ loolkit ] INF  Document ctor for url [/apps/richdocuments/wopi/files/110_ocadc83b19e7] on child [2001].| kit/Kit.cpp:460
kit-02001-2001 21:08:54.686088 [ loolkit ] INF  Creating first session for url: /apps/richdocuments/wopi/files/110_ocadc83b19e7 for sessionId: 001b on jailId: 2001| kit/Kit.cpp:494
kit-02001-2001 21:08:54.686124 [ loolkit ] INF  ChildSession ctor [ToMaster-001b].| kit/ChildSession.cpp:46
kit-02001-2067 21:08:54.686120 [ lok_handler ] DBG  Thread started.| kit/Kit.cpp:1309
kit-02001-2001 21:08:54.686146 [ loolkit ] DBG  Sessions: 1| kit/Kit.cpp:499
kit-02066-2066 21:08:54.859557 [ loolkit ] DBG  Initialized jail files.| kit/Kit.cpp:1565
kit-02066-2066 21:08:54.859869 [ loolkit ] INF  chroot("/opt/lool/child-roots/2066/")| kit/Kit.cpp:1582
kit-02066-2066 21:08:54.860038 [ loolkit ] DBG  Initialized jail nodes, dropped caps.| kit/Kit.cpp:1599
kit-02066-2066 21:08:54.920407 [ loolkit ] INF  Process is ready.| kit/Kit.cpp:1626
kit-02066-2066 21:08:54.921490 [ loolkit ] INF  SocketProcessor [child_ws_2066] starting.| common/IoUtil.cpp:49

image upload using the “insert graphic” icon of the editor"
(still “Connecting…”)

kit-02001-2001 21:09:18.760656 [ loolkit ] DBG  child_ws_2001: recv [child-001b load url=https://cloud2.domain.at/apps/richdocuments/wopi/files/110_ocadc83b19e7?access_token=9dtnk6HqTf1...].| kit/Kit.cpp:1663
kit-02001-2001 21:09:18.760834 [ loolkit ] DBG  child_ws_2001: recv [child-001b partpagerectangles].| kit/Kit.cpp:1663
kit-02001-2067 21:09:18.760900 [ lok_handler ] INF  Loading session [001b] on url [file:///user/docs/2001/New%20Spreadsheet.ods] is loading. 1 views loaded.| kit/Kit.cpp:912
kit-02001-2067 21:09:18.760988 [ lok_handler ] INF  Loading new document from URI: [file:///user/docs/2001/New%20Spreadsheet.ods] for session [001b].| kit/Kit.cpp:1126
kit-02001-2001 21:09:18.760931 [ loolkit ] DBG  child_ws_2001: recv [child-001b getchildid].| kit/Kit.cpp:1663
kit-02001-2067 21:09:18.761037 [ lok_handler ] DBG  Calling lokit::documentLoad.| kit/Kit.cpp:1141
kit-02001-2067 21:09:19.016862 [ lok_handler ] DBG  Returned lokit::documentLoad.| kit/Kit.cpp:1143
kit-02001-2067 21:09:19.034544 [ lok_handler ] INF  Document [/apps/richdocuments/wopi/files/110_ocadc83b19e7] view [0] loaded. Have 1 view.| kit/Kit.cpp:1247
kit-02001-2067 21:09:19.034614 [ lok_handler ] INF  Created new view with viewid: [0] for username: [admin] in session: [001b].| kit/ChildSession.cpp:339
kit-02001-2067 21:09:19.034662 [ lok_handler ] DBG  Sending status after loading view 0.| kit/ChildSession.cpp:352
kit-02001-2067 21:09:19.035071 [ lok_handler ] INF  Loaded session 001b| kit/ChildSession.cpp:370
kit-02001-2001 21:09:19.084185 [ loolkit ] DBG  child_ws_2001: recv [child-001b commandvalues command=.uno:StyleApply].| kit/Kit.cpp:1663
kit-02001-2001 21:09:19.089672 [ loolkit ] DBG  child_ws_2001: recv [child-001b commandvalues command=.uno:CharFontName].| kit/Kit.cpp:1663
t_ws_001b ] DBG  Session [001b] is the document owner| wsd/DocumentBroker.cpp:290
wsd-00033-0035 21:08:54.601377 [ client_ws_001b ] DBG  Setting username [admin] and userId [admin] for session [001b]| wsd/DocumentBroker.cpp:306
wsd-00033-0035 21:08:54.601392 [ client_ws_001b ] DBG  Wopi requesting: https://cloud2.domain.at/apps/richdocuments/wopi/files/110_ocadc83b19e7/contents?access_token=9dtnk6HqTf1cSGxgH4J6QJcNtc22Ys0V&access_token_ttl=0&permission=edit
wsd-00033-0035 21:08:54.684923 [ client_ws_001b ] INF  WOPI::GetFile downloaded 6549 bytes from [https://cloud2.domain.at/apps/richdocuments/wopi/files/110_ocadc83b19e7/contents?access_token=9dtnk6HqTf1cSGxgH4J6QJcNtc22Ys0V&access_token_ttl=0&permission=edit] -> /opt/lool/child-roots/2001/user/docs/2001/New Spreadsheet.ods in 0.0834662s : 200 OK| wsd/Storage.cpp:475
wsd-00033-0035 21:08:54.685330 [ client_ws_001b ] INF  TileCache ctor for uri [https://cloud2.domain.at/apps/richdocuments/wopi/files/110_ocadc83b19e7?access_token=9dtnk6HqTf1cSGxgH4J6QJcNtc22Ys0V&access_token_ttl=0&permission=edit] modifiedTime=1487020134 getLastModified()=0
wsd-00033-0035 21:08:54.686185 [ client_ws_001b ] DBG  Added admin document [/apps/richdocuments/wopi/files/110_ocadc83b19e7].| wsd/AdminModel.cpp:247
wsd-00033-0035 21:08:54.693812 [ client_ws_001b ] INF  PrisonerSession ctor [ToPrisoner-001b].| wsd/PrisonerSession.cpp:44
wsd-00033-0035 21:08:54.693979 [ client_ws_001b ] INF  SocketProcessor [client_ws_001b] starting.| common/IoUtil.cpp:49
wsd-00033-0037 21:08:54.921156 [ prsnr_req_hdl ] INF  Request from 127.0.0.1:54542: GET /loolws/newchild?pid=2066 HTTP/1.0 / Connection: Upgrade / Upgrade: websocket / Sec-WebSocket-Version: 13 / Sec-WebSocket-Key: NRSHSx4J03dO+YtWKqWVCw== / Host: 127.0.0.1:9981
wsd-00033-0037 21:08:54.921210 [ prsnr_req_hdl ] INF  New child [2066].| wsd/LOOLWSD.cpp:1312
wsd-00033-0037 21:08:54.921415 [ prsnr_req_hdl ] INF  ChildProcess ctor [2066].| wsd/DocumentBroker.hpp:51
wsd-00033-0037 21:08:54.921441 [ prsnr_req_hdl ] INF  Have 1 child.| wsd/LOOLWSD.cpp:401
wsd-00033-2074 21:08:54.921517 [ docbrk_ws_2066 ] INF  SocketProcessor [docbrk_ws_2066] starting.| common/IoUtil.cpp:49
wsd-00033-0035 21:09:18.760235 [ client_ws_001b ] INF  Requesting document load from child.
...
...
...