search

softwareCobbler / luceedebug

line debugger for lucee
GNU Lesser General Public License v2.1
44 stars 15 forks source link

fallbackResponseError - java.lang.reflect.InvocationTargetException #50

Closed zspitzer closed 2 months ago

zspitzer commented 3 months ago

Similar to this issue, connecting to a Docker container runing Ubuntu, Preside / Undertow, MacOS host, using agent/2.0.10

https://github.com/softwareCobbler/luceedebug/issues/40

2024-06-05 14:01:52 Jun 05, 2024 1:01:52 PM luceedebug_shadow.org.eclipse.lsp4j.jsonrpc.RemoteEndpoint fallbackResponseError
2024-06-05 14:01:52 SEVERE: Internal error: java.lang.reflect.InvocationTargetException
2024-06-05 14:01:52 java.lang.RuntimeException: java.lang.reflect.InvocationTargetException
2024-06-05 14:01:52     at luceedebug_shadow.org.eclipse.lsp4j.jsonrpc.services.GenericEndpoint.lambda$null$0(GenericEndpoint.java:67)
2024-06-05 14:01:52     at luceedebug_shadow.org.eclipse.lsp4j.jsonrpc.services.GenericEndpoint.request(GenericEndpoint.java:120)
2024-06-05 14:01:52     at luceedebug_shadow.org.eclipse.lsp4j.jsonrpc.RemoteEndpoint.handleRequest(RemoteEndpoint.java:261)
2024-06-05 14:01:52     at luceedebug_shadow.org.eclipse.lsp4j.jsonrpc.RemoteEndpoint.consume(RemoteEndpoint.java:190)
2024-06-05 14:01:52     at luceedebug_shadow.org.eclipse.lsp4j.jsonrpc.json.StreamMessageProducer.handleMessage(StreamMessageProducer.java:194)
2024-06-05 14:01:52     at luceedebug_shadow.org.eclipse.lsp4j.jsonrpc.json.StreamMessageProducer.listen(StreamMessageProducer.java:94)
2024-06-05 14:01:52     at luceedebug_shadow.org.eclipse.lsp4j.jsonrpc.json.ConcurrentMessageProcessor.run(ConcurrentMessageProcessor.java:113)
2024-06-05 14:01:52     at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
2024-06-05 14:01:52     at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
2024-06-05 14:01:52     at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
2024-06-05 14:01:52     at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
2024-06-05 14:01:52     at java.base/java.lang.Thread.run(Thread.java:829)
2024-06-05 14:01:52 Caused by: java.lang.reflect.InvocationTargetException
2024-06-05 14:01:52     at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
2024-06-05 14:01:52     at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
2024-06-05 14:01:52     at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
2024-06-05 14:01:52     at java.base/java.lang.reflect.Method.invoke(Method.java:566)
2024-06-05 14:01:52     at luceedebug_shadow.org.eclipse.lsp4j.jsonrpc.services.GenericEndpoint.lambda$null$0(GenericEndpoint.java:65)
2024-06-05 14:01:52     ... 11 more
2024-06-05 14:01:52 Caused by: java.lang.UnsupportedOperationException
2024-06-05 14:01:52     at luceedebug_shadow.org.eclipse.lsp4j.debug.services.IDebugProtocolServer.source(IDebugProtocolServer.java:549)
2024-06-05 14:01:52     ... 16 more
2024-06-05 14:01:52
zspitzer commented 3 months ago

https://github.com/eclipse-lsp4j/lsp4j/blob/main/org.eclipse.lsp4j.jsonrpc/src/main/java/org/eclipse/lsp4j/jsonrpc/services/GenericEndpoint.java#L67

zspitzer commented 3 months ago

@softwareCobbler looks like there's been some updates to lsp4j, latest version is 0.23.1 but there are some breaking changes https://github.com/eclipse-lsp4j/lsp4j/blob/main/CHANGELOG.md

https://github.com/zspitzer/luceedebug/actions/runs/9384040059/job/25838983670#step:6:44

softwareCobbler commented 3 months ago

Thanks, very minor breakage in the lsp4j update, I've patched them up in a recent commit.

Does it say which operation it was failing on? I don't see it in the stack trace. I thought we gracefully handled "unsupported" ops (well, I thought lsp4j just silently discarded ones we didn't register handlers for and/or didn't mark supported in the initial handshake), but I guess not.

Curious if you were connecting with vscode and what version, or maybe some other IDE with DAP capabilities?

