tty TTY_HUPPED anomaly

DISCUSSION Mark Hounschell 3 participants 10 messages Dec 23, 2011 – Jan 4, 2012

Share & tools

Mark Hounschell

author

2011-12-23 15:05 UTC #0 lore raw

I have an application that has seemingly been stable for many years and even using the 3.1.1 kernel all is fine. I'm using the openSuSE distribution. All is good with the openSuSE-11.4 dist and the 3.1.1 kernel. We recently started testing this application on openSuSE-12.1 using the same vanilla 3.1.1 kernel and now we have problems with just about all out tty/serial related devices that we use. I thought the problem maybe an openSuSE glibc problem so I built and ran the openSuSE-12.1 version of glibc on the openSuSE-11.4 dist but the application worked just fine. So I started looking at the kernel and one of our serial devices that fails. I choose the Synclink GT because its driver is "in kernel".

In our application with this particular card, the following TIOCSETD ioctl is this code snippet fails most of the time.

    int32_t hdlc_disc = N_HDLC;

    Q->fd = open(Q->FileName, (O_RDWR | O_NONBLOCK), 0);

    if (Q->fd < 0)
           return (FALSE);

    Q->File = fdopen(Q->fd, "rw");

    fcntl(Q->fd, F_SETFL, fcntl(S->fd,F_GETFL) & ~O_NONBLOCK);

    if (ioctl(Q->fd, TIOCSETD, &hdlc_disc) < 0) {
        perror("SCM_open_port: TIOCSETD failed: ");
        return (FALSE);
    }

The kernel code that results in the above code snippet failure is the following section of the tty_set_ldisc function in tty_io.c.

        if (test_bit(TTY_HUPPED, &tty->flags)) {
                /* We were raced by the hangup method. It will have stomped
                   the ldisc data and closed the ldisc down */
                clear_bit(TTY_LDISC_CHANGING, &tty->flags);
                mutex_unlock(&tty->ldisc_mutex);
                tty_ldisc_put(new_ldisc);
                tty_unlock();
                return -EIO;
        }

I do not really understand what TTY_HUPPED is or how it could be getting set. I look at it when the tty_set_ldisc function is entered and it is not set. Some where between entrance of the tty_set_ldisc and getting to the above code TTY_HUPPED gets set causing the -EIO return.

I see nothing in my code that should cause this to happen. At start up time a thread for each port used does this then goes to sleep. Again, I can't understand why now with openSuSE-12.1 this starts happening. Can someone help me understand why this might happen. I don't know if it is me, the dist, or the kernel. Frequently it all works at startup and will eventually fail during operation.

Other serial cards that I also have similar problems with (different ioctls) are various Digi serial cards. I haven't look into the kernel to see what is happening with those as yet but am sure the problem is related. Sometimes they work, most of the time they do not.

Many thanks in advance
Mark

Mark Hounschell

author

2011-12-23 18:46 UTC #1 lore raw

Quoted 57 lines · Mark Hounschell

I have an application that has seemingly been stable for many years and even using the 3.1.1 kernel all is fine. I'm using the openSuSE distribution. All is good with the openSuSE-11.4 dist and the 3.1.1 kernel. We recently started testing this application on openSuSE-12.1 using the same vanilla 3.1.1 kernel and now we have problems with just about all out tty/serial related devices that we use. I thought the problem maybe an openSuSE glibc problem so I built and ran the openSuSE-12.1 version of glibc on the openSuSE-11.4 dist but the application worked just fine. So I started looking at the kernel and one of our serial devices that fails. I choose the Synclink GT because its driver is "in kernel".
In our application with this particular card, the following TIOCSETD ioctl is this code snippet fails most of the time.
int32_t hdlc_disc = N_HDLC;
Q->fd = open(Q->FileName, (O_RDWR | O_NONBLOCK), 0);
if (Q->fd < 0)
return (FALSE);
Q->File = fdopen(Q->fd, "rw");
fcntl(Q->fd, F_SETFL, fcntl(S->fd,F_GETFL) & ~O_NONBLOCK);
if (ioctl(Q->fd, TIOCSETD, &hdlc_disc) < 0) {
perror("SCM_open_port: TIOCSETD failed: ");
return (FALSE);
}
The kernel code that results in the above code snippet failure is the following section of the tty_set_ldisc function in tty_io.c.
if (test_bit(TTY_HUPPED, &tty->flags)) {
/* We were raced by the hangup method. It will have stomped the ldisc data and closed the ldisc down */ clear_bit(TTY_LDISC_CHANGING, &tty->flags); mutex_unlock(&tty->ldisc_mutex); tty_ldisc_put(new_ldisc);
tty_unlock();
return -EIO;
}
I do not really understand what TTY_HUPPED is or how it could be getting set. I look at it when the tty_set_ldisc function is entered and it is not set. Some where between entrance of the tty_set_ldisc and getting to the above code TTY_HUPPED gets set causing the -EIO return.
I see nothing in my code that should cause this to happen. At start up time a thread for each port used does this then goes to sleep. Again, I can't understand why now with openSuSE-12.1 this starts happening. Can someone help me understand why this might happen. I don't know if it is me, the dist, or the kernel. Frequently it all works at startup and will eventually fail during operation.

