search

softwareCobbler / luceedebug

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

Trouble Connecting to Debugger (Insists on Using localhost?) #10

Closed jamiejackson closed 1 year ago

jamiejackson commented 1 year ago

I installed the extension via the Marketplace. :-)

However, I'm getting the following. It seems like it's trying localhost, instead of the host I supplied.

image 
{
    // 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-debugger",
    //         "request": "launch",
    //         "name": "CFML Debug",
    //         "program": "${workspaceFolder}/${command:AskForProgramName}",
    //         "globalConfigFilePath": "${command:globalConfigFilePath}",
    //         "project": "${command:AskForProject}",
    //         "stopOnEntry": false,
    //         "windows": {
    //             "program": "${workspaceFolder}\\${command:AskForProgramName}"
    //         }
    //     }

    {
        "type": "cfml",
        "request": "attach",
        "name": "Project A",
        "hostName": "local.hudx.net",
        "port": 10000,
        "pathTransform": { // optional
            "idePrefix": "${workspaceFolder}/cfml/deployment_root",
            "cfPrefix": "/app/www/"
        }
    }
    ]

}

As a sanity check, I then changed the port (to 10001), which is reflected in the popup:

image
softwareCobbler commented 1 year ago

Fixed in 2.0.1, should be available in next few minutes (if you look at the extension via the sidebar it will eventually say something like "restart vscode to install latest version")

jamiejackson commented 1 year ago

That worked, thanks. However, I still can't connect:

image

My config:

-agentlib:jdwp=transport=dt_socket,server=y,suspend=n,address=localhost:9999
-javaagent:/app/lib/luceedebug/luceedebug.jar=jdwpHost=localhost,jdwpPort=9999,cfHost=0.0.0.0,cfPort=10000,jarPath=/app/lib/luceedebug/luceedebug.jar

I have tried with cfHost as 0.0.0.0 and localhost.

Do you spot anything wrong with my configuration or do you have any tips for how to debug the connection?

I'd like to verify that it's actually listening at 10000 but I don't know how to check for signs of life.

Should nmap give me anything useful?

