VM auf Stand vor 2 Jahren zurück

[oftecs]

Hi,

ein Kunde hat ein wirklich außergewöhnliches Problem. Er hat eine VM mit WIndows 2000 Professionell installiert.

Hier hat er eine 8 GB Festplatte. Die Maschiene läuft seit zwei Jahren - es wurde nie mit Snapshots gearbeitet. Gestern morgen hat er die Virtuelle Maschiene heruntergefahren und wieder gestartet und auf einmal war der Stand von vor 2 jahren da. Alle Daten gelöscht und auch die Systemprotokolle sind von vor 2 Jahren.
Ich habe erst dran gedacht, er hätte irgendwas mit Snapshots gemacht, konnte aber in den VI Ereignissen nichts finden, das er Snapshots erstellt hat.

Hat jemand eine Idee was man da machen kann, das man an die ALten Daten kommt? Oder wenigstens herausfindet, was da passiert ist ?

[Dayworker]

Ganz wichtig, die VM vorerst nicht mehr starten.
Poste mal die komplette Dateiliste der VM mit sichtbaren Dateigrössen. Vielleicht kann unser *.vmdk-Papst namens Ulli ja noch was retten.

[oftecs]

habe den komletten ordner auch auf eine usb festplatte kopiert, damit man ein backup hat.

Die VM heißt build02

folgende dateien liegen in dem ordner:

build02.vmdk
build02.vmsd
build02.vmx
build02.vmxf
build02_1.vmdk
build02_1-flat.vmdk
build02_2.vmdk
build02_02-flat.vmdk
build02-flat.vmdk
delphi_5_um.nvram

und die logs:
vmware
vmware-21 - 26

die vmx datei hat folgenden inhalt:

#!/usr/bin/vmware
config.version = "8"
virtualHW.version = "4"
floppy0.present = "false"
nvram = "delphi_5_um.nvram"
powerType.powerOff = "soft"
powerType.powerOn = "default"
powerType.suspend = "soft"
powerType.reset = "soft"

displayName = "Build"
extendedConfigFile = "build02.vmxf"
svga.maxWidth = "1280"
svga.maxHeight = "1024"
svga.vramSize = "5242880"

scsi0.present = "true"
scsi0.sharedBus = "none"
memsize = "512"
scsi0:0.present = "true"
scsi0:0.fileName = "build02.vmdk"
scsi0:0.deviceType = "scsi-hardDisk"
scsi0:1.present = "true"
scsi0:1.fileName = "build02_1.vmdk"
scsi0:1.deviceType = "scsi-hardDisk"
scsi0:2.present = "true"
scsi0:2.fileName = "build02_2.vmdk"
scsi0:2.deviceType = "scsi-hardDisk"
ide1:0.present = "true"
ide1:0.fileName = "/dev/cdrom"
ide1:0.deviceType = "atapi-cdrom"
ethernet0.present = "true"
ethernet0.wakeOnPcktRcv = "false"
ethernet0.networkName = "VM Network"
ethernet0.addressType = "generated"
ethernet1.present = "true"
ethernet1.wakeOnPcktRcv = "false"
ethernet1.networkName = "VM Network"
ethernet1.addressType = "generated"
guestOS = "win2000pro"
uuid.location = "56 4d 7e 68 5b fb 27 45-a6 41 e3 85 31 25 ef 91"
sched.cpu.min = "0"
sched.cpu.units = "mhz"
sched.cpu.shares = "normal"
sched.mem.minsize = "0"
sched.mem.max = "512"
sched.mem.shares = "normal"

checkpoint.vmState = ""
ethernet0.generatedAddressOffset = "0"
ethernet1.generatedAddressOffset = "10"
gui.exitOnCLIHLT = "true"
priority.grabbed = "normal"
priority.ungrabbed = "normal"
sched.swap.derivedName = "/vmfs/volumes/45cc9449-ef5827fd-32dc-0018fe7d9618/build02/build02-e1ddb788.vswp"
scsi0:0.redo = ""
scsi0:1.redo = ""
scsi0:2.redo = ""
tools.syncTime = "FALSE"
vmware.tools.requiredversion = "7201"

ethernet0.generatedAddress = "00:0c:29:25:ef:91"
ethernet1.generatedAddress = "00:0c:29:25:ef:9b"
uuid.bios = "56 4d 7e 68 5b fb 27 45-a6 41 e3 85 31 25 ef 91"