Quoted 5 lines

Other serial cards that I also have similar problems with (different ioctls) are various Digi serial cards. I haven't look into the kernel to see what is happening with those as yet but am sure the problem is related. Sometimes they work, most of the time they do not.

More info:

I turned the TTY_DEBUG_HANGUP and added some additional printks. You see below the first port works just fine but the second fails because something is calling the tty_hangup function around 70usecs after I open the device??? What and Why???

Dec 23 13:36:19 harley kernel: [ 1139.456286] tty_open: opening ttySLG0...
Dec 23 13:36:19 harley kernel: [ 1139.456357] tiocsetd: Entered. tty = 0xe6b60c00  p = 0x0000000d tty->flags = 0x00000a00
Dec 23 13:36:19 harley kernel: [ 1139.456359] tiocsetd: setting tty ldisc to 0x0000000d
Dec 23 13:36:19 harley kernel: [ 1139.456361] tty_set_ldisc: Entered. tty = 0xe6b60c00 ldisk = 0x0000000d tty->flags = 0x00000a00 TTY_HUPPED = 0x00000000
Dec 23 13:36:19 harley kernel: [ 1139.456363] tty_set_ldisc: TTY_HUPPED-a = 0x00000000
Dec 23 13:36:19 harley kernel: [ 1139.456364] tty_set_ldisc: TTY_HUPPED-b = 0x00000000
Dec 23 13:36:19 harley kernel: [ 1139.456365] tty_set_ldisc: TTY_HUPPED-0 = 0x00000000
Dec 23 13:36:19 harley kernel: [ 1139.456368] tty_set_ldisc: TTY_HUPPED-1 = 0x00000000
Dec 23 13:36:19 harley kernel: [ 1139.456369] tty_set_ldisc: TTY_HUPPED-2 = 0x00000000
Dec 23 13:36:19 harley kernel: [ 1139.456370] tty_set_ldisc: TTY_HUPPED-3 = 0x00000000
Dec 23 13:36:19 harley kernel: [ 1139.456373] tty_set_ldisc: retval from tty_ldisc_wait_idle = 0x00000000 TTY_HUPPED = 0x00000000
Dec 23 13:36:19 harley kernel: [ 1139.456384] tty_set_ldisc: returning 0x00000000
Dec 23 13:36:19 harley kernel: [ 1139.456385] tiocsetd: Complete. ret = 0x00000000

Dec 23 13:36:19 harley kernel: [ 1139.458194] tty_open: opening ttySLG1...
Dec 23 13:36:19 harley kernel: [ 1139.458270] tty_hangup: ttySLG1 hangup...
Dec 23 13:36:19 harley kernel: [ 1139.458274] tiocsetd: Entered. tty = 0xe6b60800  p = 0x0000000d tty->flags = 0x00000a00
Dec 23 13:36:19 harley kernel: [ 1139.458276] tiocsetd: setting tty ldisc to 0x0000000d
Dec 23 13:36:19 harley kernel: [ 1139.458278] tty_set_ldisc: Entered. tty = 0xe6b60800 ldisk = 0x0000000d tty->flags = 0x00000a00 TTY_HUPPED = 0x00000000
Dec 23 13:36:19 harley kernel: [ 1139.458281] tty_set_ldisc: TTY_HUPPED-a = 0x00000000
Dec 23 13:36:19 harley kernel: [ 1139.458283] tty_set_ldisc: TTY_HUPPED-b = 0x00000000
Dec 23 13:36:19 harley kernel: [ 1139.458284] tty_set_ldisc: TTY_HUPPED-0 = 0x00000000
Dec 23 13:36:19 harley kernel: [ 1139.458288] tty_set_ldisc: TTY_HUPPED-1 = 0x00000000
Dec 23 13:36:19 harley kernel: [ 1139.458289] tty_set_ldisc: TTY_HUPPED-2 = 0x00000000
Dec 23 13:36:19 harley kernel: [ 1139.458290] tty_set_ldisc: TTY_HUPPED-3 = 0x00000000
Dec 23 13:36:19 harley kernel: [ 1139.458307] tty_hangup: ttySLG1 hangup...
Dec 23 13:36:19 harley kernel: [ 1139.458309] __tty_hangup: Entered for tty = 0xe6b60800
Dec 23 13:36:19 harley kernel: [ 1139.458340] __tty_hangup: Setting TTY_HUPPED for tty at 0xe6b60800
Dec 23 13:36:19 harley kernel: [ 1139.458347] tty_set_ldisc: retval from tty_ldisc_wait_idle = 0x00000000 TTY_HUPPED = 0x00040000
Dec 23 13:36:19 harley kernel: [ 1139.458349] tty_set_ldisc: tty->flags = 0x00040a02 TTY_HUPPED = 0x00040000 returning -EIO
Dec 23 13:36:19 harley kernel: [ 1139.458350] tiocsetd: Complete. ret = 0xfffffffb

