Bug 200445

Summary: login into system on serial line /dev/cuaU0 hangs on open of /dev/tty
Product: Base System Reporter: Matthias Apitz <guru>
Component: kernAssignee: freebsd-bugs (Nobody) <bugs>
Status: New ---    
Severity: Affects Only Me CC: amvandemore, emaste, guru, kib
Priority: ---    
Version: CURRENT   
Hardware: i386   
OS: Any   

Description Matthias Apitz 2015-05-25 19:08:21 UTC
what is not working:
 
- if I login as any other unpriv user (and I created a new one for this)
  it hangs after presenting the /etc/motd file; it just hangs
 
login: valentin
Password: .....
 
Last login: ....
FreeBSD 11.0-CURRENT (GENERIC) #1 r276659M: Tue Apr 28 15:50:23 CEST 2015
 
Welcome to FreeBSD!
 
(hanging)

I figured out what is causing it: the type of the login shell; it works
with /bin/csh, it does not work with /bin/sh.

When it hangs, if you launch a truss on the hanging process /bin/sh
this process resumes normal operation and you can login.

I have two more observations on this:

- when it hangs in the login shell /bin/sh, a Ctrl-C on the terminal
  cancels the hang and a new "login:" appears;

- regardless of the shell, if one starts the MUA 'mutt' (an alpha-mode
  MUA) and below this a 'vim' to write the mail, on return from 'vim' to
  'mutt' (the vim is already terminated as process) the 'mutt' hangs too
  and on Ctrl-C it resumes normal operation;
