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

Re: SEXPOTS timeout with onboard UART; works under strace, and with other
By: Matthew Asham to All on Sat Oct 01 2022 11:11 am

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

Do you get a different results with a lower DTE rate (say, 57600 bps)?
--
digital man (rob)

Synchronet/BBS Terminology Definition #65:
SAUCE = Standard Architecture for Universal Comment Extensions (ACiD)
Norco, CA WX: 80.5øF, 54.0% humidity, 3 mph S wind, 0.00 inches rain/24hrs
---
þ Synchronet þ Vertrauen þ Home of Synchronet þ [vert/cvs/bbs].synchro.net

Do you get a different results with a lower DTE rate (say, 57600 bps)?

57600, 38400, 19200 look to be the same behavior.

9600 and 2400 sometimes gets an ATZ through after a retry but the caller ID fails. Much the same as when testing under strace.
--- SBBSecho 3.15-Linux
* Origin: Reverse Polarity ~ Vancouver, Canada (1:153/149)
ï¿­ Synchronet ï¿­ Vertrauen ï¿­ Home of Synchronet ï¿­ [vert/cvs/bbs].synchro.net

Re: SEXPOTS timeout with onboard UART; works under strace, and with othe
By: Digital Man to Matthew Asham on Mon Oct 03 2022 10:51 am

Interesting. Thanks for experimenting. I don't have any immediate ideas, but you have the source and can see all the sexposts.ini settings available you could continue to experiment with. If strace makes it work (more often than not), then I agree,
it sounds like some kind of timing issue. --

It sure is curious. I'll try and spend some time on it but I don't have a lot of spare cycles for all the other things I have on my todo list. Will follow up on this thread if anything new comes up.

Cheers

Matthew
--- SBBSecho 3.15-Linux
* Origin: Reverse Polarity ~ Vancouver, Canada (1:153/149)
þ Synchronet þ Vertrauen þ Home of Synchronet þ [vert/cvs/bbs].synchro.net

Re: SEXPOTS timeout with onboard UART; works under strace, and with othe
By: Charles Blackburn to Matthew Asham on Mon Oct 03 2022 09:52 am

that sounds like a bad UART.. I get a similar thing on my 286 if i go above 19200 even though it has an 16550A uart in it.

Have you got a usb serial dongle? do you get a similar thing?

It could very well be flakey hardware and I'll see if I can perform some more in depth testing on it to see. I have USB adapters that work well with my USR Couriers and Sporters so I'm good on that front. Would still love to use the onboard uart though as it would mean more modems ;). The only time I've had an issue with sexpots is with this onboard uart - it works perfectly well with the USB adapters.

Thank you for the config file offer. I'll send you a seperate EMail on that just in case.

Cheers

Matthew
--- SBBSecho 3.15-Linux
* Origin: Reverse Polarity ~ Vancouver, Canada (1:153/149)
þ Synchronet þ Vertrauen þ Home of Synchronet þ [vert/cvs/bbs].synchro.net

Re: SEXPOTS timeout with onboard UART; works under strace, and with othe
By: Digital Man to Matthew Asham on Mon Oct 03 2022 10:51:09

Re: SEXPOTS timeout with onboard UART; works under strace, and with othe By: Matthew Asham to Digital Man on Sun Oct 02 2022 07:47 pm

Do you get a different results with a lower DTE rate (say, 57600 bps)?

57600, 38400, 19200 look to be the same behavior.

9600 and 2400 sometimes gets an ATZ through after a retry but the caller ID fails. Much the same as when testing under
strace.

Matthew, just replied to your email btw, sorry for the delay.

Interesting. Thanks for experimenting. I don't have any immediate ideas, but you have the source and can see all the
sexposts.ini settings available you could continue to experiment with. If strace makes it work (more often than not), then I
agree, it sounds like some kind of timing issue.

that's what I was thinking as well.. what you might want to do if you can, is play around with the size of the buffers

https://stackoverflow.com/questions/10815811/linux-serial-port-reading-can-i-change-size-of-input-buffer

regards
---

Charles Blackburn
The F.B.O BBS 21:1/221 618:250/36
bbs.thefbo.us IPV4/V6
DOVE-Net FSX-Net MicroNET USENET
---
þ Synchronet þ The FBO BBS - bbs.thefbo.us - A place for aviation fun....

Matthew, just replied to your email btw, sorry for the delay.

