mgetty won't timeout (gets hung) after MODEM hangup

[Luke]

System Information: Linux seaecho 2.6.32-40-server #87-Ubuntu SMP Tue Mar 6 02:10:02 UTC 2012 x86_64 GNU/Linux
Description: Ubuntu 10.04.4 LTS
Release: 10.04

mgetty:
  Installed: 1.1.36-1.5
  Candidate: 1.1.36-1.5
  Version table:
 *** 1.1.36-1.5 0
        500 http://us.archive.ubuntu.com/ubuntu/ lucid/universe Packages
        100 /var/lib/dpkg/status

Problem:
While mgetty is running (prior to it having accepted a \r terminated string and forking to login) if I initiate a hangup mgetty gets hung and won't timout. It stays in this condition indefinitely (until I stop/start it). In addition, DTR is soon deasserted after the hangup and stays in this condition indefinitely (until I stop/start it). It's not a cable issue, I've tried several and have "rung out" the connections and they are all wired correctly. Below is the mgetty logfile that shows the last reported entry (getlogname (FIDO AUTO_PPP), read:), no other entries occur while mgetty remains in this hung state. Finally, if I hangup *AFTER* mgetty has forked to login and then initiate a hangup there are no issues.

mgetty logfile:
04/15 13:15:23 yS0 mgetty: interim release 1.1.36-Jun15
04/15 13:15:23 yS0 check for lockfiles
04/15 13:15:23 yS0 checklock: no active process has lock, will remove
04/15 13:15:23 yS0 locking the line
04/15 13:15:23 yS0 makelock(ttyS0) called
04/15 13:15:23 yS0 do_makelock: lock='/var/lock/LCK..ttyS0'
04/15 13:15:23 yS0 lock made
04/15 13:15:23 yS0 tio_get_rs232_lines: status: RTS CTS DSR DTR
04/15 13:15:23 yS0 lowering DTR to reset Modem
04/15 13:15:24 yS0 tss: set speed to 38400 (017)
04/15 13:15:24 yS0 tio_set_flow_control( HARD )
04/15 13:15:24 yS0 waiting for line to clear (VTIME=1), read:
04/15 13:15:24 yS0 send: AT&C1[0d]
04/15 13:15:24 yS0 waiting for ``OK''
04/15 13:15:24 yS0 got: AT&C1[0d]
04/15 13:15:24 yS0 CND: AT&C1[0d][0a]OK ** found **
04/15 13:15:24 yS0 send: AT#CID=1[0d]
04/15 13:15:24 yS0 waiting for ``OK''
04/15 13:15:24 yS0 got: [0d]
04/15 13:15:24 yS0 CND: OK[0a]AT#CID=1[0d]
04/15 13:15:24 yS0 CND: AT#CID=1[0d][0a]OK ** found **
04/15 13:15:24 yS0 send: AT&A3[0d]
04/15 13:15:24 yS0 waiting for ``OK''
04/15 13:15:24 yS0 got: [0d]
04/15 13:15:24 yS0 CND: OK[0a]AT&A3[0d]
04/15 13:15:24 yS0 CND: AT&A3[0d][0a]OK ** found **
04/15 13:15:24 yS0 send: &ATX6[0d]
04/15 13:15:24 yS0 waiting for ``OK''
04/15 13:15:24 yS0 got: [0d]
04/15 13:15:24 yS0 CND: OK[0a]ATX6[0d]
04/15 13:15:24 yS0 CND: ATX6[0d][0a]OK ** found **
04/15 13:15:24 yS0 send: AT&D2[0d]
04/15 13:15:24 yS0 waiting for ``OK''
04/15 13:15:24 yS0 got: [0d]
04/15 13:15:24 yS0 CND: OK[0a]AT&D2[0d]
04/15 13:15:24 yS0 CND: AT&D2[0d][0a]OK ** found **
04/15 13:15:24 yS0 waiting for line to clear (VTIME=3), read: [0d][0a]
04/15 13:15:24 yS0 removing lock file
04/15 13:15:24 yS0 waiting...
04/15 13:16:09 yS0 select returned 1
04/15 13:16:09 yS0 checking lockfiles, locking the line
04/15 13:16:09 yS0 makelock(ttyS0) called
04/15 13:16:09 yS0 do_makelock: lock='/var/lock/LCK..ttyS0'
04/15 13:16:09 yS0 lock made
04/15 13:16:09 yS0 wfr: waiting for ``RING''
04/15 13:16:09 yS0 got: [0d][0a]RING[0d]
04/15 13:16:09 yS0 CND: RING
04/15 13:16:09 yS0 wfr: rc=0, drn=0
04/15 13:16:09 yS0 wfr: waiting for ``RING''
04/15 13:16:09 yS0 got: [0a][0d][0a]RING[0d]
04/15 13:16:15 yS0 CND: RING
04/15 13:16:15 yS0 wfr: rc=0, drn=0
04/15 13:16:15 yS0 wfr: waiting for ``RING''
04/15 13:16:15 yS0 got: [0a][0d][0a]RING[0d]
04/15 13:16:21 yS0 CND: RING
04/15 13:16:21 yS0 wfr: rc=0, drn=0
04/15 13:16:21 yS0 CND: check no: 'none'
04/15 13:16:21 yS0 send: ATA[0d]
04/15 13:16:21 yS0 waiting for ``CONNECT''
04/15 13:16:21 yS0 got: ATA[0d]
04/15 13:16:21 yS0 CND: OKATA[0d][0a]CONNECT ** found **
04/15 13:16:36 yS0 send:
04/15 13:16:36 yS0 waiting for ``_''
04/15 13:16:36 yS0 got: 26400/ARQ/V34/LAPM/V42BIS[0d]
04/15 13:16:36 yS0 CND: CONNECT 26400/ARQ/V34/LAPM/V42BIS
04/15 13:16:36 yS0 CND: found: 26400/ARQ/V34/LAPM/V42BIS[0a] ** found **
04/15 13:16:36 yS0 waiting for line to clear (VTIME=3), read:
04/15 13:16:37 yS0 looking for utmp entry... (my PID: 3331)
04/15 13:16:37 yS0 tio_set_flow_control( HARD )
04/15 13:16:37 yS0 print welcome banner (/etc/issue.apex)
04/15 13:16:37 yS0 getlogname (FIDO AUTO_PPP), read:

mgetty.config:
#
# mgetty configuration file
#
# this is a sample configuration file, see mgetty.info for details
#
# comment lines start with a "#", empty lines are ignored

# ----- global section -----
#
# In this section, you put the global defaults, per-port stuff is below

# set the global debug level to "4" (default from policy.h)
debug 4

# set the local fax station id
#fax-id

# access the modem(s) with 38400 bps
speed 38400

# use an alternate issue file, to avoid being bitten by linuxlogo
issue-file /etc/issue.mgetty

# use these options to make the /dev/tty-device owned by "uucp.uucp"
# and mode "rw-rw-r--" (0664). *LEADING ZERO NEEDED!*
#port-owner uucp
#port-group uucp
#port-mode 0664

# use these options to make incoming faxes owned by "root.uucp"
# and mode "rw-r-----" (0640). *LEADING ZERO NEEDED!*
#fax-owner root
#fax-group uucp
#fax-mode 0640

# ----- port specific section -----
#
# Here you can put things that are valid only for one line, not the others
#
#

# USRobotics 57k v.92 Sportster MODEM (Model 5686G) for APEX float telemetry. Dialin #: 831-775-1654
#
port ttyS0
  speed 38400
  debug 9
  data-only y
  rings 3
  issue-file /etc/issue.apex
  login-prompt \V\n\r\R \m\n\r\P \S (\I)\n\r(\Y)\n\r@ login:\040
  login-time 120
  statistics-chat "" ATI4 OK ATI6 OK
  init-chat "" AT&C1 OK AT#CID=1 OK AT&A3 OK &ATX6 OK AT&D3 OK

