search

softwareCobbler / luceedebug

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

Debugger failed to attach: handshake failed #29

Open isapir opened 1 year ago

isapir commented 1 year ago

When I click the "Start Debugging (F5)" button it tries to connect and then I see an error in the Lucee console:

Debugger failed to attach: handshake failed - received >Content-Length< - expected >JDWP-Handshake<

softwareCobbler commented 1 year ago

This looks sort of like the VS Code java debug plugin reporting that it cannot connect to luceedebug, which suggests the active launch config is for java.

Can you confirm that the active debug launch config is roughly like the following?

{
    "type": "cfml",
    "request": "attach",
    "name": "Attach to Lucee",
    "hostName": "localhost",
    "pathTransforms": [],
    "port": 10000
}
isapir commented 1 year ago

Here's my launch.json:

{
    // Use IntelliSense to learn about possible attributes.
    // Hover to view descriptions of existing attributes.
    // For more information, visit: https://go.microsoft.com/fwlink/?linkid=830387
    "version": "0.2.0",
    "configurations": [
        {
            "type": "cfml",
            "request": "attach",
            "name": "Attach to server",
            "hostName": "localhost",
            "pathTransforms": [
                {
                    "idePrefix": "${workspaceFolder}",
                    "serverPrefix": "/workspace/test/lucee-express-5.4.0.23-SNAPSHOT/webapps/ROOT"
                }
            ],
            "port": 9999
        }
    ]
}
softwareCobbler commented 1 year ago

Depending on the agent args string, it might be that 9999 is the port the agent was configured with to accept jdwp connections, and 10000 (or some other) is the one configured to accept IDE connections (hence 9999 reports that it was expecting a jdwp handshake).

isapir commented 1 year ago

These are the Agent settings: 

CATALINA_OPTS=-agentlib:jdwp=transport=dt_socket,server=y,suspend=n,address=127.0.0.1:9999
CATALINA_OPTS=${CATALINA_OPTS} -javaagent:/workspace/test/lucee-express-5.4.0.23-SNAPSHOT/lib/ext/luceedebug.jar=jdwpHost=127.0.0.1,jdwpPort=9999,debugHost=0.0.0.0,debugPort=10000,jarPath=/workspace/test/lucee-express-5.4.0.23-SNAPSHOT/lib/ext/luceedebug.jar
isapir commented 1 year ago

When I try port 10000 I get Connection Refused: image

jamiejackson commented 1 year ago

Is the debug port open? For me, with a good agent config, I get:

$ nmap 127.0.0.1 -p 10000
...
PORT      STATE SERVICE
10000/tcp open  snet-sensor-mgmt

Also, since it could be relevant, I want to make sure you're using a fresh copy of master (since the need for app "priming" was made unnecessary for connection). Before that change (on 12/20), the connection procedure could be confusing.

Additionally, you haven't been able to connect, so this part won't matter yet, but I think that with most local connections (where there are no VMs or containers involved), one doesn't need pathTransforms in the VS Code configuration. (Assuming that is indeed true, @softwareCobbler , I'll document it.)

softwareCobbler commented 1 year ago

Hm, I'm not sure how our setups differ. Here's output from starting up Lucee express on windows 10, 5.4.0.23-SNAPSHOT. Of interest is that it indicates it succesfully connected to jdwp and eventually is "listening for inbound debugger connection on ..."

