Skip to content
Snippets Groups Projects
New look: Off

sexpots: Entire modem init string not being sent

    • Closed Issue created by Nigel Reed @nelgin 
    # cat < /dev/ttyACM0 &
[1] 5532
root@wibble:~# systemctl start sexpots
AT&F1s0=0m0l1s48=root@wibble:~#

    As you can see, only part of the init string is sent.

    Init = AT&F1s0=0m0l1s48=7s36=5&W

    Designs

    Child items ...

    • Activity

    • Nigel Reed added SEXPOTS label

      added SEXPOTS label

    • Nigel Reed assigned to @rswindell

      assigned to @rswindell

    • Rob Swindell
      Rob Swindell @rswindell ·
      Owner

      I'm not clear that your method of debug (redirecting the "echo" from the modem) to determine which characters are sent to it is actually correct.

      The log output of sexpots should include an info-level "Modem Command:" message which includes the full command being sent to the com port. You could also use strace or something similar to see the actual "write" command from sexpots and confirm whether or not the full configured init string is being sent.

      Likely unrelated, but the "&W" in your init string (write to NVRAM) is a little unusual. Consider removing that.

    • Nigel Reed
      Nigel Reed @nelgin ·
      Author Developer

      This is going to be a puzzler.

      Running from the command line, no dice.

      root@wibble:/usr/local/etc# /usr/local/bin/sexpots /usr/local/etc/sexpots-line1.ini -syslog=sexpots-line1

Synchronet External POTS Support v2.0-Linux Copyright 2023 Rob Swindell

Oct 16 14:38:01 wibble sexpots-line1: Reading /usr/local/etc/sexpots-line1.ini
Oct 16 14:38:01 wibble sexpots-line1: Synchronet Communications I/O Library for Linux v1.19
Oct 16 14:38:01 wibble sexpots-line1: Build Apr 26 2023 17:36:57 GCC 11.3.0
Oct 16 14:38:01 wibble sexpots-line1: TCP Host: endofthelinebbs.com
Oct 16 14:38:01 wibble sexpots-line1: TCP Port: 23
Oct 16 14:38:01 wibble sexpots-line1: Opening Communications Device (COM Port): /dev/ttyACM0
Oct 16 14:38:01 wibble sexpots-line1: COM Port device handle: 3
Oct 16 14:38:01 wibble sexpots-line1: COM Port DTE rate: 0 bps
Oct 16 14:38:01 wibble sexpots-line1: Initializing modem:
Oct 16 14:38:01 wibble sexpots-line1: Modem Command: AT&F1s0=0m0l1s48=7s36=5&W
Oct 16 14:38:01 wibble sexpots-line1: ERROR 11 sending modem command (AT&F1s0=0m0l1s48=7s36=5&W) on /dev/ttyACM0
Oct 16 14:38:01 wibble sexpots-line1: Retry #1: sending modem command (AT&F1s0=0m0l1s48=7s36=5&W) on /dev/ttyACM0
Oct 16 14:38:01 wibble sexpots-line1: Dropping DTR on /dev/ttyACM0
Oct 16 14:38:01 wibble sexpots-line1: Raising DTR on /dev/ttyACM0
Oct 16 14:38:01 wibble sexpots-line1: Modem Command: AT&F1s0=0m0l1s48=7s36=5&W
Oct 16 14:38:01 wibble sexpots-line1: ERROR 11 sending modem command (AT&F1s0=0m0l1s48=7s36=5&W) on /dev/ttyACM0
Oct 16 14:38:01 wibble sexpots-line1: Retry #2: sending modem command (AT&F1s0=0m0l1s48=7s36=5&W) on /dev/ttyACM0
Oct 16 14:38:01 wibble sexpots-line1: Dropping DTR on /dev/ttyACM0
Oct 16 14:38:02 wibble sexpots-line1: Raising DTR on /dev/ttyACM0
Oct 16 14:38:02 wibble sexpots-line1: Modem Command: AT&F1s0=0m0l1s48=7s36=5&W
Oct 16 14:38:02 wibble sexpots-line1: ERROR 11 sending modem command (AT&F1s0=0m0l1s48=7s36=5&W) on /dev/ttyACM0
Oct 16 14:38:02 wibble sexpots-line1: Modem command (AT&F1s0=0m0l1s48=7s36=5&W) failure on /dev/ttyACM0 (3 attempts)
Oct 16 14:38:02 wibble sexpots-line1: Cleaning up ...
Oct 16 14:38:02 wibble sexpots-line1: Done (handled 0 calls).

      Running through strace, different result...

      root@wibble:/usr/local/etc# strace -o f -ff -s 65535 /usr/local/bin/sexpots /usr/local/etc/sexpots-line1.ini -syslog=sexpots-line1

