[NT Debug] Crashende comm driver

[farlane]

Voor een klant (in een ver land) hebben we niet lang geleden een bediening van een installatie geport van Win95 naar WinNT.

Het betreft een SCADA systeem dat dmv eigen ontwikkelde drivers met een bult Industrieele PC's communiceert, via Ethernet + TCP/IP.

Nu vertelt DrWatson ons dat er iets niet goed zit in de driver:

Application exception occurred:
App: (pid=286)
When: 5/10/2002 @ 13:7:53.779
Exception number: c0000005 (access violation)

We hebben op dit moment geen mogelijkheid om een debugger aan het systeem te hangen, dus zal ik op een of andere manier uit de log van DrWatson wat meer info moeten halen:

*----> Task List <----*
....
500 comcon.exe
482 comcon.exe
208 comcon.exe
86 comcon.exe
286 comcon.exe
..

Zoals u ziet (o.a.) PID 286 is comcon.exe. Deze dll laadt de eigenlijke comm driver, comcon.dll. ( Ik verwacht dat comcon.exe stubs bevat voor de functies die het SCADA importeert, en voor de functies die comcon.dll exporteert de aanroepen forward naar comcon.dll )

Even verder in de log:

State Dump for Thread Id 0xd4

eax=00000067 ebx=0012f8e4 ecx=000000ff edx=0000000e esi=0012ef24 edi=0012ee94
eip=5a0d1a00 esp=0012ee28 ebp=51003500 iopl=0 nv up ei pl zr na po nc
cs=001b ss=0023 ds=0023 es=0023 fs=0038 gs=0000 efl=00000246


function: <nosymbols>

*----> Stack Back Trace <----*

FramePtr ReturnAd Param#1 Param#2 Param#3 Param#4 Function Name
0012ee24 10007a00 003d5dc0 0013cd30 000000ff 0012ef08 <nosymbols>
51003500 00000000 00000000 00000000 00000000 00000000 comcon!cache

Omdat er op dit moment wel een debug build draait, kan ik in de call stack zien dat hij naar een functie comcon!cache springt. Het toeval wil echter dat dit geen functie is, maar een variabele!

Mijn vragen zijn:

- Is er een manier om erachter te komen of een thread-id bij een bepaald proces hoort? ( Achteraf dus )
- Kan het zijn dat door een of andere oorzaak de stack back trace wordt vermoerd door de access violation?
- Of anders, wat kan een oorzaak van zijn van het feit dat het ding een functie wil aanroepen op een plek waar data staat?
- Is er een manier om meer info over de crash te weten te komen, zonder er met een debugger aan te gaan hangen? Ik heb de userdump ook geprobeerd te bekijken, maar DrWatson wil me niet meer info geven. ( Misschien doordat de userdump corrupt is )
- Kortom ..... help

btw Ik heb het systeem in house gesimuleerd, maar ik heb niet de beschikking over pak um beet 20 IPC's, dus dat was behelpen. Het ding wilde op mijn test-systeem echter niet platgaan. ( darnit ).

[farlane]

*Toch maar ff kicke dan*

[Verwijderd]

Op dinsdag 28 mei 2002 19:15 schreef farlane het volgende:
- Is er een manier om meer info over de crash te weten te komen, zonder er met een debugger aan te gaan hangen? Ik heb de userdump ook geprobeerd te bekijken, maar DrWatson wil me niet meer info geven. ( Misschien doordat de userdump corrupt is )

