removing usb token on SunOS results in pcscd getting into an endless loop #5
Labels
Comments
|
BTW, I just tried disabling timerfd in libusb-1, but it didn't change the results much. |
|
It looks like a bug in libusb for SunOS. |
|
This is not a bug in pcsc-lite. |
LudovicRousseau
pushed a commit
that referenced
this issue
Dec 15, 2021
Problem:
The thread running EHStatusHandlerThread() will race all the
rContext->readerState->fields as well as the powerState and some other
flags. These flags are both consumed and set by the thread running the
ccid driver as well.
Solution:
Make the flow unidirectional*: the status thread will always set its own
copy and "stash" a unique copy ready to be consumed by the driver
thread. That copy is consumed and rcontext->readerState is updated in
RFCheckReaderStatus() and a few other functions in readerfactory.c.
Whenever a copy is consumed it is also freed. Note that even though this
adds dynamic allocation it's at most 2 instances of READER_STATE.
This PR uses the C11 _Atomic feature. I'm not very familiar with all the
compilers pcsc is built with, but if you deem this to be incompatible,
please review the overall approach and I can #ifdef and do some mutexes
for platforms which do not provide _Atomic
* the flow is unidirectional except for the readerName which is logged
at the beginning of the status thread. That should not be a problem
since the name is set from the driver thread before the status thread
is spawned.
==================
WARNING: ThreadSanitizer: data race (pid=28786)
Write of size 4 at 0x000000f55c10 by thread T3:
#0 EHStatusHandlerThread <null> (pcscd+0x4c3aed)
Previous read of size 4 at 0x000000f55c10 by main thread:
#0 RFWaitForReaderInit <null> (pcscd+0x4d0e27)
#1 main <null> (pcscd+0x4c70c6)
Location is global 'readerStates' of size 2944 at 0x000000f55b60 (pcscd+0x000000f55c10)
Thread T3 (tid=28790, running) created by main thread at:
#0 pthread_create <null> (pcscd+0x42be9b)
#1 ThreadCreate <null> (pcscd+0x4e1c79)
#2 EHSpawnEventHandler <null> (pcscd+0x4c2e9f)
#3 RFAddReader <null> (pcscd+0x4cac07)
#4 HPAddDevice <null> (pcscd+0x4e0a2e)
#5 HPScanUSB <null> (pcscd+0x4dfe65)
#6 HPRegisterForHotplugEvents <null> (pcscd+0x4dfd3a)
#7 main <null> (pcscd+0x4c705c)
SUMMARY: ThreadSanitizer: data race (/home/rousseau/sc/costa/PCSC/src/pcscd+0x4c3aed) in EHStatusHandlerThread
==================
LudovicRousseau
added a commit
that referenced
this issue
Dec 15, 2021
The problem is (in part) with the switch() that may read the variable
more than once.
==================
WARNING: ThreadSanitizer: data race (pid=10828)
Write of size 8 at 0x7b040000ae78 by thread T6 (mutexes: write M0):
#0 RFSetReaderEventState PCSC/src/readerfactory.c:1321:32 (pcscd+0x4c45ce)
#1 EHStatusHandlerThread PCSC/src/eventhandler.c:382:11 (pcscd+0x4bee54)
Previous read of size 8 at 0x7b040000ae78 by thread T8:
#0 RFCheckReaderEventState PCSC/src/readerfactory.c:1350:24 (pcscd+0x4c46c6)
#1 SCardStatus PCSC/src/winscard.c:1286:7 (pcscd+0x4ce7b5)
#2 ContextThread PCSC/src/winscard_svc.c:635:16 (pcscd+0x4d0cc1)
Location is heap block of size 16 at 0x7b040000ae70 allocated by thread T8:
#0 malloc <null> (pcscd+0x42a65c)
#1 RFAddReaderHandle PCSC/src/readerfactory.c:1249:14 (pcscd+0x4c43b4)
#2 SCardConnect PCSC/src/winscard.c:491:7 (pcscd+0x4ccc16)
#3 ContextThread PCSC/src/winscard_svc.c:502:16 (pcscd+0x4d0a70)
Mutex M0 (0x7b4c000000a0) created at:
#0 pthread_mutex_init <null> (pcscd+0x42d2fd)
#1 RFAddReader PCSC/src/readerfactory.c:329:8 (pcscd+0x4c1d18)
#2 HPAddDevice PCSC/src/hotplug_libudev.c:534:8 (pcscd+0x4cba1c)
#3 HPEstablishUSBNotifications PCSC/src/hotplug_libudev.c:668:6 (pcscd+0x4cb4d4)
Thread T6 (tid=11122, running) created by thread T2 at:
#0 pthread_create <null> (pcscd+0x42be8b)
#1 ThreadCreate PCSC/src/utils.c:184:8 (pcscd+0x4cc2dc)
#2 EHSpawnEventHandler PCSC/src/eventhandler.c:237:7 (pcscd+0x4beb59)
#3 RFAddReader PCSC/src/readerfactory.c:426:8 (pcscd+0x4c21b9)
#4 HPAddDevice PCSC/src/hotplug_libudev.c:534:8 (pcscd+0x4cba1c)
#5 HPEstablishUSBNotifications PCSC/src/hotplug_libudev.c:668:6 (pcscd+0x4cb4d4)
Thread T8 (tid=11173, running) created by main thread at:
#0 pthread_create <null> (pcscd+0x42be8b)
#1 ThreadCreate PCSC/src/utils.c:184:8 (pcscd+0x4cc2dc)
#2 CreateContextThread PCSC/src/winscard_svc.c:236:7 (pcscd+0x4cfd8b)
#3 SVCServiceRunLoop PCSC/src/pcscdaemon.c:134:9 (pcscd+0x4c1082)
#4 main PCSC/src/pcscdaemon.c:786:2 (pcscd+0x4c09c4)
SUMMARY: ThreadSanitizer: data race PCSC/src/readerfactory.c:1321:32 in RFSetReaderEventState
==================
LudovicRousseau
added a commit
that referenced
this issue
Dec 19, 2021
The problem is (in part) with the switch() that may read the variable
more than once.
==================
WARNING: ThreadSanitizer: data race (pid=10828)
Write of size 8 at 0x7b040000ae78 by thread T6 (mutexes: write M0):
#0 RFSetReaderEventState PCSC/src/readerfactory.c:1321:32 (pcscd+0x4c45ce)
#1 EHStatusHandlerThread PCSC/src/eventhandler.c:382:11 (pcscd+0x4bee54)
Previous read of size 8 at 0x7b040000ae78 by thread T8:
#0 RFCheckReaderEventState PCSC/src/readerfactory.c:1350:24 (pcscd+0x4c46c6)
#1 SCardStatus PCSC/src/winscard.c:1286:7 (pcscd+0x4ce7b5)
#2 ContextThread PCSC/src/winscard_svc.c:635:16 (pcscd+0x4d0cc1)
Location is heap block of size 16 at 0x7b040000ae70 allocated by thread T8:
#0 malloc <null> (pcscd+0x42a65c)
#1 RFAddReaderHandle PCSC/src/readerfactory.c:1249:14 (pcscd+0x4c43b4)
#2 SCardConnect PCSC/src/winscard.c:491:7 (pcscd+0x4ccc16)
#3 ContextThread PCSC/src/winscard_svc.c:502:16 (pcscd+0x4d0a70)
Mutex M0 (0x7b4c000000a0) created at:
#0 pthread_mutex_init <null> (pcscd+0x42d2fd)
#1 RFAddReader PCSC/src/readerfactory.c:329:8 (pcscd+0x4c1d18)
#2 HPAddDevice PCSC/src/hotplug_libudev.c:534:8 (pcscd+0x4cba1c)
#3 HPEstablishUSBNotifications PCSC/src/hotplug_libudev.c:668:6 (pcscd+0x4cb4d4)
Thread T6 (tid=11122, running) created by thread T2 at:
#0 pthread_create <null> (pcscd+0x42be8b)
#1 ThreadCreate PCSC/src/utils.c:184:8 (pcscd+0x4cc2dc)
#2 EHSpawnEventHandler PCSC/src/eventhandler.c:237:7 (pcscd+0x4beb59)
#3 RFAddReader PCSC/src/readerfactory.c:426:8 (pcscd+0x4c21b9)
#4 HPAddDevice PCSC/src/hotplug_libudev.c:534:8 (pcscd+0x4cba1c)
#5 HPEstablishUSBNotifications PCSC/src/hotplug_libudev.c:668:6 (pcscd+0x4cb4d4)
Thread T8 (tid=11173, running) created by main thread at:
#0 pthread_create <null> (pcscd+0x42be8b)
#1 ThreadCreate PCSC/src/utils.c:184:8 (pcscd+0x4cc2dc)
#2 CreateContextThread PCSC/src/winscard_svc.c:236:7 (pcscd+0x4cfd8b)
#3 SVCServiceRunLoop PCSC/src/pcscdaemon.c:134:9 (pcscd+0x4c1082)
#4 main PCSC/src/pcscdaemon.c:786:2 (pcscd+0x4c09c4)
SUMMARY: ThreadSanitizer: data race PCSC/src/readerfactory.c:1321:32 in RFSetReaderEventState
==================
LudovicRousseau
added a commit
that referenced
this issue
Nov 19, 2023
protect accesses to readerStates[] using a mutex so that 2 threads cannot
interfere for example by calling SCardGetStatusChange() and
SCardStatus() at the same time.
The ThreadSanitizer trace was:
==================
WARNING: ThreadSanitizer: data race (pid=13125)
Write of size 8 at 0x7fd3afc2b040 by main thread (mutexes: write M0):
#0 read <null> (pcsc_demo+0x5d8a4) (BuildId: 1ce759cdf5448d9e6401e93f7f56d4c7caa8ede7)
#1 read /usr/include/x86_64-linux-gnu/bits/unistd.h:38:10 (libpcsclite.so.1+0xab3c) (BuildId: 53195794f51c4d60ff5688d377d82ae2e264554e)
#2 MessageReceive src/winscard_msg.c:491:17 (libpcsclite.so.1+0xab3c)
#3 getReaderStates src/winscard_clnt.c:3552:7 (libpcsclite.so.1+0x4109) (BuildId: 53195794f51c4d60ff5688d377d82ae2e264554e)
#4 SCardStatus src/winscard_clnt.c:1441:7 (libpcsclite.so.1+0x4109)
#5 main /tmp/x/pcsc-lite-2.0.0/pcsc_demo.c:108:7 (pcsc_demo+0xd1bc4) (BuildId: 1ce759cdf5448d9e6401e93f7f56d4c7caa8ede7)
Previous write of size 8 at 0x7fd3afc2b040 by thread T1 (mutexes: write M1):
#0 read <null> (pcsc_demo+0x5d8a4) (BuildId: 1ce759cdf5448d9e6401e93f7f56d4c7caa8ede7)
#1 read /usr/include/x86_64-linux-gnu/bits/unistd.h:38:10 (libpcsclite.so.1+0xab3c) (BuildId: 53195794f51c4d60ff5688d377d82ae2e264554e)
#2 MessageReceive src/winscard_msg.c:491:17 (libpcsclite.so.1+0xab3c)
#3 getReaderStatesAndRegisterForEvents src/winscard_clnt.c:3571:7 (libpcsclite.so.1+0x47b3) (BuildId: 53195794f51c4d60ff5688d377d82ae2e264554e)
#4 SCardGetStatusChange src/winscard_clnt.c:1747:7 (libpcsclite.so.1+0x47b3)
#5 do_statuschange /tmp/x/pcsc-lite-2.0.0/pcsc_demo.c:35:10 (pcsc_demo+0xd1e6d) (BuildId: 1ce759cdf5448d9e6401e93f7f56d4c7caa8ede7)
#6 statuschange_thread /tmp/x/pcsc-lite-2.0.0/pcsc_demo.c:53:2 (pcsc_demo+0xd19fd) (BuildId: 1ce759cdf5448d9e6401e93f7f56d4c7caa8ede7)
Location is global 'readerStates' of size 2944 at 0x7fd3afc2b040 (libpcsclite.so.1+0xf040)
Mutex M0 (0x7b3000006010) created at:
#0 pthread_mutex_init <null> (pcsc_demo+0x5431f) (BuildId: 1ce759cdf5448d9e6401e93f7f56d4c7caa8ede7)
#1 SCardAddContext src/winscard_clnt.c:3259:8 (libpcsclite.so.1+0x6adc) (BuildId: 53195794f51c4d60ff5688d377d82ae2e264554e)
#2 SCardEstablishContextTH src/winscard_clnt.c:659:7 (libpcsclite.so.1+0x6adc)
#3 SCardEstablishContext src/winscard_clnt.c:483:7 (libpcsclite.so.1+0x6adc)
#4 main /tmp/x/pcsc-lite-2.0.0/pcsc_demo.c:86:7 (pcsc_demo+0xd1aca) (BuildId: 1ce759cdf5448d9e6401e93f7f56d4c7caa8ede7)
Mutex M1 (0x7b3000000010) created at:
#0 pthread_mutex_init <null> (pcsc_demo+0x5431f) (BuildId: 1ce759cdf5448d9e6401e93f7f56d4c7caa8ede7)
#1 SCardAddContext src/winscard_clnt.c:3259:8 (libpcsclite.so.1+0x6adc) (BuildId: 53195794f51c4d60ff5688d377d82ae2e264554e)
#2 SCardEstablishContextTH src/winscard_clnt.c:659:7 (libpcsclite.so.1+0x6adc)
#3 SCardEstablishContext src/winscard_clnt.c:483:7 (libpcsclite.so.1+0x6adc)
#4 do_statuschange /tmp/x/pcsc-lite-2.0.0/pcsc_demo.c:12:7 (pcsc_demo+0xd1d84) (BuildId: 1ce759cdf5448d9e6401e93f7f56d4c7caa8ede7)
#5 statuschange_thread /tmp/x/pcsc-lite-2.0.0/pcsc_demo.c:53:2 (pcsc_demo+0xd19fd) (BuildId: 1ce759cdf5448d9e6401e93f7f56d4c7caa8ede7)
Thread T1 (tid=13127, running) created by main thread at:
#0 pthread_create <null> (pcsc_demo+0x52b4d) (BuildId: 1ce759cdf5448d9e6401e93f7f56d4c7caa8ede7)
#1 start_thread /tmp/x/pcsc-lite-2.0.0/pcsc_demo.c:61:6 (pcsc_demo+0xd1964) (BuildId: 1ce759cdf5448d9e6401e93f7f56d4c7caa8ede7)
#2 main /tmp/x/pcsc-lite-2.0.0/pcsc_demo.c:84:8 (pcsc_demo+0xd1ab1) (BuildId: 1ce759cdf5448d9e6401e93f7f56d4c7caa8ede7)
SUMMARY: ThreadSanitizer: data race (/tmp/x/pcsc-lite-2.0.0/pcsc_demo+0x5d8a4) (BuildId: 1ce759cdf5448d9e6401e93f7f56d4c7caa8ede7) in __interceptor_read
==================
Thanks to Stefan Ehmann for the bug report.
LudovicRousseau
added a commit
that referenced
this issue
Nov 19, 2023
Use pthread_once() to initialize the variable only once.
It was possible that 2 threads were modifying the variable at the same
time.
The ThreadSanitizer trace was:
==================
WARNING: ThreadSanitizer: data race (pid=14864)
Write of size 1 at 0x7f8803cccd2b by main thread:
#0 getSocketName src/winscard_msg.c:101 (libpcsclite.so.1+0xa28c)
#1 getSocketName src/winscard_msg.c:85 (libpcsclite.so.1+0xa28c)
#2 SCardCheckDaemonAvailability src/winscard_clnt.c:3550 (libpcsclite.so.1+0x65cf)
#3 SCardEstablishContext src/winscard_clnt.c:479 (libpcsclite.so.1+0x66a7)
#4 main /tmp/pcsc/pcsc_demo.cpp:86 (pcsc_demo+0x1517)
Previous write of size 1 at 0x7f8803cccd2b by thread T1:
#0 getSocketName src/winscard_msg.c:101 (libpcsclite.so.1+0xa28c)
#1 getSocketName src/winscard_msg.c:85 (libpcsclite.so.1+0xa28c)
#2 SCardCheckDaemonAvailability src/winscard_clnt.c:3550 (libpcsclite.so.1+0x65cf)
#3 SCardEstablishContext src/winscard_clnt.c:479 (libpcsclite.so.1+0x66a7)
#4 do_statuschange /tmp/pcsc/pcsc_demo.cpp:12 (pcsc_demo+0x1264)
#5 statuschange_thread /tmp/pcsc/pcsc_demo.cpp:53 (pcsc_demo+0x1264)
Location is global '<null>' at 0x000000000000 (libpcsclite.so.1+0xfd2b)
Thread T1 (tid=14867, running) created by main thread at:
#0 pthread_create ../../../../src/libsanitizer/tsan/tsan_interceptors_posix.cpp:1001 (libtsan.so.2+0x5e686)
#1 start_thread(char const*) /tmp/pcsc/pcsc_demo.cpp:61 (pcsc_demo+0x1432)
#2 main /tmp/pcsc/pcsc_demo.cpp:84 (pcsc_demo+0x14cc)
SUMMARY: ThreadSanitizer: data race src/winscard_msg.c:101 in getSocketName
==================
ThreadSanitizer: reported 1 warnings
Thanks to Stefan Ehmann for the bug report.
LudovicRousseau
added a commit
that referenced
this issue
Nov 19, 2023
The field .cardAtrLength is used to know if a card is inserted and is
accessed from different threads.
We define it as _Atomic to have atomic accesses to the field and fix a
TSAN warning:
==================
WARNING: ThreadSanitizer: data race (pid=14987)
Read of size 4 at 0x557bacd39cb0 by main thread:
#0 RFWaitForReaderInit PCSC/src/readerfactory.c:1430:43 (pcscd+0xdda24) (BuildId: b43179fc4c418df0dad65d97dc7a0d9cc226d42f)
#1 main PCSC/src/pcscdaemon.c:773:2 (pcscd+0xd87d4) (BuildId: b43179fc4c418df0dad65d97dc7a0d9cc226d42f)
Previous write of size 8 at 0x557bacd39cb0 by thread T3:
#0 EHStatusHandlerThread PCSC/src/eventhandler.c:314:40 (pcscd+0xd6a47) (BuildId: b43179fc4c418df0dad65d97dc7a0d9cc226d42f)
Location is global 'readerStates' of size 2944 at 0x557bacd39c00 (pcscd+0x1496cb0)
Thread T3 (tid=14992, running) created by main thread at:
#0 pthread_create <null> (pcscd+0x53dfd) (BuildId: b43179fc4c418df0dad65d97dc7a0d9cc226d42f)
#1 ThreadCreate PCSC/src/utils.c:184:8 (pcscd+0xe38cb) (BuildId: b43179fc4c418df0dad65d97dc7a0d9cc226d42f)
#2 EHSpawnEventHandler PCSC/src/eventhandler.c:233:7 (pcscd+0xd6960) (BuildId: b43179fc4c418df0dad65d97dc7a0d9cc226d42f)
#3 RFAddReader PCSC/src/readerfactory.c:397:8 (pcscd+0xdb632) (BuildId: b43179fc4c418df0dad65d97dc7a0d9cc226d42f)
#4 HPAddDevice PCSC/src/hotplug_libudev.c:512:8 (pcscd+0xe3029) (BuildId: b43179fc4c418df0dad65d97dc7a0d9cc226d42f)
#5 HPScanUSB PCSC/src/hotplug_libudev.c:579:3 (pcscd+0xe263d) (BuildId: b43179fc4c418df0dad65d97dc7a0d9cc226d42f)
#6 HPRegisterForHotplugEvents PCSC/src/hotplug_libudev.c:761:2 (pcscd+0xe263d)
#7 main PCSC/src/pcscdaemon.c:766:7 (pcscd+0xd87c7) (BuildId: b43179fc4c418df0dad65d97dc7a0d9cc226d42f)
SUMMARY: ThreadSanitizer: data race PCSC/src/readerfactory.c:1430:43 in RFWaitForReaderInit
==================
Thanks to Stefan Ehmann for the bug report.
LudovicRousseau
added a commit
that referenced
this issue
Nov 19, 2023
ContextsDeinitialize() was called by thread A in the middle of
list_delete() from thread B.
We already have a mutex to protect access to contextsList.
==================
WARNING: ThreadSanitizer: data race (pid=17581)
Write of size 8 at 0x5606b8d11b60 by main thread:
#0 list_clear PCSC/src/simclist.c:694:12 (pcscd+0xde66c) (BuildId: 807b741f905324f3ef4d96796ee2663eb8beddec)
#1 list_destroy PCSC/src/simclist.c:313:5 (pcscd+0xde26c) (BuildId: 807b741f905324f3ef4d96796ee2663eb8beddec)
#2 ContextsDeinitialize PCSC/src/winscard_svc.c:159:2 (pcscd+0xe4d13) (BuildId: 807b741f905324f3ef4d96796ee2663eb8beddec)
#3 SVCServiceRunLoop PCSC/src/pcscdaemon.c:122:4 (pcscd+0xd9699) (BuildId: 807b741f905324f3ef4d96796ee2663eb8beddec)
#4 main PCSC/src/pcscdaemon.c:799:2 (pcscd+0xd8930) (BuildId: 807b741f905324f3ef4d96796ee2663eb8beddec)
Previous write of size 8 at 0x5606b8d11b60 by thread T6 (mutexes: write M0):
#0 list_drop_elem PCSC/src/simclist.c:1457:36 (pcscd+0xdf63e) (BuildId: 807b741f905324f3ef4d96796ee2663eb8beddec)
#1 list_delete_at PCSC/src/simclist.c:580:5 (pcscd+0xdf63e)
#2 list_delete PCSC/src/simclist.c:563:6 (pcscd+0xdf1c7) (BuildId: 807b741f905324f3ef4d96796ee2663eb8beddec)
#3 MSGCleanupClient PCSC/src/winscard_svc.c:1083:8 (pcscd+0xe9f6a) (BuildId: 807b741f905324f3ef4d96796ee2663eb8beddec)
#4 ContextThread PCSC/src/winscard_svc.c:818:2 (pcscd+0xe98fd) (BuildId: 807b741f905324f3ef4d96796ee2663eb8beddec)
As if synchronized via sleep:
#0 nanosleep <null> (pcscd+0x515ed) (BuildId: 807b741f905324f3ef4d96796ee2663eb8beddec)
#1 SYS_Sleep PCSC/src/sys_unix.c:69:9 (pcscd+0xdf8e9) (BuildId: 807b741f905324f3ef4d96796ee2663eb8beddec)
#2 SVCServiceRunLoop PCSC/src/pcscdaemon.c:117:10 (pcscd+0xd968a) (BuildId: 807b741f905324f3ef4d96796ee2663eb8beddec)
#3 main PCSC/src/pcscdaemon.c:799:2 (pcscd+0xd8930) (BuildId: 807b741f905324f3ef4d96796ee2663eb8beddec)
Location is global 'contextsList' of size 120 at 0x5606b8d11b50 (pcscd+0x1497b60)
Mutex M0 (0x5606b8d11bc8) created at:
#0 pthread_mutex_init <null> (pcscd+0x555cf) (BuildId: 807b741f905324f3ef4d96796ee2663eb8beddec)
#1 ContextsInitialize PCSC/src/winscard_svc.c:144:8 (pcscd+0xe4be5) (BuildId: 807b741f905324f3ef4d96796ee2663eb8beddec)
#2 main PCSC/src/pcscdaemon.c:737:7 (pcscd+0xd8780) (BuildId: 807b741f905324f3ef4d96796ee2663eb8beddec)
Thread T6 (tid=17591, finished) created by main thread at:
#0 pthread_create <null> (pcscd+0x53dfd) (BuildId: 807b741f905324f3ef4d96796ee2663eb8beddec)
#1 ThreadCreate PCSC/src/utils.c:184:8 (pcscd+0xe399b) (BuildId: 807b741f905324f3ef4d96796ee2663eb8beddec)
#2 CreateContextThread PCSC/src/winscard_svc.c:237:7 (pcscd+0xd936e) (BuildId: 807b741f905324f3ef4d96796ee2663eb8beddec)
#3 SVCServiceRunLoop PCSC/src/pcscdaemon.c:131:9 (pcscd+0xd936e)
#4 main PCSC/src/pcscdaemon.c:799:2 (pcscd+0xd8930) (BuildId: 807b741f905324f3ef4d96796ee2663eb8beddec)
#5 main PCSC/src/pcscdaemon.c:799:2 (pcscd+0xd8930) (BuildId: 807b741f905324f3ef4d96796ee2663eb8beddec)
SUMMARY: ThreadSanitizer: data race PCSC/src/simclist.c:694:12 in list_clear
==================
LudovicRousseau
added a commit
that referenced
this issue
Nov 19, 2023
The struct timeval used in log_line() can't be accessed in a atomic way
so we should protect it using a mutex.
==================
WARNING: ThreadSanitizer: data race (pid=5391)
Read of size 8 at 0x55b3bba7b950 by thread T3 (mutexes: write M17):
#0 log_line /PCSC-debug/src/debuglog.c:217 (pcscd+0x9d7e)
#1 log_msg /PCSC-debug/src/debuglog.c:148 (pcscd+0x9a85)
#2 IFDHPowerICC <null> (libccid.so+0x8a54)
#3 EHStatusHandlerThread /PCSC-debug/src/eventhandler.c:395 (pcscd+0xbafe)
Previous write of size 8 at 0x55b3bba7b950 by main thread:
#0 log_line /PCSC-debug/src/debuglog.c:232 (pcscd+0x9e77)
#1 log_msg /PCSC-debug/src/debuglog.c:148 (pcscd+0x9a85)
#2 get_driver /PCSC-debug/src/hotplug_libudev.c:298 (pcscd+0x1f75d)
#3 HPAddDevice /PCSC-debug/src/hotplug_libudev.c:394 (pcscd+0x1ff32)
#4 HPScanUSB /PCSC-debug/src/hotplug_libudev.c:579 (pcscd+0x209db)
#5 HPRegisterForHotplugEvents /PCSC-debug/src/hotplug_libudev.c:761
(pcscd+0x21255)
#6 main /PCSC-debug/src/pcscdaemon.c:766 (pcscd+0xe6fa)
Location is global 'last_time.3' of size 16 at 0x55b3bba7b950
(pcscd+0x35950)
Mutex M17 (0x7b0c000014d0) created at:
#0 pthread_mutex_init ../../../../src/libsanitizer/tsan/
tsan_interceptors_posix.cpp:1295 (libtsan.so.2+0x50468)
#1 RFAddReader /PCSC-debug/src/readerfactory.c:355 (pcscd+0x10b8c)
#2 HPAddDevice /PCSC-debug/src/hotplug_libudev.c:512 (pcscd+0x205b0)
#3 HPScanUSB /PCSC-debug/src/hotplug_libudev.c:579 (pcscd+0x209db)
#4 HPRegisterForHotplugEvents /PCSC-debug/src/hotplug_libudev.c:761
(pcscd+0x21255)
#5 main /PCSC-debug/src/pcscdaemon.c:766 (pcscd+0xe6fa)
Thread T3 (tid=5395, running) created by main thread at:
#0 pthread_create ../../../../src/libsanitizer/tsan/
tsan_interceptors_posix.cpp:1001 (libtsan.so.2+0x5e686)
#1 ThreadCreate /PCSC-debug/src/utils.c:184 (pcscd+0x21755)
#2 EHSpawnEventHandler /PCSC-debug/src/eventhandler.c:233 (pcscd+0xb2d9)
#3 RFAddReader /PCSC-debug/src/readerfactory.c:397 (pcscd+0x10f1a)
#4 HPAddDevice /PCSC-debug/src/hotplug_libudev.c:512 (pcscd+0x205b0)
#5 HPScanUSB /PCSC-debug/src/hotplug_libudev.c:579 (pcscd+0x209db)
#6 HPRegisterForHotplugEvents /PCSC-debug/src/hotplug_libudev.c:761
(pcscd+0x21255)
#7 main /PCSC-debug/src/pcscdaemon.c:766 (pcscd+0xe6fa)
SUMMARY: ThreadSanitizer: data race /PCSC-debug/src/debuglog.c:217 in log_line
==================
Thanks to Stefan Ehmann for the bug report and patch.
LudovicRousseau
added a commit
that referenced
this issue
Nov 19, 2023
The field .vHandle is used to check the validity of the reader.
It is accessed in write mode in RFUnloadReader() from a thread A while
it is also accessed in read mode in RFWaitForReaderInit() from thread B.
==================
WARNING: ThreadSanitizer: data race (pid=23997)
Write of size 8 at 0x7b4c000002d8 by thread T5:
#0 RFUnloadReader PCSC/src/readerfactory.c:1005:20 (pcscd+0xda017) (BuildId: db0b27e1c3b409153327b14d9e501205ed34fb6e)
#1 RFUnInitializeReader PCSC/src/readerfactory.c:1151:8 (pcscd+0xda017)
#2 removeReader PCSC/src/readerfactory.c:645:2 (pcscd+0xda017)
#3 _UnrefReader PCSC/src/readerfactory.c:120:3 (pcscd+0xda017)
#4 RFRemoveReader PCSC/src/readerfactory.c:624:5 (pcscd+0xdd11b) (BuildId: db0b27e1c3b409153327b14d9e501205ed34fb6e)
#5 RFRemoveReader PCSC/src/readerfactory.c:624:5 (pcscd+0xdd11b) (BuildId: db0b27e1c3b409153327b14d9e501205ed34fb6e)
#6 HPRemoveDevice PCSC/src/hotplug_libudev.c:348:4 (pcscd+0xe35af) (BuildId: db0b27e1c3b409153327b14d9e501205ed34fb6e)
#7 HPEstablishUSBNotifications PCSC/src/hotplug_libudev.c:640:6 (pcscd+0xe35af)
Previous read of size 8 at 0x7b4c000002d8 by main thread:
#0 RFWaitForReaderInit PCSC/src/readerfactory.c:1426:29 (pcscd+0xddabe) (BuildId: db0b27e1c3b409153327b14d9e501205ed34fb6e)
#1 main PCSC/src/pcscdaemon.c:773:2 (pcscd+0xd8864) (BuildId: db0b27e1c3b409153327b14d9e501205ed34fb6e)
Location is heap block of size 400 at 0x7b4c000001c0 allocated by main thread:
#0 malloc <null> (pcscd+0x52691) (BuildId: db0b27e1c3b409153327b14d9e501205ed34fb6e)
#1 RFAllocateReaderSpace PCSC/src/readerfactory.c:135:25 (pcscd+0xda3b9) (BuildId: db0b27e1c3b409153327b14d9e501205ed34fb6e)
#2 main PCSC/src/pcscdaemon.c:643:7 (pcscd+0xd85a5) (BuildId: db0b27e1c3b409153327b14d9e501205ed34fb6e)
Thread T5 (tid=24004, running) created by main thread at:
#0 pthread_create <null> (pcscd+0x53dfd) (BuildId: db0b27e1c3b409153327b14d9e501205ed34fb6e)
#1 ThreadCreate PCSC/src/utils.c:184:8 (pcscd+0xe39bb) (BuildId: db0b27e1c3b409153327b14d9e501205ed34fb6e)
#2 HPRegisterForHotplugEvents PCSC/src/hotplug_libudev.c:763:6 (pcscd+0xe2768) (BuildId: db0b27e1c3b409153327b14d9e501205ed34fb6e)
#3 main PCSC/src/pcscdaemon.c:766:7 (pcscd+0xd8857) (BuildId: db0b27e1c3b409153327b14d9e501205ed34fb6e)
SUMMARY: ThreadSanitizer: data race PCSC/src/readerfactory.c:1005:20 in RFUnloadReader
==================
LudovicRousseau
added a commit
that referenced
this issue
Nov 19, 2023
When pcscd exits we must first terminate any client thread on the
server side before closing the reader threads.
This is to prevent a client thread to access a now deactivated reader.
The error was:
^C00250854 [140433941325504] pcscdaemon.c:192:signal_thread() Received signal: 2
00000036 [140433941325504] pcscdaemon.c:226:signal_thread() Preparing for suicide
[...readers are stopped here...]
00000042 [140433995138368] pcscdaemon.c:809:at_exit() cleaning /run/pcscd
[...but we get a new request from a client...]
00000016 [140433906050752] winscard_svc.c:384:ContextThread() Received command: CMD_WAIT_READER_STATE_CHANGE from client 12
==================
WARNING: ThreadSanitizer: use of an invalid mutex (e.g. uninitialized or destroyed) (pid=62372)
#0 pthread_mutex_lock <null> (pcscd+0x71ada) (BuildId: 1bcd3f8a880d8c656c6e6bbe77b504b573d68914)
#1 EHRegisterClientForEvent PCSC/src/eventhandler.c:68:8 (pcscd+0xe5b2a) (BuildId: 1bcd3f8a880d8c656c6e6bbe77b504b573d68914)
#2 ContextThread PCSC/src/winscard_svc.c:446:5 (pcscd+0xe5b2a)
#3 __tsan_thread_start_func <null> (pcscd+0x53d66) (BuildId: 1bcd3f8a880d8c656c6e6bbe77b504b573d68914)
Location is global 'ClientsWaitingForEvent_lock' of size 40 at 0x556bd69d67c8 (pcscd+0x14977c8)
Mutex M0 (0x556bd69d67c8) created at:
[failed to restore the stack]
SUMMARY: ThreadSanitizer: use of an invalid mutex (e.g. uninitialized or destroyed) (PCSC/src/pcscd+0x71ada) (BuildId: 1bcd3f8a880d8c656c6e6bbe77b504b573d68914) in __interceptor_pthread_mutex_lock
==================
==================
WARNING: ThreadSanitizer: heap-use-after-free (pid=62372)
Read of size 8 at 0x7b0c00000060 by thread T5:
#0 list_insert_at PCSC/src/simclist.c:503:16 (pcscd+0xdea60) (BuildId: 1bcd3f8a880d8c656c6e6bbe77b504b573d68914)
#1 list_append PCSC/src/simclist.c:397:12 (pcscd+0xdea60)
#2 EHRegisterClientForEvent PCSC/src/eventhandler.c:70:8 (pcscd+0xe5b39) (BuildId: 1bcd3f8a880d8c656c6e6bbe77b504b573d68914)
#3 ContextThread PCSC/src/winscard_svc.c:446:5 (pcscd+0xe5b39)
#4 EHRegisterClientForEvent PCSC/src/eventhandler.c:70:8 (pcscd+0xe5b39) (BuildId: 1bcd3f8a880d8c656c6e6bbe77b504b573d68914)
#5 ContextThread PCSC/src/winscard_svc.c:446:5 (pcscd+0xe5b39)
#6 __tsan_thread_start_func <null> (pcscd+0x53d66) (BuildId: 1bcd3f8a880d8c656c6e6bbe77b504b573d68914)
Previous write of size 8 at 0x7b0c00000060 by main thread:
#0 free <null> (pcscd+0x52c84) (BuildId: 1bcd3f8a880d8c656c6e6bbe77b504b573d68914)
#1 list_destroy PCSC/src/simclist.c:317:5 (pcscd+0xde590) (BuildId: 1bcd3f8a880d8c656c6e6bbe77b504b573d68914)
#2 EHDeinitializeEventStructures PCSC/src/eventhandler.c:152:2 (pcscd+0xd6866) (BuildId: 1bcd3f8a880d8c656c6e6bbe77b504b573d68914)
#3 SVCServiceRunLoop PCSC/src/pcscdaemon.c:124:4 (pcscd+0xd9649) (BuildId: 1bcd3f8a880d8c656c6e6bbe77b504b573d68914)
#4 main PCSC/src/pcscdaemon.c:801:2 (pcscd+0xd88e0) (BuildId: 1bcd3f8a880d8c656c6e6bbe77b504b573d68914)
Thread T5 (tid=62379, running) created by main thread at:
#0 pthread_create <null> (pcscd+0x53dfd) (BuildId: 1bcd3f8a880d8c656c6e6bbe77b504b573d68914)
#1 ThreadCreate PCSC/src/utils.c:184:8 (pcscd+0xe3c7b) (BuildId: 1bcd3f8a880d8c656c6e6bbe77b504b573d68914)
#2 CreateContextThread PCSC/src/winscard_svc.c:258:7 (pcscd+0xd931e) (BuildId: 1bcd3f8a880d8c656c6e6bbe77b504b573d68914)
#3 SVCServiceRunLoop PCSC/src/pcscdaemon.c:133:9 (pcscd+0xd931e)
#4 main PCSC/src/pcscdaemon.c:801:2 (pcscd+0xd88e0) (BuildId: 1bcd3f8a880d8c656c6e6bbe77b504b573d68914)
#5 main PCSC/src/pcscdaemon.c:801:2 (pcscd+0xd88e0) (BuildId: 1bcd3f8a880d8c656c6e6bbe77b504b573d68914)
SUMMARY: ThreadSanitizer: heap-use-after-free PCSC/src/simclist.c:503:16 in list_insert_at
==================
etc..
LudovicRousseau
added a commit
that referenced
this issue
Nov 19, 2023
The field .readerSharing can be used from different theads at the same
time.
We define it as _Atomic to have atomic accesses to the field and fix a
TSAN warning:
==================
WARNING: ThreadSanitizer: data race (pid=63123)
Write of size 4 at 0x5575884d8cb8 by thread T3:
#0 EHStatusHandlerThread PCSC/src/eventhandler.c:449:41 (pcscd+0xd6f12) (BuildId: b2f519c8807f458b6282d631fe17086d4f6da420)
Previous write of size 4 at 0x5575884d8cb8 by thread T8:
#0 SCardDisconnect PCSC/src/winscard.c:1034:39 (pcscd+0xe4779) (BuildId: b2f519c8807f458b6282d631fe17086d4f6da420)
#1 ContextThread PCSC/src/winscard_svc.c:575:16 (pcscd+0xe6507) (BuildId: b2f519c8807f458b6282d631fe17086d4f6da420)
As if synchronized via sleep:
#0 nanosleep <null> (pcscd+0x515ed) (BuildId: b2f519c8807f458b6282d631fe17086d4f6da420)
#1 SYS_USleep PCSC/src/sys_unix.c:87:9 (pcscd+0xd6fca) (BuildId: b2f519c8807f458b6282d631fe17086d4f6da420)
#2 EHStatusHandlerThread PCSC/src/eventhandler.c (pcscd+0xd6fca)
#3 __tsan_thread_start_func <null> (pcscd+0x53d66) (BuildId: b2f519c8807f458b6282d631fe17086d4f6da420)
Location is global 'readerStates' of size 2944 at 0x5575884d8c30 (pcscd+0x1497cb8)
Thread T3 (tid=63127, running) created by main thread at:
#0 pthread_create <null> (pcscd+0x53dfd) (BuildId: b2f519c8807f458b6282d631fe17086d4f6da420)
#1 ThreadCreate PCSC/src/utils.c:184:8 (pcscd+0xe3cab) (BuildId: b2f519c8807f458b6282d631fe17086d4f6da420)
#2 EHSpawnEventHandler PCSC/src/eventhandler.c:233:7 (pcscd+0xd6840) (BuildId: b2f519c8807f458b6282d631fe17086d4f6da420)
#3 RFAddReader PCSC/src/readerfactory.c:397:8 (pcscd+0xdb6dd) (BuildId: b2f519c8807f458b6282d631fe17086d4f6da420)
#4 HPAddDevice PCSC/src/hotplug_libudev.c:512:8 (pcscd+0xe3409) (BuildId: b2f519c8807f458b6282d631fe17086d4f6da420)
#5 HPScanUSB PCSC/src/hotplug_libudev.c:579:3 (pcscd+0xe2a1d) (BuildId: b2f519c8807f458b6282d631fe17086d4f6da420)
#6 HPRegisterForHotplugEvents PCSC/src/hotplug_libudev.c:761:2 (pcscd+0xe2a1d)
#7 main PCSC/src/pcscdaemon.c:768:7 (pcscd+0xd8717) (BuildId: b2f519c8807f458b6282d631fe17086d4f6da420)
Thread T8 (tid=63221, finished) created by main thread at:
#0 pthread_create <null> (pcscd+0x53dfd) (BuildId: b2f519c8807f458b6282d631fe17086d4f6da420)
#1 ThreadCreate PCSC/src/utils.c:184:8 (pcscd+0xe3cab) (BuildId: b2f519c8807f458b6282d631fe17086d4f6da420)
#2 CreateContextThread PCSC/src/winscard_svc.c:256:7 (pcscd+0xd924e) (BuildId: b2f519c8807f458b6282d631fe17086d4f6da420)
#3 SVCServiceRunLoop PCSC/src/pcscdaemon.c:133:9 (pcscd+0xd924e)
#4 main PCSC/src/pcscdaemon.c:801:2 (pcscd+0xd8810) (BuildId: b2f519c8807f458b6282d631fe17086d4f6da420)
#5 main PCSC/src/pcscdaemon.c:801:2 (pcscd+0xd8810) (BuildId: b2f519c8807f458b6282d631fe17086d4f6da420)
SUMMARY: ThreadSanitizer: data race PCSC/src/eventhandler.c:449:41 in EHStatusHandlerThread
==================
LudovicRousseau
added a commit
that referenced
this issue
Nov 19, 2023
The field .LockCount can be used from different theads at the same
time.
We define it as _Atomic to have atomic accesses to the field and fix a
TSAN warning:
==================
WARNING: ThreadSanitizer: data race (pid=64069)
Write of size 4 at 0x7b4c00000138 by thread T6 (mutexes: write M0):
#0 RFUnlockAllSharing PCSC/src/readerfactory.c:1080:23 (pcscd+0xe3f15) (BuildId: ca24a31c13ced4613b52730b820229170aba90d6)
#1 SCardDisconnect PCSC/src/winscard.c:863:7 (pcscd+0xe3f15)
#2 ContextThread PCSC/src/winscard_svc.c:575:16 (pcscd+0xe64f7) (BuildId: ca24a31c13ced4613b52730b820229170aba90d6)
#3 ContextThread PCSC/src/winscard_svc.c:575:16 (pcscd+0xe64f7) (BuildId: ca24a31c13ced4613b52730b820229170aba90d6)
Previous write of size 4 at 0x7b4c00000138 by thread T3:
#0 RFSetReaderEventState PCSC/src/readerfactory.c:1304:23 (pcscd+0xdd8f2) (BuildId: ca24a31c13ced4613b52730b820229170aba90d6)
#1 EHStatusHandlerThread PCSC/src/eventhandler.c:362:11 (pcscd+0xd6c9c) (BuildId: ca24a31c13ced4613b52730b820229170aba90d6)
Location is heap block of size 400 at 0x7b4c00000000 allocated by main thread:
#0 malloc <null> (pcscd+0x52691) (BuildId: ca24a31c13ced4613b52730b820229170aba90d6)
#1 RFAllocateReaderSpace PCSC/src/readerfactory.c:135:25 (pcscd+0xda2e9) (BuildId: ca24a31c13ced4613b52730b820229170aba90d6)
#2 main PCSC/src/pcscdaemon.c:645:7 (pcscd+0xd8465) (BuildId: ca24a31c13ced4613b52730b820229170aba90d6)
Mutex M0 (0x55dc20366908) created at:
#0 pthread_mutex_lock <null> (pcscd+0x71ada) (BuildId: ca24a31c13ced4613b52730b820229170aba90d6)
#1 RFUnlockAllSharing PCSC/src/readerfactory.c:1076:8 (pcscd+0xe3ecf) (BuildId: ca24a31c13ced4613b52730b820229170aba90d6)
#2 SCardDisconnect PCSC/src/winscard.c:863:7 (pcscd+0xe3ecf)
#3 ContextThread PCSC/src/winscard_svc.c:575:16 (pcscd+0xe64f7) (BuildId: ca24a31c13ced4613b52730b820229170aba90d6)
#4 ContextThread PCSC/src/winscard_svc.c:575:16 (pcscd+0xe64f7) (BuildId: ca24a31c13ced4613b52730b820229170aba90d6)
Thread T6 (tid=64077, running) created by main thread at:
#0 pthread_create <null> (pcscd+0x53dfd) (BuildId: ca24a31c13ced4613b52730b820229170aba90d6)
#1 ThreadCreate PCSC/src/utils.c:184:8 (pcscd+0xe3c9b) (BuildId: ca24a31c13ced4613b52730b820229170aba90d6)
#2 CreateContextThread PCSC/src/winscard_svc.c:256:7 (pcscd+0xd924e) (BuildId: ca24a31c13ced4613b52730b820229170aba90d6)
#3 SVCServiceRunLoop PCSC/src/pcscdaemon.c:133:9 (pcscd+0xd924e)
#4 main PCSC/src/pcscdaemon.c:801:2 (pcscd+0xd8810) (BuildId: ca24a31c13ced4613b52730b820229170aba90d6)
#5 main PCSC/src/pcscdaemon.c:801:2 (pcscd+0xd8810) (BuildId: ca24a31c13ced4613b52730b820229170aba90d6)
Thread T3 (tid=64073, running) created by main thread at:
#0 pthread_create <null> (pcscd+0x53dfd) (BuildId: ca24a31c13ced4613b52730b820229170aba90d6)
#1 ThreadCreate PCSC/src/utils.c:184:8 (pcscd+0xe3c9b) (BuildId: ca24a31c13ced4613b52730b820229170aba90d6)
#2 EHSpawnEventHandler PCSC/src/eventhandler.c:233:7 (pcscd+0xd6840) (BuildId: ca24a31c13ced4613b52730b820229170aba90d6)
#3 RFAddReader PCSC/src/readerfactory.c:397:8 (pcscd+0xdb6cd) (BuildId: ca24a31c13ced4613b52730b820229170aba90d6)
#4 HPAddDevice PCSC/src/hotplug_libudev.c:512:8 (pcscd+0xe33f9) (BuildId: ca24a31c13ced4613b52730b820229170aba90d6)
#5 HPScanUSB PCSC/src/hotplug_libudev.c:579:3 (pcscd+0xe2a0d) (BuildId: ca24a31c13ced4613b52730b820229170aba90d6)
#6 HPRegisterForHotplugEvents PCSC/src/hotplug_libudev.c:761:2 (pcscd+0xe2a0d)
#7 main PCSC/src/pcscdaemon.c:768:7 (pcscd+0xd8717) (BuildId: ca24a31c13ced4613b52730b820229170aba90d6)
SUMMARY: ThreadSanitizer: data race PCSC/src/readerfactory.c:1080:23 in RFUnlockAllSharing
==================
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Running 1.8.16 on SunOS 5.11
I notice an endless loop after unplugging my gemalto usb token to insert a different one.
Here's the scenario running testpcsc:
at this stage I run testpcsc:
and here is the output from pcscd prior to yanking the usb token:
then pulling the plug:
which loops until I
This is using recently libusb-1 support for SunOS... I must say setting LIBUSB_DEBUG=4
is quite noisy...
This is the output between two sets of above:
The text was updated successfully, but these errors were encountered: