Login | Register For Free | Help
Search for: (Advanced)

Mailing List Archive: GnuPG: devel

scd: a race condition between scd_command_handler and handle_tick

 

 

GnuPG devel RSS feed   Index | Next | Previous | View Threaded


gniibe at fsij

Apr 3, 2012, 6:43 PM

Post #1 of 4 (645 views)
Permalink
scd: a race condition between scd_command_handler and handle_tick

This is a bug report for GnuPG 2.0.19 (or 2.0.18). I have not yet
checked if there is this bug in the development version or not.

This bug was found at "make check" of building scute 1.4.0 for Debian.
I think that it is a bug of a race condition.

Here are failure logs:

https://buildd.debian.org/status/fetch.php?pkg=scute&arch=armel&ver=1.4.0-2&stamp=1333006067
https://buildd.debian.org/status/fetch.php?pkg=scute&arch=ia64&ver=1.4.0-3&stamp=1333361223

It surely occured on other non-exotic architectures. In fact, I
encountered on my amd64 box too (sorry, I lost the log).


NORMAL CASE:
Since the build environment doesn't have libpcsclite.so.1, pcsc daemon
wrappers fails at start up, and it results "Card error".

In the log, it's like:
-----------------------
gpg-agent[27706]: can't create directory `/home/buildd/.gnupg': No such file or directory
scdaemon[27707]: error sending PC/SC OPEN request: Broken pipe
gpg-agent[27706]: command learn failed: Card error
Skipping test because no token is present.
PASS: t-opensession
-----------------------

BUG CASE:
It seemed that opening PC/SC driver somehow succeeded wrongly after an
failure, and it tried to send APDUs to a reader which failed. In this
case, the error code is "Not supported", and it resulted failure of
scute's test.

In the log, it's like:
-----------------------
gpg-agent[27735]: can't create directory `/home/buildd/.gnupg': No such file or directory
scdaemon[27736]: error sending PC/SC OPEN request: Broken pipe
scdaemon[27736]: apdu_send_simple(0) failed: not supported
scdaemon[27736]: apdu_send_simple(0) failed: not supported
scdaemon[27736]: apdu_send_simple(0) failed: not supported
scdaemon[27736]: apdu_send_simple(0) failed: not supported
scdaemon[27736]: apdu_send_simple(0) failed: not supported
scdaemon[27736]: apdu_send_simple(0) failed: not supported
scdaemon[27736]: apdu_send_simple(0) failed: not supported
scdaemon[27736]: apdu_send_simple(0) failed: not supported
scdaemon[27736]: no supported card application found: Not supported
gpg-agent[27735]: command learn failed: Not supported
t-closeallsessions.c:48: Function failed
FAIL: t-closeallsessions
-----------------------

For NORMAL CASE, the function open_card failed correctly, as
apdu_connect failed because reader_table[slot].used == 0.

For the BUG CASE, there is a race condition between two threads, the
command handler thread and handle_tick thread.

COMMAND HANDLER THREAD's call-chain is like:
-> scd_command_handler
-> cmd_serialno
-> open_card
->apdu_connect

HANDLE_TICK THREAD's call-chain is like:
-> handle_tick
-> scd_update_reader_status_file
-> update_reader_status_file
-> get_reader_slot
-> apdu_open_reader
-> open_pcsc_reader
-> open_pcsc_reader_wrapper
-> new_reader_slot
Then, forking gnupg-pcsc-wrapper...

For the BUG CASE, it could be considered it goes like this:

HANDLE_TICK_THREAD COMMAND HANDLER THREAD

enter scd_command_handler
ctrl->reader_slot = 0
enter handle_tick
...
enter new_reader_slot
reader_table[slot].used = 1
forking gnupg-pcsc-wrapper and
thread switch occurs
enter cmd_serialno
enter open_card
enter apdu_connect
*** It succeeds, ***
*** as reader_table[slot].used == 1 ***
exit apdu_connect with success
failure of gnupg-pcsc-wrapper...
tries sending apdu...


I think that we need mutual exclusion between threads as
there is a shared resource (the connection to gnupg-pcsc-wrapper).
--

_______________________________________________
Gnupg-devel mailing list
Gnupg-devel [at] gnupg
http://lists.gnupg.org/mailman/listinfo/gnupg-devel


gniibe at fsij

Apr 4, 2012, 7:11 PM

Post #2 of 4 (576 views)
Permalink
Re: scd: a race condition between scd_command_handler and handle_tick [In reply to]

