Debugging hangs: 'Connecting to bashdb'?

jefft · November 30, 2023, 2:26am

Hi,

Just getting started using latest BashSupport Pro in PhpStorm 2021.3.2. I create a ‘hello world’ bash script, invoke the debugger, which starts with:

/usr/bin/bash /home/jturner/.local/share/JetBrains/PhpStorm2021.3/bashsupport-pro/bashdb/5.0/bashdb --quiet --no-highlight --library /home/jturner/.local/share/JetBrains/PhpStorm2021.3/bashsupport-pro/bashdb/5.0/share/bashdb --tty_in DBG_PTY --tty DBG_PTY /opt/atl_manage/bin/test.sh

In Background Tasks I see “Connecting to bashdb”, which never completes.

I can see the bashdb process in ps:

jturner 2597886 0.0 0.0 13920 7680 ? S 13:14 0:00 /usr/bin/bash /home/jturner/.local/share/JetBrains/PhpStorm2021.3/bashsupport-pro/bashdb/5.0/bashdb --quiet --no-highlight --library /home/jturner/.local/share/JetBrains/PhpStorm2021.3/bashsupport-pro/bashdb/5.0/share/bashdb --tty_in /dev/pts/9 --tty /dev/pts/9 /opt/atl_manage/bin/test.sh

The tty’s permissions look okay:

jturner@jturner-desktop:~$ ls -lah /dev/pts/9
crw--w---- 1 jturner tty 136, 9 Nov 30 13:14 /dev/pts/9

Also happens with 4.0.0.232-beta7-eap.

Bash is version 5.1.16.

Thread dump online.

jansorg · November 30, 2023, 9:07am

Thanks for the report!

Message “Connecting to bashdb” appears while BashSupport Pro waits for the bashdb debugger to report that it’s ready.

Could you paste the output of uname -a, please?

Could you try to manually execute the debugger and post the output here, please?

To do so, execute this command (modified from above, because _DBG_PTY_ is a placeholder):

/usr/bin/bash \
/home/jturner/.local/share/JetBrains/PhpStorm2021.3/bashsupport-pro/bashdb/5.0/bashdb \
--quiet --no-highlight \
--library /home/jturner/.local/share/JetBrains/PhpStorm2021.3/bashsupport-pro/bashdb/5.0/share/bashdb \
/opt/atl_manage/bin/test.sh

This should print a message like bashdb<0> to notify you that it’s ready.
This should hopefully be enough to debug this.

There should also be a timeout of 30s, i.e. the message should go away and the red error icon should show a new exception with the initial output, which was received from bashdb. Is the Connecting... message staying there even after 30s?

Thanks!
Joachim

jefft · November 30, 2023, 9:27am

Thanks. Yes, bashdb itself seems to be working:

jturner@jturner-desktop:~$ uname -a
Linux jturner-desktop 6.2.0-36-generic #37~22.04.1-Ubuntu SMP PREEMPT_DYNAMIC Mon Oct  9 15:34:04 UTC 2 x86_64 x86_64 x86_64 GNU/Linux

jturner@jturner-desktop:~$ /usr/bin/bash \
/home/jturner/.local/share/JetBrains/PhpStorm2021.3/bashsupport-pro/bashdb/5.0/bashdb \
--quiet --no-highlight \
--library /home/jturner/.local/share/JetBrains/PhpStorm2021.3/bashsupport-pro/bashdb/5.0/share/bashdb \
/opt/atl_manage/bin/test.sh
(/opt/atl_manage/bin/test.sh:3):
3:      echo "Hello world"
bashdb<0>

but for some reason the client is hanging when connecting to /dev/pts/9

I’d guess the reading thread is this one:

"BaseDataReader: split bashdb output stream of bash" #92 prio=4 os_prio=0 cpu=17.84ms elapsed=755.17s tid=0x00007f28b400b800 nid=0x26e1b2 runnable  [0x00007f28f812c000]
   java.lang.Thread.State: RUNNABLE
    at jtermios.linux.JTermiosImpl$Linux_C_lib_DirectMapping.poll(Native Method)
    at jtermios.linux.JTermiosImpl.poll(JTermiosImpl.java:636)
    at jtermios.JTermios.poll(JTermios.java:452)
    at bashpro.pty4j.unix.Pty.poll(Pty.java:263)
    at bashpro.pty4j.unix.Pty.read(Pty.java:253)
    - locked <0x000000009d7546e0> (a java.lang.Object)
    at bashpro.pty4j.unix.PTYInputStream.read(PTYInputStream.java:47)
    at sun.nio.cs.StreamDecoder.readBytes(java.base@11.0.13/StreamDecoder.java:284)
    at sun.nio.cs.StreamDecoder.implRead(java.base@11.0.13/StreamDecoder.java:326)
    at sun.nio.cs.StreamDecoder.read(java.base@11.0.13/StreamDecoder.java:178)
    - locked <0x000000009d7587b0> (a com.intellij.util.io.BaseInputStreamReader)
    at java.io.InputStreamReader.read(java.base@11.0.13/InputStreamReader.java:181)
    at java.io.Reader.read(java.base@11.0.13/Reader.java:229)
    at com.intellij.util.io.BaseOutputReader.readAvailableBlocking(BaseOutputReader.java:133)
    at com.intellij.util.io.BaseDataReader.readAvailable(BaseDataReader.java:74)
    at com.intellij.util.io.BaseDataReader.doRun(BaseDataReader.java:155)
    at com.intellij.util.io.BaseDataReader$$Lambda$815/0x0000000100a18440.run(Unknown Source)
    at com.intellij.util.ConcurrencyUtil.runUnderThreadName(ConcurrencyUtil.java:213)
    at com.intellij.util.io.BaseDataReader.lambda$start$0(BaseDataReader.java:50)
    at com.intellij.util.io.BaseDataReader$$Lambda$812/0x00000001009c1440.run(Unknown Source)
    at java.util.concurrent.Executors$RunnableAdapter.call(java.base@11.0.13/Executors.java:515)
    at java.util.concurrent.FutureTask.run(java.base@11.0.13/FutureTask.java:264)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.13/ThreadPoolExecutor.java:1128)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.13/ThreadPoolExecutor.java:628)
    at java.util.concurrent.Executors$PrivilegedThreadFactory$1$1.run(java.base@11.0.13/Executors.java:668)
    at java.util.concurrent.Executors$PrivilegedThreadFactory$1$1.run(java.base@11.0.13/Executors.java:665)
    at java.security.AccessController.doPrivileged(java.base@11.0.13/Native Method)
    at java.util.concurrent.Executors$PrivilegedThreadFactory$1.run(java.base@11.0.13/Executors.java:665)
    at java.lang.Thread.run(java.base@11.0.13/Thread.java:829)

If it works for everyone else I’m sure it’s just some oddity of my environment.

jansorg · November 30, 2023, 10:33am

Well, the debugger is supposed to work for everybody and I’d like to fix this bug.
I haven’t received any other report about this, but it’s a core feature and definitely something which is supposed to work.

The output of bashdb is what it’s supposed to be, but I’ll try to reproduce this on Ubuntu 22.04.

The thread is running as long as the debugger session is active, i.e. it’s not clear that it’s a problem with the thread or the PTY.
Is your environment perhaps using “uncommon” settings for the terminal or the system itself (e.g. SELinux)?

If you don’t mind, this could help for debugging:

Add line #bashpro:trace at Help > Diagnostic Tools > Debug Log Settings ...
Launch the debugging session and make sure to wait at least 30s
Send the file created by Help > Collect Log and Dignostic data to mail@bashsupport.com
Remove the #bashpro:trace line again, it would slow down the plugin and your IDE

Possible workaround:

In PhpStorm, open Help > Find Action...
Type Registry and execute item Registry...
Type bashpro.debug.use.pty and uncheck the checkbox
Close the dialog and try again to debug your script
Now the debugger is executed without a PTY but with a file instead.

I hope that this is at least launching the debugger for you.

jefft · November 30, 2023, 11:24am

Is your environment perhaps using “uncommon” settings for the terminal or the system itself (e.g. SELinux)?

Nothing weird that I know of (no selinux) - pretty vanilla Ubuntu 22.04.3. FYI I upgraded to PhpStorm 2023.2.4 and it didn’t help. Also tried PyCharm.

If you don’t mind, this could help for debugging:

Add line #bashpro:trace at Help > Diagnostic Tools > Debug Log Settings …
Launch the debugging session and make sure to wait at least 30s
Send the file created by Help > Collect Log and Dignostic data to mail@bashsupport.com
Remove the #bashpro:trace line again, it would slow down the plugin and your IDE

I have done so, thanks. The interesting bit in idea.log seems to be:

The workaround did not help. The launched process became:

/usr/bin/bash /home/jturner/.local/share/JetBrains/PhpStorm2023.2/bashsupport-pro/bashdb/5.0/bashdb --quiet --no-highlight --library /home/jturner/.local/share/JetBrains/PhpStorm2023.2/bashsupport-pro/bashdb/5.0/share/bashdb --tty /tmp/bashsupport-bashdb.log /opt/atl_manage/bin/test.sh

I got the same ‘Connecting to bashdb’ hang. Possibly of interest:

root@jturner-desktop:~# lsof /tmp/bashsupport-bashdb.log 
COMMAND    PID    USER   FD   TYPE DEVICE SIZE/OFF    NODE NAME
java    651931 jturner  384r   REG   8,34       73 8520172 /tmp/bashsupport-bashdb.log
bash    652966 jturner    2w   REG   8,34       73 8520172 /tmp/bashsupport-bashdb.log
root@jturner-desktop:~# cat /tmp/bashsupport-bashdb.log 
(/opt/atl_manage/bin/test.sh:3):
3:      echo "Hello world"
bashdb<0> root@jturner-desktop:~#

The set of freaky utilities at GitHub - iovisor/bcc: BCC - Tools for BPF-based Linux IO analysis, networking, monitoring, and more includes one ttysnoop, which let me see what’s happening there:

root@jturner-desktop:/usr/share/bcc/tools# ./ttysnoop /dev/pts/12

(/opt/atl_manage/bin/test.sh:3):
3:      echo "Hello world"
bashdb<0>

Thanks for your help!

jansorg · November 30, 2023, 1:04pm

@jefft Thanks, that was helpful!

The debugger is launched successfully, but the bashdb command load /opt/atl_manage/lib/profile.sh doesn’t seem to return.

Could you manually launch the debugger again (as above) and then enter the load command and post the output, please?

/usr/bin/bash \
/home/jturner/.local/share/JetBrains/PhpStorm2021.3/bashsupport-pro/bashdb/5.0/bashdb \
--quiet --no-highlight \
--library /home/jturner/.local/share/JetBrains/PhpStorm2021.3/bashsupport-pro/bashdb/5.0/share/bashdb \
/opt/atl_manage/bin/test.sh
# now enter this command into bashdb:
#     load /opt/atl_manage/lib/profile.sh

The file is loaded because there’s apparently a breakpoint set for the file at line 651.
Does removing this breakpoint help?
Is the file readable for your user?

In the meantime I’ll double-check that BashSupport Pro isn’t somehow refusing to send the load command to bashdb…

Thanks!

jefft · December 1, 2023, 3:13am

I see - I had been viewing profile.sh – perhaps even added a breakpoint – before deciding it was way too complicated and wrote a 3-line test.sh. I hadn’t expected the profile.sh breakpoint or file to be loaded into the debugger, but there you go:

2023-11-30 21:59:56,515 [  11117]  FINER - #bashpro.debugger - textAvailable: (/opt/atl_manage/bin/test.sh:3):^M
3:  echo "Hello world"
2023-11-30 21:59:56,519 [  11121]  FINER - #bashpro.debugger - textAvailable: ^[[?2004hbashdb<0>
2023-11-30 21:59:56,523 [  11125]   FINE - #bashpro.timing - [bashdb.awaitReady] took 107 ms
2023-11-30 21:59:56,526 [  11128]   FINE - #bashpro.debug - registerBreakpoint XLineBreakpointImpl(bashpro.debug.shLine at profile.sh:651)
2023-11-30 21:59:56,531 [  11133]   FINE - #bashpro.debug - registerBreakpoint XLineBreakpointImpl(bashpro.debug.shLine at test.sh:2)
2023-11-30 21:59:56,533 [  11135]   FINE - #bashpro.debugger - cmd [0, 1] load /opt/atl_manage/lib/profile.sh

I ran bashdb by hand and fed it the load command as you suggest:

jturner@jturner-desktop:~$ /usr/bin/bash /home/jturner/.local/share/JetBrains/PhpStorm2023.2/bashsupport-pro/bashdb/5.0/bashdb --quiet --no-highlight --library /home/jturner/.local/share/JetBrains/PhpStorm2023.2/bashsupport-pro/bashdb/5.0/share/bashdb --tty /tmp/bashsupport-bashdb.log /opt/atl_manage/bin/test.sh
load /opt/atl_manage/lib/profile.sh

And if I tail -f /tmp/bashsupport-bashdb.log I see:

bashdb<0> load /opt/atl_manage/lib/profile.sh
Reading /opt/atl_manage/lib/profile.sh done.
File /opt/atl_manage/lib/profile.sh loaded.

Is the file readable for your user?

profile.sh is readable.

Does removing this breakpoint help?

Unsetting the breakpoint doesn’t help.

I regret dragging profile.sh into the mix when I just want test.sh to work, so I created a new Project in an empty directory with just test.sh:

#!/bin/bash -eu

echo "Hello"
echo "world"

When I launch the PhpStorm 2023.2.4 + bashsupport 4.0.0.232-beta7-eap debugger, bashdb runs:

/usr/bin/bash /home/jturner/.local/share/JetBrains/PhpStorm2023.2/bashsupport-pro/bashdb/5.0/bashdb --quiet --no-highlight --library /home/jturner/.local/share/JetBrains/PhpStorm2023.2/bashsupport-pro/bashdb/5.0/share/bashdb --tty /tmp/bashsupport-bashdb.log /home/jturner/bashproj/test.sh

The file contains:

root@jturner-desktop:~# tail -f /tmp/bashsupport-bashdb.log 
(/home/jturner/bashproj/test.sh:3):
3:      echo "Hello"
bashdb<0>

And idea.log (which I’ll email) contains:

2023-12-01 13:35:55,524 [  12686]   FINE - #bashpro.debug - starting debug process
2023-12-01 13:35:55,529 [  12691]  FINER - #bashpro.license - Current system time: 1701398155529, build time: 1698105600000
2023-12-01 13:35:55,529 [  12691]   FINE - #bashpro.debug - Updating system property for pty4j: /home/jturner/.local/share/JetBrains/PhpStorm2023.2/bashsupport-pro/lib/pty4j-bashsupport
2023-12-01 13:35:55,538 [  12700]   FINE - #bashpro.interpreter - detected GNU bash, version 5
2023-12-01 13:35:55,663 [  12825]   FINE - #bashpro.debugger - [0] ignoring non-bashdb output '/usr/bin/bash /home/jturner/.local/share/JetBrains/PhpStorm2023.2/bashsupport-pro/bashdb/5.0/bashdb --quiet --no-highlight --library /home/jturner/.local/share/JetBrains/PhpStorm2023.2/bashsupport-pro/bashdb/5.0/share/bashdb --tty /tmp/bashsupport-bashdb.log /home/jturner/bashproj/test.sh' and type system
2023-12-01 13:35:55,832 [  12994]   WARN - #c.i.o.a.ActionStub - ActionGroup should be registered using <group> tag: id="bashpro.SendSignal" class="pro.bashsupport.shell.nz"
2023-12-01 13:35:55,955 [  13117]  FINER - #bashpro.debugger - textAvailable: (/home/jturner/bashproj/test.sh:3):
2023-12-01 13:35:55,959 [  13121]  FINER - #bashpro.debugger - textAvailable: 3:    echo "Hello"
2023-12-01 13:35:55,960 [  13122]  FINER - #bashpro.debugger - textAvailable: ^[[?2004hbashdb<0>
2023-12-01 13:35:55,964 [  13126]   FINE - #bashpro.timing - [bashdb.awaitReady] took 115 ms
2023-12-01 13:35:55,971 [  13133]   FINE - #bashpro.debugger - cmd [0, 1] info variables -p
2023-12-01 13:35:56,242 [  13404]  FINER - #bashpro.license - Current system time: 1701398156241, build time: 1698105600000
2023-12-01 13:35:56,242 [  13404]  FINER - #bashpro.license - Current system time: 1701398156242, build time: 1698105600000
...
2023-12-01 13:35:56,245 [  13407]   FINE - #bashpro.inspections - no custom path configured
2023-12-01 13:35:56,245 [  13407]   FINE - #bashpro.inspections - Using shellcheck at null
2023-12-01 13:35:56,245 [  13407]   FINE - #bashpro.inspections - Using shellcheck at /home/jturner/.local/share/JetBrains/PhpStorm2023.2/bashsupport-pro/shellcheck/shellcheck_linux_amd64

Then 2 minutes later, the IDE kills the process for being inactive - usefully, showing the stacktrace:

If it's a long-running mostly idle daemon process, consider overriding OSProcessHandler#readerOptions with 'BaseOutputReader.Options.forMostlySilentProcess()' to reduce CPU usage.
Command line: /usr/bin/bash /home/jturner/.local/share/JetBrains/PhpStorm2023.2/bashsupport-pro/bashdb/5.0/bashdb --quiet --no-highlight --library /home/jturner/.local/share/JetBrains/PhpStorm2023.2/bashsupport-pro/bashdb/5.0/share/bashdb --tty /tmp/bashsupport-bashdb.log /home/jturner/bashproj/test.sh
java.lang.Throwable: Process creation:
    at com.intellij.execution.process.BaseOSProcessHandler.<init>(BaseOSProcessHandler.java:35)
    at com.intellij.execution.process.OSProcessHandler.<init>(OSProcessHandler.java:44)
    at com.intellij.execution.process.KillableProcessHandler.<init>(KillableProcessHandler.java:41)
    at pro.bashsupport.ir.<init>(ir.java:35)
    at pro.bashsupport.shell.rs.b(rs.java:113)
    at pro.bashsupport.shell.rg.start(rg.java:59)
    at com.intellij.xdebugger.impl.XDebuggerManagerImpl.startSession(XDebuggerManagerImpl.java:274)
    at com.intellij.xdebugger.impl.XDebuggerManagerImpl.startSession(XDebuggerManagerImpl.java:219)
    at pro.bashsupport.shell.x5.J(x5.java:95)
    at pro.bashsupport.shell.x5.execute(x5.java:75)
    at com.intellij.execution.runners.AsyncProgramRunner$execute$1.invoke(GenericProgramRunner.kt:48)
...

It appears that this time, bashpro thinks it has sent a info variables -p command. Just like bashpro thought it sent load /opt/atl_manage/lib/profile.sh last time. I don’t think these commands are actually getting through to bashdb. At least, I never see them in /tmp/bashsupport-bashdb.log.

I wonder, is the code that emits this line actually sending anything?

2023-12-01 13:35:55,971 [  13133]   FINE - #bashpro.debugger - cmd [0, 1] info variables -p

Perhaps it’s missing a newline? Or there’s some buffering and bytes aren’t actually flushed out? I can issue info variables -p to bashdb by hand and it works, just like load /opt/atl_manage/lib/profile.sh issued by hand works.

Thanks a lot for your help!

jansorg · December 1, 2023, 4:30pm

Thank you for the new logs! I’m sorry for using this much of your time…

I installed Ubuntu 22.04 (in KVM), but failed to replicate the issue.

The command shown in the log is written with an additional \n to STDIN of bashdb (if an PTY is not used, as in your current setup). The Java OutputStream is flushed after the bytes were sent.

