Quelle cose strane, che quando succedono, non sai mai a quale santo votarti per spiegare il fenomeno.. e che una volta capite possono servire da lezione Smile

Un cliente ha realizzato un servizio Windows e ha questo strano problema: il servizio parte una volta si e una volta no se lo esegue come Local System. Se lo esegue come Network Service, mai nessun problema.

Mi manda il repro, lo provo sulla mia macchina Windows 7 a 64 bit ed effettivamente, riproduco il problema.. Stranissimo..I dont know

Il servizio è realizzato in .Net. Non mi sono stati inviati i sorgenti, ma, essendo il Servizio in .Net, grazie a Reflector, è come averli.

Avvio Process Explorer, giusto per avere la certezza che il servizio parta e venga terminato, e provo ad avviare il servizio un po' di volte attraverso il Pannello di Controllo dei Servizi.

Noto all’improvviso che quando il servizio non parte, un attimo dopo viene avviato li servizio “wmiApSrv”. Dopodichè quando al riavvio successivo il servizio si avvia con successo, noto che quando lo interrompo, si interrompe anche “wmiApSrv”.

Servizio-no Veramente strano, ma almeno c’è qualcosa da indagare.

Quando il servizio si interrompe, dopo 30 secondi, che è il timeout predefinito, ritorna il classico errore 1053.

Error “Error 1053: The service did not respond to the start or control request in a timely fashion.“

Questo di solito indica problemi di inizializzazione, e mi dà anche li tempo di attaccare Windbg al processo. 30 secondi sono tanti, ed eventualmente usando la chiave di registry ServicesPipeTimeout, si può aumentare questo timeout così da riuscire efficacemente a debuggare questo problema.

Fate riferimento a questo articolo per ulteriori informazioni sul debug dei Servizi Windows:

824344    How to debug Windows services
http://support.microsoft.com/default.aspx?scid=kb;EN-US;824344

Attaccando Windbg al servizio, nel momento in cui questo è bloccato, ho potuto trovare questo stack:

00000000`0021c9e8 000007fe`feee06d3 ntdll!ZwAlpcSendWaitReceivePort+0xa
00000000`0021c9f0 000007fe`feee0c0d RPCRT4!NdrpClientCall2+0x771
00000000`0021d160 000007fe`fea56846 RPCRT4!NdrClientCall2+0x1d
00000000`0021d190 000007fe`f5fd65ee sechost!StartServiceW+0x22
00000000`0021d1e0 000007fe`f5fd5e6e wmiaprpl!WmiAdapterWrapper::Open+0xa6
00000000`0021d290 000007fe`feca7ad7 wmiaprpl!WmiOpenPerfData+0x8a
00000000`0021d2c0 000007fe`feca7868 ADVAPI32!OpenExtObjectLibrary+0x834
00000000`0021da80 000007fe`feca98e4 ADVAPI32!QueryExtensibleData+0x77c
00000000`0021dd20 00000000`772f5667 ADVAPI32!PerfRegQueryValue+0xe04
00000000`0021e1d0 00000000`7730ffa2 KERNEL32!LocalBaseRegQueryValue+0xffffffff`fffe5627
00000000`0021e350 000007fe`fecac2ed KERNEL32!RegQueryValueExW+0xf2
00000000`0021e3f0 000007fe`f550cd27 ADVAPI32!RegQueryValueExWStub+0x1d
00000000`0021e430 000007fe`f032dbd6 mscorwks!DoNDirectCall__PatchGetThreadCall+0x7b
00000000`0021e4e0 000007fe`f0d1d3a8 mscorlib_ni!DomainNeutralILStubClass.IL_STUB(Microsoft.Win32.SafeHandles.SafeRegistryHandle, System.String, Int32[], Int32 ByRef, Byte[], Int32 ByRef)+0x126
00000000`0021e610 000007fe`f032654d mscorlib_ni!Microsoft.Win32.RegistryKey.InternalGetValue(System.String, System.Object, Boolean, Boolean)+0x9efb38
00000000`0021e6b0 000007fe`efc18976 mscorlib_ni!Microsoft.Win32.RegistryKey.GetValue(System.String)+0x2d
00000000`0021e700 000007fe`efc17b15 System_ni!System.Diagnostics.PerformanceMonitor.GetData(System.String)+0x96
00000000`0021e780 000007fe`efc157f3 System_ni!System.Diagnostics.PerformanceCounterLib.GetPerformanceData(System.String)+0x85
00000000`0021e7e0 000007fe`efc15cd3 System_ni!System.Diagnostics.PerformanceCounterLib.get_CategoryTable()+0xa3
00000000`0021e8f0 000007fe`efc15bf8 System_ni!System.Diagnostics.PerformanceCounterLib.CounterExists(System.String, System.String, Boolean ByRef)+0x23
00000000`0021e960 000007fe`ef6bba21 System_ni!System.Diagnostics.PerformanceCounterLib.CounterExists(System.String, System.String, System.String)+0x58
00000000`0021e9c0 000007ff`001803eb System_ni!System.Diagnostics.PerformanceCounter.Initialize()+0x191
00000000`0021ea50 000007ff`001802a4 CPU_Service!CPU_Service.Service1.InitializeComponent()+0x11b
00000000`0021ea90 000007ff`00180157 CPU_Service!CPU_Service.Service1..ctor()+0x104
00000000`0021eaf0 000007fe`f550d502 CPU_Service!CPU_Service.Service1.Main()+0x37

Come potete notare, in cima allo stack di chiamate, ci sono delle chiamate RPC:

RPCRT4!NdrpClientCall2+0x771

RPCRT4!NdrClientCall2+0x1d

Questo significa generalmente che il processo sta chiamando un altro servizio di sistema per qualche motivo, di solito evidente dalle chiamate precedenti.

sechost!StartServiceW+0x22 
 

Una funzione che si chiama StartServiceW è di solito molto significativa Wink

Anche le due righe precedenti sono molto significative, considerato che il servizio, che abbiamo visto avviarsi dopo il timeout di questo, si chiama wmiApSrv:

wmiaprpl!WmiAdapterWrapper::Open+0xa6

wmiaprpl!WmiOpenPerfData+0x8a
 

Questa libreria è probabilmente il client di quel servizio. O comunque  in qualche modo ne utilizza le funzionalità.

Avere a disposizione il codice sorgente di wmiaprpl!WmiAdapterWrapper::Open, permette di farsi un'idea di cosa stia succedendo.

Più o meno il codice implicato nel problema assomiglia a questo, ed altro non è che una normale routine di avvio di un servizio, dove praticamente si esegue una interrogazione al Service Control Manager per conoscere lo stato di un servizio o se può essere avviato e se questo è stoppato o in pausa lo si avvia (o meglio si “cerca” di avviarlo):

////////////////////////////////////////////////////////////////////////////
// connection to worker service
////////////////////////////////////////////////////////////////////////////
if ( hSCM.GetHANDLE() != NULL )
{
__SmartServiceHANDLE hService;
if ( ( hService = ::OpenServiceW ( hSCM.GetHANDLE(), L"WMIApSrv", SERVICE_QUERY_STATUS | SERVICE_START ) ) != NULL)
{
SERVICE_STATUS s;
if ( ::QueryServiceStatus ( hService, &s ) )
{
if ( s.dwCurrentState == SERVICE_STOPPED ||
s.dwCurrentState == SERVICE_PAUSED )
{
// start service
if ( ! ::StartService ( hService, NULL, NULL ) )
 

In pratica la libreria che viene caricata all’avvio del servizio del cliente, sta cercando di avviare un altro servizio.

C’è da notare però che la chiamata iniziale allo SCM (il Service Control Manager), è stata fatta così:

hSCM = ::OpenSCManager(NULL, NULL, SC_MANAGER_ALL_ACCESS);

Quindi questo spiega perchè il problema avvenga con Local System e non con Network Service.

Local System è un Administrator e quindi può richiedere accesso allo SCM con tutti i privilegi, SC_MANAGER_ALL_ACCESS, mentre Network Service fallisce questa richiesta e quindi tutto il resto del codice viene saltato a piè pari, evitando il problema.

Tornando all’inizio dello stack, possiamo a questo punto intuire il problema:

00000000`0021e9c0 000007ff`001803eb System_ni!System.Diagnostics.PerformanceCounter.Initialize()+0x191

00000000`0021ea50 000007ff`001802a4 CPU_Service!CPU_Service.Service1.InitializeComponent()+0x11b

00000000`0021ea90 000007ff`00180157 CPU_Service!CPU_Service.Service1..ctor()+0x104

00000000`0021eaf0 000007fe`f550d502 CPU_Service!CPU_Service.Service1.Main()+0x37

Il servizio sta caricando i performance counters installati nel sistema, e uno di questi, sta a sua volta cercando di avviare un altro servizio, di cui probabilmente è client. Il tutto, dalla funzione InitializeComponent del servizio .Net.

Il problema quindi è un Deadlock. Praticamente il servizio che è ancora nella primissima fase della sua inizializzazione, non ha ancora riportato il suo stato al Service Control Manager, che quindi è lockato. Il performance counter di WMI cerca di avviare il servizio di appoggio “WMI Performance Adapter” e siccome sta girando come Local System, riesce ad aprire un canale di comunicazione con lo SCM, che però è ancora bloccato dall’avvio del servizio .Net, ed accoda la richiesta di avvio del servizio “wmiApSrv”.

Appena il tempo che il servizio .Net ha per riportare il suo stato allo SCM scade, questo lo termina e può a questo punto soddisfare la richiesta di avvio del servizio “WMI Performance Adapter” arrivata precedentemente e ancora accodata.

La volta successiva che si avvia il servizio, questo trova già il servizio “WMI Performance Adapter” avviato, e quindi riesce a terminare la fase di inizializzazione nei 30 secondi, potendo così proseguire e fare il suo lavoro.

Guardando a questo punto con Reflector la InitializeComponent del servizio .Net, possiamo vedere che effettivamente il servizio sta creando un istanza dei Performance Counters.

private void InitializeComponent()
{
this.PerformanceCounter1 = new PerformanceCounter();
this.PerformanceCounter1.BeginInit();
this.PerformanceCounter1.CategoryName = "Processor";
this.PerformanceCounter1.CounterName = "% Processor Time";
this.PerformanceCounter1.InstanceName = "_Total";
this.CanPauseAndContinue = true;
this.CanShutdown = true;
this.ServiceName = "CPUUtilization";
this.PerformanceCounter1.EndInit();
}
Questa operazione è già di per se molto costosa, ma nel caso specifico c’è anche il problema che un Performance Counter, tra le varie attività che fa durante la sua inizializzazione, esegue addirittura l’avvio di un servizio esterno di appoggio. Cosa che abbiamo visto porta inesorabolmente ad un Deadlock, nel caso il servizio stia girando come Local System che ha i privilegi necessari per eseguire una tale operazione.

Come per la DLLMain delle librerie, la InitializeComponent dei servizi .Net deve essere il più “atomica” possibile, in quanto l’architettura dei Servizi Windows, prevede un protocollo di comunicazione tra il servizio e lo SCM che ha sequenza di operazioni e tempi predefiniti da rispettare, in base ai quali lo SCM prende delle decisioni, dolorose a volte, come l’abbattere un servizio, ma che servono a favorire la stabilità del Sistema Operativo. Un servizio bloccato, che non può andare avanti e quindi perseguire il suo scopo, o peggio ancora lo SCM bloccato, che non può più rispondere e soddisfare altre richieste da parte degli altri servizi, magari già attivi e funzionanti, sono sicuramente condizioni da evitare.

La soluzione: in questo caso (come in tutti quelli che hanno sequenze di inizializzazione lente), nella InitializeComponent, è opportuno creare un thread esterno alla InitilizeComponent stessa, e da lì effettuare l’inizializzazione dei Performance Counters installati nel sistema. Questo permetterà al servizio di riportare il suo stato allo SCM nel tempo previsto ed eviterà il deadlock con l’avvio dell’altro servizio che è la causa principale di questo problema.

Alla prossima!

Mario Raccagni
Senior Support Engineer
Platform Development Support Team