SEXPOTS timeout with onboard UART; works under strace, and with other
From
Matthew Asham@VERT to
All on Sat Oct 1 16:11:05 2022
Greetings,
I'm having an odd issue with SEXPOTS using an onboard uart (onboard Asus P5BV-M). Debian 11.
* The modem works fine in 'minicom' with the same serial port settings as sexpots and the onboard uart
* the sexpots configuration works fine with the very same modem but using a usb
<> rs232 adapter is generally reliable
* sexpots works when i strace the process...
* sexpots slightly proceeds further with initialization after the strace'd version is killed off, but still ultimately fails
I've done a pit of poking around in sexpots with gdb and debug statements but nothing has stood out to me. Initially it feels like a timing problem of some sort but I'm not sure how else strace might be interacting with the process that would somehow "make it work".
linux kernel output for the uart:
[ 1.353907] 00:05: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A
sexpots works if I run it with 'strace'. But when running without, the modem times out during initialization.
I've included various outputs below showing this behavior. Any advise would be greatly appreciated.
'regular' sexpots output:
/usr/local/bin/sexpots /etc/sexpots/line1.conf
Synchronet External POTS Support v2.0-Linux Copyright 2022 Rob Swindell
10/1 10:59:19 Reading /etc/sexpots/line1.conf
10/1 10:59:19 Synchronet Communications I/O Library for Linux v1.19
10/1 10:59:19 Build Sep 22 2022 22:09:33 GCC 10.2.1
10/1 10:59:19 TCP Host: lovelybits.org
10/1 10:59:19 TCP Port: 1337
10/1 10:59:19 Opening Communications Device (COM Port): /dev/ttyS0
10/1 10:59:19 COM Port device handle: 3
10/1 10:59:19 COM Port DTE rate: 115200 bps
10/1 10:59:19 Initializing modem:
10/1 10:59:19 Modem Command: ATZ
10/1 10:59:24 Modem Response TIMEOUT (5 seconds) on /dev/ttyS0
10/1 10:59:24 Retry #1: sending modem command (ATZ) on /dev/ttyS0
10/1 10:59:24 Modem Command: ATZ
10/1 10:59:29 Modem Response TIMEOUT (5 seconds) on /dev/ttyS0
10/1 10:59:29 Retry #2: sending modem command (ATZ) on /dev/ttyS0
10/1 10:59:29 Modem Command: ATZ
10/1 10:59:34 Modem Response TIMEOUT (5 seconds) on /dev/ttyS0
10/1 10:59:34 Modem command (ATZ) failure on /dev/ttyS0 (3 attempts)
10/1 10:59:34 Cleaning up ...
10/1 10:59:34 Done (handled 0 calls).
Filtering out the expected EAGAIN and sleeps in the non blocking I/O loop in sexpots.. egrep -v 'EAGAIN|clock_nano' typescript
/usr/local/bin/sexpots /etc/sexpots/line1.conf
# strace /usr/local/bin/sexpots /etc/sexpots/line1.conf execve("/usr/local/bin/sexpots", ["/usr/local/bin/sexpots", "/etc/sexpots/line1.conf"], 0x7fffe502b048 /* 12 vars */) = 0
brk(NULL) = 0x55ecdfd5e000 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory) openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=101355, ...}) = 0
mmap(NULL, 101355, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f6a2d74d000
close(3) = 0
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libpthread.so.0", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0 l\0\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=149520, ...}) = 0
mmap(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f6a2d74b000
mmap(NULL, 136304, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f6a2d729000 mmap(0x7f6a2d72f000, 65536, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x6000) = 0x7f6a2d72f000 mmap(0x7f6a2d73f000, 24576, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x16000) = 0x7f6a2d73f000
mmap(0x7f6a2d745000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1b000) = 0x7f6a2d745000 mmap(0x7f6a2d747000, 13424, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f6a2d747000
close(3) = 0
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3 read(3, "\177ELF\2\1\1\3\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0@>\2\0\0\0\0\0"..., 832) = 832
fstat(3, {st_mode=S_IFREG|0755, st_size=1905632, ...}) = 0
mmap(NULL, 1918592, PROT_READ, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x7f6a2d554000
mmap(0x7f6a2d576000, 1417216, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x22000) = 0x7f6a2d576000 mmap(0x7f6a2d6d0000, 323584, PROT_READ, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x17c000) = 0x7f6a2d6d0000
mmap(0x7f6a2d71f000, 24576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1ca000) = 0x7f6a2d71f000 mmap(0x7f6a2d725000, 13952, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f6a2d725000
close(3) = 0
mmap(NULL, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f6a2d551000
arch_prctl(ARCH_SET_FS, 0x7f6a2d551740) = 0
mprotect(0x7f6a2d71f000, 16384, PROT_READ) = 0
mprotect(0x7f6a2d745000, 4096, PROT_READ) = 0
mprotect(0x55ecde85a000, 4096, PROT_READ) = 0
mprotect(0x7f6a2d790000, 4096, PROT_READ) = 0
munmap(0x7f6a2d74d000, 101355) = 0
set_tid_address(0x7f6a2d551a10) = 89868
set_robust_list(0x7f6a2d551a20, 24) = 0
rt_sigaction(SIGRTMIN, {sa_handler=0x7f6a2d72f690, sa_mask=[], sa_flags=SA_RESTORER|SA_SIGINFO, sa_restorer=0x7f6a2d73c140}, NULL, 8) = 0 rt_sigaction(SIGRT_1, {sa_handler=0x7f6a2d72f730, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART|SA_SIGINFO, sa_restorer=0x7f6a2d73c140}, NULL, 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [RTMIN RT_1], NULL, 8) = 0
prlimit64(0, RLIMIT_STACK, NULL, {rlim_cur=8192*1024, rlim_max=RLIM64_INFINITY}) = 0
fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(0x88, 0x3), ...}) = 0
brk(NULL) = 0x55ecdfd5e000
brk(0x55ecdfd7f000) = 0x55ecdfd7f000
write(1, "\n", 1
) = 1
write(1, "Synchronet External POTS Support"..., 73Synchronet External POTS Support v2.0-Linux Copyright 2022 Rob Swindell
) = 73
uname({sysname="Linux", nodename="commgw", ...}) = 0 stat("/usr/local/bin/sexpots.commgw.ini", 0x7ffdf4d5ad80) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/local/bin", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 3
fstat(3, {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
getdents64(3, 0x55ecdfd5e6e0 /* 3 entries */, 32768) = 80
getdents64(3, 0x55ecdfd5e6e0 /* 0 entries */, 32768) = 0
close(3) = 0 stat("/usr/local/bin/sexpots.Linux.ini", 0x7ffdf4d5ad80) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/local/bin", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 3
fstat(3, {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
getdents64(3, 0x55ecdfd5e6e0 /* 3 entries */, 32768) = 80
getdents64(3, 0x55ecdfd5e6e0 /* 0 entries */, 32768) = 0
close(3) = 0
stat("/usr/local/bin/sexpots.ini", 0x7ffdf4d5ad90) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/usr/local/bin", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 3
fstat(3, {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
getdents64(3, 0x55ecdfd5e6e0 /* 3 entries */, 32768) = 80
getdents64(3, 0x55ecdfd5e6e0 /* 0 entries */, 32768) = 0
close(3) = 0
openat(AT_FDCWD, "/usr/local/bin/sexpots.ini", O_RDONLY) = -1 ENOENT (No such file or directory)
stat("/etc/sexpots/line1.conf", {st_mode=S_IFREG|0644, st_size=2500, ...}) = 0 openat(AT_FDCWD, "/etc/sexpots/line1.conf", O_RDONLY) = 3
openat(AT_FDCWD, "/etc/localtime", O_RDONLY|O_CLOEXEC) = 4
fstat(4, {st_mode=S_IFREG|0644, st_size=2836, ...}) = 0
fstat(4, {st_mode=S_IFREG|0644, st_size=2836, ...}) = 0
read(4, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\5\0\0\0\5\0\0\0\0"..., 4096) = 2836
lseek(4, -1802, SEEK_CUR) = 1034
read(4, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\5\0\0\0\5\0\0\0\0"..., 4096) = 1802
close(4) = 0
write(1, "10/1 10:54:29 Reading /etc/sexp"..., 4710/1 10:54:29 Reading /etc/sexpots/line1.conf
) = 47
fstat(3, {st_mode=S_IFREG|0644, st_size=2500, ...}) = 0
lseek(3, 0, SEEK_SET) = 0
read(3, "LogLevel = INFO ; se"..., 4096) = 2500
read(3, "", 4096) = 0
close(3) = 0
write(1, "10/1 10:54:29 Synchronet Commun"..., 6910/1 10:54:29 Synchronet Communications I/O Library for Linux v1.19
) = 69
write(1, "10/1 10:54:29 Build Sep 22 2022"..., 5310/1 10:54:29 Build Sep 22 2022 22:09:33 GCC 10.2.1
) = 53
write(1, "10/1 10:54:29 TCP Host: lovelyb"..., 4010/1 10:54:29 TCP Host: lovelybits.org
) = 40
write(1, "10/1 10:54:29 TCP Port: 1337\n", 3010/1 10:54:29 TCP Port: 1337
) = 30
write(1, "10/1 10:54:29 Opening Communica"..., 6810/1 10:54:29 Opening Communications Device (COM Port): /dev/ttyS0
) = 68
openat(AT_FDCWD, "/dev/ttyS0", O_RDWR|O_NONBLOCK) = 3
ioctl(3, TCGETS, {B115200 -opost -isig -icanon -echo ...}) = 0
ioctl(3, TCGETS, {B115200 -opost -isig -icanon -echo ...}) = 0
ioctl(3, SNDCTL_TMR_START or TCSETS, {B0 -opost -isig -icanon -echo ...}) = 0 ioctl(3, TCGETS, {B0 -opost -isig -icanon -echo ...}) = 0
write(1, "10/1 10:54:29 COM Port device h"..., 4110/1 10:54:29 COM Port device handle: 3
) = 41
ioctl(3, TCGETS, {B0 -opost -isig -icanon -echo ...}) = 0
ioctl(3, TCGETS, {B0 -opost -isig -icanon -echo ...}) = 0
ioctl(3, SNDCTL_TMR_START or TCSETS, {B115200 -opost -isig -icanon -echo ...}) = 0
ioctl(3, TCGETS, {B115200 -opost -isig -icanon -echo ...}) = 0
ioctl(3, TCGETS, {B115200 -opost -isig -icanon -echo ...}) = 0
ioctl(3, TCGETS, {B115200 -opost -isig -icanon -echo ...}) = 0
ioctl(3, SNDCTL_TMR_START or TCSETS, {B115200 -opost -isig -icanon -echo ...}) = 0
ioctl(3, TCGETS, {B115200 -opost -isig -icanon -echo ...}) = 0
ioctl(3, TCGETS, {B115200 -opost -isig -icanon -echo ...}) = 0
ioctl(3, TCGETS, {B115200 -opost -isig -icanon -echo ...}) = 0
ioctl(3, SNDCTL_TMR_START or TCSETS, {B115200 -opost -isig -icanon -echo ...}) = 0
ioctl(3, TCGETS, {B115200 -opost -isig -icanon -echo ...}) = 0
ioctl(3, TCGETS, {B115200 -opost -isig -icanon -echo ...}) = 0
write(1, "10/1 10:54:29 COM Port DTE rate"..., 4510/1 10:54:29 COM Port DTE rate: 115200 bps
) = 45
ioctl(3, TIOCMBIS, [TIOCM_DTR]) = 0
write(1, "10/1 10:54:29 Initializing mode"..., 3510/1 10:54:29 Initializing modem:
) = 35
write(1, "10/1 10:54:29 Modem Command: AT"..., 3410/1 10:54:29 Modem Command: ATZ
) = 34
write(3, "A", 1) = 1
write(3, "T", 1) = 1
write(3, "Z", 1) = 1
ioctl(3, TCFLSH, TCIFLUSH) = 0
write(3, "\r", 1) = 1
read(3, "\r", 1) = 1
read(3, "\r", 1) = 1
read(3, "\n", 1) = 1
read(3, "O", 1) = 1
read(3, "K", 1) = 1
read(3, "\r", 1) = 1
read(3, "\n", 1) = 1
write(1, "10/1 10:54:30 Modem Response: O"..., 3410/1 10:54:30 Modem Response: OK
) = 34
write(1, "10/1 10:54:30 Enabling modem Ca"..., 4110/1 10:54:30 Enabling modem Caller-ID:
) = 41
write(1, "10/1 10:54:30 Modem Command: AT"..., 3910/1 10:54:30 Modem Command: AT#CID=1
) = 39
write(3, "A", 1) = 1
write(3, "T", 1) = 1
write(3, "#", 1) = 1
write(3, "C", 1) = 1
write(3, "I", 1) = 1
write(3, "D", 1) = 1
write(3, "=", 1) = 1
write(3, "1", 1) = 1
ioctl(3, TCFLSH, TCIFLUSH) = 0
write(3, "\r", 1) = 1
read(3, "\r", 1) = 1
write(2, "10/1 10:54:35 Modem Response TI"..., 6410/1 10:54:35 Modem Response TIMEOUT (5 seconds) on /dev/ttyS0
) = 64
write(2, "10/1 10:54:35 Retry #1: sending"..., 7210/1 10:54:35 Retry #1: sending modem command (AT#CID=1) on /dev/ttyS0
) = 72
ioctl(3, TIOCMBIC, [TIOCM_DTR]) = 0
ioctl(3, TIOCMBIS, [TIOCM_DTR]) = 0
write(1, "10/1 10:54:35 Modem Command: AT"..., 3910/1 10:54:35 Modem Command: AT#CID=1
) = 39
write(3, "A", 1) = 1
write(3, "T", 1) = 1
write(3, "#", 1) = 1
write(3, "C", 1) = 1
write(3, "I", 1) = 1
write(3, "D", 1) = 1
write(3, "=", 1) = 1
write(3, "1", 1) = 1
ioctl(3, TCFLSH, TCIFLUSH) = 0
write(3, "\r", 1) = 1
read(3, "\r", 1) = 1
write(2, "10/1 10:54:40 Modem Response TI"..., 6410/1 10:54:40 Modem Response TIMEOUT (5 seconds) on /dev/ttyS0
) = 64
write(2, "10/1 10:54:40 Retry #2: sending"..., 7210/1 10:54:40 Retry #2: sending modem command (AT#CID=1) on /dev/ttyS0
) = 72
ioctl(3, TIOCMBIC, [TIOCM_DTR]) = 0
ioctl(3, TIOCMBIS, [TIOCM_DTR]) = 0
write(1, "10/1 10:54:40 Modem Command: AT"..., 3910/1 10:54:40 Modem Command: AT#CID=1
) = 39
write(3, "A", 1) = 1
write(3, "T", 1) = 1
write(3, "#", 1) = 1
write(3, "C", 1) = 1
write(3, "I", 1) = 1
write(3, "D", 1) = 1
write(3, "=", 1) = 1
write(3, "1", 1) = 1
ioctl(3, TCFLSH, TCIFLUSH) = 0
write(3, "\r", 1) = 1
read(3, "\r", 1) = 1
read(3, "\r", 1) = 1
read(3, "\n", 1) = 1
read(3, "O", 1) = 1
read(3, "K", 1) = 1
read(3, "\r", 1) = 1
read(3, "\n", 1) = 1
write(1, "10/1 10:54:40 Modem Response: O"..., 3410/1 10:54:40 Modem Response: OK
) = 34
write(1, "10/1 10:54:40 Waiting for incom"..., 6310/1 10:54:40 Waiting for incoming call (Ring Indication) ...
) = 63
ioctl(3, TIOCMGET, [TIOCM_DTR|TIOCM_RTS|TIOCM_CTS|TIOCM_DSR|0x4000]) = 0 ioctl(3, TIOCMGET, [TIOCM_DTR|TIOCM_RTS|TIOCM_CTS|TIOCM_DSR|0x4000]) = 0 ioctl(3, TIOCMGET, [TIOCM_DTR|TIOCM_RTS|TIOCM_CTS|TIOCM_DSR|0x4000]) = 0 strace: Process 89868 detached
running 'regular' sexpots immediately after the 'strace' version has exited, the modem initialization proceeds slightly further but not by much
/usr/local/bin/sexpots /etc/sexpots/line1.conf
Synchronet External POTS Support v2.0-Linux Copyright 2022 Rob Swindell
10/1 10:59:11 Reading /etc/sexpots/line1.conf
10/1 10:59:11 Synchronet Communications I/O Library for Linux v1.19
10/1 10:59:11 Build Sep 22 2022 22:09:33 GCC 10.2.1
10/1 10:59:11 TCP Host: lovelybits.org
10/1 10:59:11 TCP Port: 1337
10/1 10:59:11 Opening Communications Device (COM Port): /dev/ttyS0
10/1 10:59:11 COM Port device handle: 3
10/1 10:59:11 COM Port DTE rate: 115200 bps
10/1 10:59:11 Initializing modem:
10/1 10:59:11 Modem Command: ATZ
10/1 10:59:12 Modem Response: OK
10/1 10:59:12 Enabling modem Caller-ID:
10/1 10:59:12 Modem Command: AT#CID=1
10/1 10:59:17 Modem Response TIMEOUT (5 seconds) on /dev/ttyS0
10/1 10:59:17 Retry #1: sending modem command (AT#CID=1) on /dev/ttyS0
10/1 10:59:17 Modem Command: AT#CID=1
...
--- SBBSecho 3.15-Linux
* Origin: Reverse Polarity ~ Vancouver, Canada (1:153/149)
þ Synchronet þ Vertrauen þ Home of Synchronet þ [vert/cvs/bbs].synchro.net
From
Matthew Asham@VERT to
Digital Man on Mon Oct 10 23:13:57 2022
Re: SEXPOTS timeout with onboard UART; works under strace, and with othe
By: Matthew Asham to Digital Man on Mon Oct 10 2022 05:19 pm
Okay, so now it's not echoing anything back when you make that change?
Is is still working fine if you just comment-out/remove the call to comPurgeInput() - but make no other changes? It seems to me that change cause all the commands to be echoed back (unless you specifically set your modem to ATE0 by default), and then fail the init for that reason.
Yes, it was just seeing the commands echo'd back from the modem. Not an 'OK'. By default I use ATE1. I also tried E0 just to see.
With ATE1
code:
comPurgeOutput(com_handle);
SLEEP(100);
comPurgeInput(com_handle);
10/10 18:08:10 COM Port device handle: 3
10/10 18:08:10 COM Port DTE rate: 115200 bps
10/10 18:08:10 Initializing modem:
10/10 18:08:10 Modem Command: ATZ
comWriteByte A
comWriteByte T
comWriteByte Z
comWriteByte
10/10 18:08:10 Waiting for Modem Response ...
' / 13dByte read '
10/10 18:08:20 Modem Response TIMEOUT (10 seconds) on /dev/ttyS0
10/10 18:08:20 Retry #1: sending modem command (ATZ) on /dev/ttyS0
10/10 18:08:20 Dropping DTR on /dev/ttyS0
10/10 18:08:20 Raising DTR on /dev/ttyS0
10/10 18:08:20 Modem Command: ATZ
comWriteByte A
comWriteByte T
comWriteByte Z
comWriteByte
10/10 18:08:20 Waiting for Modem Response ...
' / 13dByte read '
10/10 18:08:30 Modem Response TIMEOUT (10 seconds) on /dev/ttyS0
10/10 18:08:30 Retry #2: sending modem command (ATZ) on /dev/ttyS0
10/10 18:08:30 Dropping DTR on /dev/ttyS0
10/10 18:08:30 Raising DTR on /dev/ttyS0
10/10 18:08:30 Modem Command: ATZ
comWriteByte A
comWriteByte T
comWriteByte Z
comWriteByte
10/10 18:08:30 Waiting for Modem Response ...
' / 13dByte read '
10/10 18:08:40 Modem Response TIMEOUT (10 seconds) on /dev/ttyS0
10/10 18:08:40 Modem command (ATZ) failure on /dev/ttyS0 (3 attempts)
10/10 18:08:40 Cleaning up ...
10/10 18:08:40 Done (handled 0 calls).
test 2 - with comPurgeInput commented out
code:
comPurgeOutput(com_handle);
SLEEP(100);
// comPurgeInput(com_handle);
10/10 18:09:25 Reading /etc/sexpots/line3.conf
10/10 18:09:25 Synchronet Communications I/O Library for Linux v1.19
10/10 18:09:25 Build Oct 10 2022 18:08:55 GCC 10.2.1
10/10 18:09:25 TCP Host: lovelybits.org
10/10 18:09:25 TCP Port: 1337
10/10 18:09:25 Opening Communications Device (COM Port): /dev/ttyS0
10/10 18:09:25 COM Port device handle: 3
10/10 18:09:25 COM Port DTE rate: 115200 bps
10/10 18:09:25 Initializing modem:
10/10 18:09:25 Modem Command: ATZ
comWriteByte A
comWriteByte T
comWriteByte Z
comWriteByte
10/10 18:09:25 Waiting for Modem Response ...
comReadByte read 'A' / 65
' / 13dByte read '
10/10 18:09:25 Modem Response: A
10/10 18:09:25 Enabling modem Caller-ID:
10/10 18:09:25 Modem Command: AT#CID=1
comWriteByte A
comWriteByte T
comWriteByte #
comWriteByte C
comWriteByte I
comWriteByte D
comWriteByte =
comWriteByte 1
comWriteByte
10/10 18:09:25 Waiting for Modem Response ...
comReadByte read 'A' / 65
' / 13dByte read '
10/10 18:09:25 Modem Response: A
10/10 18:09:25 Waiting for incoming call (Ring Indication) ...
test 3 - both comPurgeInput and comPurgeOutput commented out:
// comPurgeOutput(com_handle);
SLEEP(100);
// comPurgeInput(com_handle);
10/10 18:09:50 Reading /etc/sexpots/line3.conf
10/10 18:09:50 Synchronet Communications I/O Library for Linux v1.19
10/10 18:09:50 Build Oct 10 2022 18:09:48 GCC 10.2.1
10/10 18:09:50 TCP Host: lovelybits.org
10/10 18:09:50 TCP Port: 1337
10/10 18:09:50 Opening Communications Device (COM Port): /dev/ttyS0
10/10 18:09:50 COM Port device handle: 3
10/10 18:09:50 COM Port DTE rate: 115200 bps
10/10 18:09:50 Initializing modem:
10/10 18:09:50 Modem Command: ATZ
comWriteByte A
comWriteByte T
comWriteByte Z
comWriteByte
10/10 18:09:50 Waiting for Modem Response ...
comReadByte read 'A' / 65
comReadByte read 'T' / 84
comReadByte read 'Z' / 90
' / 13dByte read '
10/10 18:09:50 Modem Response: ATZ
10/10 18:09:50 Enabling modem Caller-ID:
10/10 18:09:50 Modem Command: AT#CID=1
comWriteByte A
comWriteByte T
comWriteByte #
comWriteByte C
comWriteByte I
comWriteByte D
comWriteByte =
comWriteByte 1
comWriteByte
10/10 18:09:50 Waiting for Modem Response ...
comReadByte read 'A' / 65
comReadByte read 'T' / 84
comReadByte read '#' / 35
comReadByte read 'C' / 67
comReadByte read 'I' / 73
comReadByte read 'D' / 68
comReadByte read '=' / 61
comReadByte read '1' / 49
' / 13dByte read '
10/10 18:09:50 Modem Response: AT#CID=1
10/10 18:09:50 Waiting for incoming call (Ring Indication) ...
And just for my own sanity, git diff shows these are my changes:
BOOL comWriteByte(COM_HANDLE handle, BYTE ch)
{
+ int res = write(handle, &ch, 1);
+ printf("comWriteByte %c\n", ch);
+ return(res==1);
+
return(write(handle, &ch, 1)==1);
}
@@ -449,6 +453,14 @@ int comWriteString(COM_HANDLE handle, const char* str)
BOOL comReadByte(COM_HANDLE handle, BYTE* ch)
{
+ int res = read(handle, ch, 1);
+
+ if(res>0){
+ printf("comReadByte read '%c' / %d\n", *ch, *ch);
+ }
+ return(res==1);
+
+
return(read(handle, ch, 1)==1);
}
diff --git a/src/sexpots/sexpots.c b/src/sexpots/sexpots.c
index f396bcc6e..1f8c6a45f 100644
=== a/src/sexpots/sexpots.c
+++ b/src/sexpots/sexpots.c
@@ -615,8 +615,9 @@ BOOL modem_send(COM_HANDLE com_handle, const char* str)
if(!comWriteByte(com_handle,ch))
return FALSE;
}
+// comPurgeOutput(com_handle);
SLEEP(100);
- comPurgeInput(com_handle);
+// comPurgeInput(com_handle);
return comWriteByte(com_handle, '\r');
}
So it's as if it's not reading anything. I can also state that I know the modem is not getting the full ATZ because the relay is not clicking when the command is sent from SEXPOTS (Courier's have a very noticable *click* when ATZ is processed).
Now with ATE0 and both comPurge lines commented out, these are my results:
10/10 18:13:21 Reading /etc/sexpots/line3.conf
10/10 18:13:21 Synchronet Communications I/O Library for Linux v1.19
10/10 18:13:21 Build Oct 10 2022 18:13:14 GCC 10.2.1
10/10 18:13:21 TCP Host: lovelybits.org
10/10 18:13:21 TCP Port: 1337
10/10 18:13:21 Opening Communications Device (COM Port): /dev/ttyS0
10/10 18:13:21 COM Port device handle: 3
10/10 18:13:21 COM Port DTE rate: 115200 bps
10/10 18:13:21 Initializing modem:
10/10 18:13:21 Modem Command: ATZ
comWriteByte A
comWriteByte T
comWriteByte Z
comWriteByte
10/10 18:13:21 Waiting for Modem Response ...
10/10 18:13:31 Modem Response TIMEOUT (10 seconds) on /dev/ttyS0
10/10 18:13:31 Retry #1: sending modem command (ATZ) on /dev/ttyS0
10/10 18:13:31 Dropping DTR on /dev/ttyS0
10/10 18:13:31 Raising DTR on /dev/ttyS0
10/10 18:13:31 Modem Command: ATZ
comWriteByte A
comWriteByte T
comWriteByte Z
comWriteByte
10/10 18:13:31 Waiting for Modem Response ...
' / 13dByte read '
comReadByte read '
' / 10
comReadByte read 'O' / 79
comReadByte read 'K' / 75
' / 13dByte read '
comReadByte read '
' / 10
10/10 18:13:32 Modem Response: OK
10/10 18:13:32 Enabling modem Caller-ID:
10/10 18:13:32 Modem Command: AT#CID=1
comWriteByte A
comWriteByte T
comWriteByte #
comWriteByte C
comWriteByte I
comWriteByte D
comWriteByte =
comWriteByte 1
comWriteByte
10/10 18:13:32 Waiting for Modem Response ...
comReadByte read 'A' / 65
comReadByte read 'T' / 84
comReadByte read '#' / 35
comReadByte read 'C' / 67
comReadByte read 'I' / 73
comReadByte read 'D' / 68
comReadByte read '=' / 61
comReadByte read '1' / 49
' / 13dByte read '
10/10 18:13:32 Modem Response: AT#CID=1
10/10 18:13:32 Waiting for incoming call (Ring Indication) ...
--- SBBSecho 3.15-Linux
* Origin: Reverse Polarity ~ Vancouver, Canada (1:153/149)
þ Synchronet þ Vertrauen þ Home of Synchronet þ [vert/cvs/bbs].synchro.net
From
Matthew Asham@VERT to
Digital Man on Tue Oct 11 01:09:53 2022
Re: SEXPOTS timeout with onboard UART; works under strace, and with othe
By: Matthew Asham to Digital Man on Mon Oct 10 2022 06:13 pm
I suggested testing with comDrainOutput(), not comPurgeOutput(). I would not expect that to help at all and just make matters worse. Please re-read my message carefully.
Cool. Now please try the experiment I requested. :-)
Yeah sorry. As you can see in my original test I did use comDrainOutput. I added the incorrect call after I reset my code base because I was fiddling with some other experiments and didn't want to contaminate these ones.
Removing the call to comPurgeInput does cause sexpots to see the echo'd command from the modem, as mentioned in my follow up indicating it was a red herring.
From a fully reset code base:
comDrainOutput(com_handle);
SLEEP(100);
comPurgeInput(com_handle);
10/10 20:02:52 Initializing modem:
10/10 20:02:52 Modem Command: ATZ
10/10 20:02:52 Waiting for Modem Response ...
10/10 20:03:02 Modem Response TIMEOUT (10 seconds) on /dev/ttyS0
10/10 20:03:02 Retry #1: sending modem command (ATZ) on /dev/ttyS0
10/10 20:03:02 Dropping DTR on /dev/ttyS0
10/10 20:03:02 Raising DTR on /dev/ttyS0
10/10 20:03:02 Modem Command: ATZ
10/10 20:03:02 Waiting for Modem Response ...
10/10 20:03:12 Modem Response TIMEOUT (10 seconds) on /dev/ttyS0
10/10 20:03:12 Retry #2: sending modem command (ATZ) on /dev/ttyS0
10/10 20:03:12 Dropping DTR on /dev/ttyS0
10/10 20:03:12 Raising DTR on /dev/ttyS0
10/10 20:03:12 Modem Command: ATZ
10/10 20:03:12 Waiting for Modem Response ...
10/10 20:03:22 Modem Response TIMEOUT (10 seconds) on /dev/ttyS0
10/10 20:03:22 Modem command (ATZ) failure on /dev/ttyS0 (3 attempts)
10/10 20:03:22 Cleaning up ...
10/10 20:03:22 Done (handled 0 calls).
and with:
comDrainOutput(com_handle);
SLEEP(100);
// comPurgeInput(com_handle);
we get:
10/10 20:03:50 COM Port device handle: 3
10/10 20:03:50 COM Port DTE rate: 115200 bps
10/10 20:03:50 Initializing modem:
10/10 20:03:50 Modem Command: ATZ
10/10 20:03:50 Waiting for Modem Response ...
10/10 20:03:50 Modem Response: ATZ
10/10 20:03:50 Enabling modem Caller-ID:
10/10 20:03:50 Modem Command: AT#CID=1
10/10 20:03:50 Waiting for Modem Response ...
10/10 20:03:50 Modem Response: AT#CID=1
10/10 20:03:50 Waiting for incoming call (Ring Indication) ...
and with both disabled:
// comDrainOutput(com_handle);
SLEEP(100);
// comPurgeInput(com_handle);
10/10 20:04:52 Modem Command: ATZ
10/10 20:04:52 Waiting for Modem Response ...
10/10 20:04:52 Modem Response: ATZ
10/10 20:04:52 Enabling modem Caller-ID:
10/10 20:04:52 Modem Command: AT#CID=1
10/10 20:04:52 Waiting for Modem Response ...
10/10 20:04:52 Modem Response: AT#CID=1
10/10 20:04:52 Waiting for incoming call (Ring Indication) ...
and one last thing before I call it a night. While looking at the modem_command function I went ahead and added a SLEEP(100) (after performing the tests listed above!):
~line 685:
. if(!comRaiseDTR(com_handle))
lprintf(LOG_ERR,"ERROR %u raising DTR on %s", COM_ERROR_VALUE, com_dev);
SLEEP(100);
}
In this case the ATZ and AT#CID=1 are both sent twice, and sexpots eventually goes into answer mode:
10/10 20:08:14 Modem Command: ATZ
10/10 20:08:15 Waiting for Modem Response ...
10/10 20:08:25 Modem Response TIMEOUT (10 seconds) on /dev/ttyS0
10/10 20:08:25 Retry #1: sending modem command (ATZ) on /dev/ttyS0
10/10 20:08:25 Dropping DTR on /dev/ttyS0
10/10 20:08:25 Raising DTR on /dev/ttyS0
10/10 20:08:25 Modem Command: ATZ
10/10 20:08:25 Waiting for Modem Response ...
10/10 20:08:26 Modem Response: OK
10/10 20:08:26 Enabling modem Caller-ID:
10/10 20:08:26 Modem Command: AT#CID=1
10/10 20:08:26 Waiting for Modem Response ...
10/10 20:08:36 Modem Response TIMEOUT (10 seconds) on /dev/ttyS0
10/10 20:08:36 Retry #1: sending modem command (AT#CID=1) on /dev/ttyS0
10/10 20:08:36 Dropping DTR on /dev/ttyS0
10/10 20:08:36 Raising DTR on /dev/ttyS0
10/10 20:08:36 Modem Command: AT#CID=1
10/10 20:08:36 Waiting for Modem Response ...
10/10 20:08:36 Modem Response: OK
I hope I didn't miss anything else :)
--- SBBSecho 3.15-Linux
* Origin: Reverse Polarity ~ Vancouver, Canada (1:153/149)
þ Synchronet þ Vertrauen þ Home of Synchronet þ [vert/cvs/bbs].synchro.net