tty TTY_HUPPED anomaly

tty TTY_HUPPED anomaly

[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.

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

Re: tty TTY_HUPPED anomaly

[Mark Hounschell]

On 12/23/2011 09:51 AM, Mark Hounschell wrote:
> 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.
>

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

Re: tty TTY_HUPPED anomaly

[Alan Cox]

> 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

Re: tty TTY_HUPPED anomaly

[Mark Hounschell]

On 12/23/2011 03:40 PM, Alan Cox wrote:
>
>> 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

Re: tty TTY_HUPPED anomaly

[Alan Cox]

> 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.
 
> 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.

> 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).


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

Re: tty TTY_HUPPED anomaly

[Mark Hounschell]

On 01/04/2012 11:27 AM, Alan Cox wrote:
>> 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.
>
>> 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.
>
>> 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).
>
>
> 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

Re: tty TTY_HUPPED anomaly

[Jiri Slaby]

On 01/04/2012 07:59 PM, Mark Hounschell wrote:
>> 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,
-- 
js
suse labs

Re: tty TTY_HUPPED anomaly

[Mark Hounschell]

On 01/04/2012 03:28 PM, Jiri Slaby wrote:
> On 01/04/2012 07:59 PM, Mark Hounschell wrote:
>>> 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,

Yep. ModemManager-0.5-3.1.3.i586

Mark

Re: tty TTY_HUPPED anomaly

[Jiri Slaby]

On 01/04/2012 09:35 PM, Mark Hounschell wrote:
> On 01/04/2012 03:28 PM, Jiri Slaby wrote:
>> On 01/04/2012 07:59 PM, Mark Hounschell wrote:
>>>> 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,
> 
> Yep. ModemManager-0.5-3.1.3.i586

And what happens if you remove that?

-- 
js
suse labs

Re: tty TTY_HUPPED anomaly

[Mark Hounschell]

On 01/04/2012 03:40 PM, Jiri Slaby wrote:
> On 01/04/2012 09:35 PM, Mark Hounschell wrote:
>> On 01/04/2012 03:28 PM, Jiri Slaby wrote:
>>> On 01/04/2012 07:59 PM, Mark Hounschell wrote:
>>>>> 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,
>>
>> 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