NAME NOT FOUND – egy furcsa fájl hozzáférési hiba

A héten egy rejtélyes fájl hozzáférési hibába futottam bele: a fájl látszólag megvolt, a jogosultságok és az egyéb alapvető dolgok első ránézésre rendben voltak, azonban az alkalmazás mégse találta meg a kért fájlt. A hiba megértéséhez ismernünk kell egy picit az alkalmazás (ImageDistributer a neve) architektúráját. Ez egy saját alkalmazás, amit a laborokban arra használunk, hogy a nagy méretű virtuális gépeket szétterítsük a kliensekre. Két fő részből áll, .NET-es komponensek, amiket mi írtunk, és egy C-ben írt, nyílt forráskódú, UFTP nevű multicast másoló program.

image

A laborfelelős gépén van egy WinFormos GUI, a szerveren pedig két komponens fut. Az egyik az ImageDistributer szolgáltatás, ahol a fő logika van megvalósítva, a másik pedig az UFTP egyik komponense, ami a szétmásolandó fájlt küldi szét a labor klienseknek multicast csomagokként (ez eredetileg egy parancssori program volt, de készítettünk egy DLL-t belőle, amit PInvoke segítségével hív a szolgáltatás). A labor klienseken fut az UFTP másik része, ami figyel egy adott porton, és fogadja a fájl darabjait. Az ImageDistributer szolgáltatás felelős azért, hogy bekapcsolja a klienseket, lekérdezze az állapotukat WMI segítségével, a másolás végén pedig a végleges helyükre mozgassa a fájlokat, és beállítsa a megfelelő jogosultságokat.

A Vistára való átálláskor volt pár kisebb hiba, de ezek kijavítása után nagyjából jól ment az alkalmazás. A múlt héten a többiek többször is sikeresen másoltak  szét virtuális gépeket, ezért lepődtem meg, hogy most, amikor csináltam még egy utolsó tesztet, a másolás hibára futott.

image

A jobb alsó részen lévő üzenetekből látszik, hogy a test-image könyvtárában lévő egy nagyobb fájlt az uftp átküldi sikeresen, a kisebb fájlokat a szolgáltatás SMB-vel átmásolja az egyes gépekre, azonban amikor a nagy fájlt át akarja mozgatni a végleges helyére, nem találja meg az ideiglenes helyen. A fájl természetesen ott volt, és el lehetett rendesen érni, úgyhogy valószínűleg valami más hiba volt az alsóbb rétegekben. Az alkalmazás korábbi hibakereséseinél már kiderült, hogy mivel többféle technológia keveredik (háttérben futó windowsos szolgáltatás nyújt egy Windows Communication Foundation (WCF) szolgáltatást, ami egy nem menedzselt DLL-t hív, ami aszinkron elkezd egy saját multicast protokollt:), csak részletes trace napló írásával lehet kideríteni, hogy mi is történik. Erre az MS Enterprise Library Logging komponensét használjuk. Be is kapcsoltam a részletes naplózást, de túl sokkal okosabb nem lettem:

—————————————-
2009.09.22. 11:21:14:
Category: Info, RecursiveCopyFolders, CopyImage
Title: Info
Message: Unicast copied IBMLaborok\teszt-image\vmware-2.log (72 kB) to itec1
Severity: Information
—————————————-
2009.09.22. 11:21:14:
Category: Info, RecursiveCopyFolders, CopyImage
Title: Info
Message: Source file "\\itec1\c$\temp\uftp\Windows XP Professional-000001-s001.vmdk" not found, multicast copy was unsuccessful on host itec1.
Severity: Information
—————————————-
2009.09.22. 11:21:14:
Category: RecursiveCopyFolders, CopyImage
Title: TracerExit
Message: End Trace: Activity ‘814d6f3a-4604-475f-8ab3-7ff6154b386b’ in method ‘ImageDistributer.Service.ImageDistributerService.RecursiveCopyFolders’ at 17877593865 ticks (elapsed time: 6,018 seconds)
Severity: Stop
—————————————-

A hiba előtt és mögött nem volt semmi más hiba. Az első üzenet azt mondja, hogy a vmware-2.log-ot még sikeresen átmásolta, a “Windows XP Professional-000001-s001.vmdk” fájlt nem találta meg, majd utána a RecursiveCopyFolders metódus végére ér.

Fájl hozzáférési hibáknál az következő amit érdemes megnézni, az az, hogy mit lát a Sysinternals Process Monitor a fájlműveletből:

image

Az alsóbb szintek is a jó elérési utat használják, és itt se jogosultság problémát kapunk vissza, hanem azt, hogy nincs ott a fájl.

A következő ötletem az volt, hogy hátha a szóköz és a hosszú fájlnév a gond, de a fájlt átnevezve a.vmdk-ra és újra elindítva a másolást, ugyanaz lett az eredmény:(

A következő ötletem az volt, hogy próbáljuk reprodukálni a jelenséget egy egyszerű kis teszt programmal: egy rövid C#-os kód a File.Exists() metódus segítségével ellenőrzi, hogy ott van-e a fájl (a szolgáltatás is a File.Exists hívást használja). Az eredmény az lett, hogy ugyanazon az elérési úton, ugyanannak a felhasználónak a nevében futtatva, ugyanarról a gépről, ugyanúgy 32 bites folyamatként a teszt program megtalálja a fájlt. Akkor biztos valamit máshogy hívnak meg! Hát sajnos nem:

image

Process Monitorban látszik, hogy ugyanazt a hívást használják, ugyanazokkal a paraméterekkel. Ez sem jött be, kezdtem kifogyni az ötletekből:)

A következő lépés az volt, hogy megnézzem, hogy a kliens gépen mit látunk a kérésekből. Ehhez a Local Security Policy-ben a naplózási házirendnél be kell kapcsolni a sikeres és sikertelen műveletek naplózását az Object access résznél, majd az adott könyvtár tulajdonságainál a biztonság fül Auditing részében be kell állítani, hogy naplózzon minden hozzáférést.

image

Így megismételve a másolást, a kliens eseménynaplójában a Security rész a következő bekezdéseket tartalmazta (van egy jó pár egy egyszerű fájlművelethez is, végig kell lépkedni rajtuk szép sorban. Arra figyeljünk, hogy ne a SearchProtocolHost.exe kéréseit nézzük):

image

A File Share művelet az első hozzáférés a hálózati megosztáshoz, utána a Logon-nál hitelesíti magát a távoli folyamat, és utána következnek a fájl hozzáférések a C:\temp\uftp\a.vmdk fájlhoz. Így néz ki pl. egy kérés:

image

A főbb adat az a.vmdk-ra vonatkozó kérésekből (mindegyik sikeres volt, nem volt jogosultságbeli probléma):

Folyamat (PID) Felhasználó Leíró Hozzáférési maszk Szöveg
System (4) ImageDistributer 0x1220 DELETE, ReadAttributes A handle to an object was requested.
System (4) ImageDistributer 0x1220 ReadAttributes An attempt was made to access an object.
System (4) ImageDistributer 0x1220 DELETE An attempt was made to access an object.
System (4) ImageDistributer 0x1220   An object was deleted.
System (4) ImageDistributer 0x1220   The handle to an object was closed.
uftpd.exe (0xbf0) SYSTEM 0x10c WriteData, AppendData… A handle to an object was requested.
uftpd.exe (0xbf0) SYSTEM 0x10c WriteData, AppendData An attempt was made to access an object.
uftpd.exe (0xbf0) SYSTEM 0x10c   The handle to an object was closed.

Ebből már látszik, hogy hol van a gond. Az uftpd.exe még írni akart a fájlba, és az ImageDistributer ez előtt próbálta elérni a fájlt (a hálózati hozzáférések a System folyamaton keresztül látszanak, de a megszemélyesítés miatt a felhasználó már az ImageDistributer nevű tartományi felhasználó).

Így most már érthető volt, hogy a többieknek miért nem jelentkezett a probléma múlt héten. Ők egy teljes virtuális gépet másoltak, amiben sok nagy fájl volt. Ezeket egyenként másolja szét az uftp, és mire az utolsóval végzett, addigra az elsőt már rég elengedte, azt utána át tudta mozgatni a szolgáltatás a végleges helyre. A hipotézist gyorsan ellenőriztem is, az a.vmdk-t odamásoltam még egyszer a teszt könyvtárba. Így gond nélkül lement a másolás.

Újabb furcsa jelenség magyarázatára derült fény a megfelelő naplózási módszerek használatával:-)

Advertisements
Kategória: Opre | Közvetlen link a könyvjelzőhöz.

Vélemény, hozzászólás?

Adatok megadása vagy bejelentkezés valamelyik ikonnal:

WordPress.com Logo

Hozzászólhat a WordPress.com felhasználói fiók használatával. Kilépés / Módosítás )

Twitter kép

Hozzászólhat a Twitter felhasználói fiók használatával. Kilépés / Módosítás )

Facebook kép

Hozzászólhat a Facebook felhasználói fiók használatával. Kilépés / Módosítás )

Google+ kép

Hozzászólhat a Google+ felhasználói fiók használatával. Kilépés / Módosítás )

Kapcsolódás: %s