% nmap local.hudx.net -p 443,10000
Starting Nmap 7.92 ( https://nmap.org ) at 2022-12-11 14:45 EST
Nmap scan report for local.hudx.net (192.168.56.10)
Host is up (0.013s latency).

PORT      STATE  SERVICE
443/tcp   open   https
10000/tcp closed snet-sensor-mgmt

The only debug-related port that I'm publishing outside of the container is 10000. The jdwp stuff: That's all internal to the container, right? I don't need to publish that port?

softwareCobbler commented 1 year ago

The jdwp stuff is internal to the container, that's right.

The "closed" state in the nmap output suggests the container is not binding the desired port.

In my case I have a docker compose file like

services:
  ...
  ports:
    - 10000 : 10000 # bind host machine port to container port

With that config, running your nmap command gives port 10000 state: open; but if I comment that port config line out, I get state: closed (and get the ECONNREFUSED errors)

jamiejackson commented 1 year ago

Unfortunately, I'm already publishing 10000 in the same way.

$ docker service list | grep hudx_local_lucee
rojbbg7pu2ll   hudx_local_lucee                      replicated   1/1        main-stack/lucee:local_20221211.122927                      *:8088->8088/tcp, *:8888->8888/tcp, *:10000->10000/tcp

Even inside of the container it doesn't seem to be available:

root@0e489040e225:/usr/local/tomcat# nmap localhost -p 10000,8888,9999
Starting Nmap 7.70 ( https://nmap.org ) at 2022-12-11 14:37 CST
Nmap scan report for localhost (127.0.0.1)
Host is up (0.000049s latency).
Other addresses for localhost (not scanned): ::1

PORT      STATE  SERVICE
8888/tcp  open   sun-answerbook
9999/tcp  open   abyss
10000/tcp closed snet-sensor-mgmt

Nmap done: 1 IP address (1 host up) scanned in 0.29 seconds
softwareCobbler commented 1 year ago

Hm, an unfortunate case of "works on my machine". Not sure what a good next trouble shooting step would be.

All the network stuff gets booted up here, maybe strategic placement of println could be helpful. https://github.com/softwareCobbler/luceedebug/blob/6d2c3f3533f1a379133f19a67b66039d97221cbb/luceedebug/src/main/java/luceedebug/coreinject/DebugManager.java#L31

softwareCobbler commented 1 year ago

Added some trace output, there should be the following now after Lucee boots up. Any failures during this initialization step should kill the server, but maybe there's a hung thread or something.

[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...
jamiejackson commented 1 year ago

Now I can see cfHost:cfPort ~"filtered,"~ (in later tests it was "open" so let's ignore the filtered mention) which is a good sign. However, the debugger still can't connect.

I hadn't checked the JDWP port before but I see that it's closed (this is inside the container):

$ docker exec -it $(get_a_container_id_from_service.sh hudx_local_lucee) nmap localhost -p 8888,9999,10000
Starting Nmap 7.70 ( https://nmap.org ) at 2022-12-12 10:10 CST
Nmap scan report for localhost (127.0.0.1)
Host is up (0.000042s latency).
Other addresses for localhost (not scanned): ::1

PORT      STATE  SERVICE
8888/tcp  open   sun-answerbook
9999/tcp  closed abyss
10000/tcp open   snet-sensor-mgmt

Nmap done: 1 IP address (1 host up) scanned in 0.29 seconds

Is that to be expected or is that a potential clue?

Here are the startup logs, by the way:

Using CATALINA_BASE:   /usr/local/tomcat
Using CATALINA_HOME:   /usr/local/tomcat
Using CATALINA_TMPDIR: /usr/local/tomcat/temp
Using JRE_HOME:        /usr/local/openjdk-11
Using CLASSPATH:       /usr/local/tomcat/bin/bootstrap.jar:/usr/local/tomcat/bin/tomcat-juli.jar
Using CATALINA_OPTS:
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] agent premain complete
12-Dec-2022 10:05:46.980 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server version name:   Apache Tomcat/9.0.39
12-Dec-2022 10:05:46.988 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server built:          Oct 6 2020 14:11:46 UTC
12-Dec-2022 10:05:46.989 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server version number: 9.0.39.0
12-Dec-2022 10:05:46.990 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Name:               Linux
12-Dec-2022 10:05:46.990 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Version:            4.15.0-200-generic
12-Dec-2022 10:05:46.992 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Architecture:          amd64
12-Dec-2022 10:05:46.992 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Java Home:             /usr/local/openjdk-11
12-Dec-2022 10:05:46.993 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Version:           11.0.9+11
12-Dec-2022 10:05:46.995 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Vendor:            Oracle Corporation
12-Dec-2022 10:05:46.995 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_BASE:         /usr/local/tomcat
12-Dec-2022 10:05:46.996 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_HOME:         /usr/local/tomcat
12-Dec-2022 10:05:47.032 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: --add-opens=java.base/java.lang=ALL-UNNAMED
12-Dec-2022 10:05:47.033 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: --add-opens=java.base/java.io=ALL-UNNAMED
12-Dec-2022 10:05:47.033 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: --add-opens=java.rmi/sun.rmi.transport=ALL-UNNAMED
12-Dec-2022 10:05:47.033 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.config.file=/usr/local/tomcat/conf/logging.properties
12-Dec-2022 10:05:47.034 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
12-Dec-2022 10:05:47.034 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Xms512m
12-Dec-2022 10:05:47.034 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Xmx4096m
12-Dec-2022 10:05:47.035 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.security.egd=file:/dev/./urandom
12-Dec-2022 10:05:47.035 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -agentlib:jdwp=transport=dt_socket,server=y,suspend=n,address=localhost:9999
12-Dec-2022 10:05:47.035 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -javaagent:/app/lib/luceedebug/luceedebug.jar=jdwpHost=localhost,jdwpPort=9999,cfHost=localhost,cfPort=10000,jarPath=/app/lib/luceedebug/luceedebug.jar
12-Dec-2022 10:05:47.036 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djdk.tls.ephemeralDHKeySize=2048
12-Dec-2022 10:05:47.036 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.protocol.handler.pkgs=org.apache.catalina.webresources
12-Dec-2022 10:05:47.036 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dorg.apache.catalina.security.SecurityListener.UMASK=0027
12-Dec-2022 10:05:47.037 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dignore.endorsed.dirs=
12-Dec-2022 10:05:47.037 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.base=/usr/local/tomcat
12-Dec-2022 10:05:47.037 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.home=/usr/local/tomcat
12-Dec-2022 10:05:47.038 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.io.tmpdir=/usr/local/tomcat/temp
12-Dec-2022 10:05:47.047 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent Loaded Apache Tomcat Native library [1.2.25] using APR version [1.6.5].
12-Dec-2022 10:05:47.048 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent APR capabilities: IPv6 [true], sendfile [true], accept filters [false], random [true].
12-Dec-2022 10:05:47.049 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent APR/OpenSSL configuration: useAprConnector [false], useOpenSSL [true]
12-Dec-2022 10:05:47.059 INFO [main] org.apache.catalina.core.AprLifecycleListener.initializeSSL OpenSSL successfully initialized [OpenSSL 1.1.1d  10 Sep 2019]
12-Dec-2022 10:05:47.614 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["http-nio-8888"]
12-Dec-2022 10:05:47.699 INFO [main] org.apache.catalina.startup.Catalina.load Server initialization in [1216] milliseconds
12-Dec-2022 10:05:47.790 INFO [main] org.apache.catalina.core.StandardService.startInternal Starting service [Catalina]
12-Dec-2022 10:05:47.791 INFO [main] org.apache.catalina.core.StandardEngine.startInternal Starting Servlet engine: [Apache Tomcat/9.0.39]
WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by org.apache.felix.framework.ext.ClassPathExtenderFactory$DefaultClassLoaderExtender (file:/usr/local/tomcat/lucee/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
log4j:WARN No appenders could be found for logger (org.jets3t.service.Jets3tProperties).
log4j:WARN Please initialize the log4j system properly.
log4j:WARN See http://logging.apache.org/log4j/1.2/faq.html#noconfig for more info.
12-Dec-2022 10:05:51.154 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["http-nio-8888"]
12-Dec-2022 10:05:51.222 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in [3522] milliseconds

### Run App ###

SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.
[luceedebug] Method 'udfCall' in class 'info/mysite/askaquestion/aaqquestionpool_cfc$cf' became too large after instrumentation (size=70702). luceedebug won't be able to hit breakpoints in, or expose frame information for, this file.
[luceedebug] Method 'udfCall2' in class 'taportal/workplan/services/mixins/workplanscopeservice_cfm$cf' became too large after instrumentation (size=71842). luceedebug won't be able to hit breakpoints in, or expose frame information for, this file.
jamiejackson commented 1 year ago

Maybe you can make sense of this. These two probes are within the same Lucee server instance (server hadn't restarted):

vagrant@local:~$ docker exec -it $(get_a_container_id_from_service.sh hudx_local_lucee) nmap localhost -p 8888,9999,10000
Starting Nmap 7.70 ( https://nmap.org ) at 2022-12-12 10:29 CST
Nmap scan report for localhost (127.0.0.1)
Host is up (0.000043s latency).
Other addresses for localhost (not scanned): ::1

PORT      STATE  SERVICE
8888/tcp  open   sun-answerbook
9999/tcp  open   abyss
10000/tcp closed snet-sensor-mgmt

Nmap done: 1 IP address (1 host up) scanned in 0.34 seconds
vagrant@local:~$ docker exec -it $(get_a_container_id_from_service.sh hudx_local_lucee) nmap localhost -p 8888,9999,10000
Starting Nmap 7.70 ( https://nmap.org ) at 2022-12-12 10:30 CST
Nmap scan report for localhost (127.0.0.1)
Host is up (0.000059s latency).
Other addresses for localhost (not scanned): ::1

PORT      STATE  SERVICE
8888/tcp  open   sun-answerbook
9999/tcp  closed abyss
10000/tcp open   snet-sensor-mgmt

Nmap done: 1 IP address (1 host up) scanned in 0.28 seconds

It looks like 9999 and 10000 "took turns" being open. I think that the switch happens when the app is accessed for the first time.

softwareCobbler commented 1 year ago

I just tried a different machine to shake out platform assumptions; I built on a windows box, and ran it against a Tomcat instance, no docker. To my surprise it worked with java17, which I thought was going to kill reflection completely.

I did notice I had to prime Lucee by making a first request to it, to some page, in order to run the networking init parts (basically, we boot up once Lucee loads PageContextImpl). Once that first request is made, I can see

[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...

And then connections from the IDE start being accepted. If the above message doesn't appear, then something is hung or somehow silently failed to initialized properly.

softwareCobbler commented 1 year ago

image

jamiejackson commented 1 year ago

I was able to connect! I'm not sure I have established the minimal series (or even a reliable series) of steps to get it working, though.

Notes to self to pick up later:

jamiejackson commented 1 year ago

I just needed to "prime" and to use 0.0.0.0. Those were the final stumbling blocks.

Documented in the latest commit of https://github.com/softwareCobbler/luceedebug/pull/11.