System_Health extended event NLShimImpersonate hiba

SQL Server 2008-as verziótól elérhető az Extended Event, ami a zseniális eszköz hibakeresésére és sok egyéb esetben is. Ebből minden telepített SQL Server esetén van legalább egy (látható, mert, hogy nem látható több is van :) ) session, a System_Health. Ebben "sok" esemény logolva van, ebből is egy érdekeset emelnék ki: security_error_ring_buffer_recorded. Ennek az lenne a célja, hogy hitelesítési és jogosultság ellenőrzés során felmerülő hibákat vissza lehessen keresni. Sajnos ez nem teljesen van így. Lássuk az esetet:

Nagy tranzakció számú rendszeren a wait statisztikában a top wait típus a PREEMPTIVE_XE_DISPATCHER és az ehhez hasonlóak voltak. Gyanús lett, hogy ez extended event-hez köthető wait. Alapvetően 4 darab 5 MB-os file készül (érdemes átméretezni), ami gyakorlatilag percek alatt felül lett írva, így szinte hasztalan volt az event session. Szinte minden bejegyzés a következő módon nézett ki:

<Record id="68" type="RING_BUFFER_SECURITY_ERROR" time="4434688">
  <Error>
    <SPID>51</SPID>
    <APIName>ImpersonateSecurityContext</APIName>
    <CallingAPIName>NLShimImpersonate</CallingAPIName>
    <ErrorCode>0x139F</ErrorCode>
    <SQLErrorCode>x_cse_Success</SQLErrorCode>
  </Error>
  <Stack>
    <frame id="0">0X00007FFF75AB209A</frame>
    <frame id="1">0X00007FFF7593140F</frame>
    <frame id="2">0X00007FFF759337E5</frame>
    <frame id="3">0X00007FFF7592FE71</frame>
    <frame id="4">0X00007FFF7592F312</frame>
    <frame id="5">0X00007FFF75AB20B5</frame>
    <frame id="6">0X00007FFF759360A8</frame>
    <frame id="7">0X00007FFF7586FCC3</frame>
    <frame id="8">0X00007FFF75C2287D</frame>
    <frame id="9">0X00007FFF7592CCEA</frame>
    <frame id="10">0X00007FFF75385A5D</frame>
    <frame id="11">0X00007FFF75385845</frame>
    <frame id="12">0X00007FFF7538549D</frame>
    <frame id="13">0X00007FFF753AE258</frame>
    <frame id="14">0X00007FFF753AE440</frame>
    <frame id="15">0X00007FFF753AE3C7</frame>
  </Stack>
</Record>

Itt elkezdtünk gondolkodni, hogy mi is lehet ez. Az SQLErrorCode x_cse_success, ami valószínűleg valami sikeres művelet lehet. Az ErrorCode 0x139F, ami decimálisan 5023, erre meg az MS dokumentációja ezt írja: ERROR_INVALID_STATE - The group or resource is not in the correct state to perform the requested operation. Hmm, érdekes. Sikeres hiba :) 

Szerencsére van call stack (ezek a 0x0000 kezdődő értékek), amivel továbbmentem. Ennek a feloldása során a következőhöz hasonló eredményt kaptam:

sqllang!intnl_impersonate_client
sqllang!FInterrogateLogin
sqllang!FindLogin
sqllang!login
sqllang!process_login_finish
sqllang!process_login
sqllang!process_commands_internal
sqllang!process_messages
sqllang!TDSSNIClient::AddSSLProviderHandler
sqllang!SNIProcessAddProviderOnWorker
sqldk!SOS_Task::Param::Execute
sqldk!SOS_Scheduler::RunTask
sqldk!SOS_Scheduler::ProcessTasks
sqldk!SchedulerManager::WorkerEntryPoint
sqldk!SystemThread::RunWorker
sqldk!SystemThreadDispatcher::ProcessWorker

Hűűű, vajon ez mit jelent? :) Nagyjából annyit, hogy ez az SQL Server-re való bejelentkezés során jön elő. De miért, mi lehet az oka? A következő módokon álltam neki: készítettem egy új exteneded event session-t, ahol csak a security_error_ring_buffer_recorded esemény volt beállítva, majd először Windows hitelesítéssel léptem be, utána SQL hitelesítéssel. Érdekes módon Windows hitelesítés során nem volt bejegyzés, azonban az SQL hitelesítés során igen! Akár sikerült, akár nem, minden SQL hitelesítés során került egy bejegyzés az exteneded event file-ba! 

Ez volt az oka annak, hogy a wait statisztika tetején extended event-hez köthető wait típus volt. A 4x5MB file pedig azért került felülírásra gyakorlatilag percek alatt, mivel 2000+ egyidejű felhasználó csatlakozott az SQL Server-hez SQL hitelesítéssel! Megállapítható, hogy ez egy bug, erre van is visszajelzés a Microsoft oldalán, itt.

Alapvetően én kiveszem ezt az eseményt az alapértelmezett System_health session-ből vagy beállítok rá egy szűrést az alábbi módon:

ALTER EVENT SESSION [system_health] ON SERVER 
DROP EVENT sqlserver.security_error_ring_buffer_recorded
ALTER EVENT SESSION [system_health] ON SERVER 
ADD EVENT sqlserver.security_error_ring_buffer_recorded(SET collect_call_stack=(1)
    WHERE ([error_code]<>(0x139F)))
GO

Amennyiben mégis kell minden hibakódhoz, akkor a szűrést leveszem vagy indítok egy másik event session-t.

Comments (5) -

Kovács Zsolt 6/13/2018 5:31:42 AM

Szép! Smile

Azon kívül, hogy a wait stat első helyén szerepelt volt valamilyen érezhető hatása, ami miatt elkezdted felkutatni a problémát? Vagy egyszerűen csak belefutottál és ha már ott jártál, akkor megcsináltad? Smile

János Berke 6/13/2018 12:21:18 PM

Volt más jelenség is, leginkább a lemez 100%-os használata. A vicc, hogy ez az összes, a mai napig kiadott SQL verzióban, SP, CU szinten probléma. Azért is kellett megcsinálnom, mert elég sok dolgot nézek ebben az XE session-ben ;)

Kovács Zsolt 6/13/2018 1:25:37 PM

Javíts ki ha tévedek, de a 100%-os diszk használat akkor jön elő, ha olvasod is ezt a file-t és nem incrementálisan teszed ezt, hanem mindig beolvasod 0-rol az egészet.
Ez így valid?

János Berke 6/14/2018 6:12:07 AM

Alapvetően a wait volt ami feltűnt, aztán perf counterekkel láttam. Nem csak olvasáskor jön elő. Egyébként a ring buffert használom első körben, van rá tuti jó scriptem meg dashboard-om Smile érdekel?

Kovács Zsolt 6/14/2018 7:55:51 AM

Persze, egy tuti jó script mindig érdekel Smile

Add comment