On 2012-04-04 at 10:43 +0900, Niibe Yutaka wrote:
> This is a bug report for GnuPG 2.0.19 (or 2.0.18). I have not yet
> checked if there is this bug in the development version or not.
>
> This bug was found at "make check" of building scute 1.4.0 for Debian.
> I think that it is a bug of a race condition.
[...]
> It surely occured on other non-exotic architectures. In fact, I
> encountered on my amd64 box too (sorry, I lost the log).

I minimize reproducible test case. I tested on Debian sid amd64
environment.

Here is a session log:
------------------------------------
# Confirm that libpcsclite1
$ dpkg -l libpcsclite1
Desired=Unknown/Install/Remove/Purge/Hold
| Status=Not/Inst/Conf-files/Unpacked/halF-conf/Half-inst/trig-aWait/Trig-pend
|/ Err?=(none)/Reinst-required (Status,Err: uppercase=bad)
||/ Name Version Description
+++-==============-==============-============================================
un libpcsclite1 <none> (no description available)

# Setup GnuPG's homedir for testing, and enable debugging of scdaemon
$ mkdir -p $HOME/tmp/dot-gnupg
$ GNUPGHOME=$HOME/tmp/dot-gnupg
$ export GNUPGHOME
$ echo debug-level guru >tmp/dot-gnupg/scdaemon.conf
$ echo debug-all >>tmp/dot-gnupg/scdaemon.conf
$ echo log-file $HOME/tmp/dot-gnupg/scd.log >>tmp/dot-gnupg/scdaemon.conf

# Run GPG-AGENT
$ eval $(gpg-agent --daemon)

# Using GPG-CONNECT-AGENT, try to access smartcard
$ gpg-connect-agent learn /bye
ERR 100663404 Card error <SCD> # This is normal
$ gpg-connect-agent learn /bye
ERR 100663356 Not supported <SCD> # This is by a bug
$ gpg-connect-agent learn /bye
ERR 100663404 Card error <SCD>
------------------------------------