De debugging tools scoren bij microsoft (http://www.microsoft.com/ddk/debugging/) en symbols diebij de release van je os horen ( http://www.microsoft.com/ddk/debugging/symbols.asp )

Windbg starten, bij File->Symbol file path de directory in waar de symbols geinstaleerd staan (waarschijnlijk c:\winnt\symbols).

In de 4.0 beta versie van de tools kan je ook SRV*c:\websymbols*http://msdl.microsoft.com/download/symbols invullen waarna de debugger de informatie die ie nodig heeft zelf zal downloaden bij microsoft en deze in c:\websymbols plaatsen.

Vervolgens vullen we bij File ->image file path het path in waar windows geinstaleerd staat. (C:\winnt waarschijnlijk)

waarna we File->Open Crashdump onze crashdump kunnen openen.Na het openen zal windbg automatish een korte analyse geven van de dump. deze is later nog es op te roepen door !kanalyzebugcheck

!drivers geeft een overzicht van alle geladen drivers in het geheugen op het moment van de crash met de datum/tijd dat ze gecreeerd zijn.

!analyze -v Geeft een uitgebreidere analyze van de crash.

!process Laat informatie zien van het active process toen de BSOD plaatsvond. Dit is alleen mogelijk met kernel/fulldumps.

Stukje text ooit es gemaakt aan de hand van 'n lezing op teched verleden jaar. (en nu schaamteloos uit 'n ander topic ge cut'n'paste)

[farlane]

Op woensdag 29 mei 2002 23:19 schreef Yarvieh een schaamteloos stukje

Thanx voor de info. Weet je zo of het ook mogelijk is om lokaal op mijn Win2k bak die NT userdump door te pluizen (als ik de symbols van NT gebruik) ?

Het 'probleem' is namelijk dat ik met pc anywhere via een zeer onbetrouwbare telefoonlijn van +/- 32kbps werk. Je begrijpt dat symbols kopieren naar het remote systeem dan niet echt een optie is. De userdump ophalen is al een crime.

[Verwijderd]

Op donderdag 30 mei 2002 14:27 schreef farlane het volgende:
Thanx voor de info. Weet je zo of het ook mogelijk is om lokaal op mijn Win2k bak die NT userdump door te pluizen (als ik de symbols van NT gebruik) ?

Moet lukken volgens mij zolang ie maar bij z'n symbols kan en als je die instelt op autodownload komt 't wel goed gok ik.

[farlane]

Misschien nog wel aardig om te vertellen hoe dit verhaal afloopt ....

Met een collega ben ik ter plekke ( Saudi Arabie ) aan het debuggen gegaan, en zoals ik verwachtte betrof het een pointerfout die de stack smashde.

Heel vervelend want ook als de debugger meeloopt met het process, geeft deze na de crash ook niet de goede callstack weer, omdat de return addressen worden vermoerd. ( Is het niet mogelijk om een kopie van de callstack te laten maken door de debugger ? )

Nu is het zo dat de MS C compiler als extensie ook exceptions ondersteunt. Je hebt dan ook de mogelijkheid om access violations te onderscheppen, en vervolgens na het loggen van een module en functienaam de exception door te throwen naar het systeem.

Deze methode heb ik gebruikt, en het kostte me al met al 1,5 dagen om debug te vinden, en 1 minuut om hem op te lossen.

Wat ik me afvraag is, wat is de reden dat men die callstack zo opbouwt, dat bij het overschrijven van een lokale buffer ook de return adressen van de functies worden vermoerd? Is er een compilergoeroe aanwezig die me dat kan uitleggen?

[Verwijderd]

't is idd netter als je locale vars en je callstack ver bij elkaar uit de buurt zou zetten echter je hebt maaar 1 stackpointer wat dat nogal in de wegstaat

[matthijsln]

farlane:
Omdat er op dit moment wel een debug build draait, kan ik in de call stack zien dat hij naar een functie comcon!cache springt. Het toeval wil echter dat dit geen functie is, maar een variabele!

Ik ben niet zo bekend met dr. Watson logs, maar het lijkt me waarschijnlijker dat je app een keer een pointer naar die comcon!cache variabele de stack op heeft gepusht (hetzij als parameter, tijdelijke variabele of als automatische variabele) dan dat je app naar die variabele heeft geprobeerd te springen.

in een later bericht van farlane:
Nu is het zo dat de MS C compiler als extensie ook exceptions ondersteunt. Je hebt dan ook de mogelijkheid om access violations te onderscheppen, en vervolgens na het loggen van een module en functienaam de exception door te throwen naar het systeem.

Deze methode heb ik gebruikt, en het kostte me al met al 1,5 dagen om debug te vinden, en 1 minuut om hem op te lossen.

Kon je niet met een debugger uitvinden waar die access violation optrad? Daar heb je geen call stack voor nodig.

Wat ik me afvraag is, wat is de reden dat men die callstack zo opbouwt, dat bij het overschrijven van een lokale buffer ook de return adressen van de functies worden vermoerd? Is er een compilergoeroe aanwezig die me dat kan uitleggen?

Dit gebeurt met verkeerd gebruik van stackvariabelen. Dus als je een array "int a[10]" op de stack hebt en je schrijft op a[10] of verder ben je je stack aan het thrashen inclusief de return addressen die daar op staan. Op die manier werken ook de beruchte buffer overflows.

in een nog later bericht van farlane:
't is idd netter als je locale vars en je callstack ver bij elkaar uit de buurt zou zetten echter je hebt maaar 1 stackpointer wat dat nogal in de wegstaat

Netter? Als je geen bugs in je programma hebt maakt het niet uit hoe ver ze van elkaar staan. Als je buiten het gealloceerde geheugen schrijft heb je een bug. Schrijf je niet returnaddressen over dan wel wat andere data.

[Verwijderd]

farlane schreef op 28 mei 2002 @ 19:15:
...
Omdat er op dit moment wel een debug build draait, kan ik in de call stack zien dat hij naar een functie comcon!cache springt).

Even een waarschuwing tegen debug builds. Ik ben er zelf tegenaan gelopen, en het heeft me heel wat moeite gekost om eruit te komen. Wat is nl. het geval? Meneer Microsoft heeft in al zijn wijsheid kennelijk besloten dat debug builds nooit heel erg lang zullen draaien. Debug builds houden nl. bij hoe vaak je een "new" doet (ik heb het hier over Visual C++). Elke keer als je dat doet wordt een counter ge-decrement. Op het moment dat die counter op 0 staat volgt een user breakpoint, wat als gevolg heeft dat Dr. Watson om de hoek komt kijken. De bedoeling van dit geheel is, dat je als user de initiele counterwaarde kunt zetten, zodat je zelf bepaalt na hoeveel new's je breakpoint aktief wordt. Heel leuk.

