Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Enso stopped working properly when creating node during Libs compilation #6841

Closed
2 tasks
xvcgreg opened this issue May 25, 2023 · 29 comments · Fixed by #6998
Closed
2 tasks

Enso stopped working properly when creating node during Libs compilation #6841

xvcgreg opened this issue May 25, 2023 · 29 comments · Fixed by #6998
Assignees

Comments

@xvcgreg
Copy link

xvcgreg commented May 25, 2023

Discord username

No response

What type of issue is this?

Intermittent – Occurring irregularly

Is this issue blocking you from using Enso?

  • Yes, I can't use Enso because of this issue.

Is this a regression?

  • Yes, previous version of Enso did not have this issue.

What issue are you facing?

When I create node too fast (before Libs are compiled) IDE looses connection to the Engine.

2305242131_shareX.mp4

Expected behaviour

User shouldn't be allowed to create a node before Libs are compiled.

How we can reproduce it?

No response

Screenshots or screencasts

No response

Logs

2305242131_shareX 20230524-192640-619-enso-project-manager.log

Enso Version

2023.5.24 nightly

Browser or standalone distribution

Standalone distribution (local project)

Browser Version or standalone distribution

standalone

Operating System

Windows

Operating System Version

Win11pro 22H2 22621.1555

Hardware you are using

12th Gen Intel(R) Core(TM) i9-12900HK / RTX3060 Laptop / Nvidia Drivers 531.68

@xvcgreg xvcgreg added --bug Type: bug triage labels May 25, 2023
@xvcgreg xvcgreg changed the title Enso lost connection to the engine when creating node during Libs compilation Enso stopped working propperly when creating node during Libs compilation May 25, 2023
@farmaazon
Copy link
Contributor

Reproduced the issue. Two weird things were spotted:

File version mismatch, or "oh no, we are desynchronized again, aren't we"?

The file is opened properly, and the first file update (with id_map) is successful:

{
  "jsonrpc": "2.0",
  "id": 6,
  "method": "text/applyEdit",
  "params": {
    "edit": {
      "edits": [
        {
          "range": {
            "end": {
              "character": 0,
              "line": 7
            },
            "start": {
              "character": 0,
              "line": 0
            }
          },
          "text": "from Standard.Base import all\nfrom Standard.Table import all\nfrom Standard.Database import all\nfrom Standard.AWS import all\n\nmain =\n    operator1 = \"Press TAB key to create a new node\"\n\n\n\n#### METADATA ####\n[[{\"index\":{\"value\":5},\"size\":{\"value\":8}},\"1bb7a960-3d5c-4f77-ab52-65e438f05461\"],[{\"index\":{\"value\":13},\"size\":{\"value\":1}},\"6cdae421-5142-42e7-b2f1-a68feb575c91\"],[{\"index\":{\"value\":14},\"size\":{\"value\":4}},\"ff56e06b-d275-4abc-aa39-302d4a3240b4\"],[{\"index\":{\"value\":5},\"size\":{\"value\":13}},\"e1654242-73f6-49de-a15e-da1d839a3c04\"],[{\"index\":{\"value\":0},\"size\":{\"value\":29}},\"7e0d266f-f7d6-42e6-bdc7-46d751b0d372\"],[{\"index\":{\"value\":35},\"size\":{\"value\":8}},\"57a30c9f-c867-498c-a980-fc8716ec3120\"],[{\"index\":{\"value\":43},\"size\":{\"value\":1}},\"7bbec7de-b6c1-4ea6-a458-b48a88a7ac3d\"],[{\"index\":{\"value\":44},\"size\":{\"value\":5}},\"2c957e79-3278-45d3-83e2-15a2134cc577\"],[{\"index\":{\"value\":35},\"size\":{\"value\":14}},\"67ac7962-7cc9-4ae4-aab2-98f60706c6d6\"],[{\"index\":{\"value\":30},\"size\":{\"value\":30}},\"ed7b512c-ecba-4b9b-a55a-e6591db43936\"],[{\"index\":{\"value\":66},\"size\":{\"value\":8}},\"a7812475-0957-4193-8126-35905b403814\"],[{\"index\":{\"value\":74},\"size\":{\"value\":1}},\"66bb35e5-e8e5-402e-a295-8fe487ef3e71\"],[{\"index\":{\"value\":75},\"size\":{\"value\":8}},\"92a25e13-cde6-4cdc-b74b-d5fbd1b0d47b\"],[{\"index\":{\"value\":66},\"size\":{\"value\":17}},\"ee443ca8-f29a-45ca-9b09-6c5e78381f69\"],[{\"index\":{\"value\":61},\"size\":{\"value\":33}},\"ae09a313-9dfb-4ebe-8543-8e6277dcb458\"],[{\"index\":{\"value\":100},\"size\":{\"value\":8}},\"7cf764f5-bd40-4cb9-a1b6-061adec6563f\"],[{\"index\":{\"value\":108},\"size\":{\"value\":1}},\"7823c1af-1dd0-41e9-be2f-f0729a7b9e44\"],[{\"index\":{\"value\":109},\"size\":{\"value\":3}},\"5037a68c-09bd-459b-ba8e-7fb78b459e76\"],[{\"index\":{\"value\":100},\"size\":{\"value\":12}},\"4e4ccef5-e7fb-451a-8158-0bd9d3508b66\"],[{\"index\":{\"value\":95},\"size\":{\"value\":28}},\"825556d5-650c-4ce9-87ae-253968003af5\"],[{\"index\":{\"value\":125},\"size\":{\"value\":4}},\"af55033a-9a65-4c69-bccc-03a2aef0b222\"],[{\"index\":{\"value\":130},\"size\":{\"value\":1}},\"02ea852e-2cc4-4faf-ba53-a8f9026891b1\"],[{\"index\":{\"value\":136},\"size\":{\"value\":9}},\"fd07932d-07bc-4eb6-9b36-d05e6eb59ea7\"],[{\"index\":{\"value\":146},\"size\":{\"value\":1}},\"c74effd8-5b74-437b-979b-656ee08de514\"],[{\"index\":{\"value\":148},\"size\":{\"value\":36}},\"13012aa2-9f5a-43ac-9eda-892fb453f44c\"],[{\"index\":{\"value\":136},\"size\":{\"value\":48}},\"e65aa27c-79b7-4493-987e-c51216892c41\"],[{\"index\":{\"value\":131},\"size\":{\"value\":53}},\"74695c64-6437-46c8-9fca-d0807ea9deca\"],[{\"index\":{\"value\":125},\"size\":{\"value\":59}},\"722213f7-5e09-41a9-9523-e459166f5906\"]]\n{\"ide\":{\"node\":{},\"import\":{},\"project\":null}}"
        }
      ],
      "newVersion": "5563b663c93338aa10d2d8e957b5442b2bb196d656e5555d5f034a9f",
      "oldVersion": "f2738654c2a053a13c05577e71f4eca4832437b3c683b5c2a45a02d0",
      "path": {
        "rootId": "e266e7bf-c7b9-482c-85b7-280ac3ebb5cb",
        "segments": [
          "src",
          "Main.enso"
        ]
      }
    },
    "execute": true
  }
}

