Re: Potential data race in psmouse_interrupt

[Dmitry Vyukov]

I've mailed a separate patch that does serio_pause_rx before reading
out data ("input: fix data race __ps2_command").


On Sat, Sep 5, 2015 at 3:21 PM, Dmitry Vyukov  wrote:
> On Fri, Sep 4, 2015 at 10:27 PM, Dmitry Torokhov
>  wrote:
>> On Fri, Sep 4, 2015 at 12:32 PM, Dmitry Vyukov  wrote:
>>> On Fri, Sep 4, 2015 at 6:56 PM, Dmitry Torokhov
>>>  wrote:
 On Tue, Sep 1, 2015 at 11:46 AM, Dmitry Vyukov  wrote:
> On Fri, Aug 28, 2015 at 8:32 PM, Dmitry Torokhov
>  wrote:
>> On Fri, Aug 28, 2015 at 11:08 AM, Dmitry Vyukov  
>> wrote:
>>> On Fri, Aug 28, 2015 at 7:51 PM, Dmitry Torokhov
>>>  wrote:
 On Fri, Aug 28, 2015 at 10:34 AM, Dmitry Vyukov  
 wrote:
> Hello,
>
> I am looking at this code in __ps2_command again:
>
> /*
> * The reset command takes a long time to execute.
> */
> timeout = msecs_to_jiffies(command == PS2_CMD_RESET_BAT ? 4000 : 500);
>
> timeout = wait_event_timeout(ps2dev->wait,
> !(READ_ONCE(ps2dev->flags) & PS2_FLAG_CMD1), timeout);
>
> if (smp_load_acquire(>cmdcnt) &&
> !(smp_load_acquire(>flags) & PS2_FLAG_CMD1)) {
>   timeout = ps2_adjust_timeout(ps2dev, command, timeout);
>   wait_event_timeout(ps2dev->wait,
> !(smp_load_acquire(>flags) &
> PS2_FLAG_CMD), timeout);
> }
>
> if (param)
> for (i = 0; i < receive; i++)
>   param[i] = ps2dev->cmdbuf[(receive - 1) - i];
>
>
> Here are two moments I don't understand:
> 1. The last parameter of ps2_adjust_timeout is timeout in jiffies (it
> is compared against 100ms). However, timeout is assigned to result of
> wait_event_timeout, which returns 0 or 1. This does not make sense to
> me. What am I missing?

 The fact that wait_event_timeout can return value greater than one:

  * Returns:
  * 0 if the @condition evaluated to %false after the @timeout elapsed,
  * 1 if the @condition evaluated to %true after the @timeout elapsed,
  * or the remaining jiffies (at least 1) if the @condition evaluated
   ^
>>>
>>>
>>> OK, makes sense now!
>>>
> 2. This code pays great attention to timeouts, but in the end I don't
> see how it handles timeouts. That is, if a timeout is happened, we
> still copyout (garbage) from cmdbuf. What am I missing here?

 Once upon a time wait_event() did not return positive value when
 timeout expired and then condition satisfied. So we just examine the
 final state (psmpouse->cmdcnt should be 0 if command actually
 succeeded) and even if we copy in garbage nobody should care since
 we'll return error in this case.
>>>
>>>
>>> I see.
>>> But the cmdcnt is re-read after copying out response. So it is
>>> possible that we read garbage response, but then read cmdcnt==0 and
>>> return OK to caller.
>>
>> That assumes that we actually timed out, and while we were copying the
>> data the response finally came.
>
> Right.
>
>>>
>>> So far I have something along the following lines to fix data races in 
>>> libps2.c
>>
>> I don't know, maybe we should simply move call to
>> serio_pause_rx(ps2dev->serio) higher, before we check ps2dev->cmdcnt,
>> and move copying of the buffer down, after checking cmdcnt.
>
> I don't know about serio_pause_rx, but copying of response should be
> done after checking cmdcnt.

 It will stop the interrupt handler from running while we are examining
 the cmdcnt and copy out the data, thus removing the race.

> Also you need to use smp_store_release/smp_load_acquire cmdcnt and
> flags when they have dependent data. And READ_ONCE/WRITE_ONCE on
> shared state otherwise is highly desirable.
>
>>> diff --git a/drivers/input/serio/libps2.c b/drivers/input/serio/libps2.c
>>> index 7551699..51c747f 100644
>>> --- a/drivers/input/serio/libps2.c
>>> +++ b/drivers/input/serio/libps2.c
>>> @@ -43,7 +43,7 @@ int ps2_sendbyte(struct ps2dev *ps2dev, unsigned
>>> char byte, int timeout)
>>>
>>>  if (serio_write(ps2dev->serio, byte) == 0)
>>>  wait_event_timeout(ps2dev->wait,
>>> -   !(ps2dev->flags & PS2_FLAG_ACK),
>>> +   !(READ_ONCE(ps2dev->flags) & 
>>> PS2_FLAG_ACK),
>>> msecs_to_jiffies(timeout));
>>>
>>>  serio_pause_rx(ps2dev->serio);
>>> @@ -187,6 +187,7 @@ int __ps2_command(struct ps2dev *ps2dev, unsigned
>>> char *param, int command)
>>>  int receive 

Re: Potential data race in psmouse_interrupt

[Dmitry Vyukov]

I've mailed a separate patch that does serio_pause_rx before reading
out data ("input: fix data race __ps2_command").


On Sat, Sep 5, 2015 at 3:21 PM, Dmitry Vyukov  wrote:
> On Fri, Sep 4, 2015 at 10:27 PM, Dmitry Torokhov
>  wrote:
>> On Fri, Sep 4, 2015 at 12:32 PM, Dmitry Vyukov  wrote:
>>> On Fri, Sep 4, 2015 at 6:56 PM, Dmitry Torokhov
>>>  wrote:
 On Tue, Sep 1, 2015 at 11:46 AM, Dmitry Vyukov  wrote:
> On Fri, Aug 28, 2015 at 8:32 PM, Dmitry Torokhov
>  wrote:
>> On Fri, Aug 28, 2015 at 11:08 AM, Dmitry Vyukov  
>> wrote:
>>> On Fri, Aug 28, 2015 at 7:51 PM, Dmitry Torokhov
>>>  wrote:
 On Fri, Aug 28, 2015 at 10:34 AM, Dmitry Vyukov  
 wrote:
> Hello,
>
> I am looking at this code in __ps2_command again:
>
> /*
> * The reset command takes a long time to execute.
> */
> timeout = msecs_to_jiffies(command == PS2_CMD_RESET_BAT ? 4000 : 500);
>
> timeout = wait_event_timeout(ps2dev->wait,
> !(READ_ONCE(ps2dev->flags) & PS2_FLAG_CMD1), timeout);
>
> if (smp_load_acquire(>cmdcnt) &&
> !(smp_load_acquire(>flags) & PS2_FLAG_CMD1)) {
>   timeout = ps2_adjust_timeout(ps2dev, command, timeout);
>   wait_event_timeout(ps2dev->wait,
> !(smp_load_acquire(>flags) &
> PS2_FLAG_CMD), timeout);
> }
>
> if (param)
> for (i = 0; i < receive; i++)
>   param[i] = ps2dev->cmdbuf[(receive - 1) - i];
>
>
> Here are two moments I don't understand:
> 1. The last parameter of ps2_adjust_timeout is timeout in jiffies (it
> is compared against 100ms). However, timeout is assigned to result of
> wait_event_timeout, which returns 0 or 1. This does not make sense to
> me. What am I missing?

 The fact that wait_event_timeout can return value greater than one:

  * Returns:
  * 0 if the @condition evaluated to %false after the @timeout elapsed,
  * 1 if the @condition evaluated to %true after the @timeout elapsed,
  * or the remaining jiffies (at least 1) if the @condition evaluated
   ^
>>>
>>>
>>> OK, makes sense now!
>>>
> 2. This code pays great attention to timeouts, but in the end I don't
> see how it handles timeouts. That is, if a timeout is happened, we
> still copyout (garbage) from cmdbuf. What am I missing here?

 Once upon a time wait_event() did not return positive value when
 timeout expired and then condition satisfied. So we just examine the
 final state (psmpouse->cmdcnt should be 0 if command actually
 succeeded) and even if we copy in garbage nobody should care since
 we'll return error in this case.
>>>
>>>
>>> I see.
>>> But the cmdcnt is re-read after copying out response. So it is
>>> possible that we read garbage response, but then read cmdcnt==0 and
>>> return OK to caller.
>>
>> That assumes that we actually timed out, and while we were copying the
>> data the response finally came.
>
> Right.
>
>>>
>>> So far I have something along the following lines to fix data races in 
>>> libps2.c
>>
>> I don't know, maybe we should simply move call to
>> serio_pause_rx(ps2dev->serio) higher, before we check ps2dev->cmdcnt,
>> and move copying of the buffer down, after checking cmdcnt.
>
> I don't know about serio_pause_rx, but copying of response should be
> done after checking cmdcnt.

 It will stop the interrupt handler from running while we are examining
 the cmdcnt and copy out the data, thus removing the race.