Saw that thanks! I didn't see anything in my config that looked off. No worries on the delay ;)

that's what I was thinking as well.. what you might want to do if you can, is play around with the size of the buffers >https://stackoverflow.com/questions/10815811/linux-serial-port-reading-can-i-c hange-size-of-input-buffer

I performed further testing on the serial port using minicom and was able to transmit multimeg files over the course of an hour or so with minimal errors.
I suspect if I was dealing with a dodgy uart I would not have seen success in those tests.

Off hand I can't think of what sexpots is doing differently than other serial code I've poked at in the past so it remains a mystery to me. I hope to poke at it again but time constraints etc etc and I have a viable alternative for now, but for my next round I'll likely start by walking through what minicom is doing since that is my reference test case. It is odd.

Cheers

Matthew
--- SBBSecho 3.15-Linux
* Origin: Reverse Polarity ~ Vancouver, Canada (1:153/149)
ï¿­ Synchronet ï¿­ Vertrauen ï¿­ Home of Synchronet ï¿­ [vert/cvs/bbs].synchro.net

Re: SEXPOTS timeout with onboard UART; works under strace, and with othe
By: Matthew Asham to Charles Blackburn on Fri Oct 07 2022 07:17 pm

Off hand I can't think of what sexpots is doing differently than other serial code I've poked at in the past so it remains a mystery to me. I hope to poke at it again but time constraints etc etc and I have a viable alternative for now, but for my next round I'll likely start by walking through what minicom is doing since that is my reference test case. It is odd.

Could just be some serial port/UART setting that minicom is making that sexpots is not, but is needed for reliable operation with that UART.
--
digital man (rob)

This Is Spinal Tap quote #43:
I feel my role in the band is ... kind of like lukewarm water.
Norco, CA WX: 72.3øF, 73.0% humidity, 2 mph ESE wind, 0.00 inches rain/24hrs ---
þ Synchronet þ Vertrauen þ Home of Synchronet þ [vert/cvs/bbs].synchro.net

Could just be some serial port/UART setting that minicom is making that sexpots is not, but is needed for reliable operation with that UART.

Yep, that's what I'm thinking as well. The mystery continues!
--- SBBSecho 3.15-Linux
* Origin: Reverse Polarity ~ Vancouver, Canada (1:153/149)
ï¿­ Synchronet ï¿­ Vertrauen ï¿­ Home of Synchronet ï¿­ [vert/cvs/bbs].synchro.net

Re: SEXPOTS timeout with onboard UART; works under strace, and with othe
By: Matthew Asham to Charles Blackburn on Fri Oct 07 2022 19:17:10

Matthew, just replied to your email btw, sorry for the delay.

Saw that thanks! I didn't see anything in my config that looked off. No worries on the delay ;)

np.

I performed further testing on the serial port using minicom and was able to transmit multimeg files over the course of an
hour or so with minimal errors.
I suspect if I was dealing with a dodgy uart I would not have seen success in those tests.

interesting. that's possible... i assume everything else is the same ?

Off hand I can't think of what sexpots is doing differently than other serial code I've poked at in the past so it remains a
mystery to me. I hope to poke at it again but time constraints etc etc and I have a viable alternative for now, but for my
next round I'll likely start by walking through what minicom is doing since that is my reference test case. It is odd.

go see my email i just sent off about a weird thing i'm all of a suddenly getting.

what you can do is to verify it's "sexpots", try installing mgetty and running that on the modem line then connecting in and see if you get the same thing.

it should give you a *nix login where you should be able to log into the box just like ssh etc.

once mgetty is installed you can just use "mgetty -x7 <device line> -s 115200"

eg mgetty -x7 ttyS0 -s 115200

see what happens. be interesting... the -x7 is debug and that will appear in /var/log/mgetty/<logfile>

regards

Charles Blackburn
---

Charles Blackburn
The F.B.O BBS 21:1/221 618:250/36
bbs.thefbo.us IPV4/V6
DOVE-Net FSX-Net MicroNET USENET




... If little else, the brain is an educational toy.
---
þ Synchronet þ The FBO BBS - bbs.thefbo.us - A place for aviation fun....

El 1/10/22 a las 16:11, Matthew Asham escribió:

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

Hi i have "similar" issue that i report few moths ago:

https://bbs.docksud.com.ar/web/?page=001-forum.ssjs&sub=dovenetsync&thread=76618