However, the second, which seemingly sets up the metadata is not:

{
  "jsonrpc": "2.0",
  "id": 9,
  "method": "text/applyEdit",
  "params": {
    "edit": {
      "edits": [
        {
          "range": {
            "end": {
              "character": 46,
              "line": 12
            },
            "start": {
              "character": 0,
              "line": 12
            }
          },
          "text": "{\"ide\":{\"node\":{\"13012aa2-9f5a-43ac-9eda-892fb453f44c\":{\"position\":{\"vector\":[-100.0,140.0]},\"intended_method\":null,\"uploading_file\":null,\"selected\":false,\"visualization\":null}},\"import\":{},\"project\":null}}"
        }
      ],
      "newVersion": "78944d7dc2e55aa0f3bc459d6938df0b57f739a202432df3c93c9a1f",
      "oldVersion": "5563b663c93338aa10d2d8e957b5442b2bb196d656e5555d5f034a9f",
      "path": {
        "rootId": "e266e7bf-c7b9-482c-85b7-280ac3ebb5cb",
        "segments": [
          "src",
          "Main.enso"
        ]
      }
    },
    "execute": false
  }
}

{
  "jsonrpc": "2.0",
  "id": 9,
  "error": {
    "code": 3003,
    "message": "Invalid version [client version: 78944d7dc2e55aa0f3bc459d6938df0b57f739a202432df3c93c9a1f, server version: e3e99702946c8b47a3f10b4054cf55540c5db12c601d53b8910b1b9a]"
  }
}

So during the next update we reopen the text file, and all subsequent applyEdits are successful. I don't know which version is "right", so it's hard to say if it's a problem of engine or IDE.

Engine does not send any expression update

Simply, they do not arrive. I attach the logs from the offending run:

20230525-080644-925-enso-project-manager.log

@farmaazon
Copy link
Contributor

farmaazon commented May 25, 2023

More notes:

  • I was able to reproduce the bug only on newly created project.
  • When reproduced, attaching visualization did not send "attach visualization" message. This is strange.
  • The version mismatch occurs after opening a newly created project, even when not doing any change. And in that case the engine works properly (IDE gets expression updates) so it seems like an unrelated issue. So I will create a separate ticket, and this one will be for debugging missing expression updates.

@JaroslavTulach
Copy link
Member

I see following exception in Greg's log:

[warn] [2023-05-24T19:32:12.967Z] [org.enso.projectmanager.boot.ProjectManager$] Failed to read line.
java.io.EOFException: Some(There is no more input left to read)
  at zio.Console$ConsoleLive$$anon$2.readLine(Console.scala:107)
  at zio.Console$ConsoleLive$.$anonfun$readLine$3(Console.scala:87)
  at zio.ZIOCompanionPlatformSpecific.$anonfun$attemptBlockingInterrupt$6(ZIOPlatformSpecific.scala:105)
  at zio.ZIO$.$anonfun$suspend$1(ZIO.scala:4569)
  at zio.FiberRef$unsafe$$anon$2.$anonfun$getWith$1(FiberRef.scala:453)
  at zio.internal.FiberRuntime.runLoop(FiberRuntime.scala:1121)
  at zio.internal.FiberRuntime.evaluateEffect(FiberRuntime.scala:391)
  at zio.internal.FiberRuntime.evaluateMessageWhileSuspended(FiberRuntime.scala:514)
  at zio.internal.FiberRuntime.drainQueueOnCurrentThread(FiberRuntime.scala:230)
  at zio.internal.FiberRuntime.run(FiberRuntime.scala:139)
  at [email protected]/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
  at [email protected]/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
  at [email protected]/java.lang.Thread.run(Thread.java:829)
  at org.graalvm.nativeimage.builder/com.oracle.svm.core.thread.PlatformThreads.threadStartRoutine(PlatformThreads.java:775)
  at org.graalvm.nativeimage.builder/com.oracle.svm.core.windows.WindowsPlatformThreads.osThreadStartRoutine(WindowsPlatformThreads.java:178)