# Zoom V.FX 28.8, connected to ttyS0: don't do fax, less logging
#
#port ttyS0
# debug 3
# data-only y

# some other Rockwell modem, needs "switchbd 19200" to receive faxes
# properly (otherwise it will fail with "timeout").
#
#port ttyS1
# speed 38400
# switchbd 19200

# ZyXEL 2864, connected to ttyS2: maximum debugging, grab statistics
#
#port ttyS2
# debug 8
# init-chat "" \d\d\d+++\d\d\dAT&FS2=255 OK ATN3S0=0S13.2=1 OK
# statistics-chat "" AT OK ATI2 OK
# statistics-file /var/log/statistics.ttyS2
# modem-type cls2

# direct connection of a VT100 terminal which doesn't like DTR drops
# ("direct" meaning "*no* *modem*". NEVER enable "direct yes" on modem lines!)
#
#port ttyS3
# direct y
# speed 19200
# toggle-dtr n

[Launchpad Janitor (janitor)]

Status changed to 'Confirmed' because the bug affects multiple users.

[John Dunlap (dunlap)]

My symptoms are similar. I have had 4 serial modems connected with an 8-port Comtrol RocketPort OctaCable PCI board to various Linux boxes for more than 10 years without trouble until a few months ago. Currently with Ubuntu 10.04.4 I must kill -9 the mgetty jobs to get things going again after they get stuck. I've used Red Hat and earlier versions of Ubuntu in the past with no trouble. I'm pretty sure I didn't have trouble with versions of Ubuntu earlier than 10.04.4. For me, the mgettys seem to get stuck most often when the carrier is lost. Also, it's not very predictable -- it doesn't always happen. These modems are used to accept old-fashioned tty logins (not ppp) from remote science instruments via the Iridium satellite system. Regards, John

[John Dunlap (dunlap)]

I have a patch for mgetty which has been running for a more than a year and cures the problem. - John

[Luke (ljc-u)]

Some good news, the current LTS release of Ubuntu server is running the Ubuntu/Debian distribution of mgetty just fine (info below). Mgetty now respawns (doesn't hang) like it did with 12.04 (described above).

I suspect the problem was with Upstart all along, however, the mgetty package in 14.04 LTS is an update from the one used in the the 12.04 LTS release.

http://packages.ubuntu.com/trusty/mgetty
http://packages.ubuntu.com/precise/mgetty

Luke

root@somewhere:/var/log/mgetty# uname -a
Linux somewhere 3.13.0-35-generic #62-Ubuntu SMP Fri Aug 15 01:58:42 UTC 2014 x86_64 x86_64 x86_64 GNU/Linux

root@somewhere:/var/log/mgetty# lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description: Ubuntu 14.04.1 LTS
Release: 14.04
Codename: trusty

root@somewhere:/var/log/mgetty# initctl --version
initctl (upstart 1.12.1)
Copyright (C) 2006-2014 Canonical Ltd., 2011 Scott James Remnant

root@somewhere:/var/log/mgetty# apt-cache show mgetty
Package: mgetty
Priority: extra
Section: universe/comm
Installed-Size: 369
Maintainer: Ubuntu Developers <email address hidden>
Original-Maintainer: Andreas Barth <email address hidden>
Architecture: amd64
Version: 1.1.36-2ubuntu1

root@somewhere:/var/log/mgetty# dmesg | grep tty
[ 0.000000] console [tty0] enabled
[ 0.874880] 0000:37:09.0: ttyS4 at I/O 0xe080 (irq = 21, base_baud = 921600) is a 16550A
[ 0.895245] 0000:37:09.0: ttyS5 at I/O 0xe088 (irq = 21, base_baud = 921600) is a 16550A
[14326.348920] init: ttyS4 main process ended, respawning
[14573.114758] init: ttyS4 main process (2530) terminated with status 10