I have external usrobotics 56k via direct serial (no usb adapters
involved), minicom just work fine, and sexpots do not work

I cannot find the soruce of issue, I also runnin Debian 11 on Gigabyte
H81M-H
I dont think that is a hardware issue.

Saludos!

---
ï¿­ Synchronet ï¿­ Dock Sud BBS TLD 24 HS - bbs.docksud.com.ar

it should give you a *nix login where you should be able to log into the box just like ssh etc.

once mgetty is installed you can just use "mgetty -x7 <device line> -s 115200"

eg mgetty -x7 ttyS0 -s 115200

see what happens. be interesting... the -x7 is debug and that will appear in /var/log/mgetty/<logfile>

I've tested this just now using mgetty and the modem initializes without incident and happily answers.

10/10 12:37:31 yS0 locking the line
10/10 12:37:31 yS0 makelock(ttyS0) called
10/10 12:37:31 yS0 do_makelock: lock='/var/lock/LCK..ttyS0'
10/10 12:37:31 yS0 lock made
10/10 12:37:31 yS0 tio_get_rs232_lines: status: RTS CTS DSR DTR
10/10 12:37:31 yS0 lowering DTR to reset Modem
10/10 12:37:32 yS0 tss: set speed to 115200 (10002)
10/10 12:37:32 yS0 tio_set_flow_control( HARD )
10/10 12:37:32 yS0 waiting for line to clear (VTIME=1), read: [0d][0a]RING[0d][0a]
10/10 12:37:32 yS0 send: ATZ[0d]
10/10 12:37:32 yS0 waiting for ``OK''
10/10 12:37:32 yS0 got: ATZ[0d]
10/10 12:37:32 yS0 CND: ATZ[0d][0a]OK ** found **
10/10 12:37:33 yS0 waiting for line to clear (VTIME=3), read: [0d][0a]
10/10 12:37:33 yS0 removing lock file
10/10 12:37:33 yS0 waiting...
10/10 12:37:56 yS0 select returned 1
10/10 12:37:56 yS0 checking lockfiles, locking the line
10/10 12:37:56 yS0 makelock(ttyS0) called
10/10 12:37:56 yS0 do_makelock: lock='/var/lock/LCK..ttyS0'
10/10 12:37:56 yS0 lock made
10/10 12:37:56 yS0 wfr: waiting for ``RING''
10/10 12:37:56 yS0 got: [0d][0a]RING[0d]
10/10 12:37:56 yS0 CND: RING
10/10 12:37:56 yS0 wfr: rc=0, drn=0
10/10 12:37:56 yS0 CND: check no: 'none'
10/10 12:37:56 yS0 cannot set controlling tty (ioctl): Operation not permitted 10/10 12:37:56 yS0 >>> this might be caused because you have run mgetty/vgetty 10/10 12:37:56 yS0 >>> from the command line. Don't do that, use /etc/inittab!
10/10 12:37:56 yS0 send: ATA[0d]
10/10 12:37:56 yS0 waiting for ``CONNECT''
10/10 12:37:56 yS0 got: ATA[0d]
10/10 12:37:56 yS0 CND: OKATA


(oh the glorious sound of modems training voip lines. such beauty listening to their epic struggle)

Thankfully yesterday was our turkey day and I've been permitted to play a bit today. Will see what I can find.

Happy Thanks Giving and Indigenous People's Day!
--- SBBSecho 3.15-Linux
* Origin: Reverse Polarity ~ Vancouver, Canada (1:153/149)
ï¿­ Synchronet ï¿­ Vertrauen ï¿­ Home of Synchronet ï¿­ [vert/cvs/bbs].synchro.net

Okay - I found something else.

in modem_send() https://gitlab.synchro.net/main/sbbs/-/blob/master/src/sexpots/sexpots.c#L619, if I comment out the call to comPurgeInput(com_handle) - the modem initializes successfully and this is repeatable.

This happens right after the modem command is sent but before reading. tcflush(handle, TCIFLUSH) purges the input buffer, but why would strace slow the process down (or maybe i/o in the kernel?) enough so that this purge wouldn't have an affect?

I also tried putting my modem into no echo mode (ATE0) - no affect when comPurgeInput was still present in code.

I also saw the mgetty is doing an fcntl FD_NOFL - but adding the same call to sexpots made no difference.