[info] [2023-05-24T19:32:12.967Z] [org.enso.projectmanager.boot.ProjectManager$] Stopping server...

that doesn't look like a clean shutdown...

Moreover I am not sure who initialized the shutdown? IDE? Why?

@hubertp
Copy link
Collaborator

hubertp commented May 25, 2023

I see following exception in Greg's log:
...
that doesn't look like a clean shutdown...

This is fine. Will reduce/remove that in the future to avoid unnecessary confusion.

@JaroslavTulach
Copy link
Member

I am trying to reproduce with:

enso$ ./project-manager --profiling-path index.npss --profiling-events-log-path index.log --profiling-time 60

but I don't see any problem. Possibly related to the fact that I don't know how to force the "Compiling standard libraries..." message. Just removing IRs: rm -rf ~/.local/share/enso/cache/ir/ doesn't do the trick.

@farmaazon
Copy link
Contributor

but I don't see any problem. Possibly related to the fact that I don't know how to force the "Compiling standard libraries..." message. Just removing IRs: rm -rf ~/.local/share/enso/cache/ir/ doesn't do the trick.

Interesting. I see the message every time I open a project. AFAIK IDE shows the message by default and hide it on the first received "executionComplete" message.

@jdunkerley jdunkerley changed the title Enso stopped working propperly when creating node during Libs compilation Enso stopped working properly when creating node during Libs compilation May 30, 2023
@jdunkerley jdunkerley moved this from ❓New to 📤 Backlog in Issues Board May 30, 2023
@jdunkerley jdunkerley added this to the Design Partners milestone May 30, 2023
@hubertp
Copy link
Collaborator

hubertp commented May 30, 2023

I added some sleep time between loading of libraries, to simulate the problem locally. I haven't yet been able to reproduce exactly this issue, but execution of expressions and visualizations are failing with compiler errors complaining about missing names. Will need to dig it further. scratch that, broken build.

@hubertp
Copy link
Collaborator

hubertp commented May 31, 2023

It does indeed only happen on new projects. Very weird.

@hubertp hubertp moved this from 📤 Backlog to 🔧 Implementation in Issues Board May 31, 2023
@hubertp
Copy link
Collaborator

hubertp commented May 31, 2023

@farmaazon So I've added some debugging to figure out where the mismatch is happening.
The version mismatch is in the file contents after changes have been applied.
So LS calculates

from Standard.Base import all
from Standard.Table import all
from Standard.Database import all
from Standard.AWS import all

main =
    operator1 = "Press TAB key to create a new node"