Thanks again for any help on this
Regards
Mark

Alan Cox

2011-12-23 20:40 UTC #2 lore raw

Quoted 6 lines

I turned the TTY_DEBUG_HANGUP and added some additional printks. You see below the first port works just fine but the second fails because something is calling the tty_hangup function around 70usecs after I open the device???
What and Why???

The driver will be - and because the carrier dropped and the HUPCL flag is set on the port.

Alan

Mark Hounschell

author

2012-01-04 15:59 UTC #3 lore raw

Quoted 10 lines · Alan Cox

Quoted 6 lines
I turned the TTY_DEBUG_HANGUP and added some additional printks. You see below the first port works just fine but the second fails because something is calling the tty_hangup function around 70usecs after I open the device???
What and Why???
The driver will be - and because the carrier dropped and the HUPCL flag is set on the port.

Thanks Alan,

But what has carrier dropping got to do with an TIOCSETD ioctl. For that matter, any operation other than an actual read or write to the port? This seems wrong. You've obviously looked at my code being executed. What can be done to prevent tty_hangup from being called after opening the port? And if this is really supposed to happen, why does it not always happen?

Even if the first thing I do after opening the port is to clear HUPCL and set CLOCAL, this still randomly happens the first time I open the port after booting.

Thanks again for your help
Mark

Alan Cox

2012-01-04 16:27 UTC #4 lore raw

Quoted 1 line

But what has carrier dropping got to do with an TIOCSETD ioctl. For that

When the carrier is dropped and HUPCL is set then the tty is disconnected from the physical interface. It's specified behaviour and required for security. So by the time you go to issue the TIOCSETD you are no longer connected to the tty. That may well just be a timing change.

Quoted 3 lines

What can be done to prevent tty_hangup from being called after opening the port? And if this is really supposed to happen, why does it not always happen?

It should only happen if the carrier is dropped.

Quoted 3 lines

Even if the first thing I do after opening the port is to clear HUPCL and set CLOCAL, this still randomly happens the first time I open the port after booting.

I'd expect the behaviour to either be

carrier high, stays high - open works, no hangup events seen

carrier low, stays low - open blocks, but open with O_NDELAY works, hangup events not seen.

It's the act of the drop which is a hangup not the presence of low carrier if I remember the spec properly. The Synclink GT correctly does this as far as I can tell (I have no hardware or docs for it) but the code indicates that the hardware reports changes and it acts on them properly (checking CLOCAL etc).

I would guess (given the distro change is the trigger) that you've got a SuSE problem not a kernel one. The kernel behaviour and code looks correct. My guess therefore is that newer SuSE is running stuff in the boot which is probing serial ports and messing with the carrier wrongly and in ways it didn't use to. That would fit the fact that something similarly broken has apparently also appeared in the Fedora user space bootup.

Alan

Mark Hounschell

author

2012-01-04 18:59 UTC #5 lore raw

Quoted 33 lines · Alan Cox

Quoted 1 line
But what has carrier dropping got to do with an TIOCSETD ioctl. For that
When the carrier is dropped and HUPCL is set then the tty is disconnected from the physical interface. It's specified behaviour and required for security. So by the time you go to issue the TIOCSETD you are no longer connected to the tty. That may well just be a timing change.
Quoted 3 lines
What can be done to prevent tty_hangup from being called after opening the port? And if this is really supposed to happen, why does it not always happen?
It should only happen if the carrier is dropped.
Quoted 3 lines
Even if the first thing I do after opening the port is to clear HUPCL and set CLOCAL, this still randomly happens the first time I open the port after booting.
I'd expect the behaviour to either be
carrier high, stays high - open works, no hangup events seen
or
carrier low, stays low - open blocks, but open with O_NDELAY works, hangup events not seen.
It's the act of the drop which is a hangup not the presence of low carrier if I remember the spec properly. The Synclink GT correctly does this as far as I can tell (I have no hardware or docs for it) but the code indicates that the hardware reports changes and it acts on them properly (checking CLOCAL etc).