Time to take a break.
--- SBBSecho 3.15-Linux
* Origin: Reverse Polarity ~ Vancouver, Canada (1:153/149)
ï¿­ Synchronet ï¿­ Vertrauen ï¿­ Home of Synchronet ï¿­ [vert/cvs/bbs].synchro.net

Re: SEXPOTS timeout with onboard UART; works under strace, and with othe
By: Matthew Asham to Matthew Asham on Mon Oct 10 2022 04:03 pm

Okay - I found something else.

in modem_send() https://gitlab.synchro.net/main/sbbs/-/blob/master/src/sexpo ts/sexpots.c#L619, if I comment out the call to comPurgeInput(com_handle) - the modem initializes successfully and this is repeatable.

Thank you for experimenting and reporting your findings!

This happens right after the modem command is sent but before reading.

The flush is supposed to happen after all the printable characters of the AT command are sent (and potentially echoed back by the modem) but before the carriage-return ('\r') is sent.

tcflush(handle, TCIFLUSH) purges the input buffer, but why would strace slow the process down (or maybe i/o in the kernel?) enough so that this purge wouldn't have an affect?

strace will change the timing and this just looks like some kind of race condition, so not too surprising.

I also tried putting my modem into no echo mode (ATE0) - no affect when comPurgeInput was still present in code.

Ah, that's also a very good finding/report! I think this also means that if you tried increasing that SLEEP(100), just before the comPurgeInput() call, to a bigger delay, say SLEEP(500), that also might make the issue go away. I'm sure there's a better fix which I will ponder.

I also saw the mgetty is doing an fcntl FD_NOFL - but adding the same call to sexpots made no difference.

Cool, thanks.
--
digital man (rob)

Sling Blade quote #21:
Karl: Coffee makes me nervous when I drink it. Mmm.
Norco, CA WX: 78.5øF, 60.0% humidity, 11 mph SSE wind, 0.00 inches rain/24hrs ---
þ Synchronet þ Vertrauen þ Home of Synchronet þ [vert/cvs/bbs].synchro.net

Re: SEXPOTS timeout with onboard UART; works under strace, and with othe
By: Digital Man to Matthew Asham on Mon Oct 10 2022 04:46 pm

Re: SEXPOTS timeout with onboard UART; works under strace, and with othe
By: Matthew Asham to Matthew Asham on Mon Oct 10 2022 04:03 pm

Okay - I found something else.

in modem_send() https://gitlab.synchro.net/main/sbbs/-/blob/master/src/sexpo ts/sexpots.c#L619, if I comment out the call to comPurgeInput(com_handle) - the modem initializes successfully and this is repeatable.

Thank you for experimenting and reporting your findings!

This happens right after the modem command is sent but before reading.

The flush is supposed to happen after all the printable characters of the AT command are sent (and potentially echoed back by the modem) but before the carriage-return ('\r') is sent.

tcflush(handle, TCIFLUSH) purges the input buffer, but why would strace slow the process down (or maybe i/o in the kernel?) enough so that this purge wouldn't have an affect?

strace will change the timing and this just looks like some kind of race condition, so not too surprising.

I also tried putting my modem into no echo mode (ATE0) - no affect when comPurgeInput was still present in code.

Ah, that's also a very good finding/report! I think this also means that if you tried increasing that SLEEP(100), just before the comPurgeInput() call, to a bigger delay, say SLEEP(500), that also might make the issue go away. I'm sure there's a better fix which I will ponder.

I also saw the mgetty is doing an fcntl FD_NOFL - but adding the same call to sexpots made no difference.

Cool, thanks.

Another one-line experiment I'd appreciate if you could conduct and report back is to add a call to comDrainOutput() just before the SLEEP() call, like so:

comDrainOutput(com_handle); // newly-added line
SLEEP(100);
comPurgeInput(com_handle);
--
digital man (rob)

Synchronet/BBS Terminology Definition #35:
FTP = File Transfer Protocol
Norco, CA WX: 76.8øF, 63.0% humidity, 12 mph S wind, 0.00 inches rain/24hrs
---
þ Synchronet þ Vertrauen þ Home of Synchronet þ [vert/cvs/bbs].synchro.net

Thank you for experimenting and reporting your findings!

My pleasure!

The flush is supposed to happen after all the printable characters of the AT command are sent (and potentially echoed back by the modem) but before the carriage-return ('\r') is sent.

strace will change the timing and this just looks like some kind of race condition, so not too surprising.