#### METADATA ####
[[{"index":{"value":5},"size":{"value":8}},"e131b3d2-d431-48ff-abc4-10d4df8ffd27"],[{"index":{"value":13},"size":{"value":1}},"75147e9c-9240-4652-976b-997f345beb41"],[{"index":{"value":14},"size":{"value":4}},"21d10a28-6f86-4b5e-ae6e-d0b20b0b42dc"],[{"index":{"value":5},"size":{"value":13}},"1b2762a3-75d2-4973-8a10-37a65a966db5"],[{"index":{"value":0},"size":{"value":29}},"00b931ee-a4a8-4b95-a138-3f0a5d0854ca"],[{"index":{"value":35},"size":{"value":8}},"07a52be8-5f9b-474b-9055-e2bce0fe9f5e"],[{"index":{"value":43},"size":{"value":1}},"25519a95-a7a1-4660-a807-60413c8efe71"],[{"index":{"value":44},"size":{"value":5}},"1ad5e47b-8786-46c4-a603-421e58e159a8"],[{"index":{"value":35},"size":{"value":14}},"6217c7c7-0db4-4f19-b9ee-f9b09301aea3"],[{"index":{"value":30},"size":{"value":30}},"16a75b4e-9352-4734-a0a3-829becb75342"],[{"index":{"value":66},"size":{"value":8}},"7f086749-ab23-4ee4-8a05-d94883de62eb"],[{"index":{"value":74},"size":{"value":1}},"8845221b-4a73-4f88-a2d5-fa0b0fb20832"],[{"index":{"value":75},"size":{"value":8}},"49dad374-eb6f-4f02-80d8-1b096d2197f0"],[{"index":{"value":66},"size":{"value":17}},"ee47a9d8-5077-4895-8a4d-0de82d33e4f9"],[{"index":{"value":61},"size":{"value":33}},"a341e9ad-148d-43f9-9548-22fdf8305b32"],[{"index":{"value":100},"size":{"value":8}},"35a9e7a9-1876-4004-8a08-d46e53226f32"],[{"index":{"value":108},"size":{"value":1}},"3c0837df-8979-4d04-a63f-a223c7507d42"],[{"index":{"value":109},"size":{"value":3}},"338265ba-2045-42d1-bbcb-fbe9cfc405a9"],[{"index":{"value":100},"size":{"value":12}},"bcc0a763-25df-4485-a97d-f49db91d1176"],[{"index":{"value":95},"size":{"value":28}},"bea7a692-138a-4720-bd96-d599d3ca6590"],[{"index":{"value":125},"size":{"value":4}},"9f71c295-34a0-4156-98fa-07fc3c34c541"],[{"index":{"value":130},"size":{"value":1}},"a84fa21b-fe50-4324-bbca-7848a38965a7"],[{"index":{"value":136},"size":{"value":9}},"b3cc5334-86dd-4264-a3fd-c20e4a56e8f5"],[{"index":{"value":146},"size":{"value":1}},"0f0d0613-0b3f-4826-a641-10dae370106e"],[{"index":{"value":148},"size":{"value":36}},"257e0a41-490c-4152-b273-68b13e89395e"],[{"index":{"value":136},"size":{"value":48}},"95dbf67d-332f-416f-98d2-a6d5bdcd261d"],[{"index":{"value":131},"size":{"value":53}},"904f15b3-3750-41d3-99ff-dc85da71eb15"],[{"index":{"value":125},"size":{"value":59}},"83c4163f-4f9a-445d-a5a2-152277542107"]]
{"ide":{"node":{"257e0a41-490c-4152-b273-68b13e89395e":{"position":{"vector":[-100.0,140.0]},"intended_method":null,"uploading_file":null,"selected":false,"visualization":null}},"import":{},"project":null}}

as e271ef80cc8042ac649a28db0d9f2da93dd564db0a00c8ce945d4824, which I think is correct.
IDE however, in the applyEdit expected that to be aeca3b1be1e8719eb22b34c1e110314fd3944cf0d9a6d93351bbcba1. I don't know where the latter came from. Any ideas why sha calculated and passed from IDE can be different?

@enso-bot
Copy link

enso-bot bot commented May 31, 2023

Hubert Plociniczak reports a new STANDUP for yesterday (2023-05-30):

Progress: Trying to reproduce the problem described in the ticket. So far unsuccessful. Closed a few bugs that were likely fixed by changes in GUI/LS changes - no longer able to reproduce them. Various meetings and syncs. It should be finished by 2023-05-31.

Next Day: Next day I will be working on the #6841 task. Continue the investigation.

@hubertp
Copy link
Collaborator

hubertp commented May 31, 2023

The difference appears to be in the first section of metadata.
Here is what server expects:

[[{"index":{"value":5},"size":{"value":8}},"76123af6-e93d-4a6f-a847-8bd605167d94"],[{"index":{"value":13},"size":{"value":1}},"72b5ffeb-36b5-44fe-a987-8d965181b11d"],[{"index":{"value":14},"size":{"value":4}},"94aa62b8-d2b7-4f9a-ae07-7a7f0e232fbc"],[{"index":{"value":5},"size":{"value":13}},"8082b8df-b5b8-4cec-9847-c6de791a26ba"],[{"index":{"value":0},"size":{"value":29}},"2cf83374-a2a2-48d5-8a47-050fff38271c"],[{"index":{"value":35},"size":{"value":8}},"847a43ec-7163-41fa-822f-929ee0d78687"],[{"index":{"value":43},"size":{"value":1}},"4a14f74a-6137-4331-98fa-c7a47c51ac8a"],[{"index":{"value":44},"size":{"value":5}},"f49d4459-fb74-4020-a434-f6f48c9626f2"],[{"index":{"value":35},"size":{"value":14}},"7a704d43-e24a-40a9-8e6f-58b1117e8659"],[{"index":{"value":30},"size":{"value":30}},"c9f2c916-9625-437b-80b0-674c7ba57435"],[{"index":{"value":66},"size":{"value":8}},"380b9b58-8d82-4ad0-9e1a-24a54da21f32"],[{"index":{"value":74},"size":{"value":1}},"4d155ed7-b4bc-45b2-9bf3-9405beba860d"],[{"index":{"value":75},"size":{"value":8}},"1ddb76f4-ef56-40f1-88ad-9a4125fa8bd8"],[{"index":{"value":66},"size":{"value":17}},"6619c8ca-6908-446e-9512-a44f659c411e"],[{"index":{"value":61},"size":{"value":33}},"0e23f9d2-92a2-4883-8a65-7d73e07fe6f3"],[{"index":{"value":100},"size":{"value":8}},"bfabd568-c8dc-4361-9426-1a8e6386fdff"],[{"index":{"value":108},"size":{"value":1}},"088d0544-8b1d-4e64-9495-34cc7975cd2c"],[{"index":{"value":109},"size":{"value":3}},"71abacd3-9b67-410a-aa7b-72859ae28cd2"],[{"index":{"value":100},"size":{"value":12}},"19264292-d0a5-429c-a6de-8acb46d7772a"],[{"index":{"value":95},"size":{"value":28}},"436acc8d-f061-44fc-bbbc-e161ae56b58c"],[{"index":{"value":125},"size":{"value":4}},"c57a4aef-c275-4bdf-b5a9-b14205f17407"],[{"index":{"value":130},"size":{"value":1}},"26db5557-8e5a-4bbf-8109-8eba427237ce"],[{"index":{"value":136},"size":{"value":9}},"c41a4b49-4d0e-4072-bd92-860ca73d4bf3"],[{"index":{"value":146},"size":{"value":1}},"9030ba7e-704b-45fc-8914-2c5a59e3809d"],[{"index":{"value":148},"size":{"value":36}},"cd149227-c9cc-4e4f-a552-05ba21e87800"],[{"index":{"value":136},"size":{"value":48}},"fdc075cd-fe2d-41e1-bd30-50224d463384"],[{"index":{"value":131},"size":{"value":53}},"8443fcfb-64b2-4765-b650-882f0680ef9e"],[{"index":{"value":125},"size":{"value":59}},"5c9dfc5a-7866-4d70-bcb7-8f95d4b7e2bd"]]