zspitzer commented 3 months ago

Using the latest version of VSCode, the May 2024 update, the error occurs after run start debugging, after which trying to set a break point simply won't set, it adds a listing to the breakpoints, but won't enable

I just tried the latest artifact from the github actions here, https://github.com/softwareCobbler/luceedebug/actions/runs/9391885099

slightly different stack trace, but no more clues

2024-06-06 10:43:11 Jun 06, 2024 9:43:11 AM luceedebug_shadow.org.eclipse.lsp4j.jsonrpc.RemoteEndpoint fallbackResponseError
2024-06-06 10:43:11 SEVERE: Internal error: null
2024-06-06 10:43:11 java.lang.UnsupportedOperationException
2024-06-06 10:43:11     at luceedebug_shadow.org.eclipse.lsp4j.debug.services.IDebugProtocolServer.source(IDebugProtocolServer.java:549)
2024-06-06 10:43:11     at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
2024-06-06 10:43:11     at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
2024-06-06 10:43:11     at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
2024-06-06 10:43:11     at java.base/java.lang.reflect.Method.invoke(Method.java:566)
2024-06-06 10:43:11     at luceedebug_shadow.org.eclipse.lsp4j.jsonrpc.services.GenericEndpoint.lambda$recursiveFindRpcMethods$0(GenericEndpoint.java:65)
2024-06-06 10:43:11     at luceedebug_shadow.org.eclipse.lsp4j.jsonrpc.services.GenericEndpoint.request(GenericEndpoint.java:128)
2024-06-06 10:43:11     at luceedebug_shadow.org.eclipse.lsp4j.jsonrpc.RemoteEndpoint.handleRequest(RemoteEndpoint.java:271)
2024-06-06 10:43:11     at luceedebug_shadow.org.eclipse.lsp4j.jsonrpc.RemoteEndpoint.consume(RemoteEndpoint.java:201)
2024-06-06 10:43:11     at luceedebug_shadow.org.eclipse.lsp4j.jsonrpc.json.StreamMessageProducer.handleMessage(StreamMessageProducer.java:185)
2024-06-06 10:43:11     at luceedebug_shadow.org.eclipse.lsp4j.jsonrpc.json.StreamMessageProducer.listen(StreamMessageProducer.java:97)
2024-06-06 10:43:11     at luceedebug_shadow.org.eclipse.lsp4j.jsonrpc.json.ConcurrentMessageProcessor.run(ConcurrentMessageProcessor.java:114)
2024-06-06 10:43:11     at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
2024-06-06 10:43:11     at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
2024-06-06 10:43:11     at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
2024-06-06 10:43:11     at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
2024-06-06 10:43:11     at java.base/java.lang.Thread.run(Thread.java:829)
softwareCobbler commented 3 months ago

I think I see that your IDE is making a "source" request, where that is unimplemented and defaults to throwing UnsupportedOperationException. The spec doesn't say it is an optional method ... so I've implemented it to return an error instead of throwing an exception, maybe that solves it?

zspitzer commented 3 months ago

So, we are making progress, it no longer throws an exception!

but I can't set breakpoints, they are listed as unbound when I list the class and breakpoint info

update: played around a bit, I tried adding "autoAttachChildProcesses": true, to my vscode debug configuration

What i did see was when stopping the debugger tho was the following