D:\lucee-express\lucee-express-5.4.0.23-SNAPSHOT\bin>catalina run
Using CATALINA_BASE:   "D:\lucee-express\lucee-express-5.4.0.23-SNAPSHOT"
Using CATALINA_HOME:   "D:\lucee-express\lucee-express-5.4.0.23-SNAPSHOT"
Using CATALINA_TMPDIR: "D:\lucee-express\lucee-express-5.4.0.23-SNAPSHOT\temp"
Using JRE_HOME:        "C:\Program Files\Java\jdk-11.0.2"
Using CLASSPATH:       "D:\lucee-express\lucee-express-5.4.0.23-SNAPSHOT\bin\bootstrap.jar;D:\lucee-express\lucee-express-5.4.0.23-SNAPSHOT\bin\tomcat-juli.jar"
NOTE: Picked up JDK_JAVA_OPTIONS:  --add-opens=java.base/java.lang=ALL-UNNAMED --add-opens=java.base/java.io=ALL-UNNAMED --add-opens=java.rmi/sun.rmi.transport=ALL-UNNAMED
Listening for transport dt_socket at address: 9999
[luceedebug] fs is case sensitive: false
[luceedebug] agent premain complete
29-Dec-2022 21:02:42.344 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server version:        Apache Tomcat/9.0.11
29-Dec-2022 21:02:42.347 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server built:          Aug 11 2018 19:47:23 UTC
29-Dec-2022 21:02:42.347 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server number:         9.0.11.0
29-Dec-2022 21:02:42.347 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Name:               Windows 10
29-Dec-2022 21:02:42.347 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Version:            10.0
29-Dec-2022 21:02:42.347 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Architecture:          amd64
29-Dec-2022 21:02:42.348 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Java Home:             C:\Program Files\Java\jdk-11.0.2
29-Dec-2022 21:02:42.348 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Version:           11.0.2+9-LTS
29-Dec-2022 21:02:42.348 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Vendor:            Oracle Corporation
29-Dec-2022 21:02:42.348 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_BASE:         D:\lucee-express\lucee-express-5.4.0.23-SNAPSHOT
29-Dec-2022 21:02:42.348 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_HOME:         D:\lucee-express\lucee-express-5.4.0.23-SNAPSHOT
29-Dec-2022 21:02:42.349 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: --add-opens=java.base/java.lang=ALL-UNNAMED
29-Dec-2022 21:02:42.349 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: --add-opens=java.base/java.io=ALL-UNNAMED
29-Dec-2022 21:02:42.349 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: --add-opens=java.rmi/sun.rmi.transport=ALL-UNNAMED
29-Dec-2022 21:02:42.349 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.config.file=D:\lucee-express\lucee-express-5.4.0.23-SNAPSHOT\conf\logging.properties
29-Dec-2022 21:02:42.349 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
29-Dec-2022 21:02:42.349 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djdk.tls.ephemeralDHKeySize=2048
29-Dec-2022 21:02:42.350 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.protocol.handler.pkgs=org.apache.catalina.webresources
29-Dec-2022 21:02:42.350 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -agentlib:jdwp=transport=dt_socket,server=y,suspend=n,address=localhost:9999
29-Dec-2022 21:02:42.350 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -javaagent:c:\Users\anon\dev\luceedebug\java-agent\luceedebug\build\libs\luceedebug.jar=jdwpHost=localhost,jdwpPort=9999,debugHost=0.0.0.0,debugPort=10000,jarPath=c:\Users\anon\dev\luceedebug\java-agent\luceedebug\build\libs\luceedebug.jar
29-Dec-2022 21:02:42.350 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dignore.endorsed.dirs=
29-Dec-2022 21:02:42.350 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.base=D:\lucee-express\lucee-express-5.4.0.23-SNAPSHOT
29-Dec-2022 21:02:42.350 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.home=D:\lucee-express\lucee-express-5.4.0.23-SNAPSHOT
29-Dec-2022 21:02:42.350 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.io.tmpdir=D:\lucee-express\lucee-express-5.4.0.23-SNAPSHOT\temp
29-Dec-2022 21:02:42.351 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent The APR based Apache Tomcat Native library which allows optimal performance in production environments was not found on the java.library.path: [C:\Program Files\Java\jdk-11.0.2\bin;C:\WINDOWS\Sun\Java\bin;C:\WINDOWS\system32;C:\WINDOWS;C:\Program Files\NVIDIA GPU Computing Toolkit\CUDA\v11.2\bin;C:\Program Files\NVIDIA GPU Computing Toolkit\CUDA\v11.2\libnvvp;C:\Program Files\Haskell\bin;C:\Program Files\Haskell Platform\8.6.5\lib\extralibs\bin;C:\Program Files\Haskell Platform\8.6.5\bin;C:\Windows\system32;C:\Windows;C:\Windows\System32\Wbem;C:\Windows\System32\WindowsPowerShell\v1.0\;C:\Windows\System32\OpenSSH\;C:\Program Files (x86)\NVIDIA Corporation\PhysX\Common;C:\GTK\bin;C:\Program Files\Java\jdk-17.0.1\bin;C:\Program Files\Java\jdk-11.0.2\bin;C:\Program Files\Java\jdk1.8.0_231\bin;C:\Program Files\Java\jdk1.8.0_201\bin;C:\Program Files\Java\jdk-9\bin;E:\DEV\apache-ant-1.10.5\bin;E:\DEV\apache-maven-3.6.0\bin;C:\Program Files (x86)\Microsoft Visual Studio\2019\Community\VC\Tools\MSVC\14.27.29110\bin\Hostx64\x64;E:\DEV\opencv\dlls_410;C:\Program Files\dotnet\;c:\flutter\bin\;C:\Users\anon\AppData\Local\Android\Sdk\platform-tools;C:\WINDOWS\system32;C:\WINDOWS;C:\WINDOWS\System32\Wbem;C:\WINDOWS\System32\WindowsPowerShell\v1.0\;C:\WINDOWS\System32\OpenSSH\;C:\Program Files\Haskell Platform\8.6.5\mingw\bin;C:\Program Files\Microsoft SQL Server\Client SDK\ODBC\170\Tools\Binn\;C:\Program Files (x86)\Microsoft SQL Server\150\Tools\Binn\;C:\Program Files\Microsoft SQL Server\150\Tools\Binn\;C:\Program Files\Microsoft SQL Server\150\DTS\Binn\;C:\Program Files (x86)\Microsoft SQL Server\150\DTS\Binn\;C:\Program Files\NVIDIA Corporation\Nsight Compute 2020.3.0\;C:\Program Files\NVIDIA Corporation\NVIDIA NvDLISR;C:\Program Files\nodejs\;C:\Program Files (x86)\Windows Kits\10\Windows Performance Toolkit\;C:\Program Files\PuTTY\;C:\Program Files\Git\cmd;C:\Program Files\Git\mingw64\bin;C:\Program Files\Git\usr\bin;C:\Program Files\Docker\Docker\resources\bin;C:\ProgramData\DockerDesktop\version-bin;C:\Users\anon\AppData\Local\Programs\Python\Python39\Scripts\;C:\Users\anon\dev\git-forks\depot_tools;C:\Users\anon\AppData\Local\Programs\Python\Python39\;C:\Users\anon\AppData\Local\Programs\Python\Launcher\;C:\Users\anon\AppData\Roaming\cabal\bin;C:\Users\anon\AppData\Roaming\local\bin;C:\Users\anon\.cargo\bin;C:\Users\anon\AppData\Roaming\Python\Python37\Scripts;C:\Users\anon\AppData\Local\Programs\Python\Python37\Scripts\;C:\Users\anon\AppData\Local\Programs\Python\Python37\;C:\Python27\;C:\Users\anon\AppData\Local\Programs\Microsoft VS Code\bin;c:\users\anon\appdata\local\bin;C:\Program Files\CMake\bin;C:\Users\anon\dev\git-forks\opencv\build\bin\Debug;E:\DEV\opencv\dlls_410;C:\Program Files (x86)\Graphviz2.38\bin;C:\Users\anon\AppData\Local\Programs\MiKTeX 2.9\miktex\bin\x64\;C:\ffmpeg\ffmpeg-4.2.3-win64-static\bin;C:\Users\anon\.dotnet\tools;c:\users\anon\bin;C:\Program Files (x86)\Microsoft Visual Studio\2019\Community\VC\Auxiliary\Build;C:\Octave\Octave-5.2.0\mingw64\bin;C:\Users\anon\AppData\Roaming\npm;D:\DEV\apache-maven-3.8.3\bin;D:\DEV\apache-ant-1.10.12\bin;C:\Users\anon\.dotnet\tools;C:\Users\anon\AppData\Local\Programs\Azure Data Studio\bin;d:\dev\gradle-7.3\bin\;;C:\ghcup\bin;.]
29-Dec-2022 21:02:42.376 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["http-nio-8888"]
29-Dec-2022 21:02:42.713 INFO [main] org.apache.tomcat.util.net.NioSelectorPool.getSharedSelector Using a shared selector for servlet write/read
29-Dec-2022 21:02:42.717 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["ajp-nio-8009"]
29-Dec-2022 21:02:42.719 INFO [main] org.apache.tomcat.util.net.NioSelectorPool.getSharedSelector Using a shared selector for servlet write/read
29-Dec-2022 21:02:42.719 INFO [main] org.apache.catalina.startup.Catalina.load Initialization processed in 650 ms
29-Dec-2022 21:02:42.752 INFO [main] org.apache.catalina.core.StandardService.startInternal Starting service [Catalina]
29-Dec-2022 21:02:42.752 INFO [main] org.apache.catalina.core.StandardEngine.startInternal Starting Servlet Engine: Apache Tomcat/9.0.11
29-Dec-2022 21:02:42.757 INFO [main] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory [D:\lucee-express\lucee-express-5.4.0.23-SNAPSHOT\webapps\ROOT]
29-Dec-2022 21:02:43.072 INFO [main] org.apache.jasper.servlet.TldScanner.scanJars At least one JAR was scanned for TLDs yet contained no TLDs. Enable debug logging for this logger for a complete list of JARs that were scanned but no TLDs were found in them. Skipping unneeded JARs during scanning can improve startup time and JSP compilation time.
29-Dec-2022 21:02:43.411 WARNING [main] org.apache.catalina.util.SessionIdGeneratorBase.createSecureRandom Creation of SecureRandom instance for session ID generation using [SHA1PRNG] took [324] milliseconds.
WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by org.apache.felix.framework.ext.ClassPathExtenderFactory$DefaultClassLoaderExtender (file:/D:/lucee-express/lucee-express-5.4.0.23-SNAPSHOT/lib/ext/lucee.jar) to method java.net.URLClassLoader.addURL(java.net.URL)
WARNING: Please consider reporting this to the maintainers of org.apache.felix.framework.ext.ClassPathExtenderFactory$DefaultClassLoaderExtender
WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
WARNING: All illegal access operations will be denied in a future release
[luceedebug] Loaded luceedebug.coreinject.DebugManager@77f905e3 with ClassLoader 'lucee.core [49]'
[luceedebug] instrumented PageContextImpl <clinit> called spawnWorker...
[luceedebug] attempting jdwp self connect to jdwp on localhost:9999...
[luceedebug] jdwp self connect OK
[luceedebug] binding cf dap server socket on 0.0.0.0:10000
[luceedebug] dap server socket bind OK
[luceedebug] listening for inbound debugger connection on 0.0.0.0:10000...
[luceedebug] Instrumenting ajaximport_cfc$cf
[luceedebug] Instrumenting lucee/core/ajax/ajaxbase_cfc$cf
[luceedebug] Instrumenting component_cfc$cf
[luceedebug] Instrumenting mediaplayer_cfc$cf
[luceedebug] Instrumenting map_cfc$cf
...snip...

It's indicating there's a thread waiting for an inbound debugger connection. Connecting from the ide we can break in the Lucee splash index.cfm:

image