and here is what client expects

[[{"index":{"value":5},"size":{"value":8}},"76123af6-e93d-4a6f-a847-8bd605167d94"],[{"index":{"value":13},"size":{"value":1}},"72b5ffeb-36b5-44fe-a987-8d965181b11d"],[{"index":{"value":14},"size":{"value":4}},"94aa62b8-d2b7-4f9a-ae07-7a7f0e232fbc"],[{"index":{"value":5},"size":{"value":13}},"8082b8df-b5b8-4cec-9847-c6de791a26ba"],[{"index":{"value":0},"size":{"value":29}},"2cf83374-a2a2-48d5-8a47-050fff38271c"],[{"index":{"value":35},"size":{"value":8}},"847a43ec-7163-41fa-822f-929ee0d78687"],[{"index":{"value":43},"size":{"value":1}},"4a14f74a-6137-4331-98fa-c7a47c51ac8a"],[{"index":{"value":44},"size":{"value":5}},"f49d4459-fb74-4020-a434-f6f48c9626f2"],[{"index":{"value":35},"size":{"value":14}},"7a704d43-e24a-40a9-8e6f-58b1117e8659"],[{"index":{"value":30},"size":{"value":30}},"c9f2c916-9625-437b-80b0-674c7ba57435"],[{"index":{"value":66},"size":{"value":8}},"380b9b58-8d82-4ad0-9e1a-24a54da21f32"],[{"index":{"value":74},"size":{"value":1}},"4d155ed7-b4bc-45b2-9bf3-9405beba860d"],[{"index":{"value":75},"size":{"value":8}},"1ddb76f4-ef56-40f1-88ad-9a4125fa8bd8"],[{"index":{"value":66},"size":{"value":17}},"6619c8ca-6908-446e-9512-a44f659c411e"],[{"index":{"value":61},"size":{"value":33}},"0e23f9d2-92a2-4883-8a65-7d73e07fe6f3"],[{"index":{"value":100},"size":{"value":8}},"bfabd568-c8dc-4361-9426-1a8e6386fdff"],[{"index":{"value":108},"size":{"value":1}},"088d0544-8b1d-4e64-9495-34cc7975cd2c"],[{"index":{"value":109},"size":{"value":3}},"71abacd3-9b67-410a-aa7b-72859ae28cd2"],[{"index":{"value":100},"size":{"value":12}},"19264292-d0a5-429c-a6de-8acb46d7772a"],[{"index":{"value":95},"size":{"value":28}},"436acc8d-f061-44fc-bbbc-e161ae56b58c"],[{"index":{"value":131},"size":{"value":8}},"e2a36be7-d7ad-4453-856e-a3e244f80861"],[{"index":{"value":139},"size":{"value":1}},"877d9d99-368a-4238-8985-58471b52dbe5"],[{"index":{"value":140},"size":{"value":13}},"420a67ed-401b-4d73-9786-18ecdcacd07a"],[{"index":{"value":131},"size":{"value":22}},"ab639ed3-bc98-413d-8511-9e583a3725b8"],[{"index":{"value":124},"size":{"value":29}},"7eadd190-de41-4298-9efd-990ddd8fbc59"],[{"index":{"value":155},"size":{"value":4}},"c57a4aef-c275-4bdf-b5a9-b14205f17407"],[{"index":{"value":160},"size":{"value":1}},"26db5557-8e5a-4bbf-8109-8eba427237ce"],[{"index":{"value":166},"size":{"value":9}},"c41a4b49-4d0e-4072-bd92-860ca73d4bf3"],[{"index":{"value":176},"size":{"value":1}},"9030ba7e-704b-45fc-8914-2c5a59e3809d"],[{"index":{"value":178},"size":{"value":36}},"cd149227-c9cc-4e4f-a552-05ba21e87800"],[{"index":{"value":166},"size":{"value":48}},"fdc075cd-fe2d-41e1-bd30-50224d463384"],[{"index":{"value":161},"size":{"value":53}},"8443fcfb-64b2-4765-b650-882f0680ef9e"],[{"index":{"value":155},"size":{"value":59}},"5c9dfc5a-7866-4d70-bcb7-8f95d4b7e2bd"],[{"index":{"value":0},"size":{"value":215}},"1b74811a-8b05-4a1c-82e2-bceaa4de8d4e"]]