Synchronet External POTS Support v2.0-Linux Copyright 2023 Rob Swindell

Oct 16 14:39:24 wibble sexpots-line1: Reading /usr/local/etc/sexpots-line1.ini
Oct 16 14:39:24 wibble sexpots-line1: Synchronet Communications I/O Library for Linux v1.19
Oct 16 14:39:24 wibble sexpots-line1: Build Apr 26 2023 17:36:57 GCC 11.3.0
Oct 16 14:39:24 wibble sexpots-line1: TCP Host: endofthelinebbs.com
Oct 16 14:39:24 wibble sexpots-line1: TCP Port: 23
Oct 16 14:39:24 wibble sexpots-line1: Opening Communications Device (COM Port): /dev/ttyACM0
Oct 16 14:39:24 wibble sexpots-line1: COM Port device handle: 3
Oct 16 14:39:24 wibble sexpots-line1: COM Port DTE rate: 0 bps
Oct 16 14:39:24 wibble sexpots-line1: Initializing modem:
Oct 16 14:39:24 wibble sexpots-line1: Modem Command: AT&F1s0=0m0l1s48=7s36=5&W
Oct 16 14:39:24 wibble sexpots-line1: Waiting for Modem Response ...
Oct 16 14:39:29 wibble sexpots-line1: Modem Response TIMEOUT (5 seconds) on /dev/ttyACM0
Oct 16 14:39:29 wibble sexpots-line1: Retry #1: sending modem command (AT&F1s0=0m0l1s48=7s36=5&W) on /dev/ttyACM0
Oct 16 14:39:29 wibble sexpots-line1: Dropping DTR on /dev/ttyACM0
Oct 16 14:39:29 wibble sexpots-line1: Raising DTR on /dev/ttyACM0
Oct 16 14:39:29 wibble sexpots-line1: Modem Command: AT&F1s0=0m0l1s48=7s36=5&W
Oct 16 14:39:29 wibble sexpots-line1: Waiting for Modem Response ...
Oct 16 14:39:29 wibble sexpots-line1: Modem Response: AT&F1s0=0m0l1s48=7s36=5&W
Oct 16 14:39:29 wibble sexpots-line1: Enabling modem Caller-ID:
Oct 16 14:39:29 wibble sexpots-line1: Modem Command: AT#CID=1
Oct 16 14:39:29 wibble sexpots-line1: Waiting for Modem Response ...
Oct 16 14:39:30 wibble sexpots-line1: Modem Response: OK
Oct 16 14:39:30 wibble sexpots-line1: Waiting for incoming call (Ring Indication) ...

      the log looks something like this...

      sendto(4, "<14>Oct 16 14:39:24 sexpots-line1: Opening Communications Device (COM Port): /dev/ttyACM0", 89, MSG_NOSIGNAL, NULL, 0) = 89
openat(AT_FDCWD, "/dev/ttyACM0", O_RDWR|O_NONBLOCK) = 3
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, {B0 -opost -isig -icanon -echo ...}) = 0
ioctl(3, TCGETS, {B0 -opost -isig -icanon -echo ...}) = 0
sendto(4, "<14>Oct 16 14:39:24 sexpots-line1: COM Port device handle: 3", 60, MSG_NOSIGNAL, NULL, 0) = 60
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, {B0 -opost -isig -icanon -echo ...}) = 0
ioctl(3, TCGETS, {B0 -opost -isig -icanon -echo ...}) = 0
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, {B0 -opost -isig -icanon -echo ...}) = 0
ioctl(3, TCGETS, {B0 -opost -isig -icanon -echo ...}) = 0
ioctl(3, TCGETS, {B0 -opost -isig -icanon -echo ...}) = 0
sendto(4, "<14>Oct 16 14:39:24 sexpots-line1: COM Port DTE rate: 0 bps", 59, MSG_NOSIGNAL, NULL, 0) = 59
ioctl(3, TIOCMBIS, [TIOCM_DTR])         = 0
sendto(4, "<14>Oct 16 14:39:24 sexpots-line1: Initializing modem:", 54, MSG_NOSIGNAL, NULL, 0) = 54
sendto(4, "<14>Oct 16 14:39:24 sexpots-line1: Modem Command: AT&F1s0=0m0l1s48=7s36=5&W", 75, MSG_NOSIGNAL, NULL, 0) = 75
write(3, "A", 1)                        = 1
write(3, "T", 1)                        = 1
write(3, "&", 1)                        = 1
write(3, "F", 1)                        = 1
write(3, "1", 1)                        = 1
write(3, "s", 1)                        = 1
write(3, "0", 1)                        = 1
write(3, "=", 1)                        = 1
write(3, "0", 1)                        = 1
write(3, "m", 1)                        = 1
write(3, "0", 1)                        = 1
write(3, "l", 1)                        = 1
write(3, "1", 1)                        = 1
write(3, "s", 1)                        = 1
write(3, "4", 1)                        = 1
write(3, "8", 1)                        = 1
write(3, "=", 1)                        = 1
write(3, "7", 1)                        = 1
write(3, "s", 1)                        = 1
write(3, "3", 1)                        = 1
write(3, "6", 1)                        = 1
write(3, "=", 1)                        = 1
write(3, "5", 1)                        = 1
write(3, "&", 1)                        = 1
write(3, "W", 1)                        = 1
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=100000000}, 0x7ffef742a9b0) = 0
ioctl(3, TCFLSH, TCIFLUSH)              = 0
write(3, "\r", 1)                       = 1
sendto(4, "<15>Oct 16 14:39:24 sexpots-line1: Waiting for Modem Response ...", 65, MSG_NOSIGNAL, NULL, 0) = 65

      Then I get 60,000 lines of

      read(3, 0x7ffef742a98f, 1)              = -1 EAGAIN (Resource temporarily unavailable)
clock_nanosleep(CLOCK_REALTIME, 0, {tv_sec=0, tv_nsec=1000000}, 0x7ffef742aa60) = 0

      However, as we've seen the resource is (or should be) available.

      Running through service, yet a different result:

      root@wibble:/usr/local/etc# systemctl start sexpots-line1