Quoted 8 lines

I would guess (given the distro change is the trigger) that you've got a SuSE problem not a kernel one. The kernel behaviour and code looks correct. My guess therefore is that newer SuSE is running stuff in the boot which is probing serial ports and messing with the carrier wrongly and in ways it didn't use to. That would fit the fact that something similarly broken has apparently also appeared in the Fedora user space bootup.

Yes, I never really though it was a kernel problem. All though I can't say I agree with the HUPCL/security thing. In any case, with the Synclink cards, at first open after boot of SuSE-12.1, CLOCAL is not set. Whereas all pre SuSE-12.1 releases do have CLOCAL set.

Mark

Jiri Slaby

2012-01-04 20:28 UTC #6 lore raw

Quoted 7 lines · Mark Hounschell

Quoted 7 lines
I would guess (given the distro change is the trigger) that you've got a SuSE problem not a kernel one. The kernel behaviour and code looks correct. My guess therefore is that newer SuSE is running stuff in the boot which is probing serial ports and messing with the carrier wrongly and in ways it didn't use to. That would fit the fact that something similarly broken has apparently also appeared in the Fedora user space bootup.

And we (suse) have a report for enterprise, that says ModemManager causes a similar issue. Could you perhaps check whether you have that thing installed?

thanks,

Signature · 2 lines

js
suse labs

Mark Hounschell

author

2012-01-04 20:35 UTC #7 lore raw

Quoted 9 lines · Jiri Slaby

Quoted 7 lines · Mark Hounschell
Quoted 7 lines
I would guess (given the distro change is the trigger) that you've got a SuSE problem not a kernel one. The kernel behaviour and code looks correct. My guess therefore is that newer SuSE is running stuff in the boot which is probing serial ports and messing with the carrier wrongly and in ways it didn't use to. That would fit the fact that something similarly broken has apparently also appeared in the Fedora user space bootup.

Quoted 5 lines

And we (suse) have a report for enterprise, that says ModemManager causes a similar issue. Could you perhaps check whether you have that thing installed?
thanks,

Yep. ModemManager-0.5-3.1.3.i586

Mark

Jiri Slaby

2012-01-04 20:41 UTC #8 lore raw

Quoted 11 lines · Mark Hounschell

Quoted 10 lines · Jiri Slaby
Quoted 8 lines · Mark Hounschell
Quoted 8 lines
I would guess (given the distro change is the trigger) that you've got a
SuSE problem not a kernel one. The kernel behaviour and code looks correct. My guess therefore is that newer SuSE is running stuff in the boot which is probing serial ports and messing with the carrier wrongly and in ways it didn't use to. That would fit the fact that something similarly broken has apparently also appeared in the Fedora user space bootup.

Quoted 7 lines

Quoted 5 lines
And we (suse) have a report for enterprise, that says ModemManager causes a similar issue. Could you perhaps check whether you have that thing installed?
thanks,
Yep. ModemManager-0.5-3.1.3.i586

And what happens if you remove that?

Signature · 2 lines

js
suse labs

Mark Hounschell

author

2012-01-04 20:50 UTC #9 lore raw

Quoted 16 lines · Jiri Slaby

Quoted 15 lines · Mark Hounschell
Quoted 14 lines · Jiri Slaby
Quoted 8 lines · Mark Hounschell
Quoted 8 lines
I would guess (given the distro change is the trigger) that you've got a
SuSE problem not a kernel one. The kernel behaviour and code looks correct. My guess therefore is that newer SuSE is running stuff in the boot which is probing serial ports and messing with the carrier wrongly and in ways it didn't use to. That would fit the fact that something similarly broken has apparently also appeared in the Fedora user space bootup.
And we (suse) have a report for enterprise, that says ModemManager causes a similar issue. Could you perhaps check whether you have that thing installed?

Quoted 6 lines

Quoted 3 lines
Quoted 1 line
thanks,
Yep. ModemManager-0.5-3.1.3.i586
And what happens if you remove that?

It seems to fix my problem. Thanks for stepping in. I was about to take this to the SuSE-e list. Anything else ya need, let me know.

Mark