I don’t fully understand yet what’s going on, but my current thinking is that the command sent to STDIN of bashdb is not reaching bashdb, because bashdb would have printed the command output into the temp file at /tmp/.
I’m not sure why the command is not reaching it. Your machine seems to use lots of mountpoints, but even network mounts shouldn’t affect the pipe between bashdb and PhpStorm/BashSupport Pro.

As a somewhat desperate attempt, do you mind to do the following to provide logs of the data send “on the wire”?

Add a new line -Dpurejavacomm.loglevel=5 at Help > Edit Custom VM Options...
Remove or backup idea.log to only provide log data of the session
Restart PhpStorm
Open the test bash script, set a breakpoint and launch the debugger
Wait a bit and then shutdown the debugger
Send the new diagnostic data.
Remove the VM option and restart. The setting would slow down other terminal integrations of PhpStorm.

The new idea.log will provide diagnostics like - STDERR - log: > write(344,[45,0x6C,0x6F,0x61,0x64,0x20,0x2F,0x68,0x6F...],45) to debug what’s being sent to bashdb.

jefft · December 4, 2023, 1:01pm

Thanks a lot. I did what I should have done long ago, and ran PhpStorm in a clean environment (a separate unix account). There I also could not reproduce the problem.

Through a process of elimination, I found the culprit was this line in my ~/.inputrc:

Control-j: menu-complete

I had ctrl-j/k set as a pair:

Control-j: menu-complete
Control-k: menu-complete-backward

I added this years ago after reading some random “pimp your .inputrc” reddit article.

Why is mapping ctrl-j breaking bashdb? I’ve no idea. I can’t replicate the problem in the command-line:

jturner@jturner-desktop:~$ /usr/bin/bash /home/jturner/.local/share/JetBrains/PhpStorm2023.2/bashsupport-pro/bashdb/5.0/bashdb  --quiet --no-highlight --library /home/jturner/.local/share/JetBrains/PhpStorm2023.2/bashsupport-pro/bashdb/5.0/share/bashdb --tty /dev/stdout /home/jturner/bashproj/test.sh
(/home/jturner/bashproj/test.sh:3):
3:      echo "Hello"
bashdb<0> next
Hello
(/home/jturner/bashproj/test.sh:4):
4:      echo "world"
bashdb<1> next
world
(/home/jturner/.local/share/JetBrains/PhpStorm2023.2/bashsupport-pro/bashdb/5.0/bashdb:1):
1:      #!/usr/bin/bash
bashdb<2> next
Debugged program terminated normally. Use q to quit or R to restart.

When is ctrl-j even being sent?! Google trawling shows a similar bug where binding control-j to menu-complete breaks gdb, and comments there indicate ctrl-j is byte-wise identical to Enter (0x0a), so perhaps the enter is treated as ctrl-j.

Anyway, one way for BashSupport Pro to disarm this bizarre footgun is to disable ~/.inputrc reading when bashdb starts. That can be done by setting env var INPUTRC=/dev/null, i.e.:

INPUTRC=/dev/null /usr/bin/bash /home/jturner/.local/share/JetBrains/PhpStorm2023.2/bashsupport-pro/bashdb/5.0/bashdb  --quiet --no-highlight --library /home/jturner/.local/share/JetBrains/PhpStorm2023.2/bashsupport-pro/bashdb/5.0/share/bashdb --tty /tmp/bashsupport-bashdb.log /home/jturner/bashproj/test.sh

For the record, here is my idea.log with -Dpurejavacomm.loglevel=5 in Edit Custom VM Options, from a broken attempt:

2023-12-04 22:46:38,282 [  10606]   FINE - #bashpro.inspections - Using shellcheck at null
2023-12-04 22:46:38,283 [  10607]   FINE - #bashpro.inspections - Using shellcheck at /home/jturner/.local/share/JetBrains/PhpStorm2023.2/bashsupport-pro/shellcheck/shellcheck_linux_amd64
2023-12-04 22:46:42,187 [  14511]   INFO - #c.i.o.u.r.RegistryValue - Registry value 'ide.instant.shutdown' has changed to 'false'
2023-12-04 22:46:42,189 [  14513]   FINE - #bashpro.debugger - [0] bashdb process will terminate
2023-12-04 22:46:42,190 [  14514]   FINE - #bashpro.debugger - cmd [0, 1] response: process terminated
2023-12-04 22:46:42,190 [  14514]   FINE - #bashpro.timing - [bashdb.cmdAsync[1]("load /home/jturner/bashproj/test.sh")] took 4195 ms
2023-12-04 22:46:42,190 [  14514]   FINE - #bashpro.debugger - cmd [0, 1] info variables -p
2023-12-04 22:46:42,191 [  14515]   INFO - STDERR - log: > write(347,[18,0x69,0x6E,0x66,0x6F,0x20,0x76,0x61,0x72...],18)
2023-12-04 22:46:42,191 [  14515]   INFO - STDERR - log: < write(347,[18,0x69,0x6E,0x66,0x6F,0x20,0x76,0x61,0x72...],18) => 18
2023-12-04 22:46:42,219 [  14543]   INFO - STDERR - log: > write(350,[1,0x00],1)
2023-12-04 22:46:42,219 [  14543]   INFO - STDERR - log: < poll([4,0x00000160,0x00000001,0x0000015F,0x00100001],2,-1) => 1
2023-12-04 22:46:42,219 [  14543]   INFO - STDERR - log: < poll([4,0x0000015D,0x00010001,0x0000015B,0x00000001],2,-1) => 1
2023-12-04 22:46:42,220 [  14544]   INFO - STDERR - log: > close(347)
2023-12-04 22:46:42,220 [  14544]   INFO - STDERR - log: < write(350,[1,0x00],1) => 1
2023-12-04 22:46:42,220 [  14544]   INFO - STDERR - log: < close(347) => 0
2023-12-04 22:46:42,220 [  14544]   INFO - STDERR - log: > close(351)
2023-12-04 22:46:42,220 [  14544]   INFO - STDERR - log: > write(350,[1,0x00],1)
2023-12-04 22:46:42,220 [  14544]   INFO - STDERR - log: > write(353,[1,0x00],1)
2023-12-04 22:46:42,220 [  14544]   INFO - STDERR - log: < write(350,[1,0x00],1) => 1
2023-12-04 22:46:42,221 [  14545]   INFO - STDERR - log: > close(349)
2023-12-04 22:46:42,221 [  14545]   INFO - STDERR - log: < close(349) => 0
2023-12-04 22:46:42,221 [  14545]   INFO - STDERR - log: > close(350)
2023-12-04 22:46:42,221 [  14545]   INFO - STDERR - log: < close(351) => 0
2023-12-04 22:46:42,221 [  14545]   INFO - STDERR - log: < close(350) => 0
2023-12-04 22:46:42,221 [  14545]   INFO - STDERR - log: > close(348)
2023-12-04 22:46:42,221 [  14545]   INFO - STDERR - log: < write(353,[1,0x00],1) => 1
2023-12-04 22:46:42,221 [  14545]   INFO - STDERR - log: < close(348) => 0
2023-12-04 22:46:42,221 [  14545]   INFO - STDERR - log: > write(353,[1,0x00],1)
2023-12-04 22:46:42,222 [  14546]   INFO - STDERR - log: < write(353,[1,0x00],1) => 1
2023-12-04 22:46:42,222 [  14546]   INFO - STDERR - log: > close(352)
2023-12-04 22:46:42,222 [  14546]   INFO - STDERR - log: < close(352) => 0
2023-12-04 22:46:42,222 [  14546]   INFO - STDERR - log: > close(353)
2023-12-04 22:46:42,222 [  14546]   INFO - STDERR - log: < close(353) => 0
2023-12-04 22:46:42,222 [  14546]   FINE - #bashpro.debugger - [0] bashdb process terminated
2023-12-04 22:46:42,223 [  14547]   FINE - #bashpro.debug - stop called

and working:

2023-12-04 22:45:56,757 [  13318]   FINE - #bashpro.inspections - Using shellcheck at null
2023-12-04 22:45:56,757 [  13318]   FINE - #bashpro.inspections - Using shellcheck at /home/jturner/.local/share/JetBrains/PhpStorm2023.2/bashsupport-pro/shellcheck/shellcheck_linux_amd64
2023-12-04 22:45:56,760 [  13321]  FINER - #bashpro.license - Current system time: 1701690356760, build time: 1698105600000
2023-12-04 22:45:56,760 [  13321]   FINE - #bashpro.inspections - no custom path configured
2023-12-04 22:45:56,760 [  13321]   FINE - #bashpro.inspections - Using shellcheck at null
2023-12-04 22:45:56,760 [  13321]   FINE - #bashpro.inspections - Using shellcheck at /home/jturner/.local/share/JetBrains/PhpStorm2023.2/bashsupport-pro/shellcheck/shellcheck_linux_amd64
2023-12-04 22:46:02,688 [  19249]   FINE - #bashpro.debug - starting debug process
2023-12-04 22:46:02,694 [  19255]  FINER - #bashpro.license - Current system time: 1701690362693, build time: 1698105600000
2023-12-04 22:46:02,694 [  19255]   FINE - #bashpro.debug - Updating system property for pty4j: /home/jturner/.local/share/JetBrains/PhpStorm2023.2/bashsupport-pro/lib/pty4j-bashsupport
2023-12-04 22:46:02,705 [  19266]   FINE - #bashpro.interpreter - detected GNU bash, version 5
2023-12-04 22:46:02,716 [  19277]   INFO - STDERR - log: instantiating jtermios.linux.JTermiosImpl
2023-12-04 22:46:02,726 [  19287]   INFO - STDERR - log: > open('/dev/ptmx',00000102)
2023-12-04 22:46:02,727 [  19288]   INFO - STDERR - log: < open('/dev/ptmx',00000102) => 352
2023-12-04 22:46:02,727 [  19288]   INFO - STDERR - log: > open('/dev/pts/1',00000000)
2023-12-04 22:46:02,727 [  19288]   INFO - STDERR - log: < open('/dev/pts/1',00000000) => 353
2023-12-04 22:46:02,728 [  19289]   INFO - STDERR - log: > pipe([2,0,0])
2023-12-04 22:46:02,728 [  19289]   INFO - STDERR - log: < pipe([2,354,355]) => 0
2023-12-04 22:46:02,728 [  19289]   INFO - STDERR - log: > open('/dev/ptmx',00000102)
2023-12-04 22:46:02,728 [  19289]   INFO - STDERR - log: < open('/dev/ptmx',00000102) => 356
2023-12-04 22:46:02,728 [  19289]   INFO - STDERR - log: > pipe([2,0,0])
2023-12-04 22:46:02,728 [  19289]   INFO - STDERR - log: < pipe([2,357,358]) => 0
2023-12-04 22:46:02,834 [  19395]   FINE - #bashpro.debugger - [0] ignoring non-bashdb output '/usr/bin/bash /home/jturner/.local/share/JetBrains/PhpStorm2023.2/bashsupport-pro/bashdb/5.0/bashdb --quiet --no-highlight --library /home/jturner/.local/share/JetBrains/PhpStorm2023.2/bashsupport-pro/bashdb/5.0/share/bashdb --tty /tmp/bashsupport-bashdb.log /home/jturner/bashproj/test.sh' and type system
2023-12-04 22:46:02,836 [  19397]   INFO - STDERR - log: > poll([4,0x00000162,0x00000001,0x00000160,0x00000001],2,-1)
2023-12-04 22:46:02,837 [  19398]   INFO - STDERR - log: > poll([4,0x00000165,0x00000001,0x00000164,0x00000001],2,-1)
2023-12-04 22:46:03,000 [  19561]   WARN - #c.i.o.a.ActionStub - ActionGroup should be registered using <group> tag: id="bashpro.SendSignal" class="pro.bashsupport.shell.nz"
2023-12-04 22:46:03,090 [  19651]  FINER - #bashpro.debugger - textAvailable: (/home/jturner/bashproj/test.sh:3):
2023-12-04 22:46:03,095 [  19656]  FINER - #bashpro.debugger - textAvailable: 3:    echo "Hello"
2023-12-04 22:46:03,095 [  19656]  FINER - #bashpro.debugger - textAvailable: ^[[?2004hbashdb<0>
2023-12-04 22:46:03,099 [  19660]   FINE - #bashpro.timing - [bashdb.awaitReady] took 81 ms
2023-12-04 22:46:03,102 [  19663]   FINE - #bashpro.debug - registerBreakpoint XLineBreakpointImpl(bashpro.debug.shLine at test.sh:2)
2023-12-04 22:46:03,108 [  19669]   FINE - #bashpro.debugger - cmd [0, 1] load /home/jturner/bashproj/test.sh
2023-12-04 22:46:03,108 [  19669]   INFO - STDERR - log: > write(352,[36,0x6C,0x6F,0x61,0x64,0x20,0x2F,0x68,0x6F...],36)
2023-12-04 22:46:03,109 [  19670]   INFO - STDERR - log: < write(352,[36,0x6C,0x6F,0x61,0x64,0x20,0x2F,0x68,0x6F...],36) => 36
2023-12-04 22:46:03,113 [  19674]  FINER - #bashpro.debugger - textAvailable: ^[[?2004l
2023-12-04 22:46:03,113 [  19674]  FINER - #bashpro.debugger - textAvailable:
2023-12-04 22:46:03,119 [  19680]  FINER - #bashpro.debugger - textAvailable: File /home/jturner/bashproj/test.sh loaded.
2023-12-04 22:46:03,120 [  19681]  FINER - #bashpro.debugger - textAvailable: ^[[?2004hbashdb<1>
2023-12-04 22:46:03,120 [  19681]   FINE - #bashpro.debugger - cmd [0, 1] response: File /home/jturner/bashproj/test.sh loaded.\n
2023-12-04 22:46:03,121 [  19682]   FINE - #bashpro.timing - [bashdb.cmdAsync[1]("load /home/jturner/bashproj/test.sh")] took 15 ms
2023-12-04 22:46:03,121 [  19682]   FINE - #bashpro.debugger - cmd [0, 2] info variables -p
2023-12-04 22:46:03,121 [  19682]   INFO - STDERR - log: > write(352,[18,0x69,0x6E,0x66,0x6F,0x20,0x76,0x61,0x72...],18)
2023-12-04 22:46:03,121 [  19682]   INFO - STDERR - log: < write(352,[18,0x69,0x6E,0x66,0x6F,0x20,0x76,0x61,0x72...],18) => 18
2023-12-04 22:46:03,126 [  19687]  FINER - #bashpro.debugger - textAvailable: ^[[?2004l
2023-12-04 22:46:03,127 [  19688]  FINER - #bashpro.debugger - textAvailable:
2023-12-04 22:46:03,133 [  19694]  FINER - #bashpro.debugger - textAvailable: -x ANSIBLE_NOCOWS="1"
2023-12-04 22:46:03,134 [  19695]  FINER - #bashpro.debugger - textAvailable: -- BASH="/usr/bin/bash"
2023-12-04 22:46:03,136 [  19697]  FINER - #bashpro.debugger - textAvailable: -r BASHOPTS="checkwinsize:cmdhist:complete_fullquote:extdebug:extquote:force_fignore:globasciiranges:hostcomplete:interactive_comments:progcomp:promptvars:sourcepath"
2023-12-04 22:46:03,137 [  19698]  FINER - #bashpro.debugger - textAvailable: -A BASH_ALIASES=()