virtualHW.productCompatibility = "hosted"
tools.upgrade.policy = "manual"
hostCPUID.0 = "0000000a756e65476c65746e49656e69"
guestCPUID.0 = "0000000a756e65476c65746e49656e69"
userCPUID.0 = "0000000a756e65476c65746e49656e69"
hostCPUID.1 = "000006f6000208000004e3bdbfebfbff"
guestCPUID.1 = "000006f800010800000022010febfbff"
userCPUID.1 = "000006f6000208000004e3bdbfebfbff"
hostCPUID.80000001 = "00000000000000000000000120000000"
guestCPUID.80000001 = "00000000000000000000000120000000"
userCPUID.80000001 = "00000000000000000000000120000000"
evcCompatibilityMode = "FALSE"

und die vmxf diesen inhalt

<?xml version="1.0"?>
<Foundry version="1">
<VM>
<VMId type="string">52 54 13 ce 2b 8a 80 80-37 bc 6c 44 1a ca 9f 6a</VMId>
<ClientMetaData>
<clientMetaDataAttributes/>
<HistoryEventList/></ClientMetaData>
<vmxPathName type="string">build02.vmx</vmxPathName></VM></Foundry>

ich bedanke mic hshconmal für die Hilfe.

[kastlr]

Hallo,

mal ne gemeine Frage, glaubst du deinem Kunden?

Ich würde in jedem Fall alle zur Systemanalyse erforderlichen Log Files einsammeln.
Sofern dein Kunde auch noch VC nutzt, müssten dessen Logs auch eingesammelt werden.
Mit der VIC kann man das Datensammeln von VC und ESX sehr einfach durchführen.
File -> Export -> Export Diagnostic Data

Danach würde ich mir die vmware.log Files der VM ansehen, ob dort immer noch die selbe vmdk Datei verwendet wird wie vor dem Shutdown & Restart der VM.
Die Files geben dir nämlich eine schöne Übersicht aller VMware Aktivitäten und der ursprünglichen vmx Konfiguration, sofern diese "versehentlich" verändert worden ist.

Viel Erfolg
Ralf

[Tschoergez]

so, wie sich das anhört, waren die virtuellen Platten im modus independend nonpersistent. Also ohne manuellen snapshot, aber dafür mit genau einem automatischen, der beim starten erstellt und beim stoppen wieder zurückgesetzt wird.

aber wie Ralf schon geschrieben hat, das müssten Dir die Logfiles eigentlich sagen.

viele grüße,
jörg

[continuum]

so, wie sich das anhört, waren die virtuellen Platten im modus independend nonpersistent. Also ohne manuellen snapshot, aber dafür mit genau einem automatischen, der beim starten erstellt und beim stoppen wieder zurückgesetzt wird.

das wuerde ja bedeuten dass die VM 2 Jahre lang aktiv gewesen waere ...

komische geschichte - da fehlt noch ein wichtiges detail ...

[continuum]

Kannst du bitte mal alle alten vmware.logs zippen und bei ifile.it hochladen ?

Das will ich mir doch mal angucken - derzeit einzig plausible Erklaerung fuer mich ist : kunde luegt

[McStarfighter]

Kunden lügen doch nicht, sie haben nur eine andere Sicht der Dinge ...

[mangold]

so, wie sich das anhört, waren die virtuellen Platten im modus independend nonpersistent. Also ohne manuellen snapshot, aber dafür mit genau einem automatischen, der beim starten erstellt und beim stoppen wieder zurückgesetzt wird.

das wuerde ja bedeuten dass die VM 2 Jahre lang aktiv gewesen waere ...

komische geschichte - da fehlt noch ein wichtiges detail ...

nicht wenn sie nur rebootet wurde. Der original Zustand wird ja erst bei "power off" wieder hergestellt.

Nonpersistent – The disk appears to operate normally, but whenever the
virtual machine is powered off or reverted to a snapshot, the contents of
the disk return to their original state. All later changes are discarded.

[continuum]

Stimmt - finde ich aber immer noch ungewoehnlich das eine VM 2 Jahre lang nie abgeschaltetet wurde .... ?

Na ja - vielleicht bekommen wir ja die logs zu sehen - dann wissen wir mehr

[oftecs]

so hab die logs mal hochgeladen.

http://ifile.it/tsvxhji

da sind sie als zip datei.

Mit Windows und dem Editor lassen sich die logs ja blöd durchsuchen. Welche Tools nutzt ihr dafür?

