Che: Che is always asking if changes made should be overwritten ...

[sunix]

Describe the bug

Editing a file like devfile.yaml in this project: https://che.openshift.io/factory?url=https://github.com/sunix/record-preview-feature-java15

Che version

• [x] 7.11.0 on che.openshift.io

Steps to reproduce

1. Run this devfile:
2. Edit the devfile.yaml in the project
3. Constantly, Che is showing the popup which is making the development very hard
   

Workaround

Issue can be helped by either increasing the auto-save interval or disabling auto-save in Theia.

[sunix]

maybe it is because it is not ephemeral ....

[ibuziuk]

maybe it is because it is not ephemeral ....

does it happen only in the non-ephemeral mode?

[sunix]

just tested it doesn't happen

[ibuziuk]

just tested it doesn't happen

does not happen at all? could you please provide more details and steps to repro in the issue description?

[sunix]

trying to remove some workspaces ... maybe related to the storage and number of files in volumes ...

[sunix]

OK I have removed some workspaces and it seems to be better
It looks like

• you edit code, Che auto saves the file
• the file is getting saved ... but take a while
• Because of the delay, Che thinks the changes is not related to the previous change ... but it does

[sunix]

mh it's happening again .... even after removed all my workspaces ...

[ibuziuk]

@sunix is it Hosted Che specific, or happens the very same way in the upstream?

[sunix]

Hi @ibuziuk I have the feeling that it is happening only on my machine ... I am setting p2 unless someone else is raising the problem...

[digiltd]

I can confirm this happens with myself and colleagues. Seems ok for a bit then will start asking you to confirm overwriting the file. Sometimes closing the file tab and reopening the file fixes it temporarily.

[digiltd]

Developing Magento 2, so a massive codebase, typically ~50,000 files.

[sunix]

@ibuziuk I don't know how much people are affected. Could we monitor that. I think we should work on that and make that detection a bit more robust ... even on slow storage.

[amisevsk]

I'm encountering this pretty constantly when trying to work on the Che docs. I'm using Hosted Che with persistent storage, so I suspect it's a Gluster issue.

Edit to add: It's especially frustrating as the notification steals focus from the editor, so even after closing it you can't continue typing in the file.

[digiltd]

It's especially frustrating as the notification steals focus from the editor, so even after closing it you can't continue typing in the file.

i feel your pain

[sunix]

what i do is disabling auto-save ... or setting 20 seconds ....

[amisevsk]

@sunix good suggestion for the mean time -- I've added it to the issue description so that it's easier to find.

[sunix]

so async storage could be a quickfix to solve that one.

[amisevsk]

Having used async storage a fair bit now, it seems to be a good workaround.

[vzhukovs]

Could be related: https://github.com/eclipse/che/issues/17704

[sunix]

@amisevsk How do you enable async storage in che.openshift.io BTW?

[amisevsk]

@sunix See: https://github.com/eclipse/che/issues/17590

I typically add it manually by adding

attributes:
  asyncPersist: 'true'
  persistVolumes: 'false'

to my devfie.

[vzhukovs]

Will post result of investigation of this issue.

All the results are actual for the commit https://github.com/eclipse-theia/theia/commit/1e09b816511769eb206494c1bac1a595e95795f9, not for the Theia master head as Che-Theia hasn't been updated to use Theia's master head.

So, when user opens file in editor, Theia tries to get fs.Stat for the specific uri. Autosave mechanism automatically call method to save the state of currently changed file with passing current FileStat object by calling the following method calls: Resource.save > saveContents > doSaveContents > setContent.

setContent's method body.

Theia tries to obtain new fs.Stat object for the same FileStat by calling doCreateFileStat and tries to compare modification time and size with the last one, passed by the method chain call.

When there're many changes made in the same file for the short period of time we can observe such situation, provided by the following log:

_log for the fs.Stat object passed from the editor:_

2020-09-15 13:26:35.539 root INFO doCreateFileStat: uri = file:///projects/record-preview-feature-java15/devfile.yaml, stat = {
    "dev": 1048600,
    "mode": 33188,
    "nlink": 1,
    "uid": 1202920000,
    "gid": 0,
    "rdev": 0,
    "blksize": 131072,
    "ino": 13763576696610406000,
    "size": 1840,
    "blocks": 4,
    "atimeMs": 1600176395528.138,
    "mtimeMs": 1600176395535.138,
    "ctimeMs": 1600176395536.1377,
    "birthtimeMs": 1600176395536.1377,
    "atime": "2020-09-15T13:26:35.528Z",
    "mtime": "2020-09-15T13:26:35.535Z",
    "ctime": "2020-09-15T13:26:35.536Z",
    "birthtime": "2020-09-15T13:26:35.536Z"
}

_log for the new fs.Stat object to be compared:_

2020-09-15 13:26:37.036 root INFO doCreateFileStat: uri = file:///projects/record-preview-feature-java15/devfile.yaml, stat = {
    "dev": 1048600,
    "mode": 33188,
    "nlink": 1,
    "uid": 1202920000,
    "gid": 0,
    "rdev": 0,
    "blksize": 131072,
    "ino": 13763576696610406000,
    "size": 1840,
    "blocks": 4,
    "atimeMs": 1600176379374.7065,
    "mtimeMs": 1600176395535.6855,
    "ctimeMs": 1600176395536.6855,
    "birthtimeMs": 1600176395536.6855,
    "atime": "2020-09-15T13:26:19.375Z",
    "mtime": "2020-09-15T13:26:35.536Z",
    "ctime": "2020-09-15T13:26:35.537Z",
    "birthtime": "2020-09-15T13:26:35.537Z"
}

as you can see, atimeMs, mtimeMs, ctimeMs represents time in milliseconds with _nanoseconds_.

Theia transforms this fs.Stat into FileStat and takes modification time by calling stat.mtime.getTime() which has time in milliseconds rounded by nanoseconds value.

You can observe it in above logs:

"mtime": "2020-09-15T13:26:35.535Z" >> 1600176395535ms

against

"mtime": "2020-09-15T13:26:35.536Z" >> 1600176395536ms

As the result comparison these two values give us two different values for the modification time in checkInSync method. Thats why method isInSync calls client dialogue to overwrite changes.

We can refer to slow i/o of glusterfs when there're a lot modifications come from outside to update the one file and sometimes we have inconsistent modification time for the file that differs in 1 millisecond.

As the possible solutions there're two variants how we can resolve this issue:

1. Fast and requires changes only in Che-Theia:

   To rebind FileShouldOverwrite class to take into account that there is a such bias in modification time. By adding check if difference between two modification time is not bigger than 1 milliseconds. Which is already tested. With this fix issue is not reproduced anymore.

2. Slow and requires changes in Theia upstream:

   To replace lastModification: stat.mtime.getTime() with integer value of milliseconds, not taking into account value of nanoseconds. But from the other hand there're new FS Api has been merged recently and need to check how it reproduces on Theia's master head. Which is difficult to do at this moment. Which also requires additional testing.

[amisevsk]

That's a great explanation @vzhukovskii, thanks.

[azatsarynnyy]

Thank you @vzhukovskii for an excellent analysis!
If this can be reproduced in vanilla Theia then let's try to contribute it upstream first.

[vzhukovs]

Thank you @vzhukovskii for an excellent analysis!
If this can be reproduced in vanilla Theia then let's try to contribute it upstream first.

Got it

[azatsarynnyy]

update:
We've decided to start with a quick fix in Che Theia https://github.com/eclipse/che-theia/pull/862
And propose a related patch in upstream Theia.