Hence different SHAs. I think that's the source of the problem. The IDE never sends any patches for that.

@JaroslavTulach
Copy link
Member

Diff for convenience:
kdiff3

@hubertp
Copy link
Collaborator

hubertp commented May 31, 2023

And

import Standard.Visualization

wasn't sent either to the server.

@farmaazon
Copy link
Contributor

farmaazon commented Jun 1, 2023

@farmaazon So I've added some debugging to figure out where the mismatch is happening. The version mismatch is in the file contents after changes have been applied. So LS calculates

from Standard.Base import all
from Standard.Table import all
from Standard.Database import all
from Standard.AWS import all

main =
    operator1 = "Press TAB key to create a new node"



#### METADATA ####
[[{"index":{"value":5},"size":{"value":8}},"e131b3d2-d431-48ff-abc4-10d4df8ffd27"],[{"index":{"value":13},"size":{"value":1}},"75147e9c-9240-4652-976b-997f345beb41"],[{"index":{"value":14},"size":{"value":4}},"21d10a28-6f86-4b5e-ae6e-d0b20b0b42dc"],[{"index":{"value":5},"size":{"value":13}},"1b2762a3-75d2-4973-8a10-37a65a966db5"],[{"index":{"value":0},"size":{"value":29}},"00b931ee-a4a8-4b95-a138-3f0a5d0854ca"],[{"index":{"value":35},"size":{"value":8}},"07a52be8-5f9b-474b-9055-e2bce0fe9f5e"],[{"index":{"value":43},"size":{"value":1}},"25519a95-a7a1-4660-a807-60413c8efe71"],[{"index":{"value":44},"size":{"value":5}},"1ad5e47b-8786-46c4-a603-421e58e159a8"],[{"index":{"value":35},"size":{"value":14}},"6217c7c7-0db4-4f19-b9ee-f9b09301aea3"],[{"index":{"value":30},"size":{"value":30}},"16a75b4e-9352-4734-a0a3-829becb75342"],[{"index":{"value":66},"size":{"value":8}},"7f086749-ab23-4ee4-8a05-d94883de62eb"],[{"index":{"value":74},"size":{"value":1}},"8845221b-4a73-4f88-a2d5-fa0b0fb20832"],[{"index":{"value":75},"size":{"value":8}},"49dad374-eb6f-4f02-80d8-1b096d2197f0"],[{"index":{"value":66},"size":{"value":17}},"ee47a9d8-5077-4895-8a4d-0de82d33e4f9"],[{"index":{"value":61},"size":{"value":33}},"a341e9ad-148d-43f9-9548-22fdf8305b32"],[{"index":{"value":100},"size":{"value":8}},"35a9e7a9-1876-4004-8a08-d46e53226f32"],[{"index":{"value":108},"size":{"value":1}},"3c0837df-8979-4d04-a63f-a223c7507d42"],[{"index":{"value":109},"size":{"value":3}},"338265ba-2045-42d1-bbcb-fbe9cfc405a9"],[{"index":{"value":100},"size":{"value":12}},"bcc0a763-25df-4485-a97d-f49db91d1176"],[{"index":{"value":95},"size":{"value":28}},"bea7a692-138a-4720-bd96-d599d3ca6590"],[{"index":{"value":125},"size":{"value":4}},"9f71c295-34a0-4156-98fa-07fc3c34c541"],[{"index":{"value":130},"size":{"value":1}},"a84fa21b-fe50-4324-bbca-7848a38965a7"],[{"index":{"value":136},"size":{"value":9}},"b3cc5334-86dd-4264-a3fd-c20e4a56e8f5"],[{"index":{"value":146},"size":{"value":1}},"0f0d0613-0b3f-4826-a641-10dae370106e"],[{"index":{"value":148},"size":{"value":36}},"257e0a41-490c-4152-b273-68b13e89395e"],[{"index":{"value":136},"size":{"value":48}},"95dbf67d-332f-416f-98d2-a6d5bdcd261d"],[{"index":{"value":131},"size":{"value":53}},"904f15b3-3750-41d3-99ff-dc85da71eb15"],[{"index":{"value":125},"size":{"value":59}},"83c4163f-4f9a-445d-a5a2-152277542107"]]
{"ide":{"node":{"257e0a41-490c-4152-b273-68b13e89395e":{"position":{"vector":[-100.0,140.0]},"intended_method":null,"uploading_file":null,"selected":false,"visualization":null}},"import":{},"project":null}}

as e271ef80cc8042ac649a28db0d9f2da93dd564db0a00c8ce945d4824, which I think is correct. IDE however, in the applyEdit expected that to be aeca3b1be1e8719eb22b34c1e110314fd3944cf0d9a6d93351bbcba1. I don't know where the latter came from. Any ideas why sha calculated and passed from IDE can be different?

I'm sorry, but probably you missed an information in my comment #6841 (comment) (the third point: the version mismatch seems to be an unrelated issue)

