SEXPOTS timeout with onboard UART; works under strace, and with other
From
Matthew Asham@1:153/149 to
All on Sat Oct 1 11:11:04 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)