Comment 1 Ed Maste freebsd_committer freebsd_triage 2015-05-25 19:11:58 UTC
Does it also fail if you use csh as your login shell, then exec sh from there?
Comment 2 Matthias Apitz 2015-05-26 04:35:56 UTC
(In reply to Ed Maste from comment #1)

If you start a /bin/sh after correct login with /bin/csh as login-shell, the /bin/sh hangs as well forever; trussing it, it shows that it hangs in an open(2) syscall for /dev/tty:

mmap(0x0,32768,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 671612928 (0x28080000)
issetugid(0x2807e76c,0xbfbfefc8,0x20,0x0,0x0,0x0) = 0 (0x0)
lstat("/etc",{ mode=drwxr-xr-x ,inode=9229440,size=2560,blksize=32768 }) = 0 (0x0)
lstat("/etc/libmap.conf",{ mode=-rw-r--r-- ,inode=9229485,size=102,blksize=32768 }) = 0 (0x0)
open("/etc/libmap.conf",O_CLOEXEC,00)		 = 3 (0x3)
fstat(3,{ mode=-rw-r--r-- ,inode=9229485,size=102,blksize=32768 }) = 0 (0x0)
mmap(0x0,102,PROT_READ,MAP_PRIVATE,3,0x0)	 = 671645696 (0x28088000)
close(3)					 = 0 (0x0)
lstat("/usr",{ mode=drwxr-xr-x ,inode=1364352,size=512,blksize=32768 }) = 0 (0x0)
lstat("/usr/local",{ mode=drwxr-xr-x ,inode=1364414,size=512,blksize=32768 }) = 0 (0x0)
lstat("/usr/local/etc",{ mode=drwxr-xr-x ,inode=1605894,size=2048,blksize=32768 }) = 0 (0x0)
lstat("/usr/local/etc/libmap.d",{ mode=drwxr-xr-x ,inode=2416694,size=512,blksize=32768 }) = 0 (0x0)
open("/usr/local/etc/libmap.d",O_NONBLOCK|O_DIRECTORY|O_CLOEXEC,05001762160) = 3 (0x3)
__sysctl(0xbfbfd490,0x2,0x2807f170,0xbfbfd48c,0x0,0x0) = 0 (0x0)
fstatfs(0x3,0xbfbfd4c8,0x0,0x0,0x0,0x3)		 = 0 (0x0)
munmap(0x28087000,4096)				 = 0 (0x0)
mmap(0x0,40960,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 671649792 (0x28089000)
getdirentries(0x3,0x2808a000,0x1000,0x28086014,0x28086014,0x2807e470) = 24 (0x18)
getdirentries(0x3,0x2808a000,0x1000,0x28086014,0x28086014,0x2807e470) = 0 (0x0)
close(3)					 = 0 (0x0)
munmap(0x28088000,102)				 = 0 (0x0)
open("/var/run/ld-elf.so.hints",O_CLOEXEC,00)	 = 3 (0x3)
read(3,"Ehnt\^A\0\0\0\M^@\0\0\0\M-(\0\0"...,128) = 128 (0x80)
lseek(3,0x80,SEEK_SET)				 = 128 (0x80)
read(3,"/lib:/usr/lib:/usr/lib/compat:/u"...,168) = 168 (0xa8)
close(3)					 = 0 (0x0)
access("/lib/libedit.so.7",0)			 = 0 (0x0)
open("/lib/libedit.so.7",O_CLOEXEC,00)		 = 3 (0x3)
fstat(3,{ mode=-r--r--r-- ,inode=1203856,size=134368,blksize=32768 }) = 0 (0x0)
mmap(0x0,4096,PROT_READ,MAP_PRIVATE|MAP_PREFAULT_READ,3,0x0) = 671641600 (0x28087000)
mmap(0x0,147456,PROT_NONE,MAP_PRIVATE|MAP_ANON|MAP_NOCORE,-1,0x0) = 671690752 (0x28093000)
mmap(0x28093000,131072,PROT_READ|PROT_EXEC,MAP_PRIVATE|MAP_FIXED|MAP_NOCORE|MAP_PREFAULT_READ,3,0x0) = 671690752 (0x28093000)
mmap(0x280b3000,8192,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_FIXED|MAP_PREFAULT_READ,3,0x1f000) = 671821824 (0x280b3000)
mmap(0x280b5000,8192,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_FIXED|MAP_ANON,-1,0x0) = 671830016 (0x280b5000)
munmap(0x28087000,4096)				 = 0 (0x0)
close(3)					 = 0 (0x0)
access("/lib/libc.so.7",0)			 = 0 (0x0)
open("/lib/libc.so.7",O_CLOEXEC,00)		 = 3 (0x3)
fstat(3,{ mode=-r--r--r-- ,inode=1203843,size=1384432,blksize=32768 }) = 0 (0x0)
mmap(0x0,4096,PROT_READ,MAP_PRIVATE|MAP_PREFAULT_READ,3,0x0) = 671641600 (0x28087000)
mmap(0x0,1409024,PROT_NONE,MAP_PRIVATE|MAP_ANON|MAP_NOCORE,-1,0x0) = 671838208 (0x280b7000)
mmap(0x280b7000,1298432,PROT_READ|PROT_EXEC,MAP_PRIVATE|MAP_FIXED|MAP_NOCORE|MAP_PREFAULT_READ,3,0x0) = 671838208 (0x280b7000)
mmap(0x281f4000,28672,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_FIXED|MAP_PREFAULT_READ,3,0x13d000) = 673136640 (0x281f4000)
mmap(0x281fb000,81920,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_FIXED|MAP_ANON,-1,0x0) = 673165312 (0x281fb000)
munmap(0x28087000,4096)				 = 0 (0x0)
close(3)					 = 0 (0x0)
access("/lib/libncursesw.so.8",0)		 = 0 (0x0)
open("/lib/libncursesw.so.8",O_CLOEXEC,00)	 = 3 (0x3)
fstat(3,{ mode=-r--r--r-- ,inode=1203880,size=305200,blksize=32768 }) = 0 (0x0)
mmap(0x0,4096,PROT_READ,MAP_PRIVATE|MAP_PREFAULT_READ,3,0x0) = 671641600 (0x28087000)
mmap(0x0,307200,PROT_NONE,MAP_PRIVATE|MAP_ANON|MAP_NOCORE,-1,0x0) = 673247232 (0x2820f000)
mmap(0x2820f000,294912,PROT_READ|PROT_EXEC,MAP_PRIVATE|MAP_FIXED|MAP_NOCORE|MAP_PREFAULT_READ,3,0x0) = 673247232 (0x2820f000)
mmap(0x28257000,12288,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_FIXED|MAP_PREFAULT_READ,3,0x48000) = 673542144 (0x28257000)
munmap(0x28087000,4096)				 = 0 (0x0)
close(3)					 = 0 (0x0)
munmap(0x2808e000,20480)			 = 0 (0x0)
mmap(0x0,69632,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 673554432 (0x2825a000)
sysarch(0xa,0xbfbfe3ac,0x280826e0,0x2807e470,0xbfbfe3d0,0x280669c3) = 0 (0x0)
sigprocmask(SIG_BLOCK,SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2,0x0) = 0 (0x0)
sigprocmask(SIG_SETMASK,0x0,0x0)		 = 0 (0x0)
readlink("/etc/malloc.conf",0xbfbfdb47,1024)	 ERR#2 'No such file or directory'
issetugid(0x0,0xbfbfdb47,0x400,0x0,0x0,0x0)	 = 0 (0x0)
mmap(0x0,4194304,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 673624064 (0x2826b000)
munmap(0x2826b000,4194304)			 = 0 (0x0)
mmap(0x0,8384512,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 673624064 (0x2826b000)
munmap(0x2826b000,1658880)			 = 0 (0x0)
munmap(0x28800000,2531328)			 = 0 (0x0)
sigprocmask(SIG_BLOCK,SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2,0x0) = 0 (0x0)
sigprocmask(SIG_SETMASK,0x0,0x0)		 = 0 (0x0)
sigprocmask(SIG_BLOCK,SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2,0x0) = 0 (0x0)
sigprocmask(SIG_SETMASK,0x0,0x0)		 = 0 (0x0)
sigprocmask(SIG_BLOCK,SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2,0x0) = 0 (0x0)
sigprocmask(SIG_SETMASK,0x0,0x0)		 = 0 (0x0)
sigprocmask(SIG_BLOCK,SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2,0x0) = 0 (0x0)
sigprocmask(SIG_SETMASK,0x0,0x0)		 = 0 (0x0)
getpid()					 = 1807 (0x70f)
geteuid()					 = 0 (0x0)
getppid()					 = 1806 (0x70e)
mmap(0x0,4194304,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 679477248 (0x28800000)
getuid()					 = 0 (0x0)
geteuid()					 = 0 (0x0)
getgid()					 = 0 (0x0)
getegid()					 = 0 (0x0)
ioctl(0,TIOCGETA,0xbfbfec90)			 = 0 (0x0)
ioctl(1,TIOCGETA,0xbfbfec90)			 = 0 (0x0)
sigaction(SIGINT,0x0,{ SIG_DFL SA_RESTART ss_t }) = 0 (0x0)
sigaction(SIGINT,{ 0x8060590 0x0 ss_t },0x0)	 = 0 (0x0)
sigaction(SIGQUIT,0x0,{ SIG_DFL SA_RESTART ss_t }) = 0 (0x0)
sigaction(SIGQUIT,{ 0x8060590 0x0 ss_t },0x0)	 = 0 (0x0)
sigaction(SIGTERM,0x0,{ SIG_DFL SA_RESTART ss_t }) = 0 (0x0)
sigaction(SIGTERM,{ SIG_IGN 0x0 ss_t },0x0)	 = 0 (0x0)
ioctl(0,TIOCGETA,0xbfbfec58)			 = 0 (0x0)
fcntl(0,F_GETFL,)				 = 2 (0x2)
fcntl(1,F_GETFL,)				 = 2 (0x2)
fcntl(2,F_GETFL,)				 = 2 (0x2)
sigprocmask(SIG_BLOCK,SIGWINCH,0x0)		 = 0 (0x0)
ioctl(1,TIOCGETA,0xbfbfdf18)			 = 0 (0x0)
issetugid(0xbfbfdb22,0x2824cc6e,0x3fa,0x1409fc,0x281d89e0,0x2807e470) = 0 (0x0)
open("/root/.termcap.db",O_CLOEXEC,00)		 ERR#2 'No such file or directory'
open("/root/.termcap",O_CLOEXEC,00)		 ERR#2 'No such file or directory'
open("/usr/share/misc/termcap.db",O_CLOEXEC,00)	 = 3 (0x3)
fstat(3,{ mode=-r--r--r-- ,inode=1526444,size=1343488,blksize=32768 }) = 0 (0x0)
read(3,"\0\^F\^Ua\0\0\0\^B\0\0\^D\M-R\0"...,260) = 260 (0x104)
pread(0x3,0x28846000,0x1000,0x4c000,0x0,0x28810060) = 4096 (0x1000)
pread(0x3,0x2884f000,0x1000,0x6a000,0x0,0x2807e470) = 4096 (0x1000)
pread(0x3,0x28850000,0x1000,0x4000,0x0,0x1)	 = 4096 (0x1000)
close(3)					 = 0 (0x0)
ioctl(1,TIOCGETA,0xbfbfdf18)			 = 0 (0x0)
ioctl(1,TIOCGETA,0xbfbfded8)			 = 0 (0x0)
ioctl(1,TIOCGWINSZ,0xbfbfdf30)			 = 0 (0x0)
ioctl(0,TIOCGWINSZ,0xbfbfe428)			 = 0 (0x0)
sigprocmask(SIG_SETMASK,0x0,0x0)		 = 0 (0x0)
ioctl(0,TIOCGETA,0x288067a8)			 = 0 (0x0)
sigprocmask(SIG_BLOCK,SIGHUP|SIGINT|SIGQUIT|SIGTERM|SIGTSTP|SIGCONT|SIGWINCH,0x0) = 0 (0x0)
sigprocmask(SIG_SETMASK,0x0,0x0)		 = 0 (0x0)
issetugid(0xbfbfe870,0x280c02f4,0x2807e470,0xbfbfe910,0x2806aadf,0xbfbfe898) = 0 (0x0)
open("/root/.editrc",O_RDONLY,0666)		 ERR#2 'No such file or directory'


[ hit Ctrl-C here ]


open("/dev/tty",O_RDWR|O_CLOEXEC,00)		 ERR#4 'Interrupted system call'
SIGNAL 2 (SIGINT)
sigreturn(0xbfbfe8c0,0x2,0x10006,0xbfbfe8c0,0x0,0x8060590) ERR#4 'Interrupted system call'
ioctl(0,TIOCGETA,0xbfbfec70)			 = 0 (0x0)
fcntl(0,0x11,0xa)				 = 10 (0xa)
ioctl(10,TIOCGPGRP,0xbfbfeca4)			 = 0 (0x0)
getpgrp()					 = 1806 (0x70e)
sigaction(SIGTSTP,0x0,{ SIG_DFL SA_RESTART ss_t }) = 0 (0x0)
sigaction(SIGTSTP,{ SIG_IGN 0x0 ss_t },0x0)	 = 0 (0x0)
sigaction(SIGTTOU,0x0,{ SIG_DFL SA_RESTART ss_t }) = 0 (0x0)
sigaction(SIGTTOU,{ SIG_IGN 0x0 ss_t },0x0)	 = 0 (0x0)
sigaction(SIGTTIN,0x0,{ SIG_DFL SA_RESTART ss_t }) = 0 (0x0)
sigaction(SIGTTIN,{ SIG_DFL 0x0 ss_t },0x0)	 = 0 (0x0)
setpgid(0x0,0x70f,0xa,0x0,0xbfbfed70,0xbfbfece0) = 0 (0x0)
ioctl(10,TIOCSPGRP,0xbfbfeca4)			 = 0 (0x0)
stat(".",{ mode=drwxr-xr-x ,inode=11797632,size=512,blksize=32768 }) = 0 (0x0)
stat("/root",{ mode=drwxr-xr-x ,inode=11797632,size=512,blksize=32768 }) = 0 (0x0)
sigprocmask(SIG_SETMASK,0x0,0x0)		 = 0 (0x0)
setpgid(0x0,0x70e,0xbfbfec48,0x0,0xbfbfec70,0xbfbfecd8) = 0 (0x0)
ioctl(10,TIOCSPGRP,0xbfbfec24)			 = 0 (0x0)
close(10)					 = 0 (0x0)
process exit, rval = 0
Comment 3 Matthias Apitz 2015-05-26 12:36:30 UTC
I dont know if this does matter, but just for the record: the serial line device /dev/cuaU0 from which the login was done and where the problem occures, was created by the uplcom(4) USB support for Prolific PL-2303/2303X/2303HX serial adapters driver;
Comment 4 Matthias Apitz 2015-05-26 16:17:27 UTC
the real problem is, that after login por the serial line /dev/cuaU0 no process is able to open /dev/tty, it just hangs on open(2) syscall; I verified this with a small C-code:

fd = open("/dev/tty", O_RDWR|O_CLOEXEC, 0);

gives in truss:

...
open("/dev/tty",O_RDWR|O_CLOEXEC,00)             ERR#4 'Interrupted system call'
SIGNAL 2 (SIGINT)

(the SIGINT is from Ctrl-C
Comment 5 Konstantin Belousov freebsd_committer freebsd_triage 2015-05-27 08:41:54 UTC
(In reply to Matthias Apitz from comment #4)
What is the wait channel for the hung open ?

Did you specified the line to use hw flow control ?  Does your cable has necessary wires, does your usb/com adapter supports hw flow control ?
Comment 6 Matthias Apitz 2015-05-27 10:02:53 UTC
(In reply to Konstantin Belousov from comment #5)

I have not specified hw flow control and I do not know if the USB-serial supports this. As described in the handbook, I added to /etc/ttys a line:

cuaU0 "/usr/libexec/getty std.9600"	vt102	on secure

and after 'kill -HUP 1' on the terminal, login as root is possible and, for example, an 'ls -lR /' works nicely passing the output fine to the VT102; i.e. I do not think, that we have some flow control issue; 

the only things I have figured out so far are:

1) one can not use /bin/sh as login shell, it will hang on login;
2) you can not open /dev/tty after login; it will hang
3) if you use MUA mutt, and below this the vim to write the mail, mutt will
   hang too after the end of vim; and a Ctrl-C makes it continue (perhaps
   for the same reason of hang on /dev/tty open call)

what Do you want me to check or change exactly?
Thanks
Comment 7 Matthias Apitz 2015-05-27 18:43:37 UTC
it works now fine with this line in /etc/ttys:

ttyU0	"/usr/libexec/getty 3wire.9600"	vt102	on secure

and we can close the issue; maybe the cap. 26.3.1 should be changed to use 'ttyUX' and not 'ttyuX' (i.e. capital 'U') and point out the difference between '/dev/cuaUX' and '/dev/ttyUX';

please close the issue; thanks to Ed Schouten <ed@nuxi.nl> for the helping hint;
Comment 8 amvandemore 2015-10-27 19:01:36 UTC
I think you can close the ticket since you created it.

Also ttyUX is correct in your situation since it's USB -> serial adapter and ucom is in play.