Ah, that's also a very good finding/report! I think this also means that if you tried increasing that SLEEP(100), just before the comPurgeInput() call, to a bigger delay, say SLEEP(500), that also might make the issue go away. I'm sure there's a better fix which I will ponder.

I'll try this but looking back at my log (I was in a rush when I reported those findings) it looks like what I got back were the commands sent, and not an actual 'OK':

(with some extra debug stuff I added to print out additional reporting):

10/10 16:01:07 Opening Communications Device (COM Port): /dev/ttyS0
10/10 16:01:07 COM Port device handle: 3
10/10 16:01:07 COM Port DTE rate: 115200 bps
10/10 16:01:07 Initializing modem:
10/10 16:01:07 Modem Command: ATZ
do sleep 100
end sleep 100
comReadByte read 'A' / 65
sexpots.c:650 comreadbyte ok
str so far is 'A'
comReadByte read 'T' / 84
sexpots.c:650 comreadbyte ok
str so far is 'AT'
comReadByte read 'Z' / 90
sexpots.c:650 comreadbyte ok
str so far is 'ATZ'
' / 13dByte read '
sexpots.c:650 comreadbyte ok
10/10 16:01:07 Modem Response: ATZ
10/10 16:01:07 Enabling modem Caller-ID:
10/10 16:01:07 Modem Command: AT#CID=1
do sleep 100
end sleep 100
comReadByte read 'A' / 65
sexpots.c:650 comreadbyte ok
str so far is 'A'
comReadByte read 'T' / 84
sexpots.c:650 comreadbyte ok
str so far is 'AT'
comReadByte read '#' / 35
sexpots.c:650 comreadbyte ok
str so far is 'AT#'
comReadByte read 'C' / 67
sexpots.c:650 comreadbyte ok
str so far is 'AT#C'
comReadByte read 'I' / 73
sexpots.c:650 comreadbyte ok
str so far is 'AT#CI'
comReadByte read 'D' / 68
sexpots.c:650 comreadbyte ok
str so far is 'AT#CID'
comReadByte read '=' / 61
sexpots.c:650 comreadbyte ok
str so far is 'AT#CID='
comReadByte read '1' / 49
sexpots.c:650 comreadbyte ok
str so far is 'AT#CID=1'
' / 13dByte read '
sexpots.c:650 comreadbyte ok
10/10 16:01:07 Modem Response: AT#CID=1
10/10 16:01:07 Waiting for incoming call (Ring Indication) ...


so I'm afraid this may be a red herring, but I will try the timing change.
--- SBBSecho 3.15-Linux
* Origin: Reverse Polarity ~ Vancouver, Canada (1:153/149)
ï¿­ Synchronet ï¿­ Vertrauen ï¿­ Home of Synchronet ï¿­ [vert/cvs/bbs].synchro.net

Another one-line experiment I'd appreciate if you could conduct and report back is to add a call to comDrainOutput() just before the SLEEP() call, like so:

comDrainOutput(com_handle); // newly-added line
SLEEP(100);
comPurgeInput(com_handle);

tested, no dice

code:

printf("do sleep 100\n");
comDrainOutput(com_handle); // newly-added line
SLEEP(100);
printf("end sleep 100\n");
comPurgeInput(com_handle);
return comWriteByte(com_handle, '\r');



output:


10/10 17:19:00 Reading /etc/sexpots/line3.conf
10/10 17:19:00 Synchronet Communications I/O Library for Linux v1.19
10/10 17:19:00 Build Oct 10 2022 17:18:09 GCC 10.2.1
10/10 17:19:00 TCP Host: lovelybits.org
10/10 17:19:00 TCP Port: 1337
10/10 17:19:00 Opening Communications Device (COM Port): /dev/ttyS0
10/10 17:19:00 COM Port device handle: 3
10/10 17:19:00 COM Port DTE rate: 115200 bps
10/10 17:19:00 Initializing modem:
10/10 17:19:00 Modem Command: ATZ
do sleep 100
end sleep 100
10/10 17:19:00 Waiting for Modem Response ...
' / 13dByte read '
sexpots.c:652 comreadbyte ok
10/10 17:19:10 Modem Response TIMEOUT (10 seconds) on /dev/ttyS0
10/10 17:19:10 Retry #1: sending modem command (ATZ) on /dev/ttyS0
10/10 17:19:10 Dropping DTR on /dev/ttyS0
10/10 17:19:10 Raising DTR on /dev/ttyS0
10/10 17:19:10 Modem Command: ATZ
do sleep 100
end sleep 100
10/10 17:19:10 Waiting for Modem Response ...
' / 13dByte read '
sexpots.c:652 comreadbyte ok
10/10 17:19:20 Modem Response TIMEOUT (10 seconds) on /dev/ttyS0
10/10 17:19:20 Retry #2: sending modem command (ATZ) on /dev/ttyS0
10/10 17:19:20 Dropping DTR on /dev/ttyS0
10/10 17:19:20 Raising DTR on /dev/ttyS0
10/10 17:19:20 Modem Command: ATZ
do sleep 100
end sleep 100
10/10 17:19:20 Waiting for Modem Response ...
' / 13dByte read '
sexpots.c:652 comreadbyte ok
10/10 17:19:30 Modem Response TIMEOUT (10 seconds) on /dev/ttyS0
10/10 17:19:30 Modem command (ATZ) failure on /dev/ttyS0 (3 attempts)
10/10 17:19:30 Cleaning up ...
10/10 17:19:30 Done (handled 0 calls).
--- SBBSecho 3.15-Linux
* Origin: Reverse Polarity ~ Vancouver, Canada (1:153/149)
ï¿­ Synchronet ï¿­ Vertrauen ï¿­ Home of Synchronet ï¿­ [vert/cvs/bbs].synchro.net

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

Another one-line experiment I'd appreciate if you could conduct and report back is to add a call to comDrainOutput() just before the SLEEP() call, like so:

comDrainOutput(com_handle); // newly-added line
SLEEP(100);
comPurgeInput(com_handle);

tested, no dice

code:

printf("do sleep 100\n");
comDrainOutput(com_handle); // newly-added line
SLEEP(100);
printf("end sleep 100\n");
comPurgeInput(com_handle);
return comWriteByte(com_handle, '\r');

output:

10/10 17:19:00 Reading /etc/sexpots/line3.conf
10/10 17:19:00 Synchronet Communications I/O Library for Linux v1.19
10/10 17:19:00 Build Oct 10 2022 17:18:09 GCC 10.2.1
10/10 17:19:00 TCP Host: lovelybits.org
10/10 17:19:00 TCP Port: 1337
10/10 17:19:00 Opening Communications Device (COM Port): /dev/ttyS0
10/10 17:19:00 COM Port device handle: 3
10/10 17:19:00 COM Port DTE rate: 115200 bps
10/10 17:19:00 Initializing modem:
10/10 17:19:00 Modem Command: ATZ
do sleep 100
end sleep 100
10/10 17:19:00 Waiting for Modem Response ...
' / 13dByte read '
sexpots.c:652 comreadbyte ok
10/10 17:19:10 Modem Response TIMEOUT (10 seconds) on /dev/ttyS0
10/10 17:19:10 Retry #1: sending modem command (ATZ) on /dev/ttyS0
10/10 17:19:10 Dropping DTR on /dev/ttyS0
10/10 17:19:10 Raising DTR on /dev/ttyS0
10/10 17:19:10 Modem Command: ATZ
do sleep 100
end sleep 100
10/10 17:19:10 Waiting for Modem Response ...
' / 13dByte read '
sexpots.c:652 comreadbyte ok
10/10 17:19:20 Modem Response TIMEOUT (10 seconds) on /dev/ttyS0
10/10 17:19:20 Retry #2: sending modem command (ATZ) on /dev/ttyS0
10/10 17:19:20 Dropping DTR on /dev/ttyS0
10/10 17:19:20 Raising DTR on /dev/ttyS0
10/10 17:19:20 Modem Command: ATZ
do sleep 100
end sleep 100
10/10 17:19:20 Waiting for Modem Response ...
' / 13dByte read '
sexpots.c:652 comreadbyte ok
10/10 17:19:30 Modem Response TIMEOUT (10 seconds) on /dev/ttyS0
10/10 17:19:30 Modem command (ATZ) failure on /dev/ttyS0 (3 attempts)
10/10 17:19:30 Cleaning up ...
10/10 17:19:30 Done (handled 0 calls).

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.
--
digital man (rob)

Breaking Bad quote #33:
This guy [Gale], it's like scarface had sex with Mr. Rogers. - Hank Schrader Norco, CA WX: 74.8øF, 66.0% humidity, 11 mph S wind, 0.00 inches rain/24hrs
---
þ Synchronet þ Vertrauen þ Home of Synchronet þ [vert/cvs/bbs].synchro.net

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

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

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);

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.

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

