Collabora - Can't open documents

Hello
I have been trying to get the Collabora docker to work for a few days, but without success. I appreciate any help. Please let me know if there is a need for more info.

I can connect to the server just fine when I try to activate it in Nextcloud. I get a nice green checkmark, but when I try to open a file, I get

“Failed to load Collabora developer edition, please try again later” in the GUI. The error message from Nextcloud’s log is found below

I can also connect to the admin interface for Collabora, but navigating to anything beside the first admin page errors out.

My environment

I have more services running at home, everything behind a reverse proxy. The proxy handles SSL termination for some services, and some services connects to the backend over SSL as well. Working flawless for most things. The backend for the services is a mix of FreeNAS jails on the same box, and a Ubuntu box

Reverse Proxy

FreeNas 11.3
Apache 2.41
mod_md for ssl

Nextcloud
Served from cloud.domain.tld.
The software stack is
FreeNAS 11.3
Apache 2.41, and mod_md taking care of SSL
Mariadb 103
PHP 7.2
Nextcloud 18.04
Collabora app 3.6.0

Collabora
Collabora is behind the Proxy as well, served from office.domain.tld, Collabora is served on port 443, one among several vhosts.

Ubuntu 18.04
Apache2 reverse proxy
Collabora Docker image - latest as of 2020-05-13
I followed the instructions here: https://nextcloud.com/collaboraonline/.

Error logs and messages
Log from Nextcloud when opening a document

[richdocuments] Error: Doctrine\DBAL\Exception\InvalidFieldNameException: An exception occurred while executing 'INSERT INTO `oc_richdocuments_wopi`(`fileid`,`owner_uid`,`editor_uid`,`version`,`canwrite`,`server_host`,`token`,`expiry`,`template_destination`,`hide_download`,`direct`,`is_remote_token`,`template_id`) VALUES(?,?,?,?,?,?,?,?,?,?,?,?,?)' with params [1214349, "Kim", "Kim", 0, true, "https:\/\/cloud.REDACTED\/", "bTlpfxtwudGbVHkPARTLY REDACTED", 1589395547, 0, false, false, false, 0]:

SQLSTATE[42S22]: Column not found: 1054 Unknown column 'template_destination' in 'field list' at <<closure>>

 0. /usr/local/www/nextcloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/DBALException.php line 169
    Doctrine\DBAL\Driver\AbstractMySQLDriver->convertException("An exception oc ... '", Doctrine\DBAL\Dr ... ]})
 1. /usr/local/www/nextcloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/DBALException.php line 145
    Doctrine\DBAL\DBALException::wrapException(Doctrine\DBAL\Driver\PDOMySql\Driver {}, Doctrine\DBAL\Dr ... ]}, "An exception oc ... '")
 2. /usr/local/www/nextcloud/3rdparty/doctrine/dbal/lib/Doctrine/DBAL/Statement.php line 162
    Doctrine\DBAL\DBALException::driverExceptionDuringQuery(Doctrine\DBAL\Driver\PDOMySql\Driver {}, Doctrine\DBAL\Dr ... ]}, "INSERT INTO `oc ... )", {1: 1214349,2: " ... 0})
 3. /usr/local/www/nextcloud/lib/public/AppFramework/Db/Mapper.php line 255
    Doctrine\DBAL\Statement->execute()
 4. /usr/local/www/nextcloud/lib/public/AppFramework/Db/Mapper.php line 129
    OCP\AppFramework\Db\Mapper->execute("INSERT INTO `*P ... )", [1214349,"Kim"," ... 0])
 5. /usr/local/www/nextcloud/apps/richdocuments/lib/Db/WopiMapper.php line 89
    OCP\AppFramework\Db\Mapper->insert(OCA\Richdocuments\Db\Wopi {id: null})
 6. /usr/local/www/nextcloud/apps/richdocuments/lib/TokenManager.php line 205
    OCA\Richdocuments\Db\WopiMapper->generateFileToken("*** sensitive parameter replaced ***", "Kim", "Kim", "0", 1, "https://cloud.REDACTED/", null, 0, false, false, false, 0, null)
 7. /usr/local/www/nextcloud/apps/richdocuments/lib/Controller/DocumentController.php line 238
    OCA\Richdocuments\TokenManager->getToken("*** sensitive parameters replaced ***")
 8. /usr/local/www/nextcloud/lib/private/AppFramework/Http/Dispatcher.php line 170
    OCA\Richdocuments\Controller\DocumentController->index("*** sensitive parameter replaced ***")
 9. /usr/local/www/nextcloud/lib/private/AppFramework/Http/Dispatcher.php line 99
    OC\AppFramework\Http\Dispatcher->executeController(OCA\Richdocument ... {}, "index")
10. /usr/local/www/nextcloud/lib/private/AppFramework/App.php line 125
    OC\AppFramework\Http\Dispatcher->dispatch(OCA\Richdocument ... {}, "index")
11. /usr/local/www/nextcloud/lib/private/AppFramework/Routing/RouteActionHandler.php line 47
    OC\AppFramework\App::main("OCA\\Richdocume ... r", "index", OC\AppFramework\ ... {}, {_route: "richdocuments.document.index"})
12. <<closure>>
    OC\AppFramework\Routing\RouteActionHandler->__invoke({_route: "richdocuments.document.index"})
13. /usr/local/www/nextcloud/lib/private/Route/Router.php line 299
    call_user_func(OC\AppFramework\ ... {}, {_route: "richdocuments.document.index"})
14. /usr/local/www/nextcloud/lib/base.php line 1008
    OC\Route\Router->match("/apps/richdocuments/index")
15. /usr/local/www/nextcloud/index.php line 38
    OC::handleRequest()

GET /index.php/apps/richdocuments/index?fileId=1214349&requesttoken=PARTLY_REDACTED
from 192.168.1.1 by Kim at 2020-05-13T20:15:47+02:00

The docker container’s log is completely filled with

wsd-00007-00036 2020-05-13 18:15:33.631716 [ websrv_poll ] WRN  Poco::Net::DNS::resolve("192.168.1.5") failed: Host not found: 192.168.1.5| wsd/LOOLWSD.cpp:2187

192.168.1.5 is the IP of the reverse proxy. I suspect that is the clue to what is wrong, but I lack the skill to say what might be wrong.

I can probably find more info in the docker log, but I do not know how to set the log level to debug in the image. I am a complete docker noob as is evident

Reverse proxy log
Log from the fron reverse proxy, the one running in a FreeNas jail. Log sampled from when I try to open a document

[Thu May 14 07:15:01.887690 2020] [socache_shmcb:debug] [pid 85236:tid 34531953152] mod_socache_shmcb.c(493): AH00831: socache_shmcb_store (0xd4 -> subcache 20)
[Thu May 14 07:15:01.887905 2020] [socache_shmcb:debug] [pid 85236:tid 34531953152] mod_socache_shmcb.c(847): AH00847: insert happened at idx=1, data=(202:234)
[Thu May 14 07:15:01.887935 2020] [socache_shmcb:debug] [pid 85236:tid 34531953152] mod_socache_shmcb.c(850): AH00848: finished insert, subcache: idx_pos/idx_used=0/2, data_pos/data_used=0/405
[Thu May 14 07:15:01.887962 2020] [socache_shmcb:debug] [pid 85236:tid 34531953152] mod_socache_shmcb.c(515): AH00834: leaving socache_shmcb_store successfully
[Thu May 14 07:15:01.888760 2020] [ssl:debug] [pid 85236:tid 34531953152] ssl_engine_kernel.c(376): [client 192.168.1.1:34311] AH02034: Initial (No.1) HTTPS request received for child 18 (server office.REDACTED:443)
[Thu May 14 07:15:01.888858 2020] [authz_core:debug] [pid 85236:tid 34531953152] mod_authz_core.c(843): [client 192.168.1.1:34311] AH01628: authorization result: granted (no directives)
[Thu May 14 07:15:01.888947 2020] [proxy:debug] [pid 85236:tid 34531953152] mod_proxy.c(1253): [client 192.168.1.1:34311] AH01143: Running scheme https handler (attempt 0)
[Thu May 14 07:15:01.888980 2020] [proxy:debug] [pid 85236:tid 34531953152] proxy_util.c(2336): AH00942: HTTPS: has acquired connection for (192.168.1.79)
[Thu May 14 07:15:01.889011 2020] [proxy:debug] [pid 85236:tid 34531953152] proxy_util.c(2392): [client 192.168.1.1:34311] AH00944: connecting https://192.168.1.79/hosting/capabilities to 192.168.1.79:443
[Thu May 14 07:15:01.889062 2020] [proxy:debug] [pid 85236:tid 34531953152] proxy_util.c(2615): [client 192.168.1.1:34311] AH00947: connected /hosting/capabilities to 192.168.1.79:443
[Thu May 14 07:15:01.889259 2020] [proxy:debug] [pid 85236:tid 34531953152] proxy_util.c(2916): AH00951: HTTPS: backend socket is disconnected.
[Thu May 14 07:15:01.889606 2020] [proxy:debug] [pid 85236:tid 34531953152] proxy_util.c(3081): AH02824: HTTPS: connection established with 192.168.1.79:443 (192.168.1.79)
[Thu May 14 07:15:01.889695 2020] [proxy:debug] [pid 85236:tid 34531953152] proxy_util.c(3267): AH00962: HTTPS: connection complete to 192.168.1.79:443 (192.168.1.79)
[Thu May 14 07:15:01.889727 2020] [ssl:info] [pid 85236:tid 34531953152] [remote 192.168.1.79:443] AH01964: Connection to child 0 established (server office.REDACTED:443)
[Thu May 14 07:15:01.904907 2020] [ssl:debug] [pid 85236:tid 34531953152] ssl_engine_kernel.c(1741): [remote 192.168.1.79:443] AH02275: Certificate Verification, depth 1, CRL checking mode: none (0) [subject: CN=Let's Encrypt Authority X3,O=Let's Encrypt,C=US / issuer: CN=DST Root CA X3,O=Digital Signature Trust Co. / serial: 0A0141420000015385736A0B85ECA708 / notbefore: Mar 17 16:40:46 2016 GMT / notafter: Mar 17 16:40:46 2021 GMT]
[Thu May 14 07:15:01.905351 2020] [ssl:debug] [pid 85236:tid 34531953152] ssl_engine_kernel.c(1741): [remote 192.168.1.79:443] AH02275: Certificate Verification, depth 0, CRL checking mode: none (0) [subject: CN=office.REDACTED / issuer: CN=Let's Encrypt Authority X3,O=Let's Encrypt,C=US / serial: 041DE6D3DF7D13220845409409E5323F9650 / notbefore: May  4 14:24:19 2020 GMT / notafter: Aug  2 14:24:19 2020 GMT]
[Thu May 14 07:15:01.907388 2020] [ssl:debug] [pid 85236:tid 34531953152] ssl_engine_kernel.c(2231): [remote 192.168.1.79:443] AH02041: Protocol: TLSv1.2, Cipher: ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)
[Thu May 14 07:15:01.907550 2020] [ssl:debug] [pid 85236:tid 34531953152] ssl_util_ssl.c(444): AH02412: [office.REDACTED:443] Cert matches for name 'office.REDACTED' [subject: CN=office.REDACTED / issuer: CN=Let's Encrypt Authority X3,O=Let's Encrypt,C=US / serial: 041DE6D3DF7D13220845409409E5323F9650 / notbefore: May  4 14:24:19 2020 GMT / notafter: Aug  2 14:24:19 2020 GMT]
[Thu May 14 07:15:01.912099 2020] [proxy:debug] [pid 85236:tid 34531953152] proxy_util.c(2351): AH00943: https: has released connection for (192.168.1.79)
[Thu May 14 07:15:01.918132 2020] [ssl:debug] [pid 85236:tid 34531953152] ssl_engine_io.c(1102): [client 192.168.1.1:34311] AH02001: Connection closed to child 18 with standard shutdown (server office.REDACTED:443)

Log from reverse proxy on the machine with collabora


[Thu May 14 06:15:38.796862 2020] [ssl:debug] [pid 5846:tid 140655883974400] ssl_engine_kernel.c(383): [client 192.168.1.5:20591] AH02034: Initial (No.1) HTTPS request received for child 13 (server office.REDACTED:443)
[Thu May 14 06:15:38.796886 2020] [authz_core:debug] [pid 5846:tid 140655883974400] mod_authz_core.c(835): [client 192.168.1.5:20591] AH01628: authorization result: granted (no directives)
[Thu May 14 06:15:38.796906 2020] [proxy:debug] [pid 5846:tid 140655883974400] mod_proxy.c(1229): [client 192.168.1.5:20591] AH01143: Running scheme https handler (attempt 0)
[Thu May 14 06:15:38.796911 2020] [proxy_ajp:debug] [pid 5846:tid 140655883974400] mod_proxy_ajp.c(738): [client 192.168.1.5:20591] AH00894: declining URL https://127.0.0.1:9980/hosting/capabilities
[Thu May 14 06:15:38.796916 2020] [proxy:debug] [pid 5846:tid 140655883974400] proxy_util.c(2177): AH00942: HTTPS: has acquired connection for (127.0.0.1)
[Thu May 14 06:15:38.796921 2020] [proxy:debug] [pid 5846:tid 140655883974400] proxy_util.c(2230): [client 192.168.1.5:20591] AH00944: connecting https://127.0.0.1:9980/hosting/capabilities to 127.0.0.1:9980
[Thu May 14 06:15:38.796926 2020] [proxy:debug] [pid 5846:tid 140655883974400] proxy_util.c(2439): [client 192.168.1.5:20591] AH00947: connected /hosting/capabilities to 127.0.0.1:9980
[Thu May 14 06:15:38.796955 2020] [socache_shmcb:debug] [pid 5846:tid 140655883974400] mod_socache_shmcb.c(557): AH00837: socache_shmcb_remove (0x59 -> subcache 25)
[Thu May 14 06:15:38.796960 2020] [socache_shmcb:debug] [pid 5846:tid 140655883974400] mod_socache_shmcb.c(571): AH00839: leaving socache_shmcb_remove successfully
[Thu May 14 06:15:38.797031 2020] [proxy:debug] [pid 5846:tid 140655883974400] proxy_util.c(2740): AH00951: HTTPS: backend socket is disconnected.
[Thu May 14 06:15:38.797078 2020] [proxy:debug] [pid 5846:tid 140655883974400] proxy_util.c(2908): AH02824: HTTPS: connection established with 127.0.0.1:9980 (127.0.0.1)
[Thu May 14 06:15:38.797086 2020] [proxy:debug] [pid 5846:tid 140655883974400] proxy_util.c(3075): AH00962: HTTPS: connection complete to 127.0.0.1:9980 (127.0.0.1)
[Thu May 14 06:15:38.797092 2020] [ssl:info] [pid 5846:tid 140655883974400] [remote 127.0.0.1:9980] AH01964: Connection to child 0 established (server office.REDACTED:443)
[Thu May 14 06:15:38.798644 2020] [ssl:debug] [pid 5846:tid 140655883974400] ssl_engine_kernel.c(1751): [remote 127.0.0.1:9980] AH02275: Certificate Verification, depth 1, CRL checking mode: none (0) [subject: CN=Dummy Authority,O=Dummy Authority,L=Stuttgart,ST=BW,C=DE / issuer: CN=Dummy Authority,O=Dummy Authority,L=Stuttgart,ST=BW,C=DE / serial: 2E80C549FDB9C4585F944E87CAF3ACA988A1C1FE / notbefore: May 13 18:14:10 2020 GMT / notafter: May 13 18:14:10 2045 GMT]
[Thu May 14 06:15:38.798670 2020] [ssl:debug] [pid 5846:tid 140655883974400] ssl_engine_kernel.c(1751): [remote 127.0.0.1:9980] AH02275: Certificate Verification, depth 1, CRL checking mode: none (0) [subject: CN=Dummy Authority,O=Dummy Authority,L=Stuttgart,ST=BW,C=DE / issuer: CN=Dummy Authority,O=Dummy Authority,L=Stuttgart,ST=BW,C=DE / serial: 2E80C549FDB9C4585F944E87CAF3ACA988A1C1FE / notbefore: May 13 18:14:10 2020 GMT / notafter: May 13 18:14:10 2045 GMT]
[Thu May 14 06:15:38.798739 2020] [ssl:debug] [pid 5846:tid 140655883974400] ssl_engine_kernel.c(1751): [remote 127.0.0.1:9980] AH02275: Certificate Verification, depth 0, CRL checking mode: none (0) [subject: CN=office\\\\.REDACTED\\\\.se,O=Dummy Authority,L=Stuttgart,ST=BW,C=DE / issuer: CN=Dummy Authority,O=Dummy Authority,L=Stuttgart,ST=BW,C=DE / serial: 0C0D79DAAA03828B1CEB1D867F55014FA3E07C03 / notbefore: May 13 18:14:10 2020 GMT / notafter: May 13 18:14:10 2045 GMT]
[Thu May 14 06:15:38.798894 2020] [ssl:debug] [pid 5846:tid 140655883974400] ssl_engine_kernel.c(2233): [remote 127.0.0.1:9980] AH02041: Protocol: TLSv1.3, Cipher: TLS_AES_256_GCM_SHA384 (256/256 bits)
[Thu May 14 06:15:38.799013 2020] [ssl:debug] [pid 5846:tid 140655883974400] ssl_engine_kernel.c(2233): [remote 127.0.0.1:9980] AH02041: Protocol: TLSv1.3, Cipher: TLS_AES_256_GCM_SHA384 (256/256 bits)
[Thu May 14 06:15:38.799050 2020] [ssl:debug] [pid 5846:tid 140655883974400] ssl_engine_kernel.c(2233): [remote 127.0.0.1:9980] AH02041: Protocol: TLSv1.3, Cipher: TLS_AES_256_GCM_SHA384 (256/256 bits)
[Thu May 14 06:15:38.800898 2020] [proxy:debug] [pid 5846:tid 140655883974400] proxy_util.c(2192): AH00943: https: has released connection for (127.0.0.1)
[Thu May 14 06:15:43.801113 2020] [ssl:debug] [pid 5846:tid 140655800047360] ssl_engine_io.c(1106): [client 192.168.1.5:20591] AH02001: Connection closed to child 23 with standard shutdown (server office.REDACTED:443)

I am going to bump this, and add the solution to some of the issues with my installation.

TL:DR, beware if you have an old installation that you played around with!

The database error in my first post is solved. The issue seems to be due to a failed update /bug in the Collabora app. The bug is triggered when an old version of the app was installed at some point (I installed it years ago, and never used), and a sudden update post version 3.5.3 is made. Some database changes are not migrated over and the mentioned error happens
Solution is posted here, and it solved the issue for me.

Another thing that seemed to be needed was to start the docker image with a modification to the command on the official site.

docker run -t -d -p 127.0.0.1:9980:9980 -e "domain=cloud\\.domain\\.tld" -e "username=admin" -e "password=a_good_password" -e "server_name=office\.domain\.tld:443" -e "extra_params=--o:logging.level=debug" --restart always collabora/code

The user/pass directive can be skipped. the extra param is to enable debug logging in the image and shall be skipped for production. The server_name parameter is needed for hosts running behind a reverse proxy. Note the single escape slashes

This and combined with enabling the web socket proxy module in the first (internet facing) proxy has solved the issue. Collabora is now running.