I already did some investigation and reported in #6843, however, I just stopped at "the IDE is wrong, we need to check deeply". So your investigation went already deeper, and was referred to in that issue. Thanks for your effort.

I thought this task will be mainly about "why engine does not report expression updates", not the synchronization issue.

@hubertp
Copy link
Collaborator

hubertp commented Jun 1, 2023

I thought this task will be mainly about "why engine does not report expression updates", not the synchronization issue.

There are two tasks really. The first one I was able to reproduce, the second I was not. At least not yet.

I already did some investigation and reported in #6843, however, I just stopped at "the > IDE is wrong, we need to check deeply". So your investigation went already deeper, and was referred to in that issue. Thanks > for your effort.

If it helps, that's OK. I hacked IDE a bit to include a patch from the id_map section but, as I mentioned in the previous comment, I also noticed later that we were missing one additional import in the code section. I'm not familiar with the codebase enough to hack it further efficiently so I will leave it to you.

@hubertp
Copy link
Collaborator

hubertp commented Jun 1, 2023

Re lack of expression updates:
I can reproduce. Looks like a compilation job is submitted for execution, then aborted due to an edit, then another one is submitted. The last one is never executed, hence lack of executionComplete message.

@hubertp
Copy link
Collaborator

hubertp commented Jun 1, 2023

Turns out what we have is a nice example of a thread deadlock between edit file/close file and open file commands.

Screenshot from 2023-06-01 13-48-14
Screenshot from 2023-06-01 13-48-34
Screenshot from 2023-06-01 13-48-55

hubertp added a commit that referenced this issue Jun 1, 2023
At the beginning of the execution `EnsureCompiledJob` acquired write
compilation lock. When compiling individual modules it would then
- acquire file lock
- acquire read compilation lock

The second one was spurious since it already kept the write lock.
This sequence meant however that `CloseFileCmd` or `OpenFileCmd` can
lead to  a deadlock when requests come in close succession. This is
because commands:
- acquire file lock
- acquire read compilation lock

So `EnsureCompiledJob` might have the (write) compilation lock but the
commands could have file lock. And the second required lock for either
the job or the command could never be acquired.

Flipping the order did the trick.

Partially solves #6841.
@enso-bot
Copy link

enso-bot bot commented Jun 1, 2023

Hubert Plociniczak reports a new STANDUP for yesterday (2023-05-31):

Progress: Managed to reproduce reliably the problem with desynchronization. Investigated and reported the findings, looks like it is mostly a GUI issue where it does not send the necessary file patches thus resulting in version mismatch. It should be finished by 2023-05-31.

Next Day: Next day I will be working on the #6841 task. Investigate why no expression updates appear after re-sync.

@enso-bot
Copy link

enso-bot bot commented Jun 2, 2023

Hubert Plociniczak reports a new 🔴 DELAY for yesterday (2023-06-01):