2024-06-07 11:50:41 Jun 07, 2024 10:50:41 AM luceedebug_shadow.org.eclipse.lsp4j.jsonrpc.json.StreamMessageProducer fireError
2024-06-07 11:50:41 SEVERE: Missing header Content-Length in input "GET / HTTP/1.1
2024-06-07 11:50:41 Host: localhost:10000
2024-06-07 11:50:41 Connection: keep-alive
2024-06-07 11:50:41 sec-ch-ua: "Google Chrome";v="125", "Chromium";v="125", "Not.A/Brand";v="24"
2024-06-07 11:50:41 sec-ch-ua-mobile: ?0
2024-06-07 11:50:41 sec-ch-ua-platform: "macOS"
2024-06-07 11:50:41 Upgrade-Insecure-Requests: 1
2024-06-07 11:50:41 User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/125.0.0.0 Safari/537.36
2024-06-07 11:50:41 Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.7
2024-06-07 11:50:41 Sec-Fetch-Site: none
2024-06-07 11:50:41 Sec-Fetch-Mode: navigate
2024-06-07 11:50:41 Sec-Fetch-User: ?1
2024-06-07 11:50:41 Sec-Fetch-Dest: document
2024-06-07 11:50:41 Accept-Encoding: gzip, deflate, br, zstd
2024-06-07 11:50:41 Accept-Language: en-GB,en-US;q=0.9,en;q=0.8
2024-06-07 11:50:41 
2024-06-07 11:50:41 "
2024-06-07 11:50:41 java.lang.IllegalStateException: Missing header Content-Length in input "GET / HTTP/1.1
2024-06-07 11:50:41 Host: localhost:10000
2024-06-07 11:50:41 Connection: keep-alive
2024-06-07 11:50:41 sec-ch-ua: "Google Chrome";v="125", "Chromium";v="125", "Not.A/Brand";v="24"
2024-06-07 11:50:41 sec-ch-ua-mobile: ?0
2024-06-07 11:50:41 sec-ch-ua-platform: "macOS"
2024-06-07 11:50:41 Upgrade-Insecure-Requests: 1
2024-06-07 11:50:41 User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/125.0.0.0 Safari/537.36
2024-06-07 11:50:41 Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.7
2024-06-07 11:50:41 Sec-Fetch-Site: none
2024-06-07 11:50:41 Sec-Fetch-Mode: navigate
2024-06-07 11:50:41 Sec-Fetch-User: ?1
2024-06-07 11:50:41 Sec-Fetch-Dest: document
2024-06-07 11:50:41 Accept-Encoding: gzip, deflate, br, zstd
2024-06-07 11:50:41 Accept-Language: en-GB,en-US;q=0.9,en;q=0.8
2024-06-07 11:50:41 
2024-06-07 11:50:41 "
2024-06-07 11:50:41     at luceedebug_shadow.org.eclipse.lsp4j.jsonrpc.json.StreamMessageProducer.listen(StreamMessageProducer.java:94)
2024-06-07 11:50:41     at luceedebug_shadow.org.eclipse.lsp4j.jsonrpc.json.ConcurrentMessageProcessor.run(ConcurrentMessageProcessor.java:114)
2024-06-07 11:50:41     at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
2024-06-07 11:50:41     at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
2024-06-07 11:50:41     at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
2024-06-07 11:50:41     at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
2024-06-07 11:50:41     at java.base/java.lang.Thread.run(Thread.java:829)
2024-06-07 11:50:41

https://github.com/eclipse-lsp4j/lsp4j/blob/main/org.eclipse.lsp4j.jsonrpc/src/main/java/org/eclipse/lsp4j/jsonrpc/json/StreamMessageProducer.java#L94

softwareCobbler commented 3 months ago

Those request headers look like a browser is trying to connect to the debugger; I can reproduce that particular error if I try to hit localhost:<debugger-port> from Chrome. You might have configured the debugger port to accidentally overlap with ports your app wants to use. Only a DAP client (i.e. vscode) should connect to the debugger port.

fwiw, "autoAttachChildProcesses" is not a recognized option and will have no effect. When editing a launch.json file, vscode should issue a warning on that property because it is not part of the declared json schema for a "cfml" debug configuration.

zspitzer commented 3 months ago

Ok let's not worry about that error, not being able to set breakpoints is the issue, I did open the 10000 port at one point in my browser

My config is correct, as I can dump out the json config (right?) any tips on raising log levels or other debugging approaches?

softwareCobbler commented 3 months ago

On the "debug class and breakpoint info", are the files listed as files Lucee knows about? Breakpoints can't be bound on files that haven't been turned into classfiles (but unbound breakpoints will be bound during classloading, i.e. once you hit page.cfm then breakpoints in that file and any files it loads should start binding). An additional constraint is that breakpoints cannot be set on the non-code textblock portions of .cfm files, since there's no code to stop on.

zspitzer commented 3 months ago

yeah, all the files listed and paths look 100%, I even see some lucee context files, so that indicates it's coming from Lucee, right?

But the break points are listed as (unbound) both for server and client

softwareCobbler commented 3 months ago

Can you paste the full output of the "debug class and breakpoint info"?

Barring any oddities there, I'll need some kind of self contained docker repro case or something to debug this.

zspitzer commented 3 months ago

here the output, trimmed down, i have confirmed the paths exist