> Also you need to use smp_store_release/smp_load_acquire cmdcnt and
> flags when they have dependent data. And READ_ONCE/WRITE_ONCE on
> shared state otherwise is highly desirable.
>
>>> diff --git a/drivers/input/serio/libps2.c b/drivers/input/serio/libps2.c
>>> index 7551699..51c747f 100644
>>> --- a/drivers/input/serio/libps2.c
>>> +++ b/drivers/input/serio/libps2.c
>>> @@ -43,7 +43,7 @@ int ps2_sendbyte(struct ps2dev *ps2dev, unsigned
>>> char byte, int timeout)
>>>
>>>  if (serio_write(ps2dev->serio, byte) == 0)
>>>  wait_event_timeout(ps2dev->wait,
>>> -   !(ps2dev->flags & PS2_FLAG_ACK),
>>> +   !(READ_ONCE(ps2dev->flags) & 
>>> PS2_FLAG_ACK),
>>> 

Re: Potential data race in psmouse_interrupt

[Dmitry Vyukov]

On Fri, Sep 4, 2015 at 10:27 PM, Dmitry Torokhov
 wrote:
> On Fri, Sep 4, 2015 at 12:32 PM, Dmitry Vyukov  wrote:
>> On Fri, Sep 4, 2015 at 6:56 PM, Dmitry Torokhov
>>  wrote:
>>> On Tue, Sep 1, 2015 at 11:46 AM, Dmitry Vyukov  wrote:
 On Fri, Aug 28, 2015 at 8:32 PM, Dmitry Torokhov
  wrote:
> On Fri, Aug 28, 2015 at 11:08 AM, Dmitry Vyukov  
> wrote:
>> On Fri, Aug 28, 2015 at 7:51 PM, Dmitry Torokhov
>>  wrote:
>>> On Fri, Aug 28, 2015 at 10:34 AM, Dmitry Vyukov  
>>> wrote:
 Hello,

 I am looking at this code in __ps2_command again:

 /*
 * The reset command takes a long time to execute.
 */
 timeout = msecs_to_jiffies(command == PS2_CMD_RESET_BAT ? 4000 : 500);

 timeout = wait_event_timeout(ps2dev->wait,
 !(READ_ONCE(ps2dev->flags) & PS2_FLAG_CMD1), timeout);

 if (smp_load_acquire(>cmdcnt) &&
 !(smp_load_acquire(>flags) & PS2_FLAG_CMD1)) {
   timeout = ps2_adjust_timeout(ps2dev, command, timeout);
   wait_event_timeout(ps2dev->wait,
 !(smp_load_acquire(>flags) &
 PS2_FLAG_CMD), timeout);
 }

 if (param)
 for (i = 0; i < receive; i++)
   param[i] = ps2dev->cmdbuf[(receive - 1) - i];


 Here are two moments I don't understand:
 1. The last parameter of ps2_adjust_timeout is timeout in jiffies (it
 is compared against 100ms). However, timeout is assigned to result of
 wait_event_timeout, which returns 0 or 1. This does not make sense to
 me. What am I missing?
>>>
>>> The fact that wait_event_timeout can return value greater than one:
>>>
>>>  * Returns:
>>>  * 0 if the @condition evaluated to %false after the @timeout elapsed,
>>>  * 1 if the @condition evaluated to %true after the @timeout elapsed,
>>>  * or the remaining jiffies (at least 1) if the @condition evaluated
>>>   ^
>>
>>
>> OK, makes sense now!
>>
 2. This code pays great attention to timeouts, but in the end I don't
 see how it handles timeouts. That is, if a timeout is happened, we
 still copyout (garbage) from cmdbuf. What am I missing here?
>>>
>>> Once upon a time wait_event() did not return positive value when
>>> timeout expired and then condition satisfied. So we just examine the
>>> final state (psmpouse->cmdcnt should be 0 if command actually
>>> succeeded) and even if we copy in garbage nobody should care since
>>> we'll return error in this case.
>>
>>
>> I see.
>> But the cmdcnt is re-read after copying out response. So it is
>> possible that we read garbage response, but then read cmdcnt==0 and
>> return OK to caller.
>
> That assumes that we actually timed out, and while we were copying the
> data the response finally came.

 Right.

>>
>> So far I have something along the following lines to fix data races in 
>> libps2.c
>
> I don't know, maybe we should simply move call to
> serio_pause_rx(ps2dev->serio) higher, before we check ps2dev->cmdcnt,
> and move copying of the buffer down, after checking cmdcnt.

 I don't know about serio_pause_rx, but copying of response should be
 done after checking cmdcnt.
>>>
>>> It will stop the interrupt handler from running while we are examining
>>> the cmdcnt and copy out the data, thus removing the race.
>>>
 Also you need to use smp_store_release/smp_load_acquire cmdcnt and
 flags when they have dependent data. And READ_ONCE/WRITE_ONCE on
 shared state otherwise is highly desirable.

>> diff --git a/drivers/input/serio/libps2.c b/drivers/input/serio/libps2.c
>> index 7551699..51c747f 100644
>> --- a/drivers/input/serio/libps2.c
>> +++ b/drivers/input/serio/libps2.c
>> @@ -43,7 +43,7 @@ int ps2_sendbyte(struct ps2dev *ps2dev, unsigned
>> char byte, int timeout)
>>
>>  if (serio_write(ps2dev->serio, byte) == 0)
>>  wait_event_timeout(ps2dev->wait,
>> -   !(ps2dev->flags & PS2_FLAG_ACK),
>> +   !(READ_ONCE(ps2dev->flags) & 
>> PS2_FLAG_ACK),
>> msecs_to_jiffies(timeout));
>>
>>  serio_pause_rx(ps2dev->serio);
>> @@ -187,6 +187,7 @@ int __ps2_command(struct ps2dev *ps2dev, unsigned
>> char *param, int command)
>>  int receive = (command >> 8) & 0xf;
>>  int rc = -1;
>>  int i;
>> +unsigned char cmdcnt;
>>
>>  if (receive > sizeof(ps2dev->cmdbuf)) {
>>  WARN_ON(1);
>> @@ -225,23 +226,22 @@ int __ps2_command(struct ps2dev *ps2dev,
>> 

Re: Potential data race in psmouse_interrupt

[Dmitry Vyukov]

On Fri, Sep 4, 2015 at 10:27 PM, Dmitry Torokhov
 wrote:
> On Fri, Sep 4, 2015 at 12:32 PM, Dmitry Vyukov  wrote:
>> On Fri, Sep 4, 2015 at 6:56 PM, Dmitry Torokhov
>>  wrote:
>>> On Tue, Sep 1, 2015 at 11:46 AM, Dmitry Vyukov  wrote:
 On Fri, Aug 28, 2015 at 8:32 PM, Dmitry Torokhov
  wrote:
> On Fri, Aug 28, 2015 at 11:08 AM, Dmitry Vyukov  
> wrote:
>> On Fri, Aug 28, 2015 at 7:51 PM, Dmitry Torokhov
>>  wrote:
>>> On Fri, Aug 28, 2015 at 10:34 AM, Dmitry Vyukov  
>>> wrote:
 Hello,

 I am looking at this code in __ps2_command again:

 /*
 * The reset command takes a long time to execute.
 */
 timeout = msecs_to_jiffies(command == PS2_CMD_RESET_BAT ? 4000 : 500);

 timeout = wait_event_timeout(ps2dev->wait,
 !(READ_ONCE(ps2dev->flags) & PS2_FLAG_CMD1), timeout);

 if (smp_load_acquire(>cmdcnt) &&
 !(smp_load_acquire(>flags) & PS2_FLAG_CMD1)) {
   timeout = ps2_adjust_timeout(ps2dev, command, timeout);
   wait_event_timeout(ps2dev->wait,
 !(smp_load_acquire(>flags) &
 PS2_FLAG_CMD), timeout);
 }

 if (param)
 for (i = 0; i < receive; i++)
   param[i] = ps2dev->cmdbuf[(receive - 1) - i];


 Here are two moments I don't understand:
 1. The last parameter of ps2_adjust_timeout is timeout in jiffies (it
 is compared against 100ms). However, timeout is assigned to result of
 wait_event_timeout, which returns 0 or 1. This does not make sense to
 me. What am I missing?
>>>
>>> The fact that wait_event_timeout can return value greater than one:
>>>
>>>  * Returns:
>>>  * 0 if the @condition evaluated to %false after the @timeout elapsed,
>>>  * 1 if the @condition evaluated to %true after the @timeout elapsed,
>>>  * or the remaining jiffies (at least 1) if the @condition evaluated
>>>   ^
>>
>>
>> OK, makes sense now!
>>
 2. This code pays great attention to timeouts, but in the end I don't
 see how it handles timeouts. That is, if a timeout is happened, we
 still copyout (garbage) from cmdbuf. What am I missing here?
>>>
>>> Once upon a time wait_event() did not return positive value when
>>> timeout expired and then condition satisfied. So we just examine the
>>> final state (psmpouse->cmdcnt should be 0 if command actually
>>> succeeded) and even if we copy in garbage nobody should care since
>>> we'll return error in this case.
>>
>>
>> I see.
>> But the cmdcnt is re-read after copying out response. So it is
>> possible that we read garbage response, but then read cmdcnt==0 and
>> return OK to caller.
>
> That assumes that we actually timed out, and while we were copying the
> data the response finally came.

 Right.

>>
>> So far I have something along the following lines to fix data races in 
>> libps2.c
>
> I don't know, maybe we should simply move call to
> serio_pause_rx(ps2dev->serio) higher, before we check ps2dev->cmdcnt,
> and move copying of the buffer down, after checking cmdcnt.

 I don't know about serio_pause_rx, but copying of response should be
 done after checking cmdcnt.
>>>
>>> It will stop the interrupt handler from running while we are examining
>>> the cmdcnt and copy out the data, thus removing the race.
>>>
 Also you need to use smp_store_release/smp_load_acquire cmdcnt and
 flags when they have dependent data. And READ_ONCE/WRITE_ONCE on
 shared state otherwise is highly desirable.

>> diff --git a/drivers/input/serio/libps2.c b/drivers/input/serio/libps2.c
>> index 7551699..51c747f 100644
>> --- a/drivers/input/serio/libps2.c
>> +++ b/drivers/input/serio/libps2.c
>> @@ -43,7 +43,7 @@ int ps2_sendbyte(struct ps2dev *ps2dev, unsigned
>> char byte, int timeout)
>>
>>  if (serio_write(ps2dev->serio, byte) == 0)
>>  wait_event_timeout(ps2dev->wait,
>> -   !(ps2dev->flags & PS2_FLAG_ACK),
>> +   !(READ_ONCE(ps2dev->flags) & 
>> PS2_FLAG_ACK),
>> msecs_to_jiffies(timeout));
>>
>>  serio_pause_rx(ps2dev->serio);
>> @@ -187,6 +187,7 @@ int __ps2_command(struct ps2dev *ps2dev, unsigned
>> char *param, int command)
>>  int receive = (command >> 8) & 0xf;
>>  int rc = -1;
>>  int i;
>> +unsigned 

Re: Potential data race in psmouse_interrupt

[Dmitry Torokhov]

On Fri, Sep 4, 2015 at 12:32 PM, Dmitry Vyukov  wrote:
> On Fri, Sep 4, 2015 at 6:56 PM, Dmitry Torokhov
>  wrote:
>> On Tue, Sep 1, 2015 at 11:46 AM, Dmitry Vyukov  wrote:
>>> On Fri, Aug 28, 2015 at 8:32 PM, Dmitry Torokhov
>>>  wrote:
 On Fri, Aug 28, 2015 at 11:08 AM, Dmitry Vyukov  wrote:
> On Fri, Aug 28, 2015 at 7:51 PM, Dmitry Torokhov
>  wrote:
>> On Fri, Aug 28, 2015 at 10:34 AM, Dmitry Vyukov  
>> wrote:
>>> Hello,
>>>
>>> I am looking at this code in __ps2_command again:
>>>
>>> /*
>>> * The reset command takes a long time to execute.
>>> */
>>> timeout = msecs_to_jiffies(command == PS2_CMD_RESET_BAT ? 4000 : 500);
>>>
>>> timeout = wait_event_timeout(ps2dev->wait,
>>> !(READ_ONCE(ps2dev->flags) & PS2_FLAG_CMD1), timeout);
>>>
>>> if (smp_load_acquire(>cmdcnt) &&
>>> !(smp_load_acquire(>flags) & PS2_FLAG_CMD1)) {
>>>   timeout = ps2_adjust_timeout(ps2dev, command, timeout);
>>>   wait_event_timeout(ps2dev->wait,
>>> !(smp_load_acquire(>flags) &
>>> PS2_FLAG_CMD), timeout);
>>> }
>>>
>>> if (param)
>>> for (i = 0; i < receive; i++)
>>>   param[i] = ps2dev->cmdbuf[(receive - 1) - i];
>>>
>>>
>>> Here are two moments I don't understand:
>>> 1. The last parameter of ps2_adjust_timeout is timeout in jiffies (it
>>> is compared against 100ms). However, timeout is assigned to result of
>>> wait_event_timeout, which returns 0 or 1. This does not make sense to
>>> me. What am I missing?
>>
>> The fact that wait_event_timeout can return value greater than one:
>>
>>  * Returns:
>>  * 0 if the @condition evaluated to %false after the @timeout elapsed,
>>  * 1 if the @condition evaluated to %true after the @timeout elapsed,
>>  * or the remaining jiffies (at least 1) if the @condition evaluated
>>   ^
>
>
> OK, makes sense now!
>
>>> 2. This code pays great attention to timeouts, but in the end I don't
>>> see how it handles timeouts. That is, if a timeout is happened, we
>>> still copyout (garbage) from cmdbuf. What am I missing here?
>>
>> Once upon a time wait_event() did not return positive value when
>> timeout expired and then condition satisfied. So we just examine the
>> final state (psmpouse->cmdcnt should be 0 if command actually
>> succeeded) and even if we copy in garbage nobody should care since
>> we'll return error in this case.
>
>
> I see.
> But the cmdcnt is re-read after copying out response. So it is
> possible that we read garbage response, but then read cmdcnt==0 and
> return OK to caller.

 That assumes that we actually timed out, and while we were copying the
 data the response finally came.
>>>
>>> Right.
>>>
>
> So far I have something along the following lines to fix data races in 
> libps2.c

 I don't know, maybe we should simply move call to
 serio_pause_rx(ps2dev->serio) higher, before we check ps2dev->cmdcnt,
 and move copying of the buffer down, after checking cmdcnt.
>>>
>>> I don't know about serio_pause_rx, but copying of response should be
>>> done after checking cmdcnt.
>>
>> It will stop the interrupt handler from running while we are examining
>> the cmdcnt and copy out the data, thus removing the race.
>>
>>> Also you need to use smp_store_release/smp_load_acquire cmdcnt and
>>> flags when they have dependent data. And READ_ONCE/WRITE_ONCE on
>>> shared state otherwise is highly desirable.
>>>
> diff --git a/drivers/input/serio/libps2.c b/drivers/input/serio/libps2.c
> index 7551699..51c747f 100644
> --- a/drivers/input/serio/libps2.c
> +++ b/drivers/input/serio/libps2.c
> @@ -43,7 +43,7 @@ int ps2_sendbyte(struct ps2dev *ps2dev, unsigned
> char byte, int timeout)
>
>  if (serio_write(ps2dev->serio, byte) == 0)
>  wait_event_timeout(ps2dev->wait,
> -   !(ps2dev->flags & PS2_FLAG_ACK),
> +   !(READ_ONCE(ps2dev->flags) & 
> PS2_FLAG_ACK),
> msecs_to_jiffies(timeout));
>
>  serio_pause_rx(ps2dev->serio);
> @@ -187,6 +187,7 @@ int __ps2_command(struct ps2dev *ps2dev, unsigned
> char *param, int command)
>  int receive = (command >> 8) & 0xf;
>  int rc = -1;
>  int i;
> +unsigned char cmdcnt;
>
>  if (receive > sizeof(ps2dev->cmdbuf)) {
>  WARN_ON(1);
> @@ -225,23 +226,22 @@ int __ps2_command(struct ps2dev *ps2dev,
> unsigned char *param, int command)
>  timeout = msecs_to_jiffies(command == PS2_CMD_RESET_BAT ? 4000 : 
> 500);
>
>  timeout = 

Re: Potential data race in psmouse_interrupt

[Dmitry Vyukov]

On Fri, Sep 4, 2015 at 6:56 PM, Dmitry Torokhov
 wrote:
> On Tue, Sep 1, 2015 at 11:46 AM, Dmitry Vyukov  wrote:
>> On Fri, Aug 28, 2015 at 8:32 PM, Dmitry Torokhov
>>  wrote:
>>> On Fri, Aug 28, 2015 at 11:08 AM, Dmitry Vyukov  wrote:
 On Fri, Aug 28, 2015 at 7:51 PM, Dmitry Torokhov
  wrote:
> On Fri, Aug 28, 2015 at 10:34 AM, Dmitry Vyukov  
> wrote:
>> Hello,
>>
>> I am looking at this code in __ps2_command again:
>>
>> /*
>> * The reset command takes a long time to execute.
>> */
>> timeout = msecs_to_jiffies(command == PS2_CMD_RESET_BAT ? 4000 : 500);
>>
>> timeout = wait_event_timeout(ps2dev->wait,
>> !(READ_ONCE(ps2dev->flags) & PS2_FLAG_CMD1), timeout);
>>
>> if (smp_load_acquire(>cmdcnt) &&
>> !(smp_load_acquire(>flags) & PS2_FLAG_CMD1)) {
>>   timeout = ps2_adjust_timeout(ps2dev, command, timeout);
>>   wait_event_timeout(ps2dev->wait,
>> !(smp_load_acquire(>flags) &
>> PS2_FLAG_CMD), timeout);
>> }
>>
>> if (param)
>> for (i = 0; i < receive; i++)
>>   param[i] = ps2dev->cmdbuf[(receive - 1) - i];
>>
>>
>> Here are two moments I don't understand:
>> 1. The last parameter of ps2_adjust_timeout is timeout in jiffies (it
>> is compared against 100ms). However, timeout is assigned to result of
>> wait_event_timeout, which returns 0 or 1. This does not make sense to
>> me. What am I missing?
>
> The fact that wait_event_timeout can return value greater than one:
>
>  * Returns:
>  * 0 if the @condition evaluated to %false after the @timeout elapsed,
>  * 1 if the @condition evaluated to %true after the @timeout elapsed,
>  * or the remaining jiffies (at least 1) if the @condition evaluated
>   ^


 OK, makes sense now!

>> 2. This code pays great attention to timeouts, but in the end I don't
>> see how it handles timeouts. That is, if a timeout is happened, we
>> still copyout (garbage) from cmdbuf. What am I missing here?
>
> Once upon a time wait_event() did not return positive value when
> timeout expired and then condition satisfied. So we just examine the
> final state (psmpouse->cmdcnt should be 0 if command actually
> succeeded) and even if we copy in garbage nobody should care since
> we'll return error in this case.


 I see.
 But the cmdcnt is re-read after copying out response. So it is
 possible that we read garbage response, but then read cmdcnt==0 and
 return OK to caller.
>>>
>>> That assumes that we actually timed out, and while we were copying the
>>> data the response finally came.
>>
>> Right.
>>

 So far I have something along the following lines to fix data races in 
 libps2.c
>>>
>>> I don't know, maybe we should simply move call to
>>> serio_pause_rx(ps2dev->serio) higher, before we check ps2dev->cmdcnt,
>>> and move copying of the buffer down, after checking cmdcnt.
>>
>> I don't know about serio_pause_rx, but copying of response should be
>> done after checking cmdcnt.
>
> It will stop the interrupt handler from running while we are examining
> the cmdcnt and copy out the data, thus removing the race.
>
>> Also you need to use smp_store_release/smp_load_acquire cmdcnt and
>> flags when they have dependent data. And READ_ONCE/WRITE_ONCE on
>> shared state otherwise is highly desirable.
>>
 diff --git a/drivers/input/serio/libps2.c b/drivers/input/serio/libps2.c
 index 7551699..51c747f 100644
 --- a/drivers/input/serio/libps2.c
 +++ b/drivers/input/serio/libps2.c
 @@ -43,7 +43,7 @@ int ps2_sendbyte(struct ps2dev *ps2dev, unsigned
 char byte, int timeout)

  if (serio_write(ps2dev->serio, byte) == 0)
  wait_event_timeout(ps2dev->wait,
 -   !(ps2dev->flags & PS2_FLAG_ACK),
 +   !(READ_ONCE(ps2dev->flags) & 
 PS2_FLAG_ACK),
 msecs_to_jiffies(timeout));

  serio_pause_rx(ps2dev->serio);
 @@ -187,6 +187,7 @@ int __ps2_command(struct ps2dev *ps2dev, unsigned
 char *param, int command)
  int receive = (command >> 8) & 0xf;
  int rc = -1;
  int i;
 +unsigned char cmdcnt;

  if (receive > sizeof(ps2dev->cmdbuf)) {
  WARN_ON(1);
 @@ -225,23 +226,22 @@ int __ps2_command(struct ps2dev *ps2dev,
 unsigned char *param, int command)
  timeout = msecs_to_jiffies(command == PS2_CMD_RESET_BAT ? 4000 : 
 500);

  timeout = wait_event_timeout(ps2dev->wait,
 - !(ps2dev->flags &
 PS2_FLAG_CMD1), timeout);
 -
 -if (ps2dev->cmdcnt && !(ps2dev->flags & PS2_FLAG_CMD1)) 

Re: Potential data race in psmouse_interrupt

[Dmitry Torokhov]

On Tue, Sep 1, 2015 at 11:46 AM, Dmitry Vyukov  wrote:
> On Fri, Aug 28, 2015 at 8:32 PM, Dmitry Torokhov
>  wrote:
>> On Fri, Aug 28, 2015 at 11:08 AM, Dmitry Vyukov  wrote:
>>> On Fri, Aug 28, 2015 at 7:51 PM, Dmitry Torokhov
>>>  wrote:
 On Fri, Aug 28, 2015 at 10:34 AM, Dmitry Vyukov  wrote:
> Hello,
>
> I am looking at this code in __ps2_command again:
>
> /*
> * The reset command takes a long time to execute.
> */
> timeout = msecs_to_jiffies(command == PS2_CMD_RESET_BAT ? 4000 : 500);
>
> timeout = wait_event_timeout(ps2dev->wait,
> !(READ_ONCE(ps2dev->flags) & PS2_FLAG_CMD1), timeout);
>
> if (smp_load_acquire(>cmdcnt) &&
> !(smp_load_acquire(>flags) & PS2_FLAG_CMD1)) {
>   timeout = ps2_adjust_timeout(ps2dev, command, timeout);
>   wait_event_timeout(ps2dev->wait,
> !(smp_load_acquire(>flags) &
> PS2_FLAG_CMD), timeout);
> }
>
> if (param)
> for (i = 0; i < receive; i++)
>   param[i] = ps2dev->cmdbuf[(receive - 1) - i];
>
>
> Here are two moments I don't understand:
> 1. The last parameter of ps2_adjust_timeout is timeout in jiffies (it
> is compared against 100ms). However, timeout is assigned to result of
> wait_event_timeout, which returns 0 or 1. This does not make sense to
> me. What am I missing?

 The fact that wait_event_timeout can return value greater than one:

  * Returns:
  * 0 if the @condition evaluated to %false after the @timeout elapsed,
  * 1 if the @condition evaluated to %true after the @timeout elapsed,
  * or the remaining jiffies (at least 1) if the @condition evaluated
   ^
>>>
>>>
>>> OK, makes sense now!
>>>
> 2. This code pays great attention to timeouts, but in the end I don't
> see how it handles timeouts. That is, if a timeout is happened, we
> still copyout (garbage) from cmdbuf. What am I missing here?

 Once upon a time wait_event() did not return positive value when
 timeout expired and then condition satisfied. So we just examine the
 final state (psmpouse->cmdcnt should be 0 if command actually
 succeeded) and even if we copy in garbage nobody should care since
 we'll return error in this case.
>>>
>>>
>>> I see.
>>> But the cmdcnt is re-read after copying out response. So it is
>>> possible that we read garbage response, but then read cmdcnt==0 and
>>> return OK to caller.
>>
>> That assumes that we actually timed out, and while we were copying the
>> data the response finally came.
>
> Right.
>
>>>
>>> So far I have something along the following lines to fix data races in 
>>> libps2.c
>>
>> I don't know, maybe we should simply move call to
>> serio_pause_rx(ps2dev->serio) higher, before we check ps2dev->cmdcnt,
>> and move copying of the buffer down, after checking cmdcnt.
>
> I don't know about serio_pause_rx, but copying of response should be
> done after checking cmdcnt.

It will stop the interrupt handler from running while we are examining
the cmdcnt and copy out the data, thus removing the race.

> Also you need to use smp_store_release/smp_load_acquire cmdcnt and
> flags when they have dependent data. And READ_ONCE/WRITE_ONCE on
> shared state otherwise is highly desirable.
>
>>> diff --git a/drivers/input/serio/libps2.c b/drivers/input/serio/libps2.c
>>> index 7551699..51c747f 100644
>>> --- a/drivers/input/serio/libps2.c
>>> +++ b/drivers/input/serio/libps2.c
>>> @@ -43,7 +43,7 @@ int ps2_sendbyte(struct ps2dev *ps2dev, unsigned
>>> char byte, int timeout)
>>>
>>>  if (serio_write(ps2dev->serio, byte) == 0)
>>>  wait_event_timeout(ps2dev->wait,
>>> -   !(ps2dev->flags & PS2_FLAG_ACK),
>>> +   !(READ_ONCE(ps2dev->flags) & 
>>> PS2_FLAG_ACK),
>>> msecs_to_jiffies(timeout));
>>>
>>>  serio_pause_rx(ps2dev->serio);
>>> @@ -187,6 +187,7 @@ int __ps2_command(struct ps2dev *ps2dev, unsigned
>>> char *param, int command)
>>>  int receive = (command >> 8) & 0xf;
>>>  int rc = -1;
>>>  int i;
>>> +unsigned char cmdcnt;
>>>
>>>  if (receive > sizeof(ps2dev->cmdbuf)) {
>>>  WARN_ON(1);
>>> @@ -225,23 +226,22 @@ int __ps2_command(struct ps2dev *ps2dev,
>>> unsigned char *param, int command)
>>>  timeout = msecs_to_jiffies(command == PS2_CMD_RESET_BAT ? 4000 : 
>>> 500);
>>>
>>>  timeout = wait_event_timeout(ps2dev->wait,
>>> - !(ps2dev->flags &
>>> PS2_FLAG_CMD1), timeout);
>>> -
>>> -if (ps2dev->cmdcnt && !(ps2dev->flags & PS2_FLAG_CMD1)) {
>>> +!(READ_ONCE(ps2dev->flags) & PS2_FLAG_CMD1), timeout);
>>>
>>> +if (READ_ONCE(>cmdcnt) &&
>>> +!(READ_ONCE(>flags) & PS2_FLAG_CMD1)) 

Re: Potential data race in psmouse_interrupt

[Dmitry Torokhov]

On Tue, Sep 1, 2015 at 11:46 AM, Dmitry Vyukov  wrote:
> On Fri, Aug 28, 2015 at 8:32 PM, Dmitry Torokhov
>  wrote:
>> On Fri, Aug 28, 2015 at 11:08 AM, Dmitry Vyukov  wrote:
>>> On Fri, Aug 28, 2015 at 7:51 PM, Dmitry Torokhov
>>>  wrote:
 On Fri, Aug 28, 2015 at 10:34 AM, Dmitry Vyukov  wrote:
> Hello,
>
> I am looking at this code in __ps2_command again:
>
> /*
> * The reset command takes a long time to execute.
> */
> timeout = msecs_to_jiffies(command == PS2_CMD_RESET_BAT ? 4000 : 500);
>
> timeout = wait_event_timeout(ps2dev->wait,
> !(READ_ONCE(ps2dev->flags) & PS2_FLAG_CMD1), timeout);
>
> if (smp_load_acquire(>cmdcnt) &&
> !(smp_load_acquire(>flags) & PS2_FLAG_CMD1)) {
>   timeout = ps2_adjust_timeout(ps2dev, command, timeout);
>   wait_event_timeout(ps2dev->wait,
> !(smp_load_acquire(>flags) &
> PS2_FLAG_CMD), timeout);
> }
>
> if (param)
> for (i = 0; i < receive; i++)
>   param[i] = ps2dev->cmdbuf[(receive - 1) - i];
>
>
> Here are two moments I don't understand:
> 1. The last parameter of ps2_adjust_timeout is timeout in jiffies (it
> is compared against 100ms). However, timeout is assigned to result of
> wait_event_timeout, which returns 0 or 1. This does not make sense to
> me. What am I missing?

 The fact that wait_event_timeout can return value greater than one:

  * Returns:
  * 0 if the @condition evaluated to %false after the @timeout elapsed,
  * 1 if the @condition evaluated to %true after the @timeout elapsed,
  * or the remaining jiffies (at least 1) if the @condition evaluated
   ^
>>>
>>>
>>> OK, makes sense now!
>>>
> 2. This code pays great attention to timeouts, but in the end I don't
> see how it handles timeouts. That is, if a timeout is happened, we
> still copyout (garbage) from cmdbuf. What am I missing here?

 Once upon a time wait_event() did not return positive value when
 timeout expired and then condition satisfied. So we just examine the
 final state (psmpouse->cmdcnt should be 0 if command actually
 succeeded) and even if we copy in garbage nobody should care since
 we'll return error in this case.
>>>
>>>
>>> I see.
>>> But the cmdcnt is re-read after copying out response. So it is
>>> possible that we read garbage response, but then read cmdcnt==0 and
>>> return OK to caller.
>>
>> That assumes that we actually timed out, and while we were copying the
>> data the response finally came.
>
> Right.
>
>>>
>>> So far I have something along the following lines to fix data races in 
>>> libps2.c
>>
>> I don't know, maybe we should simply move call to
>> serio_pause_rx(ps2dev->serio) higher, before we check ps2dev->cmdcnt,
>> and move copying of the buffer down, after checking cmdcnt.
>
> I don't know about serio_pause_rx, but copying of response should be
> done after checking cmdcnt.

It will stop the interrupt handler from running while we are examining
the cmdcnt and copy out the data, thus removing the race.

> Also you need to use smp_store_release/smp_load_acquire cmdcnt and
> flags when they have dependent data. And READ_ONCE/WRITE_ONCE on
> shared state otherwise is highly desirable.
>
>>> diff --git a/drivers/input/serio/libps2.c b/drivers/input/serio/libps2.c
>>> index 7551699..51c747f 100644
>>> --- a/drivers/input/serio/libps2.c
>>> +++ b/drivers/input/serio/libps2.c
>>> @@ -43,7 +43,7 @@ int ps2_sendbyte(struct ps2dev *ps2dev, unsigned
>>> char byte, int timeout)
>>>
>>>  if (serio_write(ps2dev->serio, byte) == 0)
>>>  wait_event_timeout(ps2dev->wait,
>>> -   !(ps2dev->flags & PS2_FLAG_ACK),
>>> +   !(READ_ONCE(ps2dev->flags) & 
>>> PS2_FLAG_ACK),
>>> msecs_to_jiffies(timeout));
>>>
>>>  serio_pause_rx(ps2dev->serio);
>>> @@ -187,6 +187,7 @@ int __ps2_command(struct ps2dev *ps2dev, unsigned
>>> char *param, int command)
>>>  int receive = (command >> 8) & 0xf;
>>>  int rc = -1;
>>>  int i;
>>> +unsigned char cmdcnt;
>>>
>>>  if (receive > sizeof(ps2dev->cmdbuf)) {
>>>  WARN_ON(1);
>>> @@ -225,23 +226,22 @@ int __ps2_command(struct ps2dev *ps2dev,
>>> unsigned char *param, int command)
>>>  timeout = msecs_to_jiffies(command == PS2_CMD_RESET_BAT ? 4000 : 
>>> 500);
>>>
>>>  timeout = wait_event_timeout(ps2dev->wait,
>>> - !(ps2dev->flags &
>>> PS2_FLAG_CMD1), timeout);
>>> -
>>> -if (ps2dev->cmdcnt && !(ps2dev->flags & PS2_FLAG_CMD1)) {
>>> +!(READ_ONCE(ps2dev->flags) & PS2_FLAG_CMD1), 

Re: Potential data race in psmouse_interrupt

[Dmitry Vyukov]

On Fri, Sep 4, 2015 at 6:56 PM, Dmitry Torokhov
 wrote:
> On Tue, Sep 1, 2015 at 11:46 AM, Dmitry Vyukov  wrote:
>> On Fri, Aug 28, 2015 at 8:32 PM, Dmitry Torokhov
>>  wrote:
>>> On Fri, Aug 28, 2015 at 11:08 AM, Dmitry Vyukov  wrote:
 On Fri, Aug 28, 2015 at 7:51 PM, Dmitry Torokhov
  wrote:
> On Fri, Aug 28, 2015 at 10:34 AM, Dmitry Vyukov  
> wrote:
>> Hello,
>>
>> I am looking at this code in __ps2_command again:
>>
>> /*
>> * The reset command takes a long time to execute.
>> */
>> timeout = msecs_to_jiffies(command == PS2_CMD_RESET_BAT ? 4000 : 500);
>>
>> timeout = wait_event_timeout(ps2dev->wait,
>> !(READ_ONCE(ps2dev->flags) & PS2_FLAG_CMD1), timeout);
>>
>> if (smp_load_acquire(>cmdcnt) &&
>> !(smp_load_acquire(>flags) & PS2_FLAG_CMD1)) {
>>   timeout = ps2_adjust_timeout(ps2dev, command, timeout);
>>   wait_event_timeout(ps2dev->wait,
>> !(smp_load_acquire(>flags) &
>> PS2_FLAG_CMD), timeout);
>> }
>>
>> if (param)
>> for (i = 0; i < receive; i++)
>>   param[i] = ps2dev->cmdbuf[(receive - 1) - i];
>>
>>
>> Here are two moments I don't understand:
>> 1. The last parameter of ps2_adjust_timeout is timeout in jiffies (it
>> is compared against 100ms). However, timeout is assigned to result of
>> wait_event_timeout, which returns 0 or 1. This does not make sense to
>> me. What am I missing?
>
> The fact that wait_event_timeout can return value greater than one:
>
>  * Returns:
>  * 0 if the @condition evaluated to %false after the @timeout elapsed,
>  * 1 if the @condition evaluated to %true after the @timeout elapsed,
>  * or the remaining jiffies (at least 1) if the @condition evaluated
>   ^


 OK, makes sense now!

>> 2. This code pays great attention to timeouts, but in the end I don't
>> see how it handles timeouts. That is, if a timeout is happened, we
>> still copyout (garbage) from cmdbuf. What am I missing here?
>
> Once upon a time wait_event() did not return positive value when
> timeout expired and then condition satisfied. So we just examine the
> final state (psmpouse->cmdcnt should be 0 if command actually
> succeeded) and even if we copy in garbage nobody should care since
> we'll return error in this case.


 I see.
 But the cmdcnt is re-read after copying out response. So it is
 possible that we read garbage response, but then read cmdcnt==0 and
 return OK to caller.
>>>
>>> That assumes that we actually timed out, and while we were copying the
>>> data the response finally came.
>>
>> Right.
>>

 So far I have something along the following lines to fix data races in 
 libps2.c
>>>
>>> I don't know, maybe we should simply move call to
>>> serio_pause_rx(ps2dev->serio) higher, before we check ps2dev->cmdcnt,
>>> and move copying of the buffer down, after checking cmdcnt.
>>
>> I don't know about serio_pause_rx, but copying of response should be
>> done after checking cmdcnt.
>
> It will stop the interrupt handler from running while we are examining
> the cmdcnt and copy out the data, thus removing the race.
>
>> Also you need to use smp_store_release/smp_load_acquire cmdcnt and
>> flags when they have dependent data. And READ_ONCE/WRITE_ONCE on
>> shared state otherwise is highly desirable.
>>
 diff --git a/drivers/input/serio/libps2.c b/drivers/input/serio/libps2.c
 index 7551699..51c747f 100644
 --- a/drivers/input/serio/libps2.c
 +++ b/drivers/input/serio/libps2.c
 @@ -43,7 +43,7 @@ int ps2_sendbyte(struct ps2dev *ps2dev, unsigned
 char byte, int timeout)

  if (serio_write(ps2dev->serio, byte) == 0)
  wait_event_timeout(ps2dev->wait,
 -   !(ps2dev->flags & PS2_FLAG_ACK),
 +   !(READ_ONCE(ps2dev->flags) & 
 PS2_FLAG_ACK),
 msecs_to_jiffies(timeout));

  serio_pause_rx(ps2dev->serio);
 @@ -187,6 +187,7 @@ int __ps2_command(struct ps2dev *ps2dev, unsigned
 char *param, int command)
  int receive = (command >> 8) & 0xf;
  int rc = -1;
  int i;
 +unsigned char cmdcnt;

  if (receive > sizeof(ps2dev->cmdbuf)) {
  WARN_ON(1);
 @@ -225,23 +226,22 @@ int __ps2_command(struct ps2dev *ps2dev,
 unsigned char *param, int command)
  timeout = msecs_to_jiffies(command == PS2_CMD_RESET_BAT ? 4000 : 
 500);

  timeout = wait_event_timeout(ps2dev->wait,
 -  

Re: Potential data race in psmouse_interrupt

[Dmitry Torokhov]

On Fri, Sep 4, 2015 at 12:32 PM, Dmitry Vyukov  wrote:
> On Fri, Sep 4, 2015 at 6:56 PM, Dmitry Torokhov
>  wrote:
>> On Tue, Sep 1, 2015 at 11:46 AM, Dmitry Vyukov  wrote:
>>> On Fri, Aug 28, 2015 at 8:32 PM, Dmitry Torokhov
>>>  wrote:
 On Fri, Aug 28, 2015 at 11:08 AM, Dmitry Vyukov  wrote:
> On Fri, Aug 28, 2015 at 7:51 PM, Dmitry Torokhov
>  wrote:
>> On Fri, Aug 28, 2015 at 10:34 AM, Dmitry Vyukov  
>> wrote:
>>> Hello,
>>>
>>> I am looking at this code in __ps2_command again:
>>>
>>> /*
>>> * The reset command takes a long time to execute.
>>> */
>>> timeout = msecs_to_jiffies(command == PS2_CMD_RESET_BAT ? 4000 : 500);
>>>
>>> timeout = wait_event_timeout(ps2dev->wait,
>>> !(READ_ONCE(ps2dev->flags) & PS2_FLAG_CMD1), timeout);
>>>
>>> if (smp_load_acquire(>cmdcnt) &&
>>> !(smp_load_acquire(>flags) & PS2_FLAG_CMD1)) {
>>>   timeout = ps2_adjust_timeout(ps2dev, command, timeout);
>>>   wait_event_timeout(ps2dev->wait,
>>> !(smp_load_acquire(>flags) &
>>> PS2_FLAG_CMD), timeout);
>>> }
>>>
>>> if (param)
>>> for (i = 0; i < receive; i++)
>>>   param[i] = ps2dev->cmdbuf[(receive - 1) - i];
>>>
>>>
>>> Here are two moments I don't understand:
>>> 1. The last parameter of ps2_adjust_timeout is timeout in jiffies (it
>>> is compared against 100ms). However, timeout is assigned to result of
>>> wait_event_timeout, which returns 0 or 1. This does not make sense to
>>> me. What am I missing?
>>
>> The fact that wait_event_timeout can return value greater than one:
>>
>>  * Returns:
>>  * 0 if the @condition evaluated to %false after the @timeout elapsed,
>>  * 1 if the @condition evaluated to %true after the @timeout elapsed,
>>  * or the remaining jiffies (at least 1) if the @condition evaluated
>>   ^
>
>
> OK, makes sense now!
>
>>> 2. This code pays great attention to timeouts, but in the end I don't
>>> see how it handles timeouts. That is, if a timeout is happened, we
>>> still copyout (garbage) from cmdbuf. What am I missing here?
>>
>> Once upon a time wait_event() did not return positive value when
>> timeout expired and then condition satisfied. So we just examine the
>> final state (psmpouse->cmdcnt should be 0 if command actually
>> succeeded) and even if we copy in garbage nobody should care since
>> we'll return error in this case.
>
>
> I see.
> But the cmdcnt is re-read after copying out response. So it is
> possible that we read garbage response, but then read cmdcnt==0 and
> return OK to caller.

 That assumes that we actually timed out, and while we were copying the
 data the response finally came.
>>>
>>> Right.
>>>
>
> So far I have something along the following lines to fix data races in 
> libps2.c

 I don't know, maybe we should simply move call to
 serio_pause_rx(ps2dev->serio) higher, before we check ps2dev->cmdcnt,
 and move copying of the buffer down, after checking cmdcnt.
>>>
>>> I don't know about serio_pause_rx, but copying of response should be
>>> done after checking cmdcnt.
>>
>> It will stop the interrupt handler from running while we are examining
>> the cmdcnt and copy out the data, thus removing the race.
>>
>>> Also you need to use smp_store_release/smp_load_acquire cmdcnt and
>>> flags when they have dependent data. And READ_ONCE/WRITE_ONCE on
>>> shared state otherwise is highly desirable.
>>>
> diff --git a/drivers/input/serio/libps2.c b/drivers/input/serio/libps2.c
> index 7551699..51c747f 100644
> --- a/drivers/input/serio/libps2.c
> +++ b/drivers/input/serio/libps2.c
> @@ -43,7 +43,7 @@ int ps2_sendbyte(struct ps2dev *ps2dev, unsigned
> char byte, int timeout)
>
>  if (serio_write(ps2dev->serio, byte) == 0)
>  wait_event_timeout(ps2dev->wait,
> -   !(ps2dev->flags & PS2_FLAG_ACK),
> +   !(READ_ONCE(ps2dev->flags) & 
> PS2_FLAG_ACK),
> msecs_to_jiffies(timeout));
>
>  serio_pause_rx(ps2dev->serio);
> @@ -187,6 +187,7 @@ int __ps2_command(struct ps2dev *ps2dev, unsigned
> char *param, int command)
>  int receive = (command >> 8) & 0xf;
>  int rc = -1;
>  int i;
> +unsigned char cmdcnt;
>
>  if (receive > sizeof(ps2dev->cmdbuf)) {
>  WARN_ON(1);
> @@ -225,23 +226,22 @@ int __ps2_command(struct ps2dev *ps2dev,
> unsigned char *param, 

Re: Potential data race in psmouse_interrupt

[Dmitry Vyukov]

On Fri, Aug 28, 2015 at 8:32 PM, Dmitry Torokhov
 wrote:
> On Fri, Aug 28, 2015 at 11:08 AM, Dmitry Vyukov  wrote:
>> On Fri, Aug 28, 2015 at 7:51 PM, Dmitry Torokhov
>>  wrote:
>>> On Fri, Aug 28, 2015 at 10:34 AM, Dmitry Vyukov  wrote:
 Hello,

 I am looking at this code in __ps2_command again:

 /*
 * The reset command takes a long time to execute.
 */
 timeout = msecs_to_jiffies(command == PS2_CMD_RESET_BAT ? 4000 : 500);

 timeout = wait_event_timeout(ps2dev->wait,
 !(READ_ONCE(ps2dev->flags) & PS2_FLAG_CMD1), timeout);

 if (smp_load_acquire(>cmdcnt) &&
 !(smp_load_acquire(>flags) & PS2_FLAG_CMD1)) {
   timeout = ps2_adjust_timeout(ps2dev, command, timeout);
   wait_event_timeout(ps2dev->wait,
 !(smp_load_acquire(>flags) &
 PS2_FLAG_CMD), timeout);
 }

 if (param)
 for (i = 0; i < receive; i++)
   param[i] = ps2dev->cmdbuf[(receive - 1) - i];


 Here are two moments I don't understand:
 1. The last parameter of ps2_adjust_timeout is timeout in jiffies (it
 is compared against 100ms). However, timeout is assigned to result of
 wait_event_timeout, which returns 0 or 1. This does not make sense to
 me. What am I missing?
>>>
>>> The fact that wait_event_timeout can return value greater than one:
>>>
>>>  * Returns:
>>>  * 0 if the @condition evaluated to %false after the @timeout elapsed,
>>>  * 1 if the @condition evaluated to %true after the @timeout elapsed,
>>>  * or the remaining jiffies (at least 1) if the @condition evaluated
>>>   ^
>>
>>
>> OK, makes sense now!
>>
 2. This code pays great attention to timeouts, but in the end I don't
 see how it handles timeouts. That is, if a timeout is happened, we
 still copyout (garbage) from cmdbuf. What am I missing here?
>>>
>>> Once upon a time wait_event() did not return positive value when
>>> timeout expired and then condition satisfied. So we just examine the
>>> final state (psmpouse->cmdcnt should be 0 if command actually
>>> succeeded) and even if we copy in garbage nobody should care since
>>> we'll return error in this case.
>>
>>
>> I see.
>> But the cmdcnt is re-read after copying out response. So it is
>> possible that we read garbage response, but then read cmdcnt==0 and
>> return OK to caller.
>
> That assumes that we actually timed out, and while we were copying the
> data the response finally came.

Right.

>>
>> So far I have something along the following lines to fix data races in 
>> libps2.c
>
> I don't know, maybe we should simply move call to
> serio_pause_rx(ps2dev->serio) higher, before we check ps2dev->cmdcnt,
> and move copying of the buffer down, after checking cmdcnt.

I don't know about serio_pause_rx, but copying of response should be
done after checking cmdcnt.
Also you need to use smp_store_release/smp_load_acquire cmdcnt and
flags when they have dependent data. And READ_ONCE/WRITE_ONCE on
shared state otherwise is highly desirable.

>> diff --git a/drivers/input/serio/libps2.c b/drivers/input/serio/libps2.c
>> index 7551699..51c747f 100644
>> --- a/drivers/input/serio/libps2.c
>> +++ b/drivers/input/serio/libps2.c
>> @@ -43,7 +43,7 @@ int ps2_sendbyte(struct ps2dev *ps2dev, unsigned
>> char byte, int timeout)
>>
>>  if (serio_write(ps2dev->serio, byte) == 0)
>>  wait_event_timeout(ps2dev->wait,
>> -   !(ps2dev->flags & PS2_FLAG_ACK),
>> +   !(READ_ONCE(ps2dev->flags) & 
>> PS2_FLAG_ACK),
>> msecs_to_jiffies(timeout));
>>
>>  serio_pause_rx(ps2dev->serio);
>> @@ -187,6 +187,7 @@ int __ps2_command(struct ps2dev *ps2dev, unsigned
>> char *param, int command)
>>  int receive = (command >> 8) & 0xf;
>>  int rc = -1;
>>  int i;
>> +unsigned char cmdcnt;
>>
>>  if (receive > sizeof(ps2dev->cmdbuf)) {
>>  WARN_ON(1);
>> @@ -225,23 +226,22 @@ int __ps2_command(struct ps2dev *ps2dev,
>> unsigned char *param, int command)
>>  timeout = msecs_to_jiffies(command == PS2_CMD_RESET_BAT ? 4000 : 
>> 500);
>>
>>  timeout = wait_event_timeout(ps2dev->wait,
>> - !(ps2dev->flags &
>> PS2_FLAG_CMD1), timeout);
>> -
>> -if (ps2dev->cmdcnt && !(ps2dev->flags & PS2_FLAG_CMD1)) {
>> +!(READ_ONCE(ps2dev->flags) & PS2_FLAG_CMD1), timeout);
>>
>> +if (READ_ONCE(>cmdcnt) &&
>> +!(READ_ONCE(>flags) & PS2_FLAG_CMD1)) {
>>  timeout = ps2_adjust_timeout(ps2dev, command, timeout);
>>  wait_event_timeout(ps2dev->wait,
>> -   !(ps2dev->flags & PS2_FLAG_CMD), 
>> timeout);
>> +!(READ_ONCE(>flags) & PS2_FLAG_CMD), 
>> timeout);
>
> What all these 

Re: Potential data race in psmouse_interrupt

[Dmitry Vyukov]

On Fri, Aug 28, 2015 at 8:32 PM, Dmitry Torokhov
 wrote:
> On Fri, Aug 28, 2015 at 11:08 AM, Dmitry Vyukov  wrote:
>> On Fri, Aug 28, 2015 at 7:51 PM, Dmitry Torokhov
>>  wrote:
>>> On Fri, Aug 28, 2015 at 10:34 AM, Dmitry Vyukov  wrote:
 Hello,

 I am looking at this code in __ps2_command again:

 /*
 * The reset command takes a long time to execute.
 */
 timeout = msecs_to_jiffies(command == PS2_CMD_RESET_BAT ? 4000 : 500);

 timeout = wait_event_timeout(ps2dev->wait,
 !(READ_ONCE(ps2dev->flags) & PS2_FLAG_CMD1), timeout);

 if (smp_load_acquire(>cmdcnt) &&
 !(smp_load_acquire(>flags) & PS2_FLAG_CMD1)) {
   timeout = ps2_adjust_timeout(ps2dev, command, timeout);
   wait_event_timeout(ps2dev->wait,
 !(smp_load_acquire(>flags) &
 PS2_FLAG_CMD), timeout);
 }

 if (param)
 for (i = 0; i < receive; i++)
   param[i] = ps2dev->cmdbuf[(receive - 1) - i];


 Here are two moments I don't understand:
 1. The last parameter of ps2_adjust_timeout is timeout in jiffies (it
 is compared against 100ms). However, timeout is assigned to result of
 wait_event_timeout, which returns 0 or 1. This does not make sense to
 me. What am I missing?
>>>
>>> The fact that wait_event_timeout can return value greater than one:
>>>
>>>  * Returns:
>>>  * 0 if the @condition evaluated to %false after the @timeout elapsed,
>>>  * 1 if the @condition evaluated to %true after the @timeout elapsed,
>>>  * or the remaining jiffies (at least 1) if the @condition evaluated
>>>   ^
>>
>>
>> OK, makes sense now!
>>
 2. This code pays great attention to timeouts, but in the end I don't
 see how it handles timeouts. That is, if a timeout is happened, we
 still copyout (garbage) from cmdbuf. What am I missing here?
>>>
>>> Once upon a time wait_event() did not return positive value when
>>> timeout expired and then condition satisfied. So we just examine the
>>> final state (psmpouse->cmdcnt should be 0 if command actually
>>> succeeded) and even if we copy in garbage nobody should care since
>>> we'll return error in this case.
>>
>>
>> I see.
>> But the cmdcnt is re-read after copying out response. So it is
>> possible that we read garbage response, but then read cmdcnt==0 and
>> return OK to caller.
>
> That assumes that we actually timed out, and while we were copying the
> data the response finally came.

Right.

>>
>> So far I have something along the following lines to fix data races in 
>> libps2.c
>
> I don't know, maybe we should simply move call to
> serio_pause_rx(ps2dev->serio) higher, before we check ps2dev->cmdcnt,
> and move copying of the buffer down, after checking cmdcnt.

I don't know about serio_pause_rx, but copying of response should be
done after checking cmdcnt.
Also you need to use smp_store_release/smp_load_acquire cmdcnt and
flags when they have dependent data. And READ_ONCE/WRITE_ONCE on
shared state otherwise is highly desirable.

>> diff --git a/drivers/input/serio/libps2.c b/drivers/input/serio/libps2.c
>> index 7551699..51c747f 100644
>> --- a/drivers/input/serio/libps2.c
>> +++ b/drivers/input/serio/libps2.c
>> @@ -43,7 +43,7 @@ int ps2_sendbyte(struct ps2dev *ps2dev, unsigned
>> char byte, int timeout)
>>
>>  if (serio_write(ps2dev->serio, byte) == 0)
>>  wait_event_timeout(ps2dev->wait,
>> -   !(ps2dev->flags & PS2_FLAG_ACK),
>> +   !(READ_ONCE(ps2dev->flags) & 
>> PS2_FLAG_ACK),
>> msecs_to_jiffies(timeout));
>>
>>  serio_pause_rx(ps2dev->serio);
>> @@ -187,6 +187,7 @@ int __ps2_command(struct ps2dev *ps2dev, unsigned
>> char *param, int command)
>>  int receive = (command >> 8) & 0xf;
>>  int rc = -1;
>>  int i;
>> +unsigned char cmdcnt;
>>
>>  if (receive > sizeof(ps2dev->cmdbuf)) {
>>  WARN_ON(1);
>> @@ -225,23 +226,22 @@ int __ps2_command(struct ps2dev *ps2dev,
>> unsigned char *param, int command)
>>  timeout = msecs_to_jiffies(command == PS2_CMD_RESET_BAT ? 4000 : 
>> 500);
>>
>>  timeout = wait_event_timeout(ps2dev->wait,
>> - !(ps2dev->flags &
>> PS2_FLAG_CMD1), timeout);
>> -
>> -if (ps2dev->cmdcnt && !(ps2dev->flags & PS2_FLAG_CMD1)) {
>> +!(READ_ONCE(ps2dev->flags) & PS2_FLAG_CMD1), timeout);
>>
>> +if (READ_ONCE(>cmdcnt) &&
>> +!(READ_ONCE(>flags) & PS2_FLAG_CMD1)) {
>>  timeout = ps2_adjust_timeout(ps2dev, command, timeout);
>>  wait_event_timeout(ps2dev->wait,
>> -   !(ps2dev->flags & PS2_FLAG_CMD), 
>> timeout);
>> 

Re: Potential data race in psmouse_interrupt

[Dmitry Torokhov]

On Fri, Aug 28, 2015 at 11:32 AM, Dmitry Torokhov
 wrote:
> On Fri, Aug 28, 2015 at 11:08 AM, Dmitry Vyukov  wrote:
>> On Fri, Aug 28, 2015 at 7:51 PM, Dmitry Torokhov
>>  wrote:
>>> On Fri, Aug 28, 2015 at 10:34 AM, Dmitry Vyukov  wrote:
 Hello,

 I am looking at this code in __ps2_command again:

 /*
 * The reset command takes a long time to execute.
 */
 timeout = msecs_to_jiffies(command == PS2_CMD_RESET_BAT ? 4000 : 500);

 timeout = wait_event_timeout(ps2dev->wait,
 !(READ_ONCE(ps2dev->flags) & PS2_FLAG_CMD1), timeout);

 if (smp_load_acquire(>cmdcnt) &&
 !(smp_load_acquire(>flags) & PS2_FLAG_CMD1)) {
   timeout = ps2_adjust_timeout(ps2dev, command, timeout);
   wait_event_timeout(ps2dev->wait,
 !(smp_load_acquire(>flags) &
 PS2_FLAG_CMD), timeout);
 }

 if (param)
 for (i = 0; i < receive; i++)
   param[i] = ps2dev->cmdbuf[(receive - 1) - i];


 Here are two moments I don't understand:
 1. The last parameter of ps2_adjust_timeout is timeout in jiffies (it
 is compared against 100ms). However, timeout is assigned to result of
 wait_event_timeout, which returns 0 or 1. This does not make sense to
 me. What am I missing?
>>>
>>> The fact that wait_event_timeout can return value greater than one:
>>>
>>>  * Returns:
>>>  * 0 if the @condition evaluated to %false after the @timeout elapsed,
>>>  * 1 if the @condition evaluated to %true after the @timeout elapsed,
>>>  * or the remaining jiffies (at least 1) if the @condition evaluated
>>>   ^
>>
>>
>> OK, makes sense now!
>>
 2. This code pays great attention to timeouts, but in the end I don't
 see how it handles timeouts. That is, if a timeout is happened, we
 still copyout (garbage) from cmdbuf. What am I missing here?
>>>
>>> Once upon a time wait_event() did not return positive value when
>>> timeout expired and then condition satisfied. So we just examine the
>>> final state (psmpouse->cmdcnt should be 0 if command actually
>>> succeeded) and even if we copy in garbage nobody should care since
>>> we'll return error in this case.
>>
>>
>> I see.
>> But the cmdcnt is re-read after copying out response. So it is
>> possible that we read garbage response, but then read cmdcnt==0 and
>> return OK to caller.
>
> That assumes that we actually timed out, and while we were copying the
> data the response finally came.
>
>>
>> So far I have something along the following lines to fix data races in 
>> libps2.c
>
> I don't know, maybe we should simply move call to
> serio_pause_rx(ps2dev->serio) higher, before we check ps2dev->cmdcnt,
> and move copying of the buffer down, after checking cmdcnt.

By the way, please either drop ktsan group from public postngs or open
it to post from public.

Thanks.

-- 
Dmitry
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

Re: Potential data race in psmouse_interrupt

[Dmitry Torokhov]

On Fri, Aug 28, 2015 at 11:08 AM, Dmitry Vyukov  wrote:
> On Fri, Aug 28, 2015 at 7:51 PM, Dmitry Torokhov
>  wrote:
>> On Fri, Aug 28, 2015 at 10:34 AM, Dmitry Vyukov  wrote:
>>> Hello,
>>>
>>> I am looking at this code in __ps2_command again:
>>>
>>> /*
>>> * The reset command takes a long time to execute.
>>> */
>>> timeout = msecs_to_jiffies(command == PS2_CMD_RESET_BAT ? 4000 : 500);
>>>
>>> timeout = wait_event_timeout(ps2dev->wait,
>>> !(READ_ONCE(ps2dev->flags) & PS2_FLAG_CMD1), timeout);
>>>
>>> if (smp_load_acquire(>cmdcnt) &&
>>> !(smp_load_acquire(>flags) & PS2_FLAG_CMD1)) {
>>>   timeout = ps2_adjust_timeout(ps2dev, command, timeout);
>>>   wait_event_timeout(ps2dev->wait,
>>> !(smp_load_acquire(>flags) &
>>> PS2_FLAG_CMD), timeout);
>>> }
>>>
>>> if (param)
>>> for (i = 0; i < receive; i++)
>>>   param[i] = ps2dev->cmdbuf[(receive - 1) - i];
>>>
>>>
>>> Here are two moments I don't understand:
>>> 1. The last parameter of ps2_adjust_timeout is timeout in jiffies (it
>>> is compared against 100ms). However, timeout is assigned to result of
>>> wait_event_timeout, which returns 0 or 1. This does not make sense to
>>> me. What am I missing?
>>
>> The fact that wait_event_timeout can return value greater than one:
>>
>>  * Returns:
>>  * 0 if the @condition evaluated to %false after the @timeout elapsed,
>>  * 1 if the @condition evaluated to %true after the @timeout elapsed,
>>  * or the remaining jiffies (at least 1) if the @condition evaluated
>>   ^
>
>
> OK, makes sense now!
>
>>> 2. This code pays great attention to timeouts, but in the end I don't
>>> see how it handles timeouts. That is, if a timeout is happened, we
>>> still copyout (garbage) from cmdbuf. What am I missing here?
>>
>> Once upon a time wait_event() did not return positive value when
>> timeout expired and then condition satisfied. So we just examine the
>> final state (psmpouse->cmdcnt should be 0 if command actually
>> succeeded) and even if we copy in garbage nobody should care since
>> we'll return error in this case.
>
>
> I see.
> But the cmdcnt is re-read after copying out response. So it is
> possible that we read garbage response, but then read cmdcnt==0 and
> return OK to caller.

That assumes that we actually timed out, and while we were copying the
data the response finally came.

>
> So far I have something along the following lines to fix data races in 
> libps2.c

I don't know, maybe we should simply move call to
serio_pause_rx(ps2dev->serio) higher, before we check ps2dev->cmdcnt,
and move copying of the buffer down, after checking cmdcnt.

>
>
> diff --git a/drivers/input/serio/libps2.c b/drivers/input/serio/libps2.c
> index 7551699..51c747f 100644
> --- a/drivers/input/serio/libps2.c
> +++ b/drivers/input/serio/libps2.c
> @@ -43,7 +43,7 @@ int ps2_sendbyte(struct ps2dev *ps2dev, unsigned
> char byte, int timeout)
>
>  if (serio_write(ps2dev->serio, byte) == 0)
>  wait_event_timeout(ps2dev->wait,
> -   !(ps2dev->flags & PS2_FLAG_ACK),
> +   !(READ_ONCE(ps2dev->flags) & 
> PS2_FLAG_ACK),
> msecs_to_jiffies(timeout));
>
>  serio_pause_rx(ps2dev->serio);
> @@ -187,6 +187,7 @@ int __ps2_command(struct ps2dev *ps2dev, unsigned
> char *param, int command)
>  int receive = (command >> 8) & 0xf;
>  int rc = -1;
>  int i;
> +unsigned char cmdcnt;
>
>  if (receive > sizeof(ps2dev->cmdbuf)) {
>  WARN_ON(1);
> @@ -225,23 +226,22 @@ int __ps2_command(struct ps2dev *ps2dev,
> unsigned char *param, int command)
>  timeout = msecs_to_jiffies(command == PS2_CMD_RESET_BAT ? 4000 : 
> 500);
>
>  timeout = wait_event_timeout(ps2dev->wait,
> - !(ps2dev->flags &
> PS2_FLAG_CMD1), timeout);
> -
> -if (ps2dev->cmdcnt && !(ps2dev->flags & PS2_FLAG_CMD1)) {
> +!(READ_ONCE(ps2dev->flags) & PS2_FLAG_CMD1), timeout);
>
> +if (READ_ONCE(>cmdcnt) &&
> +!(READ_ONCE(>flags) & PS2_FLAG_CMD1)) {
>  timeout = ps2_adjust_timeout(ps2dev, command, timeout);
>  wait_event_timeout(ps2dev->wait,
> -   !(ps2dev->flags & PS2_FLAG_CMD), timeout);
> +!(READ_ONCE(>flags) & PS2_FLAG_CMD), 
> timeout);

What all these READ_ONCE()s give us?

>  }
>
> -if (param)
> -for (i = 0; i < receive; i++)
> -param[i] = ps2dev->cmdbuf[(receive - 1) - i];
> -
> -if (ps2dev->cmdcnt && (command != PS2_CMD_RESET_BAT ||
> ps2dev->cmdcnt != 1))
> -goto out;
> -
> -rc = 0;
> +cmdcnt = smp_load_acquire(>cmdcnt);
> +if (!cmdcnt || command == PS2_CMD_RESET_BAT && ps2dev->cmdcnt == 1) {
> +   

Re: Potential data race in psmouse_interrupt

[Dmitry Vyukov]

On Fri, Aug 28, 2015 at 7:51 PM, Dmitry Torokhov
 wrote:
> On Fri, Aug 28, 2015 at 10:34 AM, Dmitry Vyukov  wrote:
>> Hello,
>>
>> I am looking at this code in __ps2_command again:
>>
>> /*
>> * The reset command takes a long time to execute.
>> */
>> timeout = msecs_to_jiffies(command == PS2_CMD_RESET_BAT ? 4000 : 500);
>>
>> timeout = wait_event_timeout(ps2dev->wait,
>> !(READ_ONCE(ps2dev->flags) & PS2_FLAG_CMD1), timeout);
>>
>> if (smp_load_acquire(>cmdcnt) &&
>> !(smp_load_acquire(>flags) & PS2_FLAG_CMD1)) {
>>   timeout = ps2_adjust_timeout(ps2dev, command, timeout);
>>   wait_event_timeout(ps2dev->wait,
>> !(smp_load_acquire(>flags) &
>> PS2_FLAG_CMD), timeout);
>> }
>>
>> if (param)
>> for (i = 0; i < receive; i++)
>>   param[i] = ps2dev->cmdbuf[(receive - 1) - i];
>>
>>
>> Here are two moments I don't understand:
>> 1. The last parameter of ps2_adjust_timeout is timeout in jiffies (it
>> is compared against 100ms). However, timeout is assigned to result of
>> wait_event_timeout, which returns 0 or 1. This does not make sense to
>> me. What am I missing?
>
> The fact that wait_event_timeout can return value greater than one:
>
>  * Returns:
>  * 0 if the @condition evaluated to %false after the @timeout elapsed,
>  * 1 if the @condition evaluated to %true after the @timeout elapsed,
>  * or the remaining jiffies (at least 1) if the @condition evaluated
>   ^


OK, makes sense now!

>> 2. This code pays great attention to timeouts, but in the end I don't
>> see how it handles timeouts. That is, if a timeout is happened, we
>> still copyout (garbage) from cmdbuf. What am I missing here?
>
> Once upon a time wait_event() did not return positive value when
> timeout expired and then condition satisfied. So we just examine the
> final state (psmpouse->cmdcnt should be 0 if command actually
> succeeded) and even if we copy in garbage nobody should care since
> we'll return error in this case.


I see.
But the cmdcnt is re-read after copying out response. So it is
possible that we read garbage response, but then read cmdcnt==0 and
return OK to caller.

So far I have something along the following lines to fix data races in libps2.c


diff --git a/drivers/input/serio/libps2.c b/drivers/input/serio/libps2.c
index 7551699..51c747f 100644
--- a/drivers/input/serio/libps2.c
+++ b/drivers/input/serio/libps2.c
@@ -43,7 +43,7 @@ int ps2_sendbyte(struct ps2dev *ps2dev, unsigned
char byte, int timeout)

 if (serio_write(ps2dev->serio, byte) == 0)
 wait_event_timeout(ps2dev->wait,
-   !(ps2dev->flags & PS2_FLAG_ACK),
+   !(READ_ONCE(ps2dev->flags) & PS2_FLAG_ACK),
msecs_to_jiffies(timeout));

 serio_pause_rx(ps2dev->serio);
@@ -187,6 +187,7 @@ int __ps2_command(struct ps2dev *ps2dev, unsigned
char *param, int command)
 int receive = (command >> 8) & 0xf;
 int rc = -1;
 int i;
+unsigned char cmdcnt;

 if (receive > sizeof(ps2dev->cmdbuf)) {
 WARN_ON(1);
@@ -225,23 +226,22 @@ int __ps2_command(struct ps2dev *ps2dev,
unsigned char *param, int command)
 timeout = msecs_to_jiffies(command == PS2_CMD_RESET_BAT ? 4000 : 500);

 timeout = wait_event_timeout(ps2dev->wait,
- !(ps2dev->flags &
PS2_FLAG_CMD1), timeout);
-
-if (ps2dev->cmdcnt && !(ps2dev->flags & PS2_FLAG_CMD1)) {
+!(READ_ONCE(ps2dev->flags) & PS2_FLAG_CMD1), timeout);

+if (READ_ONCE(>cmdcnt) &&
+!(READ_ONCE(>flags) & PS2_FLAG_CMD1)) {
 timeout = ps2_adjust_timeout(ps2dev, command, timeout);
 wait_event_timeout(ps2dev->wait,
-   !(ps2dev->flags & PS2_FLAG_CMD), timeout);
+!(READ_ONCE(>flags) & PS2_FLAG_CMD), timeout);
 }

-if (param)
-for (i = 0; i < receive; i++)
-param[i] = ps2dev->cmdbuf[(receive - 1) - i];
-
-if (ps2dev->cmdcnt && (command != PS2_CMD_RESET_BAT ||
ps2dev->cmdcnt != 1))
-goto out;
-
-rc = 0;
+cmdcnt = smp_load_acquire(>cmdcnt);
+if (!cmdcnt || command == PS2_CMD_RESET_BAT && ps2dev->cmdcnt == 1) {
+if (param)
+for (i = 0; i < receive; i++)
+param[i] = ps2dev->cmdbuf[(receive - 1) - i];
+rc = 0;
+}

  out:
 serio_pause_rx(ps2dev->serio);
@@ -284,19 +284,21 @@ EXPORT_SYMBOL(ps2_init);

 int ps2_handle_ack(struct ps2dev *ps2dev, unsigned char data)
 {
+unsigned long flags = ps2dev->flags;
+
 switch (data) {
 case PS2_RET_ACK:
 ps2dev->nak = 0;
 break;

 case 

Re: Potential data race in psmouse_interrupt

[Dmitry Torokhov]

On Fri, Aug 28, 2015 at 10:34 AM, Dmitry Vyukov  wrote:
> Hello,
>
> I am looking at this code in __ps2_command again:
>
> /*
> * The reset command takes a long time to execute.
> */
> timeout = msecs_to_jiffies(command == PS2_CMD_RESET_BAT ? 4000 : 500);
>
> timeout = wait_event_timeout(ps2dev->wait,
> !(READ_ONCE(ps2dev->flags) & PS2_FLAG_CMD1), timeout);
>
> if (smp_load_acquire(>cmdcnt) &&
> !(smp_load_acquire(>flags) & PS2_FLAG_CMD1)) {
>   timeout = ps2_adjust_timeout(ps2dev, command, timeout);
>   wait_event_timeout(ps2dev->wait,
> !(smp_load_acquire(>flags) &
> PS2_FLAG_CMD), timeout);
> }
>
> if (param)
> for (i = 0; i < receive; i++)
>   param[i] = ps2dev->cmdbuf[(receive - 1) - i];
>
>
> Here are two moments I don't understand:
> 1. The last parameter of ps2_adjust_timeout is timeout in jiffies (it
> is compared against 100ms). However, timeout is assigned to result of
> wait_event_timeout, which returns 0 or 1. This does not make sense to
> me. What am I missing?

The fact that wait_event_timeout can return value greater than one:

 * Returns:
 * 0 if the @condition evaluated to %false after the @timeout elapsed,
 * 1 if the @condition evaluated to %true after the @timeout elapsed,
 * or the remaining jiffies (at least 1) if the @condition evaluated
  ^

> 2. This code pays great attention to timeouts, but in the end I don't
> see how it handles timeouts. That is, if a timeout is happened, we
> still copyout (garbage) from cmdbuf. What am I missing here?

Once upon a time wait_event() did not return positive value when
timeout expired and then condition satisfied. So we just examine the
final state (psmpouse->cmdcnt should be 0 if command actually
succeeded) and even if we copy in garbage nobody should care since
we'll return error in this case.

Thanks.

-- 
Dmitry
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

Re: Potential data race in psmouse_interrupt

[Dmitry Vyukov]

Hello,

I am looking at this code in __ps2_command again:

/*
* The reset command takes a long time to execute.
*/
timeout = msecs_to_jiffies(command == PS2_CMD_RESET_BAT ? 4000 : 500);

timeout = wait_event_timeout(ps2dev->wait,
!(READ_ONCE(ps2dev->flags) & PS2_FLAG_CMD1), timeout);

if (smp_load_acquire(>cmdcnt) &&
!(smp_load_acquire(>flags) & PS2_FLAG_CMD1)) {
  timeout = ps2_adjust_timeout(ps2dev, command, timeout);
  wait_event_timeout(ps2dev->wait,
!(smp_load_acquire(>flags) &
PS2_FLAG_CMD), timeout);
}

if (param)
for (i = 0; i < receive; i++)
  param[i] = ps2dev->cmdbuf[(receive - 1) - i];


Here are two moments I don't understand:
1. The last parameter of ps2_adjust_timeout is timeout in jiffies (it
is compared against 100ms). However, timeout is assigned to result of
wait_event_timeout, which returns 0 or 1. This does not make sense to
me. What am I missing?
2. This code pays great attention to timeouts, but in the end I don't
see how it handles timeouts. That is, if a timeout is happened, we
still copyout (garbage) from cmdbuf. What am I missing here?

Thank you
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

Re: Potential data race in psmouse_interrupt

[Dmitry Vyukov]

Hello,

I am looking at this code in __ps2_command again:

/*
* The reset command takes a long time to execute.
*/
timeout = msecs_to_jiffies(command == PS2_CMD_RESET_BAT ? 4000 : 500);

timeout = wait_event_timeout(ps2dev-wait,
!(READ_ONCE(ps2dev-flags)  PS2_FLAG_CMD1), timeout);

if (smp_load_acquire(ps2dev-cmdcnt) 
!(smp_load_acquire(ps2dev-flags)  PS2_FLAG_CMD1)) {
  timeout = ps2_adjust_timeout(ps2dev, command, timeout);
  wait_event_timeout(ps2dev-wait,
!(smp_load_acquire(ps2dev-flags) 
PS2_FLAG_CMD), timeout);
}

if (param)
for (i = 0; i  receive; i++)
  param[i] = ps2dev-cmdbuf[(receive - 1) - i];


Here are two moments I don't understand:
1. The last parameter of ps2_adjust_timeout is timeout in jiffies (it
is compared against 100ms). However, timeout is assigned to result of
wait_event_timeout, which returns 0 or 1. This does not make sense to
me. What am I missing?
2. This code pays great attention to timeouts, but in the end I don't
see how it handles timeouts. That is, if a timeout is happened, we
still copyout (garbage) from cmdbuf. What am I missing here?

Thank you
--
To unsubscribe from this list: send the line unsubscribe linux-kernel in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

Re: Potential data race in psmouse_interrupt

[Dmitry Torokhov]

On Fri, Aug 28, 2015 at 10:34 AM, Dmitry Vyukov dvyu...@google.com wrote:
 Hello,

 I am looking at this code in __ps2_command again:

 /*
 * The reset command takes a long time to execute.
 */
 timeout = msecs_to_jiffies(command == PS2_CMD_RESET_BAT ? 4000 : 500);

 timeout = wait_event_timeout(ps2dev-wait,
 !(READ_ONCE(ps2dev-flags)  PS2_FLAG_CMD1), timeout);

 if (smp_load_acquire(ps2dev-cmdcnt) 
 !(smp_load_acquire(ps2dev-flags)  PS2_FLAG_CMD1)) {
   timeout = ps2_adjust_timeout(ps2dev, command, timeout);
   wait_event_timeout(ps2dev-wait,
 !(smp_load_acquire(ps2dev-flags) 
 PS2_FLAG_CMD), timeout);
 }

 if (param)
 for (i = 0; i  receive; i++)
   param[i] = ps2dev-cmdbuf[(receive - 1) - i];


 Here are two moments I don't understand:
 1. The last parameter of ps2_adjust_timeout is timeout in jiffies (it
 is compared against 100ms). However, timeout is assigned to result of
 wait_event_timeout, which returns 0 or 1. This does not make sense to
 me. What am I missing?

The fact that wait_event_timeout can return value greater than one:

 * Returns:
 * 0 if the @condition evaluated to %false after the @timeout elapsed,
 * 1 if the @condition evaluated to %true after the @timeout elapsed,
 * or the remaining jiffies (at least 1) if the @condition evaluated
  ^

 2. This code pays great attention to timeouts, but in the end I don't
 see how it handles timeouts. That is, if a timeout is happened, we
 still copyout (garbage) from cmdbuf. What am I missing here?

Once upon a time wait_event() did not return positive value when
timeout expired and then condition satisfied. So we just examine the
final state (psmpouse-cmdcnt should be 0 if command actually
succeeded) and even if we copy in garbage nobody should care since
we'll return error in this case.

Thanks.

-- 
Dmitry
--
To unsubscribe from this list: send the line unsubscribe linux-kernel in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

Re: Potential data race in psmouse_interrupt

[Dmitry Torokhov]

On Fri, Aug 28, 2015 at 11:32 AM, Dmitry Torokhov
dmitry.torok...@gmail.com wrote:
 On Fri, Aug 28, 2015 at 11:08 AM, Dmitry Vyukov dvyu...@google.com wrote:
 On Fri, Aug 28, 2015 at 7:51 PM, Dmitry Torokhov
 dmitry.torok...@gmail.com wrote:
 On Fri, Aug 28, 2015 at 10:34 AM, Dmitry Vyukov dvyu...@google.com wrote:
 Hello,

 I am looking at this code in __ps2_command again:

 /*
 * The reset command takes a long time to execute.
 */
 timeout = msecs_to_jiffies(command == PS2_CMD_RESET_BAT ? 4000 : 500);

 timeout = wait_event_timeout(ps2dev-wait,
 !(READ_ONCE(ps2dev-flags)  PS2_FLAG_CMD1), timeout);

 if (smp_load_acquire(ps2dev-cmdcnt) 
 !(smp_load_acquire(ps2dev-flags)  PS2_FLAG_CMD1)) {
   timeout = ps2_adjust_timeout(ps2dev, command, timeout);
   wait_event_timeout(ps2dev-wait,
 !(smp_load_acquire(ps2dev-flags) 
 PS2_FLAG_CMD), timeout);
 }

 if (param)
 for (i = 0; i  receive; i++)
   param[i] = ps2dev-cmdbuf[(receive - 1) - i];


 Here are two moments I don't understand:
 1. The last parameter of ps2_adjust_timeout is timeout in jiffies (it
 is compared against 100ms). However, timeout is assigned to result of
 wait_event_timeout, which returns 0 or 1. This does not make sense to
 me. What am I missing?

 The fact that wait_event_timeout can return value greater than one:

  * Returns:
  * 0 if the @condition evaluated to %false after the @timeout elapsed,
  * 1 if the @condition evaluated to %true after the @timeout elapsed,
  * or the remaining jiffies (at least 1) if the @condition evaluated
   ^


 OK, makes sense now!

 2. This code pays great attention to timeouts, but in the end I don't
 see how it handles timeouts. That is, if a timeout is happened, we
 still copyout (garbage) from cmdbuf. What am I missing here?

 Once upon a time wait_event() did not return positive value when
 timeout expired and then condition satisfied. So we just examine the
 final state (psmpouse-cmdcnt should be 0 if command actually
 succeeded) and even if we copy in garbage nobody should care since
 we'll return error in this case.


 I see.
 But the cmdcnt is re-read after copying out response. So it is
 possible that we read garbage response, but then read cmdcnt==0 and
 return OK to caller.

 That assumes that we actually timed out, and while we were copying the
 data the response finally came.


 So far I have something along the following lines to fix data races in 
 libps2.c

 I don't know, maybe we should simply move call to
 serio_pause_rx(ps2dev-serio) higher, before we check ps2dev-cmdcnt,
 and move copying of the buffer down, after checking cmdcnt.

By the way, please either drop ktsan group from public postngs or open
it to post from public.

Thanks.

-- 
Dmitry
--
To unsubscribe from this list: send the line unsubscribe linux-kernel in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

Re: Potential data race in psmouse_interrupt

[Dmitry Vyukov]

On Fri, Aug 28, 2015 at 7:51 PM, Dmitry Torokhov
dmitry.torok...@gmail.com wrote:
 On Fri, Aug 28, 2015 at 10:34 AM, Dmitry Vyukov dvyu...@google.com wrote:
 Hello,

 I am looking at this code in __ps2_command again:

 /*
 * The reset command takes a long time to execute.
 */
 timeout = msecs_to_jiffies(command == PS2_CMD_RESET_BAT ? 4000 : 500);

 timeout = wait_event_timeout(ps2dev-wait,
 !(READ_ONCE(ps2dev-flags)  PS2_FLAG_CMD1), timeout);

 if (smp_load_acquire(ps2dev-cmdcnt) 
 !(smp_load_acquire(ps2dev-flags)  PS2_FLAG_CMD1)) {
   timeout = ps2_adjust_timeout(ps2dev, command, timeout);
   wait_event_timeout(ps2dev-wait,
 !(smp_load_acquire(ps2dev-flags) 
 PS2_FLAG_CMD), timeout);
 }

 if (param)
 for (i = 0; i  receive; i++)
   param[i] = ps2dev-cmdbuf[(receive - 1) - i];


 Here are two moments I don't understand:
 1. The last parameter of ps2_adjust_timeout is timeout in jiffies (it
 is compared against 100ms). However, timeout is assigned to result of
 wait_event_timeout, which returns 0 or 1. This does not make sense to
 me. What am I missing?

 The fact that wait_event_timeout can return value greater than one:

  * Returns:
  * 0 if the @condition evaluated to %false after the @timeout elapsed,
  * 1 if the @condition evaluated to %true after the @timeout elapsed,
  * or the remaining jiffies (at least 1) if the @condition evaluated
   ^


OK, makes sense now!

 2. This code pays great attention to timeouts, but in the end I don't
 see how it handles timeouts. That is, if a timeout is happened, we
 still copyout (garbage) from cmdbuf. What am I missing here?

 Once upon a time wait_event() did not return positive value when
 timeout expired and then condition satisfied. So we just examine the
 final state (psmpouse-cmdcnt should be 0 if command actually
 succeeded) and even if we copy in garbage nobody should care since
 we'll return error in this case.


I see.
But the cmdcnt is re-read after copying out response. So it is
possible that we read garbage response, but then read cmdcnt==0 and
return OK to caller.

So far I have something along the following lines to fix data races in libps2.c


diff --git a/drivers/input/serio/libps2.c b/drivers/input/serio/libps2.c
index 7551699..51c747f 100644
--- a/drivers/input/serio/libps2.c
+++ b/drivers/input/serio/libps2.c
@@ -43,7 +43,7 @@ int ps2_sendbyte(struct ps2dev *ps2dev, unsigned
char byte, int timeout)

 if (serio_write(ps2dev-serio, byte) == 0)
 wait_event_timeout(ps2dev-wait,
-   !(ps2dev-flags  PS2_FLAG_ACK),
+   !(READ_ONCE(ps2dev-flags)  PS2_FLAG_ACK),
msecs_to_jiffies(timeout));

 serio_pause_rx(ps2dev-serio);
@@ -187,6 +187,7 @@ int __ps2_command(struct ps2dev *ps2dev, unsigned
char *param, int command)
 int receive = (command  8)  0xf;
 int rc = -1;
 int i;
+unsigned char cmdcnt;

 if (receive  sizeof(ps2dev-cmdbuf)) {
 WARN_ON(1);
@@ -225,23 +226,22 @@ int __ps2_command(struct ps2dev *ps2dev,
unsigned char *param, int command)
 timeout = msecs_to_jiffies(command == PS2_CMD_RESET_BAT ? 4000 : 500);

 timeout = wait_event_timeout(ps2dev-wait,
- !(ps2dev-flags 
PS2_FLAG_CMD1), timeout);
-
-if (ps2dev-cmdcnt  !(ps2dev-flags  PS2_FLAG_CMD1)) {
+!(READ_ONCE(ps2dev-flags)  PS2_FLAG_CMD1), timeout);

+if (READ_ONCE(ps2dev-cmdcnt) 
+!(READ_ONCE(ps2dev-flags)  PS2_FLAG_CMD1)) {
 timeout = ps2_adjust_timeout(ps2dev, command, timeout);
 wait_event_timeout(ps2dev-wait,
-   !(ps2dev-flags  PS2_FLAG_CMD), timeout);
+!(READ_ONCE(ps2dev-flags)  PS2_FLAG_CMD), timeout);
 }

-if (param)
-for (i = 0; i  receive; i++)
-param[i] = ps2dev-cmdbuf[(receive - 1) - i];
-
-if (ps2dev-cmdcnt  (command != PS2_CMD_RESET_BAT ||
ps2dev-cmdcnt != 1))
-goto out;
-
-rc = 0;
+cmdcnt = smp_load_acquire(ps2dev-cmdcnt);
+if (!cmdcnt || command == PS2_CMD_RESET_BAT  ps2dev-cmdcnt == 1) {
+if (param)
+for (i = 0; i  receive; i++)
+param[i] = ps2dev-cmdbuf[(receive - 1) - i];
+rc = 0;
+}

  out:
 serio_pause_rx(ps2dev-serio);
@@ -284,19 +284,21 @@ EXPORT_SYMBOL(ps2_init);

 int ps2_handle_ack(struct ps2dev *ps2dev, unsigned char data)
 {
+unsigned long flags = ps2dev-flags;
+
 switch (data) {
 case PS2_RET_ACK:
 ps2dev-nak = 0;
 break;

 case PS2_RET_NAK:
-ps2dev-flags |= 

Re: Potential data race in psmouse_interrupt

[Dmitry Torokhov]

On Fri, Aug 28, 2015 at 11:08 AM, Dmitry Vyukov dvyu...@google.com wrote:
 On Fri, Aug 28, 2015 at 7:51 PM, Dmitry Torokhov
 dmitry.torok...@gmail.com wrote:
 On Fri, Aug 28, 2015 at 10:34 AM, Dmitry Vyukov dvyu...@google.com wrote:
 Hello,

 I am looking at this code in __ps2_command again:

 /*
 * The reset command takes a long time to execute.
 */
 timeout = msecs_to_jiffies(command == PS2_CMD_RESET_BAT ? 4000 : 500);

 timeout = wait_event_timeout(ps2dev-wait,
 !(READ_ONCE(ps2dev-flags)  PS2_FLAG_CMD1), timeout);

 if (smp_load_acquire(ps2dev-cmdcnt) 
 !(smp_load_acquire(ps2dev-flags)  PS2_FLAG_CMD1)) {
   timeout = ps2_adjust_timeout(ps2dev, command, timeout);
   wait_event_timeout(ps2dev-wait,
 !(smp_load_acquire(ps2dev-flags) 
 PS2_FLAG_CMD), timeout);
 }

 if (param)
 for (i = 0; i  receive; i++)
   param[i] = ps2dev-cmdbuf[(receive - 1) - i];


 Here are two moments I don't understand:
 1. The last parameter of ps2_adjust_timeout is timeout in jiffies (it
 is compared against 100ms). However, timeout is assigned to result of
 wait_event_timeout, which returns 0 or 1. This does not make sense to
 me. What am I missing?

 The fact that wait_event_timeout can return value greater than one:

  * Returns:
  * 0 if the @condition evaluated to %false after the @timeout elapsed,
  * 1 if the @condition evaluated to %true after the @timeout elapsed,
  * or the remaining jiffies (at least 1) if the @condition evaluated
   ^


 OK, makes sense now!

 2. This code pays great attention to timeouts, but in the end I don't
 see how it handles timeouts. That is, if a timeout is happened, we
 still copyout (garbage) from cmdbuf. What am I missing here?

 Once upon a time wait_event() did not return positive value when
 timeout expired and then condition satisfied. So we just examine the
 final state (psmpouse-cmdcnt should be 0 if command actually
 succeeded) and even if we copy in garbage nobody should care since
 we'll return error in this case.


 I see.
 But the cmdcnt is re-read after copying out response. So it is
 possible that we read garbage response, but then read cmdcnt==0 and
 return OK to caller.

That assumes that we actually timed out, and while we were copying the
data the response finally came.


 So far I have something along the following lines to fix data races in 
 libps2.c

I don't know, maybe we should simply move call to
serio_pause_rx(ps2dev-serio) higher, before we check ps2dev-cmdcnt,
and move copying of the buffer down, after checking cmdcnt.



 diff --git a/drivers/input/serio/libps2.c b/drivers/input/serio/libps2.c
 index 7551699..51c747f 100644
 --- a/drivers/input/serio/libps2.c
 +++ b/drivers/input/serio/libps2.c
 @@ -43,7 +43,7 @@ int ps2_sendbyte(struct ps2dev *ps2dev, unsigned
 char byte, int timeout)

  if (serio_write(ps2dev-serio, byte) == 0)
  wait_event_timeout(ps2dev-wait,
 -   !(ps2dev-flags  PS2_FLAG_ACK),
 +   !(READ_ONCE(ps2dev-flags)  
 PS2_FLAG_ACK),
 msecs_to_jiffies(timeout));

  serio_pause_rx(ps2dev-serio);
 @@ -187,6 +187,7 @@ int __ps2_command(struct ps2dev *ps2dev, unsigned
 char *param, int command)
  int receive = (command  8)  0xf;
  int rc = -1;
  int i;
 +unsigned char cmdcnt;

  if (receive  sizeof(ps2dev-cmdbuf)) {
  WARN_ON(1);
 @@ -225,23 +226,22 @@ int __ps2_command(struct ps2dev *ps2dev,
 unsigned char *param, int command)
  timeout = msecs_to_jiffies(command == PS2_CMD_RESET_BAT ? 4000 : 
 500);

  timeout = wait_event_timeout(ps2dev-wait,
 - !(ps2dev-flags 
 PS2_FLAG_CMD1), timeout);
 -
 -if (ps2dev-cmdcnt  !(ps2dev-flags  PS2_FLAG_CMD1)) {
 +!(READ_ONCE(ps2dev-flags)  PS2_FLAG_CMD1), timeout);

 +if (READ_ONCE(ps2dev-cmdcnt) 
 +!(READ_ONCE(ps2dev-flags)  PS2_FLAG_CMD1)) {
  timeout = ps2_adjust_timeout(ps2dev, command, timeout);
  wait_event_timeout(ps2dev-wait,
 -   !(ps2dev-flags  PS2_FLAG_CMD), timeout);
 +!(READ_ONCE(ps2dev-flags)  PS2_FLAG_CMD), 
 timeout);

What all these READ_ONCE()s give us?

  }

 -if (param)
 -for (i = 0; i  receive; i++)
 -param[i] = ps2dev-cmdbuf[(receive - 1) - i];
 -
 -if (ps2dev-cmdcnt  (command != PS2_CMD_RESET_BAT ||
 ps2dev-cmdcnt != 1))
 -goto out;
 -
 -rc = 0;
 +cmdcnt = smp_load_acquire(ps2dev-cmdcnt);
 +if (!cmdcnt || command == PS2_CMD_RESET_BAT  ps2dev-cmdcnt == 1) {
 +if (param)
 +for (i = 0; i  receive; i++)
 +param[i] = ps2dev-cmdbuf[(receive - 

Re: Potential data race in psmouse_interrupt

[Pali Rohár]

Hi! This log looks like there can be race condition in initialization
code, but not in receiving ALPS packets after initialization...

On Thursday 23 July 2015 15:31:46 Andrey Konovalov wrote:
> Hi Pali,
> 
> There are a few reports in psmouse-base.c/alps.c code as well.
> Here is a couple of them that are printed one right after another.
> The second one tells about a race on ps2dev->cmdcnt.
> 
> ==
> ThreadSanitizer: data-race in ps2_handle_ack
> 
> Write of size 8 by thread T6 (K6):
>  [] ps2_handle_ack+0xf3/0x180 
> drivers/input/serio/libps2.c:322
>  [] psmouse_interrupt+0x207/0x690
> drivers/input/mouse/psmouse-base.c:317
>  [] serio_interrupt+0x66/0xb0 
> drivers/input/serio/serio.c:1008
>  [] i8042_interrupt+0x240/0x4d0
> drivers/input/serio/i8042.c:541
>  [] handle_irq_event_percpu+0x62/0x2a0 
> kernel/irq/handle.c:143
>  [] handle_irq_event+0xa2/0xf0 kernel/irq/handle.c:192
>  [] handle_edge_irq+0x104/0x380 kernel/irq/chip.c:608
>  [< inlined>] handle_irq+0xf6/0x220 generic_handle_irq_desc
> include/linux/irqdesc.h:146
>  [] handle_irq+0xf6/0x220 arch/x86/kernel/irq_64.c:81
>  [] do_IRQ+0x5e/0x110 arch/x86/kernel/irq.c:223
>  [] ret_from_intr+0x0/0x1f arch/x86/entry/entry_64.S:601
>  [< inlined>] irq_exit+0x98/0xa0 invoke_softirq kernel/softirq.c:350
>  [] irq_exit+0x98/0xa0 kernel/softirq.c:391
>  [< inlined>] smp_apic_timer_interrupt+0x63/0x80 exiting_irq
> ./arch/x86/include/asm/apic.h:655
>  [] smp_apic_timer_interrupt+0x63/0x80
> arch/x86/kernel/apic/apic.c:915
>  [] apic_timer_interrupt+0x6b/0x70
> arch/x86/entry/entry_64.S:782
>  [] _do_fork+0x133/0x500 kernel/fork.c:1719
>  [] kernel_thread+0x3c/0x60 kernel/fork.c:1772
>  [] __call_usermodehelper+0x5c/0x90 kernel/kmod.c:317
>  [] process_one_work+0x2a9/0x6d0 kernel/workqueue.c:2036
>  [] worker_thread+0xbf/0x710 kernel/workqueue.c:2170
>  [] kthread+0x15c/0x180 kernel/kthread.c:207
>  [] ret_from_fork+0x3f/0x70 arch/x86/entry/entry_64.S:526
> DBG: cpu = 88053fd9fe68
> DBG: cpu id = 3
> 
> Previous read of size 8 by thread T397 (K394):
>  [] ps2_sendbyte+0xe2/0x210 drivers/input/serio/libps2.c:45
>  [] __ps2_command+0x159/0x660 
> drivers/input/serio/libps2.c:214
>  [] ps2_command+0x35/0x60 drivers/input/serio/libps2.c:260
>  [] alps_rpt_cmd+0x42/0xe0
> drivers/input/mouse/alps.c:1665 (discriminator 1)
>  [] alps_identify+0x36/0xc80 drivers/input/mouse/alps.c:2690
>  [] alps_detect+0x28/0x150 drivers/input/mouse/alps.c:2960
>  [< inlined>] psmouse_extensions+0x25e/0x4e0 psmouse_do_detect
> drivers/input/mouse/psmouse-base.c:752
>  [] psmouse_extensions+0x25e/0x4e0
> drivers/input/mouse/psmouse-base.c:870
>  [] psmouse_switch_protocol+0x2ad/0x330
> drivers/input/mouse/psmouse-base.c:1467
>  [] psmouse_connect+0x2e6/0x450
> drivers/input/mouse/psmouse-base.c:1554 (discriminator 4)
>  [< inlined>] serio_driver_probe+0x57/0x80
> serio_connect_driver drivers/input/serio/serio.c:65
>  [] serio_driver_probe+0x57/0x80
> drivers/input/serio/serio.c:796
>  [< inlined>] driver_probe_device+0x1da/0x460 really_probe
> drivers/base/dd.c:308
>  [] driver_probe_device+0x1da/0x460 drivers/base/dd.c:414
>  [] __driver_attach+0xc4/0xd0 drivers/base/dd.c:612
>  [] bus_for_each_dev+0x93/0xe0 drivers/base/bus.c:314
>  [] driver_attach+0x33/0x50 drivers/base/dd.c:631
>  [< inlined>] serio_handle_event+0x2d3/0x3b0
> serio_attach_driver drivers/input/serio/serio.c:826
>  [] serio_handle_event+0x2d3/0x3b0
> drivers/input/serio/serio.c:245
>  [] process_one_work+0x2a9/0x6d0 kernel/workqueue.c:2036
>  [] worker_thread+0xbf/0x710 kernel/workqueue.c:2170
>  [] kthread+0x15c/0x180 kernel/kthread.c:207
>  [] ret_from_fork+0x3f/0x70 arch/x86/entry/entry_64.S:526
> DBG: cpu = 0
> 
> DBG: addr: 88019a923a58
> DBG: first offset: 0, second offset: 0
> DBG: T6 clock: {T6: 2264295, T397: 174118}
> DBG: T397 clock: {T397: 174122}
> ==
> ==
> ThreadSanitizer: data-race in __ps2_command
> 
> Read of size 1 by thread T397 (K394):
>  [] __ps2_command+0x270/0x660
> drivers/input/serio/libps2.c:230 (discriminator 21)
>  [] ps2_command+0x35/0x60 drivers/input/serio/libps2.c:260
>  [] alps_rpt_cmd+0xae/0xe0 drivers/input/mouse/alps.c:1674
>  [] alps_identify+0x36/0xc80 drivers/input/mouse/alps.c:2690
>  [] alps_detect+0x28/0x150 drivers/input/mouse/alps.c:2960
>  [< inlined>] psmouse_extensions+0x25e/0x4e0 psmouse_do_detect
> drivers/input/mouse/psmouse-base.c:752
>  [] psmouse_extensions+0x25e/0x4e0
> drivers/input/mouse/psmouse-base.c:870
>  [] psmouse_switch_protocol+0x2ad/0x330
> drivers/input/mouse/psmouse-base.c:1467
>  [] psmouse_connect+0x2e6/0x450
> drivers/input/mouse/psmouse-base.c:1554 (discriminator 4)
>  [< inlined>] serio_driver_probe+0x57/0x80
> serio_connect_driver drivers/input/serio/serio.c:65
>  [] 

Re: Potential data race in psmouse_interrupt

[Pali Rohár]

Hi! This log looks like there can be race condition in initialization
code, but not in receiving ALPS packets after initialization...

On Thursday 23 July 2015 15:31:46 Andrey Konovalov wrote:
 Hi Pali,
 
 There are a few reports in psmouse-base.c/alps.c code as well.
 Here is a couple of them that are printed one right after another.
 The second one tells about a race on ps2dev-cmdcnt.
 
 ==
 ThreadSanitizer: data-race in ps2_handle_ack
 
 Write of size 8 by thread T6 (K6):
  [819c0b83] ps2_handle_ack+0xf3/0x180 
 drivers/input/serio/libps2.c:322
  [819d55d7] psmouse_interrupt+0x207/0x690
 drivers/input/mouse/psmouse-base.c:317
  [819bcf46] serio_interrupt+0x66/0xb0 
 drivers/input/serio/serio.c:1008
  [819be820] i8042_interrupt+0x240/0x4d0
 drivers/input/serio/i8042.c:541
  [810f03b2] handle_irq_event_percpu+0x62/0x2a0 
 kernel/irq/handle.c:143
  [810f0692] handle_irq_event+0xa2/0xf0 kernel/irq/handle.c:192
  [810f5414] handle_edge_irq+0x104/0x380 kernel/irq/chip.c:608
  [ inlined] handle_irq+0xf6/0x220 generic_handle_irq_desc
 include/linux/irqdesc.h:146
  [81009f86] handle_irq+0xf6/0x220 arch/x86/kernel/irq_64.c:81
  [810093ce] do_IRQ+0x5e/0x110 arch/x86/kernel/irq.c:223
  [81e728ab] ret_from_intr+0x0/0x1f arch/x86/entry/entry_64.S:601
  [ inlined] irq_exit+0x98/0xa0 invoke_softirq kernel/softirq.c:350
  [8108edd8] irq_exit+0x98/0xa0 kernel/softirq.c:391
  [ inlined] smp_apic_timer_interrupt+0x63/0x80 exiting_irq
 ./arch/x86/include/asm/apic.h:655
  [8105c503] smp_apic_timer_interrupt+0x63/0x80
 arch/x86/kernel/apic/apic.c:915
  [81e72b9b] apic_timer_interrupt+0x6b/0x70
 arch/x86/entry/entry_64.S:782
  [81086fe3] _do_fork+0x133/0x500 kernel/fork.c:1719
  [810873ec] kernel_thread+0x3c/0x60 kernel/fork.c:1772
  [810a71dc] __call_usermodehelper+0x5c/0x90 kernel/kmod.c:317
  [810adcf9] process_one_work+0x2a9/0x6d0 kernel/workqueue.c:2036
  [810aeddf] worker_thread+0xbf/0x710 kernel/workqueue.c:2170
  [810b700c] kthread+0x15c/0x180 kernel/kthread.c:207
  [81e7215f] ret_from_fork+0x3f/0x70 arch/x86/entry/entry_64.S:526
 DBG: cpu = 88053fd9fe68
 DBG: cpu id = 3
 
 Previous read of size 8 by thread T397 (K394):
  [819c0cf2] ps2_sendbyte+0xe2/0x210 drivers/input/serio/libps2.c:45
  [819c1109] __ps2_command+0x159/0x660 
 drivers/input/serio/libps2.c:214
  [819c1645] ps2_command+0x35/0x60 drivers/input/serio/libps2.c:260
  [819dd412] alps_rpt_cmd+0x42/0xe0
 drivers/input/mouse/alps.c:1665 (discriminator 1)
  [819e12b6] alps_identify+0x36/0xc80 drivers/input/mouse/alps.c:2690
  [819e3498] alps_detect+0x28/0x150 drivers/input/mouse/alps.c:2960
  [ inlined] psmouse_extensions+0x25e/0x4e0 psmouse_do_detect
 drivers/input/mouse/psmouse-base.c:752
  [819d60fe] psmouse_extensions+0x25e/0x4e0
 drivers/input/mouse/psmouse-base.c:870
  [819d662d] psmouse_switch_protocol+0x2ad/0x330
 drivers/input/mouse/psmouse-base.c:1467
  [819d7656] psmouse_connect+0x2e6/0x450
 drivers/input/mouse/psmouse-base.c:1554 (discriminator 4)
  [ inlined] serio_driver_probe+0x57/0x80
 serio_connect_driver drivers/input/serio/serio.c:65
  [819bd1a7] serio_driver_probe+0x57/0x80
 drivers/input/serio/serio.c:796
  [ inlined] driver_probe_device+0x1da/0x460 really_probe
 drivers/base/dd.c:308
  [81813d4a] driver_probe_device+0x1da/0x460 drivers/base/dd.c:414
  [81814094] __driver_attach+0xc4/0xd0 drivers/base/dd.c:612
  [81810b63] bus_for_each_dev+0x93/0xe0 drivers/base/bus.c:314
  [81813583] driver_attach+0x33/0x50 drivers/base/dd.c:631
  [ inlined] serio_handle_event+0x2d3/0x3b0
 serio_attach_driver drivers/input/serio/serio.c:826
  [819bdb13] serio_handle_event+0x2d3/0x3b0
 drivers/input/serio/serio.c:245
  [810adcf9] process_one_work+0x2a9/0x6d0 kernel/workqueue.c:2036
  [810aeddf] worker_thread+0xbf/0x710 kernel/workqueue.c:2170
  [810b700c] kthread+0x15c/0x180 kernel/kthread.c:207
  [81e7215f] ret_from_fork+0x3f/0x70 arch/x86/entry/entry_64.S:526
 DBG: cpu = 0
 
 DBG: addr: 88019a923a58
 DBG: first offset: 0, second offset: 0
 DBG: T6 clock: {T6: 2264295, T397: 174118}
 DBG: T397 clock: {T397: 174122}
 ==
 ==
 ThreadSanitizer: data-race in __ps2_command
 
 Read of size 1 by thread T397 (K394):
  [819c1220] __ps2_command+0x270/0x660
 drivers/input/serio/libps2.c:230 (discriminator 21)
  [819c1645] ps2_command+0x35/0x60 drivers/input/serio/libps2.c:260
  [819dd47e] alps_rpt_cmd+0xae/0xe0 drivers/input/mouse/alps.c:1674
  [819e12b6] alps_identify+0x36/0xc80 

Re: Potential data race in psmouse_interrupt

[Andrey Konovalov]

Hi Pali,

There are a few reports in psmouse-base.c/alps.c code as well.
Here is a couple of them that are printed one right after another.
The second one tells about a race on ps2dev->cmdcnt.

==
ThreadSanitizer: data-race in ps2_handle_ack

Write of size 8 by thread T6 (K6):
 [] ps2_handle_ack+0xf3/0x180 drivers/input/serio/libps2.c:322
 [] psmouse_interrupt+0x207/0x690
drivers/input/mouse/psmouse-base.c:317
 [] serio_interrupt+0x66/0xb0 drivers/input/serio/serio.c:1008
 [] i8042_interrupt+0x240/0x4d0
drivers/input/serio/i8042.c:541
 [] handle_irq_event_percpu+0x62/0x2a0 kernel/irq/handle.c:143
 [] handle_irq_event+0xa2/0xf0 kernel/irq/handle.c:192
 [] handle_edge_irq+0x104/0x380 kernel/irq/chip.c:608
 [< inlined>] handle_irq+0xf6/0x220 generic_handle_irq_desc
include/linux/irqdesc.h:146
 [] handle_irq+0xf6/0x220 arch/x86/kernel/irq_64.c:81
 [] do_IRQ+0x5e/0x110 arch/x86/kernel/irq.c:223
 [] ret_from_intr+0x0/0x1f arch/x86/entry/entry_64.S:601
 [< inlined>] irq_exit+0x98/0xa0 invoke_softirq kernel/softirq.c:350
 [] irq_exit+0x98/0xa0 kernel/softirq.c:391
 [< inlined>] smp_apic_timer_interrupt+0x63/0x80 exiting_irq
./arch/x86/include/asm/apic.h:655
 [] smp_apic_timer_interrupt+0x63/0x80
arch/x86/kernel/apic/apic.c:915
 [] apic_timer_interrupt+0x6b/0x70
arch/x86/entry/entry_64.S:782
 [] _do_fork+0x133/0x500 kernel/fork.c:1719
 [] kernel_thread+0x3c/0x60 kernel/fork.c:1772
 [] __call_usermodehelper+0x5c/0x90 kernel/kmod.c:317
 [] process_one_work+0x2a9/0x6d0 kernel/workqueue.c:2036
 [] worker_thread+0xbf/0x710 kernel/workqueue.c:2170
 [] kthread+0x15c/0x180 kernel/kthread.c:207
 [] ret_from_fork+0x3f/0x70 arch/x86/entry/entry_64.S:526
DBG: cpu = 88053fd9fe68
DBG: cpu id = 3

Previous read of size 8 by thread T397 (K394):
 [] ps2_sendbyte+0xe2/0x210 drivers/input/serio/libps2.c:45
 [] __ps2_command+0x159/0x660 drivers/input/serio/libps2.c:214
 [] ps2_command+0x35/0x60 drivers/input/serio/libps2.c:260
 [] alps_rpt_cmd+0x42/0xe0
drivers/input/mouse/alps.c:1665 (discriminator 1)
 [] alps_identify+0x36/0xc80 drivers/input/mouse/alps.c:2690
 [] alps_detect+0x28/0x150 drivers/input/mouse/alps.c:2960
 [< inlined>] psmouse_extensions+0x25e/0x4e0 psmouse_do_detect
drivers/input/mouse/psmouse-base.c:752
 [] psmouse_extensions+0x25e/0x4e0
drivers/input/mouse/psmouse-base.c:870
 [] psmouse_switch_protocol+0x2ad/0x330
drivers/input/mouse/psmouse-base.c:1467
 [] psmouse_connect+0x2e6/0x450
drivers/input/mouse/psmouse-base.c:1554 (discriminator 4)
 [< inlined>] serio_driver_probe+0x57/0x80
serio_connect_driver drivers/input/serio/serio.c:65
 [] serio_driver_probe+0x57/0x80
drivers/input/serio/serio.c:796
 [< inlined>] driver_probe_device+0x1da/0x460 really_probe
drivers/base/dd.c:308
 [] driver_probe_device+0x1da/0x460 drivers/base/dd.c:414
 [] __driver_attach+0xc4/0xd0 drivers/base/dd.c:612
 [] bus_for_each_dev+0x93/0xe0 drivers/base/bus.c:314
 [] driver_attach+0x33/0x50 drivers/base/dd.c:631
 [< inlined>] serio_handle_event+0x2d3/0x3b0
serio_attach_driver drivers/input/serio/serio.c:826
 [] serio_handle_event+0x2d3/0x3b0
drivers/input/serio/serio.c:245
 [] process_one_work+0x2a9/0x6d0 kernel/workqueue.c:2036
 [] worker_thread+0xbf/0x710 kernel/workqueue.c:2170
 [] kthread+0x15c/0x180 kernel/kthread.c:207
 [] ret_from_fork+0x3f/0x70 arch/x86/entry/entry_64.S:526
DBG: cpu = 0

DBG: addr: 88019a923a58
DBG: first offset: 0, second offset: 0
DBG: T6 clock: {T6: 2264295, T397: 174118}
DBG: T397 clock: {T397: 174122}
==
==
ThreadSanitizer: data-race in __ps2_command

Read of size 1 by thread T397 (K394):
 [] __ps2_command+0x270/0x660
drivers/input/serio/libps2.c:230 (discriminator 21)
 [] ps2_command+0x35/0x60 drivers/input/serio/libps2.c:260
 [] alps_rpt_cmd+0xae/0xe0 drivers/input/mouse/alps.c:1674
 [] alps_identify+0x36/0xc80 drivers/input/mouse/alps.c:2690
 [] alps_detect+0x28/0x150 drivers/input/mouse/alps.c:2960
 [< inlined>] psmouse_extensions+0x25e/0x4e0 psmouse_do_detect
drivers/input/mouse/psmouse-base.c:752
 [] psmouse_extensions+0x25e/0x4e0
drivers/input/mouse/psmouse-base.c:870
 [] psmouse_switch_protocol+0x2ad/0x330
drivers/input/mouse/psmouse-base.c:1467
 [] psmouse_connect+0x2e6/0x450
drivers/input/mouse/psmouse-base.c:1554 (discriminator 4)
 [< inlined>] serio_driver_probe+0x57/0x80
serio_connect_driver drivers/input/serio/serio.c:65
 [] serio_driver_probe+0x57/0x80
drivers/input/serio/serio.c:796
 [< inlined>] driver_probe_device+0x1da/0x460 really_probe
drivers/base/dd.c:308
 [] driver_probe_device+0x1da/0x460 drivers/base/dd.c:414
 [] __driver_attach+0xc4/0xd0 drivers/base/dd.c:612
 [] bus_for_each_dev+0x93/0xe0 drivers/base/bus.c:314
 [] driver_attach+0x33/0x50 drivers/base/dd.c:631
 [< inlined>] 

Re: Potential data race in psmouse_interrupt

[Pali Rohár]

On Wednesday 22 July 2015 15:14:42 Andrey Konovalov wrote:
> Hi!
> 
> We are working on a dynamic data race detector for Linux kernel called
> KernelThreadSanitizer (ktsan) (https://github.com/google/ktsan/wiki).
> 
> Here is a report we got while running ktsan (upstream revision
> 21bdb584af8cca7c6df3c44cba268be050a234eb).
> 
> ==
> ThreadSanitizer: data-race in psmouse_interrupt
> 
> Write of size 1 by thread T1 (K1):
>  [] psmouse_interrupt+0xd2/0x690
> drivers/input/mouse/psmouse-base.c:337
>  [] serio_interrupt+0x66/0xb0 
> drivers/input/serio/serio.c:1008
>  [] i8042_interrupt+0x240/0x4d0
> drivers/input/serio/i8042.c:541
>  [] handle_irq_event_percpu+0x62/0x2a0 
> kernel/irq/handle.c:143
>  [] handle_irq_event+0xa2/0xf0 kernel/irq/handle.c:192
>  [] handle_edge_irq+0x104/0x380 kernel/irq/chip.c:608
>  [< inlined>] handle_irq+0xf6/0x220 generic_handle_irq_desc
> include/linux/irqdesc.h:146
>  [] handle_irq+0xf6/0x220 arch/x86/kernel/irq_64.c:81
>  [] do_IRQ+0x5e/0x110 arch/x86/kernel/irq.c:223
>  [] ret_from_intr+0x0/0x1f arch/x86/entry/entry_64.S:601
>  [< inlined>] irq_exit+0x98/0xa0 invoke_softirq kernel/softirq.c:350
>  [] irq_exit+0x98/0xa0 kernel/softirq.c:391
>  [< inlined>] smp_apic_timer_interrupt+0x63/0x80 exiting_irq
> ./arch/x86/include/asm/apic.h:655
>  [] smp_apic_timer_interrupt+0x63/0x80
> arch/x86/kernel/apic/apic.c:915
>  [] apic_timer_interrupt+0x6b/0x70
> arch/x86/entry/entry_64.S:782
>  [] kvasprintf+0x5d/0x90 lib/kasprintf.c:24
>  [] kasprintf+0x4e/0x70 lib/kasprintf.c:40
>  [< inlined>] module_add_driver+0x8f/0x180 make_driver_name
> drivers/base/module.c:18
>  [] module_add_driver+0x8f/0x180 drivers/base/module.c:63
>  [] bus_add_driver+0x204/0x340 drivers/base/bus.c:713
>  [] driver_register+0xdb/0x190 drivers/base/driver.c:168
>  [] __hid_register_driver+0xb6/0x100
> drivers/hid/hid-core.c:2677
>  [] apple_driver_init+0x24/0x31 drivers/hid/hid-apple.c:574
>  [] do_one_initcall+0xb9/0x220 init/main.c:798
>  [< inlined>] kernel_init_freeable+0x2ca/0x397
> do_initcall_level init/main.c:863
>  [< inlined>] kernel_init_freeable+0x2ca/0x397 do_initcalls
> init/main.c:871
>  [< inlined>] kernel_init_freeable+0x2ca/0x397 do_basic_setup
> init/main.c:890
>  [] kernel_init_freeable+0x2ca/0x397 init/main.c:1013
>  [] kernel_init+0x16/0x140 init/main.c:941
>  [] ret_from_fork+0x3f/0x70 arch/x86/entry/entry_64.S:526
> DBG: cpu = 88053fd9fe68
> DBG: cpu id = 3
> 
> Previous read of size 1 by thread T509 (K506):
>  [< inlined>] cypress_send_ext_cmd+0x193/0x500
> cypress_ps2_read_cmd_status drivers/input/mouse/cypress_ps2.c:123
>  [] cypress_send_ext_cmd+0x193/0x500
> drivers/input/mouse/cypress_ps2.c:192
>  [] cypress_detect+0x2a/0xb0
> drivers/input/mouse/cypress_ps2.c:208
>  [] psmouse_extensions+0x1f6/0x4e0
> drivers/input/mouse/psmouse-base.c:849 (discriminator 1)
>  [] psmouse_switch_protocol+0x2ad/0x330
> drivers/input/mouse/psmouse-base.c:1467
>  [] psmouse_connect+0x2e6/0x450
> drivers/input/mouse/psmouse-base.c:1554 (discriminator 4)
>  [< inlined>] serio_driver_probe+0x57/0x80
> serio_connect_driver drivers/input/serio/serio.c:65
>  [] serio_driver_probe+0x57/0x80
> drivers/input/serio/serio.c:796
>  [< inlined>] driver_probe_device+0x1da/0x460 really_probe
> drivers/base/dd.c:308
>  [] driver_probe_device+0x1da/0x460 drivers/base/dd.c:414
>  [] __driver_attach+0xc4/0xd0 drivers/base/dd.c:612
>  [] bus_for_each_dev+0x93/0xe0 drivers/base/bus.c:314
>  [] driver_attach+0x33/0x50 drivers/base/dd.c:631
>  [< inlined>] serio_handle_event+0x2d3/0x3b0
> serio_attach_driver drivers/input/serio/serio.c:826
>  [] serio_handle_event+0x2d3/0x3b0
> drivers/input/serio/serio.c:245
>  [] process_one_work+0x2a9/0x6d0 kernel/workqueue.c:2036
>  [] worker_thread+0xbf/0x710 kernel/workqueue.c:2170
>  [] kthread+0x15c/0x180 kernel/kthread.c:207
>  [] ret_from_fork+0x3f/0x70 arch/x86/entry/entry_64.S:526
> DBG: cpu = 0
> 
> DBG: addr: 88019d703909
> DBG: first offset: 1, second offset: 1
> DBG: T1 clock: {T1: 17075020, T509: 142163}
> DBG: T509 clock: {T509: 142167}
> ==
> 
> It seems that accessing 'psmouse->pktcnt' in
> 'psmouse->packet[psmouse->pktcnt++] = data' in 'psmouse_interrupt()'
> is racing with 'wait_event_timeout(ps2dev->wait, (psmouse->pktcnt >=
> pktsize), msecs_to_jiffies(CYTP_CMD_TIMEOUT))' in
> 'cypress_ps2_read_cmd_status()'.
> If that's the case, it's possible that 'psmouse->pktcnt' is
> incremented, but no data is written yet, so '(psmouse->pktcnt >=
> pktsize)' will evaluate to true and the following 'memcpy' will access
> invalid data.
> 
> Could you confirm if this is a real data race?
> 
> Thanks in advance!
> 

Hi Andrey,

I would like to ask you, did not you noticed some problem from Sanitizer
with psmouse-base.c and alps.c code?

There is unknown 

Re: Potential data race in psmouse_interrupt

[Andrey Konovalov]

Hi Pali,

There are a few reports in psmouse-base.c/alps.c code as well.
Here is a couple of them that are printed one right after another.
The second one tells about a race on ps2dev-cmdcnt.

==
ThreadSanitizer: data-race in ps2_handle_ack

Write of size 8 by thread T6 (K6):
 [819c0b83] ps2_handle_ack+0xf3/0x180 drivers/input/serio/libps2.c:322
 [819d55d7] psmouse_interrupt+0x207/0x690
drivers/input/mouse/psmouse-base.c:317
 [819bcf46] serio_interrupt+0x66/0xb0 drivers/input/serio/serio.c:1008
 [819be820] i8042_interrupt+0x240/0x4d0
drivers/input/serio/i8042.c:541
 [810f03b2] handle_irq_event_percpu+0x62/0x2a0 kernel/irq/handle.c:143
 [810f0692] handle_irq_event+0xa2/0xf0 kernel/irq/handle.c:192
 [810f5414] handle_edge_irq+0x104/0x380 kernel/irq/chip.c:608
 [ inlined] handle_irq+0xf6/0x220 generic_handle_irq_desc
include/linux/irqdesc.h:146
 [81009f86] handle_irq+0xf6/0x220 arch/x86/kernel/irq_64.c:81
 [810093ce] do_IRQ+0x5e/0x110 arch/x86/kernel/irq.c:223
 [81e728ab] ret_from_intr+0x0/0x1f arch/x86/entry/entry_64.S:601
 [ inlined] irq_exit+0x98/0xa0 invoke_softirq kernel/softirq.c:350
 [8108edd8] irq_exit+0x98/0xa0 kernel/softirq.c:391
 [ inlined] smp_apic_timer_interrupt+0x63/0x80 exiting_irq
./arch/x86/include/asm/apic.h:655
 [8105c503] smp_apic_timer_interrupt+0x63/0x80
arch/x86/kernel/apic/apic.c:915
 [81e72b9b] apic_timer_interrupt+0x6b/0x70
arch/x86/entry/entry_64.S:782
 [81086fe3] _do_fork+0x133/0x500 kernel/fork.c:1719
 [810873ec] kernel_thread+0x3c/0x60 kernel/fork.c:1772
 [810a71dc] __call_usermodehelper+0x5c/0x90 kernel/kmod.c:317
 [810adcf9] process_one_work+0x2a9/0x6d0 kernel/workqueue.c:2036
 [810aeddf] worker_thread+0xbf/0x710 kernel/workqueue.c:2170
 [810b700c] kthread+0x15c/0x180 kernel/kthread.c:207
 [81e7215f] ret_from_fork+0x3f/0x70 arch/x86/entry/entry_64.S:526
DBG: cpu = 88053fd9fe68
DBG: cpu id = 3

Previous read of size 8 by thread T397 (K394):
 [819c0cf2] ps2_sendbyte+0xe2/0x210 drivers/input/serio/libps2.c:45
 [819c1109] __ps2_command+0x159/0x660 drivers/input/serio/libps2.c:214
 [819c1645] ps2_command+0x35/0x60 drivers/input/serio/libps2.c:260
 [819dd412] alps_rpt_cmd+0x42/0xe0
drivers/input/mouse/alps.c:1665 (discriminator 1)
 [819e12b6] alps_identify+0x36/0xc80 drivers/input/mouse/alps.c:2690
 [819e3498] alps_detect+0x28/0x150 drivers/input/mouse/alps.c:2960
 [ inlined] psmouse_extensions+0x25e/0x4e0 psmouse_do_detect
drivers/input/mouse/psmouse-base.c:752
 [819d60fe] psmouse_extensions+0x25e/0x4e0
drivers/input/mouse/psmouse-base.c:870
 [819d662d] psmouse_switch_protocol+0x2ad/0x330
drivers/input/mouse/psmouse-base.c:1467
 [819d7656] psmouse_connect+0x2e6/0x450
drivers/input/mouse/psmouse-base.c:1554 (discriminator 4)
 [ inlined] serio_driver_probe+0x57/0x80
serio_connect_driver drivers/input/serio/serio.c:65
 [819bd1a7] serio_driver_probe+0x57/0x80
drivers/input/serio/serio.c:796
 [ inlined] driver_probe_device+0x1da/0x460 really_probe
drivers/base/dd.c:308
 [81813d4a] driver_probe_device+0x1da/0x460 drivers/base/dd.c:414
 [81814094] __driver_attach+0xc4/0xd0 drivers/base/dd.c:612
 [81810b63] bus_for_each_dev+0x93/0xe0 drivers/base/bus.c:314
 [81813583] driver_attach+0x33/0x50 drivers/base/dd.c:631
 [ inlined] serio_handle_event+0x2d3/0x3b0
serio_attach_driver drivers/input/serio/serio.c:826
 [819bdb13] serio_handle_event+0x2d3/0x3b0
drivers/input/serio/serio.c:245
 [810adcf9] process_one_work+0x2a9/0x6d0 kernel/workqueue.c:2036
 [810aeddf] worker_thread+0xbf/0x710 kernel/workqueue.c:2170
 [810b700c] kthread+0x15c/0x180 kernel/kthread.c:207
 [81e7215f] ret_from_fork+0x3f/0x70 arch/x86/entry/entry_64.S:526
DBG: cpu = 0

DBG: addr: 88019a923a58
DBG: first offset: 0, second offset: 0
DBG: T6 clock: {T6: 2264295, T397: 174118}
DBG: T397 clock: {T397: 174122}
==
==
ThreadSanitizer: data-race in __ps2_command

Read of size 1 by thread T397 (K394):
 [819c1220] __ps2_command+0x270/0x660
drivers/input/serio/libps2.c:230 (discriminator 21)
 [819c1645] ps2_command+0x35/0x60 drivers/input/serio/libps2.c:260
 [819dd47e] alps_rpt_cmd+0xae/0xe0 drivers/input/mouse/alps.c:1674
 [819e12b6] alps_identify+0x36/0xc80 drivers/input/mouse/alps.c:2690
 [819e3498] alps_detect+0x28/0x150 drivers/input/mouse/alps.c:2960
 [ inlined] psmouse_extensions+0x25e/0x4e0 psmouse_do_detect
drivers/input/mouse/psmouse-base.c:752
 [819d60fe] psmouse_extensions+0x25e/0x4e0

Re: Potential data race in psmouse_interrupt

[Pali Rohár]

On Wednesday 22 July 2015 15:14:42 Andrey Konovalov wrote:
 Hi!
 
 We are working on a dynamic data race detector for Linux kernel called
 KernelThreadSanitizer (ktsan) (https://github.com/google/ktsan/wiki).
 
 Here is a report we got while running ktsan (upstream revision
 21bdb584af8cca7c6df3c44cba268be050a234eb).
 
 ==
 ThreadSanitizer: data-race in psmouse_interrupt
 
 Write of size 1 by thread T1 (K1):
  [819d5272] psmouse_interrupt+0xd2/0x690
 drivers/input/mouse/psmouse-base.c:337
  [819bcd16] serio_interrupt+0x66/0xb0 
 drivers/input/serio/serio.c:1008
  [819be5f0] i8042_interrupt+0x240/0x4d0
 drivers/input/serio/i8042.c:541
  [810f03b2] handle_irq_event_percpu+0x62/0x2a0 
 kernel/irq/handle.c:143
  [810f0692] handle_irq_event+0xa2/0xf0 kernel/irq/handle.c:192
  [810f5414] handle_edge_irq+0x104/0x380 kernel/irq/chip.c:608
  [ inlined] handle_irq+0xf6/0x220 generic_handle_irq_desc
 include/linux/irqdesc.h:146
  [81009f86] handle_irq+0xf6/0x220 arch/x86/kernel/irq_64.c:81
  [810093ce] do_IRQ+0x5e/0x110 arch/x86/kernel/irq.c:223
  [81e726ab] ret_from_intr+0x0/0x1f arch/x86/entry/entry_64.S:601
  [ inlined] irq_exit+0x98/0xa0 invoke_softirq kernel/softirq.c:350
  [8108edd8] irq_exit+0x98/0xa0 kernel/softirq.c:391
  [ inlined] smp_apic_timer_interrupt+0x63/0x80 exiting_irq
 ./arch/x86/include/asm/apic.h:655
  [8105c503] smp_apic_timer_interrupt+0x63/0x80
 arch/x86/kernel/apic/apic.c:915
  [81e7299b] apic_timer_interrupt+0x6b/0x70
 arch/x86/entry/entry_64.S:782
  [8153223d] kvasprintf+0x5d/0x90 lib/kasprintf.c:24
  [815322be] kasprintf+0x4e/0x70 lib/kasprintf.c:40
  [ inlined] module_add_driver+0x8f/0x180 make_driver_name
 drivers/base/module.c:18
  [8183059f] module_add_driver+0x8f/0x180 drivers/base/module.c:63
  [81812c94] bus_add_driver+0x204/0x340 drivers/base/bus.c:713
  [81814e2b] driver_register+0xdb/0x190 drivers/base/driver.c:168
  [81a5ed16] __hid_register_driver+0xb6/0x100
 drivers/hid/hid-core.c:2677
  [825ab67d] apple_driver_init+0x24/0x31 drivers/hid/hid-apple.c:574
  [81000339] do_one_initcall+0xb9/0x220 init/main.c:798
  [ inlined] kernel_init_freeable+0x2ca/0x397
 do_initcall_level init/main.c:863
  [ inlined] kernel_init_freeable+0x2ca/0x397 do_initcalls
 init/main.c:871
  [ inlined] kernel_init_freeable+0x2ca/0x397 do_basic_setup
 init/main.c:890
  [8253d919] kernel_init_freeable+0x2ca/0x397 init/main.c:1013
  [81e5ad66] kernel_init+0x16/0x140 init/main.c:941
  [81e71f5f] ret_from_fork+0x3f/0x70 arch/x86/entry/entry_64.S:526
 DBG: cpu = 88053fd9fe68
 DBG: cpu id = 3
 
 Previous read of size 1 by thread T509 (K506):
  [ inlined] cypress_send_ext_cmd+0x193/0x500
 cypress_ps2_read_cmd_status drivers/input/mouse/cypress_ps2.c:123
  [819e6b23] cypress_send_ext_cmd+0x193/0x500
 drivers/input/mouse/cypress_ps2.c:192
  [819e6f5a] cypress_detect+0x2a/0xb0
 drivers/input/mouse/cypress_ps2.c:208
  [819d5e66] psmouse_extensions+0x1f6/0x4e0
 drivers/input/mouse/psmouse-base.c:849 (discriminator 1)
  [819d63fd] psmouse_switch_protocol+0x2ad/0x330
 drivers/input/mouse/psmouse-base.c:1467
  [819d7426] psmouse_connect+0x2e6/0x450
 drivers/input/mouse/psmouse-base.c:1554 (discriminator 4)
  [ inlined] serio_driver_probe+0x57/0x80
 serio_connect_driver drivers/input/serio/serio.c:65
  [819bcf77] serio_driver_probe+0x57/0x80
 drivers/input/serio/serio.c:796
  [ inlined] driver_probe_device+0x1da/0x460 really_probe
 drivers/base/dd.c:308
  [81813b1a] driver_probe_device+0x1da/0x460 drivers/base/dd.c:414
  [81813e64] __driver_attach+0xc4/0xd0 drivers/base/dd.c:612
  [81810933] bus_for_each_dev+0x93/0xe0 drivers/base/bus.c:314
  [81813353] driver_attach+0x33/0x50 drivers/base/dd.c:631
  [ inlined] serio_handle_event+0x2d3/0x3b0
 serio_attach_driver drivers/input/serio/serio.c:826
  [819bd8e3] serio_handle_event+0x2d3/0x3b0
 drivers/input/serio/serio.c:245
  [810adcf9] process_one_work+0x2a9/0x6d0 kernel/workqueue.c:2036
  [810aeddf] worker_thread+0xbf/0x710 kernel/workqueue.c:2170
  [810b700c] kthread+0x15c/0x180 kernel/kthread.c:207
  [81e71f5f] ret_from_fork+0x3f/0x70 arch/x86/entry/entry_64.S:526
 DBG: cpu = 0
 
 DBG: addr: 88019d703909
 DBG: first offset: 1, second offset: 1
 DBG: T1 clock: {T1: 17075020, T509: 142163}
 DBG: T509 clock: {T509: 142167}
 ==
 
 It seems that accessing 'psmouse-pktcnt' in
 'psmouse-packet[psmouse-pktcnt++] = data' in 'psmouse_interrupt()'
 is racing with 'wait_event_timeout(ps2dev-wait, (psmouse-pktcnt =
 pktsize), msecs_to_jiffies(CYTP_CMD_TIMEOUT))' in

Re: Fwd: Potential data race in psmouse_interrupt

[Dmitry Torokhov]

On Wed, Jul 22, 2015 at 03:14:42PM +0200, Andrey Konovalov wrote:
> Hi!
> 
> We are working on a dynamic data race detector for Linux kernel called
> KernelThreadSanitizer (ktsan) (https://github.com/google/ktsan/wiki).
> 
> Here is a report we got while running ktsan (upstream revision
> 21bdb584af8cca7c6df3c44cba268be050a234eb).
> 
> ==
> ThreadSanitizer: data-race in psmouse_interrupt
> 
> Write of size 1 by thread T1 (K1):
>  [] psmouse_interrupt+0xd2/0x690
> drivers/input/mouse/psmouse-base.c:337
>  [] serio_interrupt+0x66/0xb0 
> drivers/input/serio/serio.c:1008
>  [] i8042_interrupt+0x240/0x4d0
> drivers/input/serio/i8042.c:541
>  [] handle_irq_event_percpu+0x62/0x2a0 
> kernel/irq/handle.c:143
>  [] handle_irq_event+0xa2/0xf0 kernel/irq/handle.c:192
>  [] handle_edge_irq+0x104/0x380 kernel/irq/chip.c:608
>  [< inlined>] handle_irq+0xf6/0x220 generic_handle_irq_desc
> include/linux/irqdesc.h:146
>  [] handle_irq+0xf6/0x220 arch/x86/kernel/irq_64.c:81
>  [] do_IRQ+0x5e/0x110 arch/x86/kernel/irq.c:223
>  [] ret_from_intr+0x0/0x1f arch/x86/entry/entry_64.S:601
>  [< inlined>] irq_exit+0x98/0xa0 invoke_softirq kernel/softirq.c:350
>  [] irq_exit+0x98/0xa0 kernel/softirq.c:391
>  [< inlined>] smp_apic_timer_interrupt+0x63/0x80 exiting_irq
> ./arch/x86/include/asm/apic.h:655
>  [] smp_apic_timer_interrupt+0x63/0x80
> arch/x86/kernel/apic/apic.c:915
>  [] apic_timer_interrupt+0x6b/0x70
> arch/x86/entry/entry_64.S:782
>  [] kvasprintf+0x5d/0x90 lib/kasprintf.c:24
>  [] kasprintf+0x4e/0x70 lib/kasprintf.c:40
>  [< inlined>] module_add_driver+0x8f/0x180 make_driver_name
> drivers/base/module.c:18
>  [] module_add_driver+0x8f/0x180 drivers/base/module.c:63
>  [] bus_add_driver+0x204/0x340 drivers/base/bus.c:713
>  [] driver_register+0xdb/0x190 drivers/base/driver.c:168
>  [] __hid_register_driver+0xb6/0x100
> drivers/hid/hid-core.c:2677
>  [] apple_driver_init+0x24/0x31 drivers/hid/hid-apple.c:574
>  [] do_one_initcall+0xb9/0x220 init/main.c:798
>  [< inlined>] kernel_init_freeable+0x2ca/0x397
> do_initcall_level init/main.c:863
>  [< inlined>] kernel_init_freeable+0x2ca/0x397 do_initcalls
> init/main.c:871
>  [< inlined>] kernel_init_freeable+0x2ca/0x397 do_basic_setup
> init/main.c:890
>  [] kernel_init_freeable+0x2ca/0x397 init/main.c:1013
>  [] kernel_init+0x16/0x140 init/main.c:941
>  [] ret_from_fork+0x3f/0x70 arch/x86/entry/entry_64.S:526
> DBG: cpu = 88053fd9fe68
> DBG: cpu id = 3
> 
> Previous read of size 1 by thread T509 (K506):
>  [< inlined>] cypress_send_ext_cmd+0x193/0x500
> cypress_ps2_read_cmd_status drivers/input/mouse/cypress_ps2.c:123
>  [] cypress_send_ext_cmd+0x193/0x500
> drivers/input/mouse/cypress_ps2.c:192
>  [] cypress_detect+0x2a/0xb0
> drivers/input/mouse/cypress_ps2.c:208
>  [] psmouse_extensions+0x1f6/0x4e0
> drivers/input/mouse/psmouse-base.c:849 (discriminator 1)
>  [] psmouse_switch_protocol+0x2ad/0x330
> drivers/input/mouse/psmouse-base.c:1467
>  [] psmouse_connect+0x2e6/0x450
> drivers/input/mouse/psmouse-base.c:1554 (discriminator 4)
>  [< inlined>] serio_driver_probe+0x57/0x80
> serio_connect_driver drivers/input/serio/serio.c:65
>  [] serio_driver_probe+0x57/0x80
> drivers/input/serio/serio.c:796
>  [< inlined>] driver_probe_device+0x1da/0x460 really_probe
> drivers/base/dd.c:308
>  [] driver_probe_device+0x1da/0x460 drivers/base/dd.c:414
>  [] __driver_attach+0xc4/0xd0 drivers/base/dd.c:612
>  [] bus_for_each_dev+0x93/0xe0 drivers/base/bus.c:314
>  [] driver_attach+0x33/0x50 drivers/base/dd.c:631
>  [< inlined>] serio_handle_event+0x2d3/0x3b0
> serio_attach_driver drivers/input/serio/serio.c:826
>  [] serio_handle_event+0x2d3/0x3b0
> drivers/input/serio/serio.c:245
>  [] process_one_work+0x2a9/0x6d0 kernel/workqueue.c:2036
>  [] worker_thread+0xbf/0x710 kernel/workqueue.c:2170
>  [] kthread+0x15c/0x180 kernel/kthread.c:207
>  [] ret_from_fork+0x3f/0x70 arch/x86/entry/entry_64.S:526
> DBG: cpu = 0
> 
> DBG: addr: 88019d703909
> DBG: first offset: 1, second offset: 1
> DBG: T1 clock: {T1: 17075020, T509: 142163}
> DBG: T509 clock: {T509: 142167}
> ==
> 
> It seems that accessing 'psmouse->pktcnt' in
> 'psmouse->packet[psmouse->pktcnt++] = data' in 'psmouse_interrupt()'
> is racing with 'wait_event_timeout(ps2dev->wait, (psmouse->pktcnt >=
> pktsize), msecs_to_jiffies(CYTP_CMD_TIMEOUT))' in
> 'cypress_ps2_read_cmd_status()'.
> If that's the case, it's possible that 'psmouse->pktcnt' is
> incremented, but no data is written yet, so '(psmouse->pktcnt >=
> pktsize)' will evaluate to true and the following 'memcpy' will access
> invalid data.
> 
> Could you confirm if this is a real data race?

Yes, looks like real positive.

Thanks.

-- 
Dmitry
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to 

Fwd: Potential data race in psmouse_interrupt

[Andrey Konovalov]

Hi!

We are working on a dynamic data race detector for Linux kernel called
KernelThreadSanitizer (ktsan) (https://github.com/google/ktsan/wiki).

Here is a report we got while running ktsan (upstream revision
21bdb584af8cca7c6df3c44cba268be050a234eb).

==
ThreadSanitizer: data-race in psmouse_interrupt

Write of size 1 by thread T1 (K1):
 [] psmouse_interrupt+0xd2/0x690
drivers/input/mouse/psmouse-base.c:337
 [] serio_interrupt+0x66/0xb0 drivers/input/serio/serio.c:1008
 [] i8042_interrupt+0x240/0x4d0
drivers/input/serio/i8042.c:541
 [] handle_irq_event_percpu+0x62/0x2a0 kernel/irq/handle.c:143
 [] handle_irq_event+0xa2/0xf0 kernel/irq/handle.c:192
 [] handle_edge_irq+0x104/0x380 kernel/irq/chip.c:608
 [< inlined>] handle_irq+0xf6/0x220 generic_handle_irq_desc
include/linux/irqdesc.h:146
 [] handle_irq+0xf6/0x220 arch/x86/kernel/irq_64.c:81
 [] do_IRQ+0x5e/0x110 arch/x86/kernel/irq.c:223
 [] ret_from_intr+0x0/0x1f arch/x86/entry/entry_64.S:601
 [< inlined>] irq_exit+0x98/0xa0 invoke_softirq kernel/softirq.c:350
 [] irq_exit+0x98/0xa0 kernel/softirq.c:391
 [< inlined>] smp_apic_timer_interrupt+0x63/0x80 exiting_irq
./arch/x86/include/asm/apic.h:655
 [] smp_apic_timer_interrupt+0x63/0x80
arch/x86/kernel/apic/apic.c:915
 [] apic_timer_interrupt+0x6b/0x70
arch/x86/entry/entry_64.S:782
 [] kvasprintf+0x5d/0x90 lib/kasprintf.c:24
 [] kasprintf+0x4e/0x70 lib/kasprintf.c:40
 [< inlined>] module_add_driver+0x8f/0x180 make_driver_name
drivers/base/module.c:18
 [] module_add_driver+0x8f/0x180 drivers/base/module.c:63
 [] bus_add_driver+0x204/0x340 drivers/base/bus.c:713
 [] driver_register+0xdb/0x190 drivers/base/driver.c:168
 [] __hid_register_driver+0xb6/0x100
drivers/hid/hid-core.c:2677
 [] apple_driver_init+0x24/0x31 drivers/hid/hid-apple.c:574
 [] do_one_initcall+0xb9/0x220 init/main.c:798
 [< inlined>] kernel_init_freeable+0x2ca/0x397
do_initcall_level init/main.c:863
 [< inlined>] kernel_init_freeable+0x2ca/0x397 do_initcalls
init/main.c:871
 [< inlined>] kernel_init_freeable+0x2ca/0x397 do_basic_setup
init/main.c:890
 [] kernel_init_freeable+0x2ca/0x397 init/main.c:1013
 [] kernel_init+0x16/0x140 init/main.c:941
 [] ret_from_fork+0x3f/0x70 arch/x86/entry/entry_64.S:526
DBG: cpu = 88053fd9fe68
DBG: cpu id = 3

Previous read of size 1 by thread T509 (K506):
 [< inlined>] cypress_send_ext_cmd+0x193/0x500
cypress_ps2_read_cmd_status drivers/input/mouse/cypress_ps2.c:123
 [] cypress_send_ext_cmd+0x193/0x500
drivers/input/mouse/cypress_ps2.c:192
 [] cypress_detect+0x2a/0xb0
drivers/input/mouse/cypress_ps2.c:208
 [] psmouse_extensions+0x1f6/0x4e0
drivers/input/mouse/psmouse-base.c:849 (discriminator 1)
 [] psmouse_switch_protocol+0x2ad/0x330
drivers/input/mouse/psmouse-base.c:1467
 [] psmouse_connect+0x2e6/0x450
drivers/input/mouse/psmouse-base.c:1554 (discriminator 4)
 [< inlined>] serio_driver_probe+0x57/0x80
serio_connect_driver drivers/input/serio/serio.c:65
 [] serio_driver_probe+0x57/0x80
drivers/input/serio/serio.c:796
 [< inlined>] driver_probe_device+0x1da/0x460 really_probe
drivers/base/dd.c:308
 [] driver_probe_device+0x1da/0x460 drivers/base/dd.c:414
 [] __driver_attach+0xc4/0xd0 drivers/base/dd.c:612
 [] bus_for_each_dev+0x93/0xe0 drivers/base/bus.c:314
 [] driver_attach+0x33/0x50 drivers/base/dd.c:631
 [< inlined>] serio_handle_event+0x2d3/0x3b0
serio_attach_driver drivers/input/serio/serio.c:826
 [] serio_handle_event+0x2d3/0x3b0
drivers/input/serio/serio.c:245
 [] process_one_work+0x2a9/0x6d0 kernel/workqueue.c:2036
 [] worker_thread+0xbf/0x710 kernel/workqueue.c:2170
 [] kthread+0x15c/0x180 kernel/kthread.c:207
 [] ret_from_fork+0x3f/0x70 arch/x86/entry/entry_64.S:526
DBG: cpu = 0

DBG: addr: 88019d703909
DBG: first offset: 1, second offset: 1
DBG: T1 clock: {T1: 17075020, T509: 142163}
DBG: T509 clock: {T509: 142167}
==

It seems that accessing 'psmouse->pktcnt' in
'psmouse->packet[psmouse->pktcnt++] = data' in 'psmouse_interrupt()'
is racing with 'wait_event_timeout(ps2dev->wait, (psmouse->pktcnt >=
pktsize), msecs_to_jiffies(CYTP_CMD_TIMEOUT))' in
'cypress_ps2_read_cmd_status()'.
If that's the case, it's possible that 'psmouse->pktcnt' is
incremented, but no data is written yet, so '(psmouse->pktcnt >=
pktsize)' will evaluate to true and the following 'memcpy' will access
invalid data.

Could you confirm if this is a real data race?

Thanks in advance!
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majord...@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Please read the FAQ at  http://www.tux.org/lkml/

Re: Fwd: Potential data race in psmouse_interrupt

[Dmitry Torokhov]

On Wed, Jul 22, 2015 at 03:14:42PM +0200, Andrey Konovalov wrote:
 Hi!
 
 We are working on a dynamic data race detector for Linux kernel called
 KernelThreadSanitizer (ktsan) (https://github.com/google/ktsan/wiki).
 
 Here is a report we got while running ktsan (upstream revision
 21bdb584af8cca7c6df3c44cba268be050a234eb).
 
 ==
 ThreadSanitizer: data-race in psmouse_interrupt
 
 Write of size 1 by thread T1 (K1):
  [819d5272] psmouse_interrupt+0xd2/0x690
 drivers/input/mouse/psmouse-base.c:337
  [819bcd16] serio_interrupt+0x66/0xb0 
 drivers/input/serio/serio.c:1008
  [819be5f0] i8042_interrupt+0x240/0x4d0
 drivers/input/serio/i8042.c:541
  [810f03b2] handle_irq_event_percpu+0x62/0x2a0 
 kernel/irq/handle.c:143
  [810f0692] handle_irq_event+0xa2/0xf0 kernel/irq/handle.c:192
  [810f5414] handle_edge_irq+0x104/0x380 kernel/irq/chip.c:608
  [ inlined] handle_irq+0xf6/0x220 generic_handle_irq_desc
 include/linux/irqdesc.h:146
  [81009f86] handle_irq+0xf6/0x220 arch/x86/kernel/irq_64.c:81
  [810093ce] do_IRQ+0x5e/0x110 arch/x86/kernel/irq.c:223
  [81e726ab] ret_from_intr+0x0/0x1f arch/x86/entry/entry_64.S:601
  [ inlined] irq_exit+0x98/0xa0 invoke_softirq kernel/softirq.c:350
  [8108edd8] irq_exit+0x98/0xa0 kernel/softirq.c:391
  [ inlined] smp_apic_timer_interrupt+0x63/0x80 exiting_irq
 ./arch/x86/include/asm/apic.h:655
  [8105c503] smp_apic_timer_interrupt+0x63/0x80
 arch/x86/kernel/apic/apic.c:915
  [81e7299b] apic_timer_interrupt+0x6b/0x70
 arch/x86/entry/entry_64.S:782
  [8153223d] kvasprintf+0x5d/0x90 lib/kasprintf.c:24
  [815322be] kasprintf+0x4e/0x70 lib/kasprintf.c:40
  [ inlined] module_add_driver+0x8f/0x180 make_driver_name
 drivers/base/module.c:18
  [8183059f] module_add_driver+0x8f/0x180 drivers/base/module.c:63
  [81812c94] bus_add_driver+0x204/0x340 drivers/base/bus.c:713
  [81814e2b] driver_register+0xdb/0x190 drivers/base/driver.c:168
  [81a5ed16] __hid_register_driver+0xb6/0x100
 drivers/hid/hid-core.c:2677
  [825ab67d] apple_driver_init+0x24/0x31 drivers/hid/hid-apple.c:574
  [81000339] do_one_initcall+0xb9/0x220 init/main.c:798
  [ inlined] kernel_init_freeable+0x2ca/0x397
 do_initcall_level init/main.c:863
  [ inlined] kernel_init_freeable+0x2ca/0x397 do_initcalls
 init/main.c:871
  [ inlined] kernel_init_freeable+0x2ca/0x397 do_basic_setup
 init/main.c:890
  [8253d919] kernel_init_freeable+0x2ca/0x397 init/main.c:1013
  [81e5ad66] kernel_init+0x16/0x140 init/main.c:941
  [81e71f5f] ret_from_fork+0x3f/0x70 arch/x86/entry/entry_64.S:526
 DBG: cpu = 88053fd9fe68
 DBG: cpu id = 3
 
 Previous read of size 1 by thread T509 (K506):
  [ inlined] cypress_send_ext_cmd+0x193/0x500
 cypress_ps2_read_cmd_status drivers/input/mouse/cypress_ps2.c:123
  [819e6b23] cypress_send_ext_cmd+0x193/0x500
 drivers/input/mouse/cypress_ps2.c:192
  [819e6f5a] cypress_detect+0x2a/0xb0
 drivers/input/mouse/cypress_ps2.c:208
  [819d5e66] psmouse_extensions+0x1f6/0x4e0
 drivers/input/mouse/psmouse-base.c:849 (discriminator 1)
  [819d63fd] psmouse_switch_protocol+0x2ad/0x330
 drivers/input/mouse/psmouse-base.c:1467
  [819d7426] psmouse_connect+0x2e6/0x450
 drivers/input/mouse/psmouse-base.c:1554 (discriminator 4)
  [ inlined] serio_driver_probe+0x57/0x80
 serio_connect_driver drivers/input/serio/serio.c:65
  [819bcf77] serio_driver_probe+0x57/0x80
 drivers/input/serio/serio.c:796
  [ inlined] driver_probe_device+0x1da/0x460 really_probe
 drivers/base/dd.c:308
  [81813b1a] driver_probe_device+0x1da/0x460 drivers/base/dd.c:414
  [81813e64] __driver_attach+0xc4/0xd0 drivers/base/dd.c:612
  [81810933] bus_for_each_dev+0x93/0xe0 drivers/base/bus.c:314
  [81813353] driver_attach+0x33/0x50 drivers/base/dd.c:631
  [ inlined] serio_handle_event+0x2d3/0x3b0
 serio_attach_driver drivers/input/serio/serio.c:826
  [819bd8e3] serio_handle_event+0x2d3/0x3b0
 drivers/input/serio/serio.c:245
  [810adcf9] process_one_work+0x2a9/0x6d0 kernel/workqueue.c:2036
  [810aeddf] worker_thread+0xbf/0x710 kernel/workqueue.c:2170
  [810b700c] kthread+0x15c/0x180 kernel/kthread.c:207
  [81e71f5f] ret_from_fork+0x3f/0x70 arch/x86/entry/entry_64.S:526
 DBG: cpu = 0
 
 DBG: addr: 88019d703909
 DBG: first offset: 1, second offset: 1
 DBG: T1 clock: {T1: 17075020, T509: 142163}
 DBG: T509 clock: {T509: 142167}
 ==
 
 It seems that accessing 'psmouse-pktcnt' in
 'psmouse-packet[psmouse-pktcnt++] = data' in 'psmouse_interrupt()'
 is racing with 'wait_event_timeout(ps2dev-wait, (psmouse-pktcnt =
 pktsize), 

Fwd: Potential data race in psmouse_interrupt

[Andrey Konovalov]

Hi!

We are working on a dynamic data race detector for Linux kernel called
KernelThreadSanitizer (ktsan) (https://github.com/google/ktsan/wiki).

Here is a report we got while running ktsan (upstream revision
21bdb584af8cca7c6df3c44cba268be050a234eb).

==
ThreadSanitizer: data-race in psmouse_interrupt

Write of size 1 by thread T1 (K1):
 [819d5272] psmouse_interrupt+0xd2/0x690
drivers/input/mouse/psmouse-base.c:337
 [819bcd16] serio_interrupt+0x66/0xb0 drivers/input/serio/serio.c:1008
 [819be5f0] i8042_interrupt+0x240/0x4d0
drivers/input/serio/i8042.c:541
 [810f03b2] handle_irq_event_percpu+0x62/0x2a0 kernel/irq/handle.c:143
 [810f0692] handle_irq_event+0xa2/0xf0 kernel/irq/handle.c:192
 [810f5414] handle_edge_irq+0x104/0x380 kernel/irq/chip.c:608
 [ inlined] handle_irq+0xf6/0x220 generic_handle_irq_desc
include/linux/irqdesc.h:146
 [81009f86] handle_irq+0xf6/0x220 arch/x86/kernel/irq_64.c:81
 [810093ce] do_IRQ+0x5e/0x110 arch/x86/kernel/irq.c:223
 [81e726ab] ret_from_intr+0x0/0x1f arch/x86/entry/entry_64.S:601
 [ inlined] irq_exit+0x98/0xa0 invoke_softirq kernel/softirq.c:350
 [8108edd8] irq_exit+0x98/0xa0 kernel/softirq.c:391
 [ inlined] smp_apic_timer_interrupt+0x63/0x80 exiting_irq
./arch/x86/include/asm/apic.h:655
 [8105c503] smp_apic_timer_interrupt+0x63/0x80
arch/x86/kernel/apic/apic.c:915
 [81e7299b] apic_timer_interrupt+0x6b/0x70
arch/x86/entry/entry_64.S:782
 [8153223d] kvasprintf+0x5d/0x90 lib/kasprintf.c:24
 [815322be] kasprintf+0x4e/0x70 lib/kasprintf.c:40
 [ inlined] module_add_driver+0x8f/0x180 make_driver_name
drivers/base/module.c:18
 [8183059f] module_add_driver+0x8f/0x180 drivers/base/module.c:63
 [81812c94] bus_add_driver+0x204/0x340 drivers/base/bus.c:713
 [81814e2b] driver_register+0xdb/0x190 drivers/base/driver.c:168
 [81a5ed16] __hid_register_driver+0xb6/0x100
drivers/hid/hid-core.c:2677
 [825ab67d] apple_driver_init+0x24/0x31 drivers/hid/hid-apple.c:574
 [81000339] do_one_initcall+0xb9/0x220 init/main.c:798
 [ inlined] kernel_init_freeable+0x2ca/0x397
do_initcall_level init/main.c:863
 [ inlined] kernel_init_freeable+0x2ca/0x397 do_initcalls
init/main.c:871
 [ inlined] kernel_init_freeable+0x2ca/0x397 do_basic_setup
init/main.c:890
 [8253d919] kernel_init_freeable+0x2ca/0x397 init/main.c:1013
 [81e5ad66] kernel_init+0x16/0x140 init/main.c:941
 [81e71f5f] ret_from_fork+0x3f/0x70 arch/x86/entry/entry_64.S:526
DBG: cpu = 88053fd9fe68
DBG: cpu id = 3

Previous read of size 1 by thread T509 (K506):
 [ inlined] cypress_send_ext_cmd+0x193/0x500
cypress_ps2_read_cmd_status drivers/input/mouse/cypress_ps2.c:123
 [819e6b23] cypress_send_ext_cmd+0x193/0x500
drivers/input/mouse/cypress_ps2.c:192
 [819e6f5a] cypress_detect+0x2a/0xb0
drivers/input/mouse/cypress_ps2.c:208
 [819d5e66] psmouse_extensions+0x1f6/0x4e0
drivers/input/mouse/psmouse-base.c:849 (discriminator 1)
 [819d63fd] psmouse_switch_protocol+0x2ad/0x330
drivers/input/mouse/psmouse-base.c:1467
 [819d7426] psmouse_connect+0x2e6/0x450
drivers/input/mouse/psmouse-base.c:1554 (discriminator 4)
 [ inlined] serio_driver_probe+0x57/0x80
serio_connect_driver drivers/input/serio/serio.c:65
 [819bcf77] serio_driver_probe+0x57/0x80
drivers/input/serio/serio.c:796
 [ inlined] driver_probe_device+0x1da/0x460 really_probe
drivers/base/dd.c:308
 [81813b1a] driver_probe_device+0x1da/0x460 drivers/base/dd.c:414
 [81813e64] __driver_attach+0xc4/0xd0 drivers/base/dd.c:612
 [81810933] bus_for_each_dev+0x93/0xe0 drivers/base/bus.c:314
 [81813353] driver_attach+0x33/0x50 drivers/base/dd.c:631
 [ inlined] serio_handle_event+0x2d3/0x3b0
serio_attach_driver drivers/input/serio/serio.c:826
 [819bd8e3] serio_handle_event+0x2d3/0x3b0
drivers/input/serio/serio.c:245
 [810adcf9] process_one_work+0x2a9/0x6d0 kernel/workqueue.c:2036
 [810aeddf] worker_thread+0xbf/0x710 kernel/workqueue.c:2170
 [810b700c] kthread+0x15c/0x180 kernel/kthread.c:207
 [81e71f5f] ret_from_fork+0x3f/0x70 arch/x86/entry/entry_64.S:526
DBG: cpu = 0

DBG: addr: 88019d703909
DBG: first offset: 1, second offset: 1
DBG: T1 clock: {T1: 17075020, T509: 142163}
DBG: T509 clock: {T509: 142167}
==

It seems that accessing 'psmouse-pktcnt' in
'psmouse-packet[psmouse-pktcnt++] = data' in 'psmouse_interrupt()'
is racing with 'wait_event_timeout(ps2dev-wait, (psmouse-pktcnt =
pktsize), msecs_to_jiffies(CYTP_CMD_TIMEOUT))' in
'cypress_ps2_read_cmd_status()'.
If that's the case, it's possible that 'psmouse-pktcnt' is
incremented, but no data is written yet, so '(psmouse-pktcnt =