WOPI with Collabora does not save a file on tab close

[wkloucek]

Describe the bug

If you open a file in Collabora, do some changes and just close the tab without saving first, your changes will be lost.

Steps to reproduce

Steps to reproduce the behavior:

1. Open file in Collabora
2. do some changes
3. close tab

Expected behavior

Changes are persisted

Actual behavior

Changes are lost

Setup

oCIS with WOPI deployment example

Additional context

Collabora seems to first unlock a file before saving it when the user closes the session. The WOPI server only uploads the file if it is still locked.
-> We need to debug the behavior. Collabora should NOT unlock before saving the file. But the WOPI server also should allow to save to a unlocked file?

WOPI server logs:

ocis_wopi-wopiserver-1  | {"time": "2022-09-13T07:57:32.152", "host": "73f72c251862", "level": "DEBUG", "process": "wopiserver", "module": "wopiutils", "msg": "Unlock: client context", "user": "hiYmHC1Dsgst4EUBZ68w", "filename": "9d4c96e7-635e-4b3b-a46f-17347cda293c/file-sample_1MB.odt", "token": "XCs6QprtjqBqZYakP0rA", "deviceId": "None", "reqId": "None", "sessionId": "None", "app": "None", "appEndpoint": "None", "correlationId": "None", "wopits": "63798652652.13403"}
ocis_wopi-wopiserver-1  | DEBUG:wopiserver:"module": "wopiutils", "msg": "Unlock: client context", "user": "hiYmHC1Dsgst4EUBZ68w", "filename": "9d4c96e7-635e-4b3b-a46f-17347cda293c/file-sample_1MB.odt", "token": "XCs6QprtjqBqZYakP0rA", "deviceId": "None", "reqId": "None", "sessionId": "None", "app": "None", "appEndpoint": "None", "correlationId": "None", "wopits": "63798652652.13403"
ocis_wopi-wopiserver-1  | DEBUG:wopiserver:"module": "cs3iface", "payload": ""msg=\"Invoked getlock\" filepath=\"9d4c96e7-635e-4b3b-a46f-17347cda293c/file-sample_1MB.odt\" result=\"lock_id: \"opaquelocktoken:797356a8-0500-4ceb-a8a0-c94c8cde7eba Y29vbC1sb2NrNTc0Mjk5ODc=\"\ntype: LOCK_TYPE_WRITE\napp_name: \"Collabora\"\nexpiration {\n  seconds: 1663059383\n}\n\"""
ocis_wopi-wopiserver-1  | {"time": "2022-09-13T07:57:32.162", "host": "73f72c251862", "level": "DEBUG", "process": "wopiserver", "module": "cs3iface", "payload": ""msg=\"Invoked getlock\" filepath=\"9d4c96e7-635e-4b3b-a46f-17347cda293c/file-sample_1MB.odt\" result=\"lock_id: \"opaquelocktoken:797356a8-0500-4ceb-a8a0-c94c8cde7eba Y29vbC1sb2NrNTc0Mjk5ODc=\"\ntype: LOCK_TYPE_WRITE\napp_name: \"Collabora\"\nexpiration {\n  seconds: 1663059383\n}\n\"""}
ocis_wopi-wopiserver-1  | INFO:wopiserver:"module": "wopiutils", "msg": "Retrieved lock", "lockop": "Unlock", "user": "hiYmHC1Dsgst4EUBZ68w", "filename": "9d4c96e7-635e-4b3b-a46f-17347cda293c/file-sample_1MB.odt", "fileid": "1284d238-aa92-42ce-bdc4-0b0000009157-MzcyNTZkYjMtNDdiZC00OTA1LWFmNjItYzM1Y2FiMzU5OGE2", "lock": "cool-lock57429987", "retrievedlock": "cool-lock57429987", "expTime": "2022-09-13T08:56:23", "token": "XCs6QprtjqBqZYakP0rA"
ocis_wopi-wopiserver-1  | {"time": "2022-09-13T07:57:32.163", "host": "73f72c251862", "level": "INFO", "process": "wopiserver", "module": "wopiutils", "msg": "Retrieved lock", "lockop": "Unlock", "user": "hiYmHC1Dsgst4EUBZ68w", "filename": "9d4c96e7-635e-4b3b-a46f-17347cda293c/file-sample_1MB.odt", "fileid": "1284d238-aa92-42ce-bdc4-0b0000009157-MzcyNTZkYjMtNDdiZC00OTA1LWFmNjItYzM1Y2FiMzU5OGE2", "lock": "cool-lock57429987", "retrievedlock": "cool-lock57429987", "expTime": "2022-09-13T08:56:23", "token": "XCs6QprtjqBqZYakP0rA"}
ocis_wopi-wopiserver-1  | DEBUG:wopiserver:"module": "wopiutils", "msg": "compareLocks", "lock1": "cool-lock57429987", "lock2": "cool-lock57429987", "result": "True"
ocis_wopi-wopiserver-1  | {"time": "2022-09-13T07:57:32.163", "host": "73f72c251862", "level": "DEBUG", "process": "wopiserver", "module": "wopiutils", "msg": "compareLocks", "lock1": "cool-lock57429987", "lock2": "cool-lock57429987", "result": "True"}
ocis_wopi-wopiserver-1  | INFO:wopiserver:"module": "cs3iface", "msg": "Invoked stat", "fileref": "9d4c96e7-635e-4b3b-a46f-17347cda293c/file-sample_1MB.odt", "trace": "00000000000000000000000000000000", "inode": "1284d238-aa92-42ce-bdc4-0b0000009157-MzcyNTZkYjMtNDdiZC00OTA1LWFmNjItYzM1Y2FiMzU5OGE2", "filepath": "9d4c96e7-635e-4b3b-a46f-17347cda293c/file-sample_1MB.odt", "elapsedTimems": "7.6"
ocis_wopi-wopiserver-1  | {"time": "2022-09-13T07:57:32.171", "host": "73f72c251862", "level": "INFO", "process": "wopiserver", "module": "cs3iface", "msg": "Invoked stat", "fileref": "9d4c96e7-635e-4b3b-a46f-17347cda293c/file-sample_1MB.odt", "trace": "00000000000000000000000000000000", "inode": "1284d238-aa92-42ce-bdc4-0b0000009157-MzcyNTZkYjMtNDdiZC00OTA1LWFmNjItYzM1Y2FiMzU5OGE2", "filepath": "9d4c96e7-635e-4b3b-a46f-17347cda293c/file-sample_1MB.odt", "elapsedTimems": "7.6"}
ocis_wopi-wopiserver-1  | DEBUG:wopiserver:"module": "cs3iface", "msg": "Invoked unlock", "filepath": "9d4c96e7-635e-4b3b-a46f-17347cda293c/file-sample_1MB.odt", "value": "opaquelocktoken:797356a8-0500-4ceb-a8a0-c94c8cde7eba Y29vbC1sb2NrNTc0Mjk5ODc=", "result": "code: CODE_OK\ntrace: \"00000000000000000000000000000000\"\n"
ocis_wopi-wopiserver-1  | {"time": "2022-09-13T07:57:32.178", "host": "73f72c251862", "level": "DEBUG", "process": "wopiserver", "module": "cs3iface", "msg": "Invoked unlock", "filepath": "9d4c96e7-635e-4b3b-a46f-17347cda293c/file-sample_1MB.odt", "value": "opaquelocktoken:797356a8-0500-4ceb-a8a0-c94c8cde7eba Y29vbC1sb2NrNTc0Mjk5ODc=", "result": "code: CODE_OK\ntrace: \"00000000000000000000000000000000\"\n"}
ocis_wopi-wopiserver-1  | DEBUG:wopiserver:"module": "wopiutils", "msg": "Putfile: client context", "user": "hiYmHC1Dsgst4EUBZ68w", "filename": "9d4c96e7-635e-4b3b-a46f-17347cda293c/file-sample_1MB.odt", "token": "XCs6QprtjqBqZYakP0rA", "deviceId": "None", "reqId": "None", "sessionId": "None", "app": "None", "appEndpoint": "None", "correlationId": "None", "wopits": "63798652652.12956"
ocis_wopi-wopiserver-1  | {"time": "2022-09-13T07:57:32.201", "host": "73f72c251862", "level": "DEBUG", "process": "wopiserver", "module": "wopiutils", "msg": "Putfile: client context", "user": "hiYmHC1Dsgst4EUBZ68w", "filename": "9d4c96e7-635e-4b3b-a46f-17347cda293c/file-sample_1MB.odt", "token": "XCs6QprtjqBqZYakP0rA", "deviceId": "None", "reqId": "None", "sessionId": "None", "app": "None", "appEndpoint": "None", "correlationId": "None", "wopits": "63798652652.12956"}
ocis_wopi-wopiserver-1  | DEBUG:wopiserver:"module": "cs3iface", "msg": "Invoked getlock on unlocked or missing file", "filepath": "9d4c96e7-635e-4b3b-a46f-17347cda293c/file-sample_1MB.odt"
ocis_wopi-wopiserver-1  | {"time": "2022-09-13T07:57:32.206", "host": "73f72c251862", "level": "DEBUG", "process": "wopiserver", "module": "cs3iface", "msg": "Invoked getlock on unlocked or missing file", "filepath": "9d4c96e7-635e-4b3b-a46f-17347cda293c/file-sample_1MB.odt"}
ocis_wopi-wopiserver-1  | INFO:wopiserver:"module": "wopiutils", "msg": "No lock found", "lockop": "Putfile", "user": "hiYmHC1Dsgst4EUBZ68w", "filename": "9d4c96e7-635e-4b3b-a46f-17347cda293c/file-sample_1MB.odt", "token": "XCs6QprtjqBqZYakP0rA"
ocis_wopi-wopiserver-1  | {"time": "2022-09-13T07:57:32.206", "host": "73f72c251862", "level": "INFO", "process": "wopiserver", "module": "wopiutils", "msg": "No lock found", "lockop": "Putfile", "user": "hiYmHC1Dsgst4EUBZ68w", "filename": "9d4c96e7-635e-4b3b-a46f-17347cda293c/file-sample_1MB.odt", "token": "XCs6QprtjqBqZYakP0rA"}
ocis_wopi-wopiserver-1  | {"time": "2022-09-13T07:57:32.207", "host": "73f72c251862", "level": "WARNING", "process": "wopiserver", "module": "wopiutils", "msg": "Returning conflict", "lockop": "Putfile", "user": "eyJ", "filename": "9d4c96e7-635e-4b3b-a46f-17347cda293c/file-sample_1MB.odt", "token": "XCs6QprtjqBqZYakP0rA", "lock": "cool-lock57429987", "oldlock": "NA", "retrievedlock": "None", "reason": "Cannot overwrite unlocked file"}
ocis_wopi-wopiserver-1  | WARNING:wopiserver:"module": "wopiutils", "msg": "Returning conflict", "lockop": "Putfile", "user": "eyJ", "filename": "9d4c96e7-635e-4b3b-a46f-17347cda293c/file-sample_1MB.odt", "token": "XCs6QprtjqBqZYakP0rA", "lock": "cool-lock57429987", "oldlock": "NA", "retrievedlock": "None", "reason": "Cannot overwrite unlocked file"

[C0rby]

From what I could observe, Collabora does automatically save the document after some time after editing (30 Seconds or so?). If the tab gets closed before that it won't be saved.
OnlyOffice seems to save a few seconds after the last keystroke. Maybe there is a setting or something to have something similar in Collabora?

[wkloucek]

The Cannot overwrite unlocked file part is highly suspicious (see above logs). I think Collabora saves on close.

[C0rby]

Ah, I see! Now whose behavior needs to change? Collabora or Wopi?

[wkloucek]

Probably WOPI server, I don't see a reason why we shouln't save on a unlocked file. But still it's weird that Collabora seems to perform an unlock before saving the file.

[micbar]

I have a local debug setup. Happy to share!

[micbar]

I can confirm that the file gets unlocked before saving the file.

Onlyoffice does that differently.

[micbar]

How could this ever work?

[micbar]

@pmaier1 Who can help us talk with the collabora people?

IMO this is ugly. Nothing meaningful we could do IMO.

We could allow to write to an unlocked file, but .... well that opens soo many ugly possibilities.

[pmaier1]

@pmaier1 Who can help us talk with the collabora people?

I can do that. Maybe it works directly here. Otherwise I'll start an email thread.

Who can help us with this? @timar @kendy @merttumer @Ashod

[micbar]

@pmaier1 Seems that we need the email thread.

Can I remove it from the GA Blocker list?

[pmaier1]

@pmaier1 Seems that we need the email thread.

Ok.

Can I remove it from the GA Blocker list?

Agreed.

[micbar]

@pmaier1 @timar pinging

[micbar]

Fixed with collabora/code:22.05.8.4.1

Tested on ocis.team.owncloud.works

[Ashod]

Thanks for confirming the fix, @micbar.