Breakpoints luceedebug has:
  (ide)    /Users/zac/work/pixl8/clients/project/website/application/views/page-types/submission_event_listing/_popularFilters.cfm:11 (unbound)
  (server) /var/www/website/application/views/page-types/submission_event_listing/_popularFilters.cfm:11 (unbound)

  (ide)    /Users/zac/work/pixl8/clients/project/website/application/views/page-types/submission_event_listing/_popularFilters.cfm:12 (unbound)
  (server) /var/www/website/application/views/page-types/submission_event_listing/_popularFilters.cfm:12 (unbound)

  (ide)    /Users/zac/work/pixl8/clients/project/website/application/views/page-types/submission_event_listing/_popularFilters.cfm:13 (unbound)
  (server) /var/www/website/application/views/page-types/submission_event_listing/_popularFilters.cfm:13 (unbound)

  (ide)    /Users/zac/work/pixl8/clients/project/website/application/views/page-types/submission_event_listing/_popularFilters.cfm:17 (unbound)
  (server) /var/www/website/application/views/page-types/submission_event_listing/_popularFilters.cfm:17 (unbound)

Path transforms:
  PrefixPathTransform{idePrefix='/Users/zac/work/pixl8/clients/project', serverPrefix='/var/www'}

Files luceedebug knows about (all filenames are as the server sees them, and match against breakpoint 'server' paths):
  /opt/lucee/conf/lucee-server/context/library/function/throw.cfm
  /opt/lucee/conf/lucee-server/context/library/tag/Dump.cfc
  /opt/lucee/conf/lucee-server/context/library/tag/MediaPlayer.cfc
  /opt/lucee/conf/lucee-web/components/org/lucee/cfml/HelperBase.cfc
  /opt/lucee/conf/lucee-web/components/org/lucee/cfml/Http.cfc
  /opt/lucee/conf/lucee-web/components/org/lucee/cfml/Query.cfc
  /opt/lucee/conf/lucee-web/components/org/lucee/cfml/Result.cfc
  /opt/lucee/conf/lucee-web/context/Component.cfc
  /var/www/Application.cfc
  /var/www/application/base/Lookup.cfc
  /var/www/application/config/Cachebox.cfc
  /var/www/application/config/Config.cfc
  /var/www/application/config/RmMissionControlConfig.cfc
  /var/www/application/config/Routes.cfm
  /var/www/application/views/page-types/submission_event_listing/_popularFilters.cfm

  CIPage.java
  ComponentPage.java
  ComponentPageImpl.java
  InterfacePage.java
  InterfacePageImpl.java
  PageImpl.java
softwareCobbler commented 3 months ago

I think your path transform should be: idePrefix='/Users/zac/work/pixl8/clients/project/website', serverPrefix='/var/www'

Because:

/Users/zac/work/pixl8/clients/project/website/application/views/page-types/submission_event_listing/_popularFilters.cfm

becomes, by the current transform {idePrefix='/Users/zac/work/pixl8/clients/project', serverPrefix='/var/www'}:

/var/www/website/application/views/page-types/submission_event_listing/_popularFilters.cfm

But Lucee only knows about:

/var/www/application/views/page-types/submission_event_listing/_popularFilters.cfm

If transform was {idePrefix='/Users/zac/work/pixl8/clients/project/website', serverPrefix='/var/www'}, then we'd get:

/var/www/application/views/page-types/submission_event_listing/_popularFilters.cfm

which matches a file Lucee knows about.

Visually lining them up:

/Users/zac/work/pixl8/clients/project/website/application/views/page-types/submission_event_listing/_popularFilters.cfm
                                     /var/www/application/views/page-types/submission_event_listing/_popularFilters.cfm
zspitzer commented 3 months ago

Boom and doh, thanks for all your help and patience with me on this!

Is it possible maybe to add a sanity check for silly mistakes made like that?

Also you able to publish that new release?

softwareCobbler commented 3 months ago

Not sure what we could do for "typos" like that, maybe some kind of Levenshtein distance thing, and surface it near the unbound lines ... like "this breakpoint is unbound but maybe you meant \<some path we do know about>".

jamiejackson commented 3 months ago

It seems hard to justify, going through extra lengths to help with those mapping issues, unless one of those distance algorithms is straightforward to implement.

One easy-ish thing that might help:

Near the top of the debug report, it could list directories for the serverPrefix and idePrefix pairs and say something like, "if you're having trouble mapping or resolving breakpoints, compare these directory listings to make sure their contents correspond as intended."

Early on in this ticket I was tempted to ask @zspitzer to pick any given cfm file and show us the actual server path and the actual IDE path.

Info like my workaround could help shed that kind of light.

zspitzer commented 2 months ago

let's close this ticket as the core issue has been resolved