Here is a scdaemon debug output:
------------------------------------
2012-04-05 02:04:59 scdaemon[14197] listening on socket `/tmp/gpg-oBXWNe/S.scdaemon'
2012-04-05 02:04:59 scdaemon[14197] handler for fd -1 started
2012-04-05 02:05:00 scdaemon[14197] error sending PC/SC OPEN request: Broken pipe
scdaemon[14197]: chan_7 -> OK GNU Privacy Guard's Smartcard server ready
scdaemon[14197]: chan_7 <- GETINFO socket_name
scdaemon[14197]: chan_7 -> D /tmp/gpg-oBXWNe/S.scdaemon
scdaemon[14197]: chan_7 -> OK
scdaemon[14197]: chan_7 <- OPTION event-signal=12
scdaemon[14197]: chan_7 -> OK
scdaemon[14197]: chan_7 <- SERIALNO
scdaemon[14197]: chan_7 -> ERR 100663404 Card error <SCD>
scdaemon[14197]: chan_7 <- RESTART
scdaemon[14197]: chan_7 -> OK
2012-04-05 02:05:01 scdaemon[14197] error sending PC/SC OPEN request: Broken pipe
2012-04-05 02:05:01 scdaemon[14197] error sending PC/SC OPEN request: Broken pipe
scdaemon[14197]: chan_7 <- SERIALNO
2012-04-05 02:05:02 scdaemon[14197] DBG: send apdu: c=00 i=A4 p1=00 p2=0C lc=2 le=-1 em=0
2012-04-05 02:05:02 scdaemon[14197] apdu_send_simple(0) failed: not supported
2012-04-05 02:05:02 scdaemon[14197] DBG: send apdu: c=00 i=A4 p1=04 p2=00 lc=6 le=-1 em=0
2012-04-05 02:05:02 scdaemon[14197] apdu_send_simple(0) failed: not supported
2012-04-05 02:05:02 scdaemon[14197] DBG: send apdu: c=00 i=A4 p1=04 p2=0C lc=7 le=-1 em=0
2012-04-05 02:05:02 scdaemon[14197] apdu_send_simple(0) failed: not supported
2012-04-05 02:05:02 scdaemon[14197] DBG: send apdu: c=00 i=A4 p1=04 p2=0C lc=12 le=-1 em=0
2012-04-05 02:05:02 scdaemon[14197] apdu_send_simple(0) failed: not supported
2012-04-05 02:05:02 scdaemon[14197] DBG: send apdu: c=00 i=A4 p1=08 p2=0C lc=2 le=-1 em=0
2012-04-05 02:05:02 scdaemon[14197] apdu_send_simple(0) failed: not supported
2012-04-05 02:05:02 scdaemon[14197] DBG: send apdu: c=00 i=A4 p1=01 p2=0C lc=2 le=-1 em=0
2012-04-05 02:05:02 scdaemon[14197] apdu_send_simple(0) failed: not supported
2012-04-05 02:05:02 scdaemon[14197] DBG: send apdu: c=00 i=A4 p1=04 p2=0C lc=6 le=-1 em=0
2012-04-05 02:05:02 scdaemon[14197] apdu_send_simple(0) failed: not supported
2012-04-05 02:05:02 scdaemon[14197] DBG: send apdu: c=00 i=A4 p1=04 p2=0C lc=9 le=-1 em=0
2012-04-05 02:05:02 scdaemon[14197] apdu_send_simple(0) failed: not supported
2012-04-05 02:05:02 scdaemon[14197] no supported card application found: Not supported
scdaemon[14197]: chan_7 -> ERR 100663356 Not supported <SCD>
scdaemon[14197]: chan_7 <- RESTART
scdaemon[14197]: chan_7 -> OK
2012-04-05 02:05:02 scdaemon[14197] error sending PC/SC OPEN request: Broken pipe
2012-04-05 02:05:03 scdaemon[14197] error sending PC/SC OPEN request: Broken pipe
2012-04-05 02:05:04 scdaemon[14197] error sending PC/SC OPEN request: Broken pipe
2012-04-05 02:05:04 scdaemon[14197] error sending PC/SC OPEN request: Broken pipe
scdaemon[14197]: chan_7 <- SERIALNO
scdaemon[14197]: chan_7 -> ERR 100663404 Card error <SCD>
scdaemon[14197]: chan_7 <- RESTART
scdaemon[14197]: chan_7 -> OK
2012-04-05 02:05:05 scdaemon[14197] error sending PC/SC OPEN request: Broken pipe
2012-04-05 02:05:06 scdaemon[14197] error sending PC/SC OPEN request: Broken pipe
------------------------------------

Because of the race condition, we see apdu_send_simple in the log.
--



_______________________________________________
Gnupg-devel mailing list
Gnupg-devel [at] gnupg
http://lists.gnupg.org/mailman/listinfo/gnupg-devel


gniibe at fsij

Jun 5, 2012, 10:30 PM

Post #3 of 4 (510 views)
Permalink
Re: scd: a race condition between scd_command_handler and handle_tick [In reply to]

On 2012-04-04 at 10:43 +0900, Niibe Yutaka wrote:
> This is a bug report for GnuPG 2.0.19 (or 2.0.18). I have not yet
> checked if there is this bug in the development version or not.

The bug is in the master branch too.

> For the BUG CASE, there is a race condition between two threads, the
> command handler thread and handle_tick thread.
>
> COMMAND HANDLER THREAD's call-chain is like:
> -> scd_command_handler
> -> cmd_serialno
> -> open_card
> ->apdu_connect
>
> HANDLE_TICK THREAD's call-chain is like:
> -> handle_tick
> -> scd_update_reader_status_file
> -> update_reader_status_file
> -> get_reader_slot
> -> apdu_open_reader
> -> open_pcsc_reader
> -> open_pcsc_reader_wrapper
> -> new_reader_slot
> Then, forking gnupg-pcsc-wrapper...


I think that a patch like following is needed, at least
at the lower layer.

That is, success of new_reader_slot, it returns with the slot's lock.
The lock will be released by caller.

I haven't test it yet.

diff --git a/scd/apdu.c b/scd/apdu.c
index 7641e91..f88047a 100644
--- a/scd/apdu.c
+++ b/scd/apdu.c
@@ -346,8 +346,56 @@ static int pcsc_keypad_modify (int slot, int class, int ins, int p0, int p1,
*/


+static int
+lock_slot (int slot)
+{
+#ifdef USE_NPTH
+ int err;
+
+ err = npth_mutex_lock (&reader_table[slot].lock);
+ if (err)
+ {
+ log_error ("failed to acquire apdu lock: %s\n", strerror (err));
+ return SW_HOST_LOCKING_FAILED;
+ }
+#endif /*USE_NPTH*/
+ return 0;
+}
+
+static int
+trylock_slot (int slot)
+{
+#ifdef USE_NPTH
+ int err;
+
+ err = npth_mutex_trylock (&reader_table[slot].lock);
+ if (err == EBUSY)
+ return SW_HOST_BUSY;
+ else if (err)
+ {
+ log_error ("failed to acquire apdu lock: %s\n", strerror (err));
+ return SW_HOST_LOCKING_FAILED;
+ }
+#endif /*USE_NPTH*/
+ return 0;
+}
+
+static void
+unlock_slot (int slot)
+{
+#ifdef USE_NPTH
+ int err;
+
+ err = npth_mutex_unlock (&reader_table[slot].lock);
+ if (err)
+ log_error ("failed to release apdu lock: %s\n", strerror (errno));
+#endif /*USE_NPTH*/
+}
+
+
/* Find an unused reader slot for PORTSTR and put it into the reader
- table. Return -1 on error or the index into the reader table. */
+ table. Return -1 on error or the index into the reader table.
+ Acquire slot's lock on successful return. Caller needs to unlock it. */
static int
new_reader_slot (void)
{
@@ -375,6 +423,12 @@ new_reader_slot (void)
}
reader_table[reader].lock_initialized = 1;
}
+
+ if (lock_slot (reader))
+ {
+ log_error ("error locking mutex: %s\n", strerror (err));
+ return -1;
+ }
#endif /*USE_NPTH*/
reader_table[reader].connect_card = NULL;
reader_table[reader].disconnect_card = NULL;
@@ -660,6 +714,7 @@ open_ct_reader (int port)
log_error ("apdu_open_ct_reader failed on port %d: %s\n",
port, ct_error_string (rc));
reader_table[reader].used = 0;
+ unlock_slot (reader);
return -1;
}

@@ -681,6 +736,7 @@ open_ct_reader (int port)
reader_table[reader].keypad_modify = NULL;

dump_reader_status (reader);
+ unlock_slot (reader);
return reader;
}

@@ -1693,6 +1749,7 @@ open_pcsc_reader_direct (const char *portstr)
reader_table[slot].used = 0;
if (err == 0x8010001d)
pcsc_no_service = 1;
+ unlock_slot (slot);
return -1;
}
pcsc_no_service = 0;
@@ -1707,6 +1764,7 @@ open_pcsc_reader_direct (const char *portstr)
log_error ("error allocating memory for reader list\n");
pcsc_release_context (reader_table[slot].pcsc.context);
reader_table[slot].used = 0;
+ unlock_slot (slot);
return -1 /*SW_HOST_OUT_OF_CORE*/;
}
err = pcsc_list_readers (reader_table[slot].pcsc.context,
@@ -1719,6 +1777,7 @@ open_pcsc_reader_direct (const char *portstr)
pcsc_release_context (reader_table[slot].pcsc.context);
reader_table[slot].used = 0;
xfree (list);
+ unlock_slot (slot);
return -1;
}

@@ -1745,6 +1804,7 @@ open_pcsc_reader_direct (const char *portstr)
log_error ("error allocating memory for reader name\n");
pcsc_release_context (reader_table[slot].pcsc.context);
reader_table[slot].used = 0;
+ unlock_slot (slot);
return -1;
}
strcpy (reader_table[slot].rdrname, portstr? portstr : list);
@@ -1764,6 +1824,7 @@ open_pcsc_reader_direct (const char *portstr)
reader_table[slot].dump_status_reader = dump_pcsc_reader_status;

dump_reader_status (slot);
+ unlock_slot (slot);
return slot;
}
#endif /*!NEED_PCSC_WRAPPER */
@@ -1810,6 +1871,7 @@ open_pcsc_reader_wrapped (const char *portstr)
{
log_error ("error creating a pipe: %s\n", strerror (errno));
slotp->used = 0;
+ unlock_slot (slot);
return -1;
}
if (pipe (wp) == -1)
@@ -1818,6 +1880,7 @@ open_pcsc_reader_wrapped (const char *portstr)
close (rp[0]);
close (rp[1]);
slotp->used = 0;
+ unlock_slot (slot);
return -1;
}

@@ -1830,6 +1893,7 @@ open_pcsc_reader_wrapped (const char *portstr)
close (wp[0]);
close (wp[1]);
slotp->used = 0;
+ unlock_slot (slot);
return -1;
}
slotp->pcsc.pid = pid;
@@ -1963,6 +2027,7 @@ open_pcsc_reader_wrapped (const char *portstr)
pcsc_get_status (slot, &dummy_status);

dump_reader_status (slot);
+ unlock_slot (slot);
return slot;

command_failed:
@@ -1974,6 +2039,7 @@ open_pcsc_reader_wrapped (const char *portstr)
kill (slotp->pcsc.pid, SIGTERM);
slotp->pcsc.pid = (pid_t)(-1);
slotp->used = 0;
+ unlock_slot (slot);
/* There is no way to return SW. */
return -1;

@@ -2412,6 +2478,7 @@ open_ccid_reader (const char *portstr)
if (err)
{
slotp->used = 0;
+ unlock_slot (slot);
return -1;
}

@@ -2446,6 +2513,7 @@ open_ccid_reader (const char *portstr)
reader_table[slot].is_t0 = 0;

dump_reader_status (slot);
+ unlock_slot (slot);
return slot;
}

@@ -2684,6 +2752,7 @@ open_rapdu_reader (int portno,
if (!slotp->rapdu.handle)
{
slotp->used = 0;
+ unlock_slot (slot);
return -1;
}

@@ -2738,12 +2807,14 @@ open_rapdu_reader (int portno,

dump_reader_status (slot);
rapdu_msg_release (msg);
+ unlock_slot (slot);
return slot;

failure:
rapdu_msg_release (msg);
rapdu_release (slotp->rapdu.handle);
slotp->used = 0;
+ unlock_slot (slot);
return -1;
}

@@ -2756,53 +2827,6 @@ open_rapdu_reader (int portno,
*/


-static int
-lock_slot (int slot)
-{
-#ifdef USE_NPTH
- int err;
-
- err = npth_mutex_lock (&reader_table[slot].lock);
- if (err)
- {
- log_error ("failed to acquire apdu lock: %s\n", strerror (err));
- return SW_HOST_LOCKING_FAILED;
- }
-#endif /*USE_NPTH*/
- return 0;
-}
-
-static int
-trylock_slot (int slot)
-{
-#ifdef USE_NPTH
- int err;
-
- err = npth_mutex_trylock (&reader_table[slot].lock);
- if (err == EBUSY)
- return SW_HOST_BUSY;
- else if (err)
- {
- log_error ("failed to acquire apdu lock: %s\n", strerror (err));
- return SW_HOST_LOCKING_FAILED;
- }
-#endif /*USE_NPTH*/
- return 0;
-}
-
-static void
-unlock_slot (int slot)
-{
-#ifdef USE_NPTH
- int err;
-
- err = npth_mutex_unlock (&reader_table[slot].lock);
- if (err)
- log_error ("failed to release apdu lock: %s\n", strerror (errno));
-#endif /*USE_NPTH*/
-}
-
-
/* Open the reader and return an internal slot number or -1 on
error. If PORTSTR is NULL we default to a suitable port (for ctAPI:
the first USB reader. For PC/SC the first listed reader). */
--



_______________________________________________
Gnupg-devel mailing list
Gnupg-devel [at] gnupg
http://lists.gnupg.org/mailman/listinfo/gnupg-devel


wk at gnupg

Jun 7, 2012, 11:42 AM

Post #4 of 4 (499 views)
Permalink
Re: scd: a race condition between scd_command_handler and handle_tick [In reply to]

On Wed, 6 Jun 2012 07:30, gniibe [at] fsij said:

> The bug is in the master branch too.

Hmmm.

>> -> open_pcsc_reader
>> -> open_pcsc_reader_wrapper
>> -> new_reader_slot
>> Then, forking gnupg-pcsc-wrapper...

There should be no pcsc wrapper in master anymore. We don't need it
after the switch to npth. I guess we simply forgot to remove the need
for the wrapper.

The wrapper was needed because it is not possible to use Pth and pthread
together. libpcsclite uses pthread. nPth solves the problem by
internally using pthread.



Salam-Shalom,

Werner

--
Die Gedanken sind frei. Ausnahmen regelt ein Bundesgesetz.


_______________________________________________
Gnupg-devel mailing list
Gnupg-devel [at] gnupg
http://lists.gnupg.org/mailman/listinfo/gnupg-devel

GnuPG devel RSS feed   Index | Next | Previous | View Threaded
 
 


Interested in having your list archived? Contact Gossamer Threads
 
  Web Applications & Managed Hosting Powered by Gossamer Threads Inc.