Welche weiteren logs des esx Servers werden benötigt?

VCenter läuft beim Kunden leider nicht.

[McStarfighter]

Der Editor mit seiner SuFu reicht eigentlich meist ...

[oftecs]

wenn man weiß wonach man suchen muss

hat schon einer in den Logs etwas finden können?

[Tschoergez]

also, dass hier noch nie jemand mit snapshots gearbeitet hat, kann so nicht stimmen. In allen logs steht beim laden der vmx bei den platten immer ...-000001.vmdk, also ein snapshot.

so wie's Deiner bisherigen BEschreibung nach ausschaut, lief die VM also seit zwei jahren auf dem Snapshot. Und jetzt hat wahrscheinlich ein benutzer auf revert-to-snapshot geklickt, und alles funktionierte wie designed ...

In der vmware.log ist das wohl die Zeile

Code: Alles auswählen

Jun 30 09:39:52.682: vmx| SnapshotVMX_Consolidate: starting

Nachdem vorher ein paar sekunden pause in den logeinträgen sind, sieht das nacht manuellem antriggern des Tasks aus.

Allerdings kann ich aus den logfiles jetzt nicht erkennen, ob obiger Eintrag beim löschen(=committen/consolidieren) und/oder beim revert to snapshot kommt.

Evtl. kanns ichs beizeiten mal in ner Testumgebung ausprobieren...

edit: Hm, anscheinend kommt obiger Eintrag wirklich beim löschen eines Snapshots. Das allerdings sollte den aktuellen Zustand der VM nicht verändern... da müssmer wohl tiefer in die logs. hab gerade gesehen, dass die älteren log nicht so lange her sind, evtl. liegt der hund schon früher... bis gleich


viele grüße,
jörg

[Tschoergez]

ok, nun scheints klarer:
anscheinend hat jemand am 30. juni einen revert to snapshot gemacht (zu einem, der ohne speicherinhalt ist, weshalb die VM danach logischerweise aus war):

Code: Alles auswählen

Jun 30 09:25:21.829: vmx| Stopping VCPU threads...

ohne sonstige "Ankündigung" weist wohl darauf hin (ist in vmware-24.log)

10 Sekunden später machte den Täter dann wohl der
schwatze Bildschirm nervös, und er hat die VM wieder gestartet, drum ne neue log-datei vmware-25.log.
Von da weg lief die VM ganz normal, aber halt mit dem 2 Jahre alten Status (den snapshot gabs immer noch, den ein revert-to löscht selbigen ja nicht, sondern "leert" ihn nur aus, damit man immer wieder zurückspringen kann).

Irgendwann fiel der fauxpas dann auf, und der snapshot wurde gelöscht (siehe oben, sichtbar in der letzten vmware.log).

Sieht schwer nach Layer8-Problem aus, für genauere Infos bräuchten wir jetzt die logfiles vom vmware-hostd bzw. vom Virtual Center.

Aber es gab ganz klar einen Snapshot für diese VM, da kann Dein Kunde im Verhör nicht mehr raus

Viele Grüße,
Jörg

[McStarfighter]

Ich seh Jörg schon als Verhörspezi, ihm gegenüber der "Kunde", und alles in einem Raum mit nur einem Tisch und zwei Stühlen. Auf dem Tisch eine auf den "Kunden" gerichtete Lampe ...

[continuum]

Interessanter Fall

als Tatzeit vermute ich die 10 sekunden zwischen log 24 und log 25.
Anders kann ich mir das unvermittelte Auftauchen von snapshot 000002.vmdk in log 25 nicht erklaeren ???

Joerg - weisst du ob ein "revert to snapshot" via remoteCli oder Vitoolkit klare Spuren hinterlaesst ?

[McStarfighter]

CSI:VMware ....

mit continuum als Supervisor Ulli Hankeln, Tschoergez als Verhörspezialist Jörg, oftecs als zwielichtiger Zeuge, dem unbekannten Hauptverdächtigen und als Special Guest: McStarfighter als nutzlose Laborratte Christian ... in seiner ersten und wohl auch letzten Gastrolle ...

[continuum]

oftecs als zwielichtiger Zeuge

Ich wuerde ihn eher als Opfer betrachten ... und jetzt Laborrratte: Laber nicht rum und bring Kaffee und die Daumenschrauben

[McStarfighter]

Sofort Sir !


Hier Sir, ihr Kaffee ! Daumenschrauben sind grad alle, aber der Chief stellt uns den "Wasser"-Raum zur Verfügung!

[Tschoergez]

Ihr seid einfach spitze!!!

Doch zurück zum Thema:
@Ulli: genau die 10 Sekunden hatte ich auch im Blick.
Den snapshot2 kann ich sogar erklären: Wenn ein Snapshot einer VM etwas größer ist, und man den via VI Client (und ich denke auch via API und vmware-cmd) löscht/committed, dann legt der ESX automatisch kurz einen zweiten Snapshot an, committet die ersten deltas und dann die zweiten, so dass am schluss alles wieder sauber ist und kein Snapshot mehr da ist.

Das dient dazu, die Zeit während des committens der letzten Deltas (da friert die VM nämlich ein!) so kurz wie möglich zu halten.

Man kann das recht gut auf der Konsole beobachten, wenn man im Verzeichnis der VM den Befehl

Code: Alles auswählen

watch --interval=1 'ls -ahl'

mitlaufen lässt, während man die Snapshots anlegt, löscht, zurückspringt usw. Super Experiment fürs Verständnis!

Doch zurück zum Fall: Ich hab das mal ausprobiert, aber ein revert-to-snapshot erzeugt anscheindend keine eindeutigen Einträge in der vmware.log.
Wenns ein snapshot MIT speicher war, also die VM danach weiterläuft, gibts einen Eintrag "resuming from ....vmsn"; wenns ein snapshot OHNE speicher war (so wie hier anscheinend), ist die VM danach ja einfach aus.
Drum eben das scheibar "unmotivierte" "Stopping VCPU threads" am ende des entsprechenden logs, und ein rotieren der logs, als der Verdächtige dann die VM wieder angeschaltet hat 10 Sekunden später.

Da dann aber die VM ganz normal startet (und wieder in leere deltas schreibt, denn ein revert-to snapshot löscht selbigen nicht), gibts da dann keine besonderheiten.

im letzten log siehts dann so aus als hätte jemand (nicht ganz so erfolgreich anscheind ) versucht, die Spuren zu verwischen, in dem er den Snapshot ganz löscht.

Ich aber mal, zumindest im Log vom vmware-hostd müsste ein eintrag zum revert-to-snapshot sein, wenn wir das hätten, (wir haben ja gott sei dank den genauen Tatzeitpunkt), könnten wir den Täter endgültig überführen.


Viele Grüße,
Jörg

(gibt leider keinen cool-sonnenbrille-aufsetz-und-abnehm-smilie )

[irix]

...
Den snapshot2 kann ich sogar erklären: Wenn ein Snapshot einer VM etwas größer ist, und man den via VI Client (und ich denke auch via API und vmware-cmd) löscht/committed, dann legt der ESX automatisch kurz einen zweiten Snapshot an, committet die ersten deltas und dann die zweiten, so dass am schluss alles wieder sauber ist und kein Snapshot mehr da ist.

Das ist IIRC das normale Verhalten das beim Loeschen/Comit ein Helper Snapshot angelegt wird welche den Platzbedarf hat von den beiden welche man loescht. Zumind wenn man mehrere hat und ein "Delete All" macht. In einem der vielen Blogs gabs dazu auch eine nette Grafik welche das veranschaulicht und drauf aufmerksam macht das zum loeschen erstmal "mehr" Platz gebraucht wird. Mal gucken ob ich das wiederfinde.

Ich aber mal, zumindest im Log vom vmware-hostd müsste ein eintrag zum revert-to-snapshot sein, wenn wir das hätten, (wir haben ja gott sei dank den genauen Tatzeitpunkt), könnten wir den Täter endgültig überführen.

Mit anderen Worten die Jury kann sich schon mal zurueck ziehen um ueber das Strafmass zuberaten

Gruss
Joerg

[oftecs]

Hey, cool danke

Das ist doch mal eine gute Aussage.

2 Fragen hät ich da noch.

Zum einen, woher bekomm ich die Logs vom Host, welche uns nun den genauen Täter auflisten

Und zweite, gibt es irgendwo ein Manuel seitens VM um die Logs zu interpretieren?

[continuum]

Und zweite, gibt es irgendwo ein Manuel seitens VM um die Logs zu interpretieren?

Leider nein - ich habe das schon x-mal bei VMware angefragt - das Ergebnis ist immer gleich null