SVT: Server.xml hover support not working (times out) with the ACME application

rumanaHaque commented 2 years ago

Found this issue while trying to test Liberty Tools in Eclipse - using test case - https://github.ibm.com/websphere/system-test/issues/479

After installing new Eclipse version (22-06), and Liberty Tools plugin, when I install the simple App - https://github.com/OpenLiberty/application-stack-intro, and click on server.xml, I can hover over the features and I see the pop-ups. I can also do "<fe" and Ctrl+space, and it will complete it as "". However, when I import my Application (https://github.ibm.com/was-svt/acme-ee) as an existing Maven app, and put in a server.xml in my AcmeWebEjbEar/src/main/liberty/config dir, and open that server.xml, I do not see any of the popups or the feature completions.

scottkurz commented 2 years ago

@cherylking @mattbsox - flagging this maybe for some help.

mattbsox commented 2 years ago

Seems like this might be related to https://github.com/OpenLiberty/liberty-language-server/issues/82

Do the popups and completion work correctly when all the server.xml files are closed and reopened?

scottkurz commented 1 year ago

@rumanaHaque - I'm assuming this was on your list to retry, just noting we still have the original issue to follow-up on. Note I tried a similar scenario on the latest code and did NOT experience this problem, whereas I had intermittently seen it around the timeframe you'd opened this. Thanks.

rumanaHaque commented 1 year ago

@scottkurz As I had mentioned to you earlier, I am seeing the same problem with the latest driver as well.

scottkurz commented 1 year ago

Looking at the XML LSP log, I see these three textDocument/completion requests:


# REQUEST 1
[t=1669081349427] LSP4E to org.eclipse.wildwebdeveloper.xml:{"jsonrpc":"2.0","id":"13","method":"textDocument/completion","params":{"textDocument":{"uri":"file:///C:/eclipse-workspace/liberty_tools_Acme/acme-ee9/AcmeWebEjbEar/src/main/liberty/config/server.xml"},"position":{"line":20,"character":9}}}
[t=1669081356303] org.eclipse.wildwebdeveloper.xml to LSP4E:{"jsonrpc":"2.0","id":"13","error":{"code":-32800,"message":"The request (id: 13, method: \u0027textDocument/completion\u0027) has been cancelled"}}

# REQUEST 2
[t=1669081356680] LSP4E to org.eclipse.wildwebdeveloper.xml
{"jsonrpc":"2.0","id":"24","method":"textDocument/completion","params":{"textDocument":{"uri":"file:///C:/eclipse-workspace/liberty_tools_Acme/acme-ee9/AcmeWebEjbEar/src/main/liberty/config/server.xml"},"position":{"line":20,"character":11}}}

# REQUEST 3
[t=1669081378326] LSP4E to org.eclipse.wildwebdeveloper.xml:
{"jsonrpc":"2.0","id":"25","method":"textDocument/completion","params":{"textDocument":{"uri":"file:///C:/eclipse-workspace/liberty_tools_Acme/acme-ee9/AcmeWebEjbEar/src/main/liberty/config/server.xml"},"position":{"line":20,"character":11}}}

So the first one gets a "..has been cancelled" response. In my experience this can happen in cases where things end up working. I'm not saying it's irrelevant but I don't think it's in and of itself the full problem.

The second request never gets a response (for "id":"24")

The third request never gets a response (for "id":"25")

As a next step, I think we need to take a Java dump of both Eclipse IDE and the XML LS processes when this happens. Not sure what else we can do.

From: https://github.com/eclipse/wildwebdeveloper/discussions/974 the XML LS (Lemminx) process isn't easily traceable with our current level of integration.

scottkurz commented 1 year ago

Since we don't seem to have logging at the Java source level, I think making use of OpenJ9/Semeru Xtrace might be a good option to try to make some progress.

Let me try to lay out some steps.

1. Enable LSP logging

In Eclipse Preferences enable both console and file logging for XML Language Server

2. Run with Semeru (Open J9) JDK (and enable consoleLog), and lemminx logging

In eclipse.ini, add something like (point to your Semeru install). Also add the -consoleLog option as shown, and add the last entry somewhere after the -vmargs line:

-vm
C:/JavaEcl/SemeruJava17/bin
-consoleLog
...  
-vmargs
...
-Dorg.eclipse.wildwebdeveloper.xml.internal.XMLLanguageServer.log.level=INFO

3. Update the options.default file in Semeru install lib dir

Go edit the path, (continuing my example from above): C:/JavaEcl/SemeruJava17/lib/options.default

Copy/paste this trace string to the end of this file (for me it worked best without quotes for this option and the option already in the file (I removed those quotes)

Note: you'll have to substitute a real path for /path/to/tracefrompid%p.trc. (I'm not sure whether this needs backwards or forward slashes on Windows).

-Xtrace:none,maximal=mt,methods={org/eclipse/lemminx*.*(),io/openliberty/tools/langserver*.*()},output=/path/to/tracefrompid%p.trc -Xjit:exclude={org/eclipse/lemminx*,io/openliberty/tools/langserver*},dontinline={org/eclipse/lemminx*,io/openliberty/tools/langserver*}

4. Launch Eclipse and collect the stdout/stderr

LEMMINX_DEBUG=true ./eclipse.exe 2>&1 | tee consoleLog.1.txt

NOTE: Be careful not to overwrite this before saving/copying !

5. Perform the UI sequence

Open server.xml
Insert cursor and type <fe , wait for suggestion of .
Select suggestion
Move cursor inside the element and type <Ctrl>+<Space>
Select any suggested feature
Hover over one of the previously-existing features until the help pops up a feature description.

Note that step 6. isn't that interesting in the working case. The point in my mind is to see, if the previous steps fail, if the XML LS is completely dead at that point or if it works in some ways but not others. We could try something else instead but I'm also trying to keep it simple so we know what input we've provided as we look in the logs.

6. Produce dumps for Eclipse & XML LS

We're going to be running jcmd from the Semeru install home bin dir

Run jcmd -l,e.g.

$ jcmd -l
24636 Eclipse
30544 <no information available>
37532 org.eclipse.lemminx.XMLServerLauncher

For each of Eclipse, and the XML LS, gather system and Java dumps

$ jcmd 24636 Dump.system  # If you don't have the space we can skip this step.   Hopefully we won't have to look at this. 
$ jcmd 24636 Dump.java       # saves us the trouble of extracting the Java dump from system dump
$ jcmd 37532 Dump.system
$ jcmd 37532 Dump.java

7. Kill eclipse.exe process (XML LS should go down soon after)

8. Gather logs/dumps

This should include:

<eclipse workspace>/.metadata/.log
<eclipse workspace>/.metadata/lemminx.log
<eclipse workspace>/languageServers-log # you can just grab the directory
console log: consoleLog.1.txt
Two tracefrompidNNNN.trc files
Two javacore.*.txt files

rumanaHaque commented 1 year ago

I was able to collect the traces using the instructions that Scott mentioned above, as well as with @ajm01 help. Here are the traces when I was able to reproduce the error. https://rtpgsa.ibm.com/projects/w/wassvt/defects/LDT/eclipse/xtraces.zip

Initially, I was not able to recreate it after I enabled tracing. Here are the traces for that. https://rtpgsa.ibm.com/projects/w/wassvt/defects/LDT/eclipse/xtraces_prev.zip

rumanaHaque commented 1 year ago

I had already closed the eclipse earlier. I recreated the problem again, after restarting Eclipse.

I was able to collect all the logs requested above, with the exception of the XML LS dumps. I was able to get the Eclipse dumps (both system and java).

Uploaded all the logs to https://rtpgsa.ibm.com/projects/w/wassvt/defects/LDT/eclipse/latest/

rumanaHaque commented 1 year ago

Here's a screenshot of what the exception looks like once I see the error.

Also - once I see the exception, I cannot hover over anything and get any popups. So once it reaches this state, cannot make much progress in server.xml.

scottkurz commented 1 year ago

Moving out of the milestone.

rumanaHaque commented 10 months ago

Tried to reproduce this using the latest Liberty Tools 23.0.12 LTE driver. Using the later builds, completion works (i.e <fe Ctrl+Space showd feature). However I still don't get any text to pop-up while hovering.

Here's the behavior when I try to hover, and later when I try to do feature complete. org.eclipse.wildwebdeveloper.xml.log