Many thanks for your excellent support. I have a 17kloc bash codebase for which interactive debugging could be very helpful.

jansorg · December 4, 2023, 3:47pm

Thanks a lot for finding the root cause! I’m glad that you found it and that debugging is now (hopefully) working for you.

I’ll reproduce and investigate why this particular .inputrc is breaking bashdb.

jansorg · December 5, 2023, 11:16am

I think I know what may be going on, but I’m not entirely sure…

bashdb is using Bash’s read -e in emacs mode by default, i.e. it’s using readline.

GNU Readline Library says:

If your keyboard lacks a LFD key, typing C-j will produce the desired character. The RET key may be labeled Return or Enter on some keyboards.

LFD is \n, RET is \r.

BashSupport Pro was appending \n to the commands sent to the bashdb PTY.
If C-j (the default binding for \n) is now mapped to something else, read -e is somehow reverse-mapping the \n to menu-complete. I’m not sure why the reverse-mapping happens, because I’m unable to reproduce it in a terminal window.

I’m now assuming that terminal emulators are sending \r and not \n, but I’m not sure about it.
Changing BashSupport Pro to append \r instead of \n is fixing the hanging debugger.
(It seem like readline is handling both \r and \n as EOL, although I don’t know if this is the method handling line input: input.c - readline.git - The GNU Readline library). Seems like I’ll have to learn a bit more about terminal emulation

I’ll have to be careful with a fix because I don’t want to break things for others. For now, I’ll probably turn off readline integration of the bundled bashdb debugger. It’s not useful with the default settings because BashSupport Pro is launching bashdb on a hidden PTY.
For the upcoming 4.0 I may apply a broader fix, e.g. sending just \r or overriding INPUTRC for the call to read -e.

Thanks again for your help to find the culprit

jefft · December 6, 2023, 2:23am

Yes, same here.

Historically, Unix used \n, Macs used \r and Windows uses \r\n. I don’t think BSP is doing anything wrong sending \n. It’s what my terminal sends, as can be seen by using a file instead of a tty and then using cat -A to print control chars:

jturner@jturner-desktop:~$ INPUTRC=/dev/null /usr/bin/bash /home/jturner/.local/share/JetBrains/PhpStorm2023.2/bashsupport-pro/bashdb/5.0/bashdb  --quiet --no-highlight --library /home/jturner/.local/share/JetBrains/PhpStorm2023.2/bashsupport-pro/bashdb/5.0/share/bashdb --tty /tmp/bashsupport-bashdb.log /home/jturner/bashproj/test.sh
Hello
jturner@jturner-desktop:~$ cat -A /tmp/bashsupport-bashdb.log 
(/home/jturner/bashproj/test.sh:3):$
3:^Iecho "Hello"$
^[[?2004hbashdb<0> next$
^[[?2004l^M(/home/jturner/bashproj/test.sh:4):$
4:^Iecho "world"$
^[[?2004hbashdb<1> quit$
^[[?2004l^Mbashdb: That's all, folks...$
jturner@jturner-desktop:~$

Disabling readline would be best, if you can find some way of doing it besides INPUTRC=/dev/null which I assume won’t work on Windows. The real bug is that readline is being used at all. readline isn’t used in non-interactive uses normally unless -i is given, e.g:

jturner@jturner-desktop:~$ cat ~/.inputrc
set readline_has_sourced_inputrc off
jturner@jturner-desktop:~$ echo foo | bash -c 'cat'
foo
jturner@jturner-desktop:~$ echo foo | bash -i -c 'cat'
readline: ~/.inputrc: line 1: readline_has_sourced_inputrc: unknown variable name
foo
jturner@jturner-desktop:~$

jansorg · December 6, 2023, 7:20am

bashdb uses read -e to enable readline by default, even with TTYs of non-interactive terminals.
I’ve removed -e and published 3.3.5, the new update should fix things for you even with your custom inputrc settings.

For the record, a TTY/terminal emulator takes several options to convert between \n and \r. This probably the reason why sending \r instead of UNIX’s \n is working with the custom inputrc setting, https://man7.org/linux/man-pages/man1/stty.1.html:

  * [-]onlcr
         translate newline to carriage return-newline
  * [-]onlret
         newline performs a carriage return
  * [-]onocr
         do not print carriage returns in the first column

Anyway, it should be fixed now. Please let me know if it’s not or when you run into any other bug with the software.

Thank you!
Joachim

jefft · December 6, 2023, 10:59am

Confirmed fixed in 3.3.5.232, thanks!