Oct 16 14:44:10 wibble systemd[1]: Started sexpots-line1.service.
Oct 16 14:44:10 wibble sexpots-line1: Reading /usr/local/etc/sexpots-line1.ini
Oct 16 14:44:10 wibble sexpots-line1: Synchronet Communications I/O Library for Linux v1.19
Oct 16 14:44:10 wibble sexpots-line1: Build Apr 26 2023 17:36:57 GCC 11.3.0
Oct 16 14:44:10 wibble sexpots-line1: TCP Host: endofthelinebbs.com
Oct 16 14:44:10 wibble sexpots-line1: TCP Port: 23
Oct 16 14:44:10 wibble sexpots-line1: Opening Communications Device (COM Port): /dev/ttyACM0
root@wibble:/usr/local/etc# Oct 16 14:44:10 wibble sexpots-line1: COM Port device handle: 3
Oct 16 14:44:10 wibble sexpots-line1: COM Port DTE rate: 0 bps
Oct 16 14:44:10 wibble sexpots-line1: Initializing modem:
Oct 16 14:44:10 wibble sexpots-line1: Modem Command: AT&F1s0=0m0l1s48=7s36=5&W
Oct 16 14:44:10 wibble sexpots-line1: ERROR 11 sending modem command (AT&F1s0=0m0l1s48=7s36=5&W) on /dev/ttyACM0
Oct 16 14:44:10 wibble sexpots-line1: Retry #1: sending modem command (AT&F1s0=0m0l1s48=7s36=5&W) on /dev/ttyACM0
Oct 16 14:44:10 wibble sexpots-line1: Dropping DTR on /dev/ttyACM0
Oct 16 14:44:11 wibble sexpots-line1: Raising DTR on /dev/ttyACM0
Oct 16 14:44:11 wibble sexpots-line1: Modem Command: AT&F1s0=0m0l1s48=7s36=5&W
Oct 16 14:44:11 wibble sexpots-line1: ERROR 11 sending modem command (AT&F1s0=0m0l1s48=7s36=5&W) on /dev/ttyACM0
Oct 16 14:44:11 wibble sexpots-line1: Retry #2: sending modem command (AT&F1s0=0m0l1s48=7s36=5&W) on /dev/ttyACM0
Oct 16 14:44:11 wibble sexpots-line1: Dropping DTR on /dev/ttyACM0
Oct 16 14:44:11 wibble sexpots-line1: Raising DTR on /dev/ttyACM0
Oct 16 14:44:11 wibble sexpots-line1: Modem Command: AT&F1s0=0m0l1s48=7s36=5&W
Oct 16 14:44:11 wibble sexpots-line1: ERROR 11 sending modem command (AT&F1s0=0m0l1s48=7s36=5&W) on /dev/ttyACM0
Oct 16 14:44:11 wibble sexpots-line1: Modem command (AT&F1s0=0m0l1s48=7s36=5&W) failure on /dev/ttyACM0 (3 attempts)
Oct 16 14:44:11 wibble sexpots-line1: Cleaning up ...
Oct 16 14:44:11 wibble sexpots-line1: Done (handled 0 calls).
Oct 16 14:44:11 wibble sexpots[31739]: Synchronet External POTS Support v2.0-Linux Copyright 2023 Rob Swindell
Oct 16 14:44:11 wibble systemd[1]: sexpots-line1.service: Deactivated successfully.

      So I'm at a bit of a loss as to what is happening here.

      I run minicom with minicom -D /dev/ttyACM0 and then send the command

      Welcome to minicom 2.8

OPTIONS: I18n
Port /dev/ttyACM0, 14:44:10

Press CTRL-A Z for help on special keys

AT&F1s0=0m0l1s48=7s36=5&W
OK

OK

      Works fine.

    • Rob Swindell
      Rob Swindell @rswindell ·
      Owner

      The strace output shows that the entire init string is being sent to the com port by sexpots.

      So the issue description "Entire modem init string not being sent" is not actually happening.

      If the actual question you wanted to ask was: why I am getting an "ERROR 11 sending modem command" or what does that error mean? That would be a different issue.

    • Nigel Reed
      Nigel Reed @nelgin ·
      Author Developer

      Can't be arsed. Just going to close it.

    • Nigel Reed closed

      closed

    • Rob Swindell
      Rob Swindell @rswindell ·
      Owner

      Error 11 is EAGAIN ("Try again") - for which there is no retry/loop in sexpots today. I could add one, thought I'm not sure it'd solve this issue. Might be worth an experiment.

    • Rob Swindell mentioned in commit 54a05b65

      mentioned in commit 54a05b65

    Please register or sign in to reply