Echter: als je die functie niet gebruikt, wordt die counter initieel op -1 gezet, hetgeen overeenkomt met de maximale waarde (ik geloof dat 't een long int is). Echter, als je programma zeer lang loopt, en je doet regelmatig een "new", dan zal die counter uiteindelijk ooit weleens 0 worden. Gevolg: Hallo Dr. Watson!

Zoals gezegd ben ik er zelf tegenaan gelopen doordat een klant klaagde dat zijn programma na een maand of drie crashde (ja, zo lang liep het continu!). Het geval was dat we juist vanwege mogelijke foutjes daar een debug build hadden neergezet, om kijken wat er eventueel mis ging. In dit geval was de debug build zelf juist de oorzaak van de crash! Hetzelfde programma in release build loopt nu al meer dan een jaar goed!

't Is maar effe dat jullie het weten...

[farlane]

matthijsln schreef op 30 augustus 2002 @ 15:40:
[...]

Ik ben niet zo bekend met dr. Watson logs, maar het lijkt me waarschijnlijker dat je app een keer een pointer naar die comcon!cache variabele de stack op heeft gepusht (hetzij als parameter, tijdelijke variabele of als automatische variabele) dan dat je app naar die variabele heeft geprobeerd te springen.

Beide dus. Je return adres ligt ergens midden in een databuffer. Dus of het return adres was vernaggeld, of die pointer werd aangezien voor een return adres.

Kon je niet met een debugger uitvinden waar die access violation optrad? Daar heb je geen call stack voor nodig.

Het was een installatie dat al vier jaar draaide, zonder problemen. Plotseling treden deze problemen op, zonder dat ik inhouse de situatie kan nabootsen. Ik heb er een debugger terplekke aangehad, maar zoals gezegd geeft deze ( en dus ook DrWatson ) geen zinnige informatie _nadat_ de stack getrashed is.

Welke functionaliteit van de debugger had ik moeten gebruiken volgens jou om deze fout te vinden?

Dit gebeurt met verkeerd gebruik van stackvariabelen. Dus als je een array "int a[10]" op de stack hebt en je schrijft op a[10] of verder ben je je stack aan het thrashen inclusief de return addressen die daar op staan. Op die manier werken ook de beruchte buffer overflows.

Ik ben bekend met de reden waarom het optreedt. Mijn vraag was echter niet waarom het optreedt, maar de reden dat men de constructie zo maakt dat de fout _kan_ optreden.

Netter? Als je geen bugs in je programma hebt maakt het niet uit hoe ver ze van elkaar staan. Als je buiten het gealloceerde geheugen schrijft heb je een bug. Schrijf je niet returnaddressen over dan wel wat andere data.

Kip en ei? Stel je hebt een dergelijke bug, maar hoe vind je die? Een oplossing zou zijn om het geheugen van je lokale variabelen uit de buurt van je return adres te houden. Maar dit is niet mooi volgens jou omdat je geen bugs mag hebben? ( Overigens was dit niet een opmerking van mij, maar van Yarvieh. )

[matthijsln]

farlane schreef op 30 augustus 2002 @ 21:18:
Welke functionaliteit van de debugger had ik moeten gebruiken volgens jou om deze fout te vinden?

Het dr. Watson log geeft aan eip=5a0d1a00. Dit is het adres van de instructie die de av veroorzaakt. Dit is volgens mij hetzelfde adres dat jij in je exception handler krijgt. Ik snap niet waarom je met die exception handler wel erachter kan komen waar de fout zit en met het log niet. Hoe kom je in die handler dan aan de module en functienaam? Met het adres 5a0d1a00 en een mapfile zou dat evengoed mogelijk moeten zijn.

Heb je misschien het complete log nog inclusief data rond eip=5a0d1a00? Dat zou misschien wat verduidelijken.

Ik ben bekend met de reden waarom het optreedt. Mijn vraag was echter niet waarom het optreedt, maar de reden dat men de constructie zo maakt dat de fout _kan_ optreden.

Dus waarom lokale variabelen en return adressen op dezelfde stack staan? Een extra stack erbij kost meer. En wat is het voordeel van het apart houden? Volgens mij niet dat je beter bugs kunt vinden.

Kip en ei? Stel je hebt een dergelijke bug, maar hoe vind je die?
Een oplossing zou zijn om het geheugen van je lokale variabelen uit de buurt van je return adres te houden. Maar dit is niet mooi volgens jou omdat je geen bugs mag hebben?

Met deze oplossing verdwijnt je bug niet maar creeer je een ander probleem: dan wordt andere data dan returnadressen overschreven. Misschien merk je niet eens dat je ergens geheugen overschrijft. Waarom is dit beter? Is het nu makkelijker te vinden waar de fout zit?

( Overigens was dit niet een opmerking van mij, maar van Yarvieh. )

Excuses daarvoor.

[farlane]

matthijsln schreef op 31 augustus 2002 @ 12:23:
[...]
Het dr. Watson log geeft aan eip=5a0d1a00. Dit is het adres van de instructie die de av veroorzaakt. Dit is volgens mij hetzelfde adres dat jij in je exception handler krijgt. Ik snap niet waarom je met die exception handler wel erachter kan komen waar de fout zit en met het log niet. Hoe kom je in die handler dan aan de module en functienaam? Met het adres 5a0d1a00 en een mapfile zou dat evengoed mogelijk moeten zijn.

Heb je misschien het complete log nog inclusief data rond eip=5a0d1a00? Dat zou misschien wat verduidelijken.

Nee helaas heb ik die logs inmiddels getrashed ( uit vreugde dat ik de bug gevonden had denk ik )

Module en functienaam zijn macros die de compiler kent ( __FILE__ en __FUNCTION__ meende ik )

Idd zou die ip in de mapfile moeten aangeven welke functie het betreft.

Dus waarom lokale variabelen en return adressen op dezelfde stack staan? Een extra stack erbij kost meer. En wat is het voordeel van het apart houden? Volgens mij niet dat je beter bugs kunt vinden.

Volgens mij wel. Een niet corrupte callstack zou me heel wat sneller in de goede richting hebben gestuurd denk ik, aangezien DrWatson dan wel een geldige callstack had laten zien.

Met deze oplossing verdwijnt je bug niet maar creeer je een ander probleem: dan wordt andere data dan returnadressen overschreven. Misschien merk je niet eens dat je ergens geheugen overschrijft. Waarom is dit beter? Is het nu makkelijker te vinden waar de fout zit?

Ik denk het wel. Je return addressen blijven onaangetast in dit geval. Het overschrijven van buffers kan dan in principe alleen je variabelen nog trashen, maar dit probleem heb je nu ook.

Excuses daarvoor.

Nu ja, hier is niet echt excuses voor nodig.


Ik meende btw een document + code te hebben gevonden van een meneer die iets had bedacht om dit type fouten iets minder wazig te maken, maar ik kan het niet terugvinden. Volgens mij wilde hij het return address en de lokale vars omdraaien in het stackframe en nog andere dingetjes. Ik zoek nog ff ...

[matthijsln]

farlane schreef op 31 augustus 2002 @ 18:50:
Module en functienaam zijn macros die de compiler kent ( __FILE__ en __FUNCTION__ meende ik )

Dus je hebt niet SetUnhandledExceptionFilter() gebruikt maar om elke functie-body
zoiets als "__try { .... } __catch(GetExceptionCode() == EXCEPTION_ACCESS_VIOLATION) { ...}" gezet? Want als je die macros in de exception handler functie gezet door SetUnhandledExceptionFilter() gebruikt krijg je de naam van de exception-handler functie in plaats van die van de functie met de bug.

Volgens mij wel. Een niet corrupte callstack zou me heel wat sneller in de goede richting hebben gestuurd denk ik, aangezien DrWatson dan wel een geldige callstack had laten zien.
[...]
Ik denk het wel. Je return addressen blijven onaangetast in dit geval. Het overschrijven van buffers kan dan in principe alleen je variabelen nog trashen, maar dit probleem heb je nu ook.

Je hebt dan wel een intacte call stack en ik geef toe dat dan inderdaad makkelijker de fout te vinden is.

Het is denk ik echter niet zo'n voordeel om de kosten voor een extra stack erbij te rechtvaardigen (de performance impact zou enorm zijn met de huidige machine architecturen). Met de huidige situatie is ook wel te vinden waar de fout zit, al moet je wel wat meer moeite doen.

[farlane]

Ik had zoiets gedaan van ( foutje in die macronamen hierboven ):

code:

__try
{
    .. code hier ..
}
__except( handle_exception( GetExceptionCode ( ), __FILE__, __LINE__ ) ){ };

en verder ...

code:

int handle_exception( int exception, const char * module ,int line )
{
    char writebuff[100];

    static bool reentry = false;

    if( ! reentry )
    {
        reentry = true;
        _snprintf( writebuff,100,"EXCEPTION handler called @ line %d module : %s",line ,module );
        write_log( writebuff,true );

        if( exception == STATUS_ACCESS_VIOLATION )
        {
            _snprintf( writebuff,100,"AV handler called @ line %d module : %s",line ,module );
            write_log( writebuff,true );
        }
    }

    reentry = false;

    return EXCEPTION_CONTINUE_SEARCH;
}

Die reentry zorgt ervoor dat een access violation in je logfunctie ( als je je filehandle hebt overschreven bijvoorbeeld ) niet de hele boel verstiert.

Misschien is zo'n aangepaste stackframe iets voor een debug build ?