WelcomeWelcome | FAQFAQ | DownloadsDownloads | WikiWiki

Author Topic: Perl: forked child screws up serial port settings on exit  (Read 1898 times)

Offline vbs

  • Newbie
  • *
  • Posts: 21
Perl: forked child screws up serial port settings on exit
« on: May 15, 2014, 04:49:39 PM »
Guys,

I am new to TC but I like it quite a lot! Its working fine for me but I am having one quite strange issue. I am really not sure if it is actually TinyCore related at all. It might also be a perl, kernel, vmware or FTDI or whatever issue :( But I hope you guys can point me in the right direction where to search for a solution.

The problem is like this:
I am using latest TC (5.3) running in VMware Workstation 10 hosted on a Windows 8.1 machine. I have one USB-serial-port (FTDI) connected to the VM (and so to TC). I have running a perl script (fhem http://fhem.de/) reading and writing to that serial port which is working fine to some point. Also the script uses 'fork' to spawn a child processes from time to time. Then suddenly the serial ports stops working and neither can receive nor send further data. After intensive testing it turned out that the serial port stops working exactly in the moment when a forked process dies.

I wrote a small test script in perl which does recreate this exact scenario. It does nothing but permanently reading data from a serial port then forking a child which exits after some seconds. Its like this:
Code: [Select]
require Device::SerialPort;
my $po = new Device::SerialPort("/dev/ttyS0@38400");
die("could not open port") unless $po;

$po->reset_error();
      $po->baudrate(38400);
      $po->databits(8);
      $po->parity('none');
      $po->stopbits(1);
      $po->handshake('none');

      # This part is for some Linux kernel versions whih has strange default
      # settings.  Device::SerialPort is nice: if the flag is not defined for
      # your OS then it will be ignored.

      $po->stty_icanon(0);
      #$po->stty_parmrk(0); # The debian standard install does not have it
      $po->stty_icrnl(0);
      $po->stty_echoe(0);
      $po->stty_echok(0);
      $po->stty_echoctl(0);

      # Needed for some strange distros
      $po->stty_echo(0);
      $po->stty_icanon(0);
      $po->stty_isig(0);
      $po->stty_opost(0);
      $po->stty_icrnl(0);
   
    $po->write_settings;


my $i=0;
while(1) {
my $buf = $po->input();
    print "LEN: " . length($buf) . " :";
    (my $hex = unpack("H*", $buf)) =~ s/(..)/$1 /g;
    print $hex, "\n";
       
sleep 1;
$i = $i + 1;

if ($i == 7)
{
my $pid = fork();
if ($pid) {
print "I HAVE FORKED\n";
}
else
{
print "CHILD\n";
sleep 5;
print "EXIT\n";
exit(0);
}
    }
}

Exactly after the forked child calls "exit" the main process cannot longer read data from the port (it calls "input" but no data appears).
I used strace to find out what the perl process is doing and it seems like the child does reconfigure the stty heavily upon exit. It changes the baud rate and several other parameters:
Code: [Select]
[pid  4699] rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4699] rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
[pid  4699] nanosleep({1, 0}, 0xbfc935ac) = 0
[pid  4699] time(NULL)                  = 1400151956
[pid  4699] read(3, "", 255)            = 0
[pid  4699] time(NULL)                  = 1400151956
[pid  4699] rt_sigprocmask(SIG_BLOCK, [CHLD], [], 8) = 0
[pid  4699] rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4699] rt_sigprocmask(SIG_SETMASK, [], NULL, 8) = 0
[pid  4699] nanosleep({1, 0},  <unfinished ...>
[pid  4701] <... nanosleep resumed> 0xbfc935ac) = 0
[pid  4701] time(NULL)                  = 1400151957
[pid  4701] ioctl(3, TCFLSH, 0x2)       = 0
[pid  4701] ioctl(3, SNDCTL_TMR_START or TCSETS, {B9600 opost isig icanon echo ...}) = 0  [b]<<<------------------- HERE IT DOES CALL SET A NEW BAUD RATE[/b]
[pid  4701] close(3)                    = 0
[pid  4701] close(3)                    = -1 EBADF (Bad file descriptor)
[pid  4701] rt_sigaction(SIG_0, NULL, {SIG_DFL, ~[HUP INT ILL TRAP ABRT USR1 PIPE TERM STKFLT TSTP TTIN XCPU WINCH SYS RT_1 RT_2 RT_3 RT_5 RT_6 RT_9 RT_10 RT_12 RT_13 RT_14 RT_15 RT_17 RT_18 RT_20 RT_21 RT_22 RT_23 RT_24 RT_25 RT_26 RT_27 RT_29 RT_30 RT_31], SA_RESTORER|SA_RESTART|SA_INTERRUPT|SA_RESETHAND|0x37814c0, 0x804863e}, 8) = -1 EINVAL (Invalid argument)
[pid  4701] rt_sigaction(SIGHUP, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGINT, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGQUIT, NULL, {SIG_IGN, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGILL, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGTRAP, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGABRT, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGBUS, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGFPE, NULL, {SIG_IGN, [FPE], SA_RESTART}, 8) = 0
[pid  4701] rt_sigaction(SIGKILL, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGUSR1, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGSEGV, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGUSR2, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGPIPE, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGALRM, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGTERM, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGSTKFLT, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGCONT, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGSTOP, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGTSTP, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGTTIN, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGTTOU, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGURG, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGXCPU, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGXFSZ, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGVTALRM, NULL,  <unfinished ...>
[pid  4699] <... nanosleep resumed> 0xbfc935ac) = 0
[pid  4701] <... rt_sigaction resumed> {SIG_DFL, [], 0}, 8) = 0
[pid  4699] time( <unfinished ...>
[pid  4701] rt_sigaction(SIGPROF, NULL,  <unfinished ...>
[pid  4699] <... time resumed> NULL)    = 1400151957
[pid  4699] read(3,  <unfinished ...>
[pid  4701] <... rt_sigaction resumed> {SIG_DFL, [], 0}, 8) = 0
[pid  4699] <... read resumed> 0x8538220, 255) = -1 EAGAIN (Resource temporarily unavailable)
[pid  4701] rt_sigaction(SIGWINCH, NULL,  <unfinished ...>
[pid  4699] time( <unfinished ...>
[pid  4701] <... rt_sigaction resumed> {SIG_DFL, [], 0}, 8) = 0
[pid  4699] <... time resumed> NULL)    = 1400151957
[pid  4701] rt_sigaction(SIGIO, NULL,  <unfinished ...>
[pid  4699] rt_sigprocmask(SIG_BLOCK, [CHLD],  <unfinished ...>
[pid  4701] <... rt_sigaction resumed> {SIG_DFL, [], 0}, 8) = 0
[pid  4699] <... rt_sigprocmask resumed> [], 8) = 0
[pid  4701] rt_sigaction(SIGPWR, NULL,  <unfinished ...>
[pid  4699] rt_sigaction(SIGCHLD, NULL,  <unfinished ...>
[pid  4701] <... rt_sigaction resumed> {SIG_DFL, [], 0}, 8) = 0
[pid  4699] <... rt_sigaction resumed> {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGSYS, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4699] rt_sigprocmask(SIG_SETMASK, [],  <unfinished ...>
[pid  4701] rt_sigaction(SIGRT_2, NULL,  <unfinished ...>
[pid  4699] <... rt_sigprocmask resumed> NULL, 8) = 0
[pid  4701] <... rt_sigaction resumed> {SIG_DFL, [], 0}, 8) = 0
[pid  4699] nanosleep({1, 0},  <unfinished ...>
[pid  4701] rt_sigaction(SIGRT_3, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGRT_4, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGRT_5, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGRT_6, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGRT_7, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGRT_8, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGRT_9, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGRT_10, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGRT_11, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGRT_12, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGRT_13, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGRT_14, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGRT_15, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGRT_16, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGRT_17, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGRT_18, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGRT_19, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGRT_20, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGRT_21, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGRT_22, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGRT_23, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGRT_24, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGRT_25, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGRT_26, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGRT_27, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGRT_28, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGRT_29, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGRT_30, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGRT_31, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGRT_32, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGABRT, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGCHLD, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGIO, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] rt_sigaction(SIGSYS, NULL, {SIG_DFL, [], 0}, 8) = 0
[pid  4701] write(1, "CHILD\nEXIT\n", 11CHILD

So, besides several other settings I can see the forked process is calling "[pid  4701] ioctl(3, SNDCTL_TMR_START or TCSETS, {B9600 opost isig icanon echo ...}) = 0" which seems to reconfigure the fd to 9600 baud (and changing several other settings). I can also confirm this by calling "stty -F /dev/ttyS0" on the shell.
These are the settings the script configured sttyS0 to when it works correctly:
Code: [Select]
speed 38400 baud;stty: /dev/ttyS0
 line = 0;
intr = ^C; quit = ^\; erase = ^?; kill = ^U; eof = ^D; eol = <undef>; eol2 = <undef>; swtch = <undef>; start = ^Q; stop = ^S; susp = ^Z; rprnt = ^R; werase = ^W; lnext = ^V;
flush = ^O; min = 0; time = 0;
-parenb -parodd cs8 hupcl -cstopb cread clocal -crtscts
ignbrk -brkint -ignpar -parmrk -inpck -istrip -inlcr -igncr -icrnl -ixon -ixoff -iuclc -ixany -imaxbel -iutf8
-opost -olcuc -ocrnl onlcr -onocr -onlret -ofill -ofdel nl0 cr0 tab0 bs0 vt0 ff0
-isig -icanon -iexten -echo -echoe -echok -echonl -noflsh -xcase -tostop -echoprt -echoctl echoke

After the child exited the settings look like this:
Code: [Select]
speed 9600 baud;stty: /dev/ttyS0
 line = 0;
intr = ^C; quit = ^\; erase = ^?; kill = ^U; eof = ^D; eol = <undef>; eol2 = <undef>; swtch = <undef>; start = ^Q; stop = ^S; susp = ^Z; rprnt = ^R; werase = ^W; lnext = ^V;
flush = ^O; min = 1; time = 0;
-parenb -parodd cs8 hupcl -cstopb cread clocal -crtscts
-ignbrk -brkint -ignpar -parmrk -inpck -istrip -inlcr -igncr icrnl ixon -ixoff -iuclc -ixany -imaxbel -iutf8
opost -olcuc -ocrnl onlcr -onocr -onlret -ofill -ofdel nl0 cr0 tab0 bs0 vt0 ff0
isig icanon iexten echo echoe echok -echonl -noflsh -xcase -tostop -echoprt echoctl echoke

Another strange thing is that is not 100% reproducable. Sometimes it happens and sometimes it does not. But after rebooting the VM it usually starts happening again.

I am really out of ideas here :( What could I do to stop the child to reconfigure the stty upon exit (or at least reconfigure it to the same settings)? Any idea?
Big thanks in advance! Help is really appreciated!

Offline gerald_clark

  • TinyCore Moderator
  • Hero Member
  • *****
  • Posts: 4254
Re: Perl: forked child screws up serial port settings on exit
« Reply #1 on: May 15, 2014, 05:00:24 PM »
Try it on bare metal.