Cool. Now please try the experiment I requested. :-)
--
digital man (rob)

Sling Blade quote #2:
Karl (re: killing Doyle): I hit him two good whacks in the head with it.
Norco, CA WX: 69.4øF, 77.0% humidity, 7 mph ESE wind, 0.00 inches rain/24hrs ---
þ Synchronet þ Vertrauen þ Home of Synchronet þ [vert/cvs/bbs].synchro.net

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

Re: SEXPOTS timeout with onboard UART; works under strace, and with othe
By: Matthew Asham to Charles Blackburn on Mon Oct 10 2022 12:40:11

it should give you a *nix login where you should be able to log into the box just like ssh etc.
once mgetty is installed you can just use "mgetty -x7 <device line> -s 115200"
eg mgetty -x7 ttyS0 -s 115200
see what happens. be interesting... the -x7 is debug and that will appear in /var/log/mgetty/<logfile>

I've tested this just now using mgetty and the modem initializes without incident and happily answers.

yay, finally getting 5 minutes to sit down at the computer while in the hotel room.

i'll answer your email in a few :D

regards
---

Charles Blackburn
The F.B.O BBS 21:1/221 618:250/36
bbs.thefbo.us IPV4/V6
DOVE-Net FSX-Net MicroNET USENET




... Under capitalism man exploits man; under socialism the reverse is true.
---
þ Synchronet þ The FBO BBS - bbs.thefbo.us - A place for aviation fun....

Re: SEXPOTS timeout with onboard UART; works under strace, and with othe
By: Matthew Asham to Matthew Asham on Mon Oct 10 2022 16:03:05

Okay - I found something else.

in modem_send() https://gitlab.synchro.net/main/sbbs/-/blob/master/src/sexpots/sexpots.c#L619, if I comment out the call to comPurgeInput(com_handle) - the modem initializes successfully
and this is repeatable.
This happens right after the modem command is sent but before reading. tcflush(handle, TCIFLUSH) purges the input buffer, but why would strace slow the process down (or maybe i/o in the
kernel?) enough so that this purge wouldn't have an affect?

it could actually be the other way around..... it inits the modem and flushes the input which in turn flushes away the result code so therefore sexpots doesnt see the "OK" (or ERROR)

having strace in the way could slow it down just enough.

i might take a look at sexpots when i get back, normally though you flush the buffers right before you send something out, at least that's what i used to do

I also tried putting my modem into no echo mode (ATE0) - no affect when comPurgeInput was still present in code.

not sure that would work if that's what SP is expecting

I also saw the mgetty is doing an fcntl FD_NOFL - but adding the same call to sexpots made no difference.

iirc NNO-FL is no flush so it doesnt flush the buffer right after a send. nut that's from memory

regards
---

Charles Blackburn
The F.B.O BBS 21:1/221 618:250/36
bbs.thefbo.us IPV4/V6
DOVE-Net FSX-Net MicroNET USENET




... We have phasers; I vote we blast 'em!
---
þ Synchronet þ The FBO BBS - bbs.thefbo.us - A place for aviation fun....

Re: SEXPOTS timeout with onboard UART; works under strace, and with othe
By: Matthew Asham to Digital Man on Mon Oct 10 2022 08:09 pm

I hope I didn't miss anything else :)

I didn't see any results from experiments with increasing the SLEEP() duration (e.g. to 500, 1000, etc.).
--
digital man (rob)

This Is Spinal Tap quote #42:
What day the Lord created Spinal Tap and couldn't he have rested on that day? Norco, CA WX: 76.0øF, 66.0% humidity, 2 mph SE wind, 0.00 inches rain/24hrs
---
þ Synchronet þ Vertrauen þ Home of Synchronet þ [vert/cvs/bbs].synchro.net

I didn't see any results from experiments with increasing the SLEEP() duration (e.g. to 500, 1000, etc.).

This didn't really help the problem and I'll have to come back to this down the road. Side lined with other projects atm but will share further testing as I can.

Cheers
--- SBBSecho 3.15-Linux
* Origin: Reverse Polarity ~ Vancouver, Canada (1:153/149)
ï¿­ Synchronet ï¿­ Vertrauen ï¿­ Home of Synchronet ï¿­ [vert/cvs/bbs].synchro.net