Summary: There is 2 days delay in implementation of the Enso stopped working properly when creating node during Libs compilation (#6841) task.
It will cause 0 days delay for the delivery of this weekly plan.

Delay Cause: The ticked has multiple issue, it seems. Fixing one problem unblocks others.

@enso-bot
Copy link

enso-bot bot commented Jun 2, 2023

Hubert Plociniczak reports a new STANDUP for yesterday (2023-06-01):

Progress: Investigated backend getting stuck after re-sync on new project startup. Turns out we had a deadlock that could be reproduced reliably. PR is ready. But there is still a problem with expression updates not including information about newly added expressions (everything appears to be Nothing). It should be finished by 2023-06-02.

Next Day: Next day I will be working on the #6841 task. Investigate another part of the problem.

@enso-bot
Copy link

enso-bot bot commented Jun 5, 2023

Hubert Plociniczak reports a new STANDUP for the provided date (2023-06-02):

Progress: Started investigating the remaining problem with wrong expression updates for #6841 but got distracted and decided to pick it up next week. Instead started looking into #6897. Runtime exception was preventing IDE from receiving any expression updates (including method pointers and calls). PR is ready, although runtime exceptions can still wreak havoc if they appear again. It should be finished by 2023-06-02.

Next Day: Next day I will be working on the #6841 task. Go back to #6841, also investigate if we can remove the remaining runtime exceptions.

mergify bot pushed a commit that referenced this issue Jun 6, 2023
At the beginning of the execution `EnsureCompiledJob` acquired write compilation lock. When compiling individual modules it would then
- acquire file lock
- acquire read compilation lock

The second one was spurious since it already kept the write lock. This sequence meant however that `CloseFileCmd` or `OpenFileCmd` can lead to  a deadlock when requests come in close succession. This is because commands:
- acquire file lock
- acquire read compilation lock

So `EnsureCompiledJob` might have the (write) compilation lock but the commands could have file lock. And the second required lock for either the job or the command could never be acquired.

Flipping the order did the trick.

Partially solves #6841.

# Important Notes
For some reason we don't get updates for the newly added node, as illustrated in the screenshot, but that could be related to the close/open action. Will need to dig more.

![Screenshot from 2023-06-01 16-45-17](https://github.com/enso-org/enso/assets/292128/900aa9b3-b2b2-4e4d-93c8-267f92b79352)
@enso-bot
Copy link

enso-bot bot commented Jun 7, 2023

Hubert Plociniczak reports a new 🔴 DELAY for yesterday (2023-06-06):

Summary: There is 5 days delay in implementation of the Enso stopped working properly when creating node during Libs compilation (#6841) task.
It will cause 0 days delay for the delivery of this weekly plan.

Delay Cause: Temporarily moved to other issues, picking the problem again now that deadlock is resolved. The bug is hard to track down.

@enso-bot
Copy link

enso-bot bot commented Jun 7, 2023

Hubert Plociniczak reports a new STANDUP for yesterday (2023-06-06):

Progress: Back to investigating lack of expression updates. Confirming that edits are recorded and applied to the source. For some reason the corresponding nodes for new expressions aren't created. Will need to dig further. It should be finished by 2023-06-07.

Next Day: Next day I will be working on the #6841 task. Continue the investigation, sync with Dmitry for potential hints.

@enso-bot
Copy link

enso-bot bot commented Jun 8, 2023

Hubert Plociniczak reports a new 🔴 DELAY for yesterday (2023-06-07):

Summary: There is 3 days delay in implementation of the Enso stopped working properly when creating node during Libs compilation (#6841) task.
It will cause 0 days delay for the delivery of this weekly plan.

Delay Cause: Put wrong delay in the last report. Race condition is proving to be rather hard to identify & fix.

@enso-bot
Copy link

enso-bot bot commented Jun 8, 2023

Hubert Plociniczak reports a new STANDUP for yesterday (2023-06-07):

Progress: Ideintified a race condition between edits and open file cmd which eliminates them. Put up draft PR demonstrating the problem. The problem is that command and job are executed by different schedulers making the synchronization rather hard. Potentially the order of execution should be sequential. Investigating potential fixes. It should be finished by 2023-06-10.

Next Day: Next day I will be working on the #6841 task. Continue the investigation now that problem is identified.

@enso-bot
Copy link

enso-bot bot commented Jun 9, 2023

Hubert Plociniczak reports a new STANDUP for yesterday (2023-06-08):

Progress: PR with a fix is ready. runtime commands can now be executed asynchronously, as before, as well as synchronously. OpenFile and CloseFile are the latter now. There was no other way to make sure that edit/close/open actions don't interfere with each other. Tested extensively, seems to work. It should be finished by 2023-06-10.

Next Day: Next day I will be working on the #6841 task. Address PR review, pick up next task.

@mergify mergify bot closed this as completed in #6998 Jun 9, 2023
mergify bot pushed a commit that referenced this issue Jun 9, 2023
There was an inherent race condition between edit, close & open commands which could not be prevented solely using locks. `EditFileCmd` triggered `EnsureCompiledJob` which was applying edits collected over time. At the same `CloseFileCmd` and `OpenFileCmd` were executed asynchronously and required locks on compilation unit  and file lock.

Additionally, open file was resetting the module's runtime source irrespective of any edits that could already have been applied with the asynchronous execution in `EnsureCompiledJob`. This was visible especially during early manipulation of the project when open/close was performed due to a bug in IDE (#6843).

Now commands can be run either synchronously or asynchronously. Only that way can we ensure that `close` & `open` commands finish by the time any editions are being applied to module's sources.

Closes #6841.

# Important Notes
In the given video, `"foo"` would be greyed out because it would never be part of the module's (runtime) sources. Therefore no IR would be generated for it or instrumentation, meaning it would be present in `expressionUpdates` information necessary for IDE.

[Kazam_screencast_00014.webm](https://github.com/enso-org/enso/assets/292128/226a17b8-729a-415a-803f-003a9695b2f1)
@github-project-automation github-project-automation bot moved this from 🔧 Implementation to 🟢 Accepted in Issues Board Jun 9, 2023
@enso-bot
Copy link

enso-bot bot commented Jun 12, 2023

Hubert Plociniczak reports a new STANDUP for the provided date (2023-06-09):

Progress: More testing of the fix for the race condition, PR merged. Investigated issues with using Scala-generated classes in Java code and the related IDE problems. Looks like the problem could be fixed either on javac or scalac side but both are unlikely in a short term (will file a ticket for the latter). We will likely rewrite IR.scala to avoid deep nested structures. Started looking into various visualization failures/timeouts errors comming from LS. It should be finished by 2023-06-10.

Next Day: Next day I will be working on the #6841 task. Continue investigation into visualizations.

@enso-bot
Copy link

enso-bot bot commented Jun 16, 2023

Hubert Plociniczak reports a new 🔴 DELAY for yesterday (2023-06-15):

Summary: There is 2 days delay in implementation of the Enso stopped working properly when creating node during Libs compilation (#6841) task.
It will cause 0 days delay for the delivery of this weekly plan.

Delay Cause: Discovered some serious flaws in the existing design of job execution that needed to be addressed.

@hubertp
Copy link
Collaborator

hubertp commented Jun 16, 2023

Hubert Plociniczak reports a new red_circle DELAY for yesterday (2023-06-15):

Please ignore. Wrong ticket.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
Archived in project
Development

Successfully merging a pull request may close this issue.

5 participants