scottkurz commented 10 months ago

Some observations from the last log...

Initialization

 [2023-11-13T15:36:04.506862800-08:00] LSP4E_TO_LANGUAGE_SERVER org.eclipse.wildwebdeveloper.xml:
 {"jsonrpc":"2.0","id":"1","method":"initialize","params":{"processId":11176,"rootPath":"/C:/eclipse-workspace/acme-ee10/acme-ee/AcmeWebEjbEar/","rootUri":"file:///C:/eclipse-workspace/acme-ee10/acme-ee/AcmeWebEjbEar/","initializationOptions":{"settings":{"xml":{"maven":{},"downloadExternalResources":{"enabled":false},"catalogs":["C:\\eclipse-workspace\\

First hover request takes 10 seconds

[2023-11-13T15:36:16.687885600-08:00] LSP4E_TO_LANGUAGE_SERVER org.eclipse.wildwebdeveloper.xml:
{"jsonrpc":"2.0","id":"12","method":"textDocument/hover","params":{"textDocument":{"uri":"file:///C:/eclipse-workspace/acme-ee10/acme-ee/AcmeWebEjbEar/src/main/liberty/config/server.xml"},"position":{"line":4,"character":23}}}

[2023-11-13T15:36:26.502594400-08:00] LANGUAGE_SERVER_TO_LSP4E org.eclipse.wildwebdeveloper.xml:
{"jsonrpc":"2.0","id":"12","result":{"contents":{"kind":"plaintext","value":"This feature enables the Liberty server to process Jakarta EE client modules and support remote Jakarta EE client containers."},"range":{"start":{"line":4,"character":17},"end":{"line":4,"character":37}}}}

There are a lot of progress updates in between

[2023-11-13T15:36:17.781873100-08:00] LANGUAGE_SERVER_TO_LSP4E org.eclipse.wildwebdeveloper.xml:
{"jsonrpc":"2.0","method":"$/progress","params":{"token":"838082f1-c4aa-44e2-b70b-bc7f64f3fb23","value":{"kind":"report","message":"Scanning folder \u0027\u0027commons-logging\u0027\u0027 (207 / 229)...","percentage":90}}}

Second hover request takes 4 seconds

[2023-11-13T15:37:54.382451600-08:00] LSP4E_TO_LANGUAGE_SERVER org.eclipse.wildwebdeveloper.xml:
{"jsonrpc":"2.0","id":"40","method":"textDocument/hover","params":{"textDocument":{"uri":"file:///C:/eclipse-workspace/acme-ee10/acme-ee/AcmeWebEjbEar/src/main/liberty/config/server.xml"},"position":{"line":22,"character":16}}}

[2023-11-13T15:37:58.620449400-08:00] LANGUAGE_SERVER_TO_LSP4E org.eclipse.wildwebdeveloper.xml:
{"jsonrpc":"2.0","id":"40","result":{"contents":{"kind":"markdown","value":"Specifies a feature to be used when the server runs.\r\n\r\nSource: [ol-23.0.0.10.xsd](file:/C:/eclipse-workspace/acme-ee10/acme-ee/AcmeWebEjbEar/target/.libertyls/ol-23.0.0.10.xsd)"},"range":{"start":{"line":22,"character":9},"end":{"line":22,"character":16}}}}

NOTES

So even after we're well past initializing, the last request takes 4s, but we only have a 1s timeout.

We'll have to figure out a way to break this down further.

scottkurz commented 9 months ago

This problem seems to have gone away, for now. I'm going to close but we could always reopen. If it reoccurs we might simply need to pursue a configurable timeout in lsp4e (or possibly WWD if it turns out that's involved). Though it'd be nice to have a bit more of a fine-grained view of where the time is being spent...possibly there is something in the LCLS lemminx ext. that could be tuned somehow?

rumanaHaque commented 9 months ago

As mentioned in the slack channel, I was unable to recreate this defect (using the same app in the same machine) - while using this driver - 23.0.12.202311151445.zip. I had been able to consistently recreate this defect earlier, using the prev builds. Since I cannot recreate using latest driver, agree this should be closed for now.

OpenLiberty / liberty-tools-eclipse