VMware

This Question is Possibly Answered

1 "correct" answer available (10 pts) 2 "helpful" answers available (6 pts)
10 Replies Last post: Mar 31, 2009 9:33 AM by petedr  

Checking logs for a VM that locked up posted: Mar 31, 2009 6:26 AM

Click to view jaygriffin's profile Hot Shot
jaygriffin
165 posts since
May 3, 2006

I have ESX 3.5 with all latest updates (except for those released last night). I use esXpress to backup my VM's. Recently a VM that was in the process of being backed up stopped responding -- could not ping it, RDP, and even opening the console was just a blank window. Pretty much all the commands were grayed out when I right clicked on the machin in Virtual Center.

I am trying to figure out what logs I could check to see if there are errors reported. I checked the machine's vmware.log and did not see anything in there. The esXpress log just shows the machine being backed up -- it was not snapshotting or committing a snapshot.

I know there are several logs on the ESX server that I can access through the console. I am just not sure which log files would be appropriate to investigate. What is the location/name of files I should check?

Thanks!

Re: Checking logs for a VM that locked up

1. Mar 31, 2009 6:43 AM in response to: jaygriffin
Click to view ZaWizZ's profile Expert
ZaWizZ
268 posts since
Jul 27, 2007

I had issues with VMs like this before and probably you won't find any clues in the vmware logs.

You could check the vCenter log files to see if there was anything happening at that time and maybe check the vmkernel at /var/log/vmkernel.

I suggest you look into the Windows log files/ Event viewer too.

-Arnim van Lieshout

Blogging: http://www.van-lieshout.com/
Twitter: http://www.twitter.com/avlieshout

If you find this information useful, please award points for "correct" or "helpful".

Re: Checking logs for a VM that locked up

2. Mar 31, 2009 6:54 AM in response to: ZaWizZ
Click to view jaygriffin's profile Hot Shot
jaygriffin
165 posts since
May 3, 2006

I didn't find anything in the Windows Event Viewer. This is from the vmkernel at the time it occured. The stuff in red seems to be abnormal compared to the rest of the log.

Mar 26 15:07:05 vsql1 vmkernel: 46:21:24:37.002 cpu0:1024)StorageMonitor: 196: vmhba1:0:2:0 status = 0/2 0x0 0x0 0x0
Mar 26 15:07:05 vsql1 vmkernel: 46:21:24:37.123 cpu7:1067)<6>qla24xx_abort_command(0): handle to abort=1296
Mar 26 15:07:05 vsql1 vmkernel: 46:21:24:37.123 cpu7:1031)StorageMonitor: 196: vmhba1:0:1:0 status = 0/2 0x0 0x0 0x0
Mar 26 15:07:05 vsql1 vmkernel: 46:21:24:37.175 cpu3:1039)Fil3: 5004: READ error 0xbad00e5
Mar 26 15:07:05 vsql1 vmkernel: 46:21:24:37.305 cpu0:1024)StorageMonitor: 196: vmhba1:0:1:0 status = 0/2 0x0 0x0 0x0
Mar 26 15:07:06 vsql1 vmkernel: 46:21:24:37.809 cpu0:1024)StorageMonitor: 196: vmhba1:0:1:0 status = 0/2 0x0 0x0 0x0
Mar 26 15:07:06 vsql1 vmkernel: 46:21:24:37.913 cpu7:5594)VSCSIFs: 439: fd 1889720 status Busy
Mar 26 15:07:06 vsql1 vmkernel: 46:21:24:37.914 cpu0:1037)FS3: 5034: Waiting for timed-out heartbeat [HB state abcdef02 offset 41
69216 gen 23 stamp 4051473055855 uuid 498dba04-ed491def-854d-001f29e07c24 jrnl <FB 821004> drv 4.31]
Mar 26 15:07:06 vsql1 vmkernel: 46:21:24:38.057 cpu7:1067)<6>qla24xx_abort_command(0): handle to abort=1291
Mar 26 15:07:06 vsql1 vmkernel: 46:21:24:38.057 cpu7:1067)<6>qla24xx_abort_command(0): handle to abort=1292
Mar 26 15:07:06 vsql1 vmkernel: 46:21:24:38.057 cpu7:1031)StorageMonitor: 196: vmhba1:0:1:0 status = 0/2 0x0 0x0 0x0
Mar 26 15:07:06 vsql1 vmkernel: 46:21:24:38.057 cpu7:1031)StorageMonitor: 196: vmhba1:0:2:0 status = 0/2 0x0 0x0 0x0
Mar 26 15:07:08 vsql1 vmkernel: 46:21:24:40.177 cpu3:1039)FS3: 5034: Waiting for timed-out heartbeat [HB state abcdef02 offset 41
69216 gen 23 stamp 4051478126515 uuid 498dba04-ed491def-854d-001f29e07c24 jrnl <FB 821004> drv 4.31]
Mar 26 15:07:10 vsql1 vmkernel: 46:21:24:42.408 cpu2:1043)FS3: 4831: Reclaimed timed out heartbeat [HB state abcdef02 offset 4169
216 gen 23 stamp 4051462912216 uuid 498dba04-ed491def-854d-001f29e07c24 jrnl <FB 821004> drv 4.31]
Mar 26 15:07:11 vsql1 vmkernel: 46:21:24:42.843 cpu0:1024)StorageMonitor: 196: vmhba1:0:1:0 status = 24/0 0x0 0x0 0x0
Mar 26 15:07:11 vsql1 last message repeated 7 times
Mar 26 15:07:11 vsql1 vmkernel: 46:21:24:42.899 cpu0:1090)StorageMonitor: 196: vmhba1:0:1:0 status = 24/0 0x0 0x0 0x0
Mar 26 15:07:11 vsql1 vmkernel: 46:21:24:42.906 cpu0:1024)StorageMonitor: 196: vmhba1:0:1:0 status = 24/0 0x0 0x0 0x0
Mar 26 15:07:11 vsql1 vmkernel: 46:21:24:42.907 cpu0:1024)StorageMonitor: 196: vmhba1:0:1:0 status = 24/0 0x0 0x0 0x0
Mar 26 15:07:13 vsql1 vmkernel: 46:21:24:45.075 cpu0:1024)StorageMonitor: 196: vmhba1:0:1:0 status = 24/0 0x0 0x0 0x0
Mar 26 15:07:13 vsql1 vmkernel: 46:21:24:45.075 cpu0:1024)StorageMonitor: 196: vmhba1:0:1:0 status = 24/0 0x0 0x0 0x0
Mar 26 15:07:13 vsql1 vmkernel: 46:21:24:45.166 cpu6:5594)Cow: 866: IO to deltadisk handle 164331 failed: Busy
Mar 26 15:07:13 vsql1 vmkernel: 46:21:24:45.324 cpu2:1043)FS3: 4831: Reclaimed timed out heartbeat [HB state abcdef02 offset 4169
216 gen 594 stamp 4051462912216 uuid 498dba04-ed491def-854d-001f29e07c24 jrnl <FB 122607> drv 4.31]
Mar 26 15:07:18 vsql1 vmkernel: 46:21:24:50.118 cpu0:1024)StorageMonitor: 196: vmhba1:0:1:0 status = 24/0 0x0 0x0 0x0
Mar 26 15:07:18 vsql1 vmkernel: 46:21:24:50.191 cpu0:1024)StorageMonitor: 196: vmhba1:0:1:0 status = 24/0 0x0 0x0 0x0
Mar 26 15:07:21 vsql1 vmkernel: 46:21:24:52.797 cpu0:1024)StorageMonitor: 196: vmhba1:0:1:0 status = 24/0 0x0 0x0 0x0
Mar 26 15:08:31 vsql1 vmkernel: 46:21:26:02.923 cpu0:1024)StorageMonitor: 196: vmhba1:0:1:0 status = 24/0 0x0 0x0 0x0

Re: Checking logs for a VM that locked up

3. Mar 31, 2009 7:06 AM in response to: jaygriffin
Click to view Texiwill's profile Guru
Texiwill
10,213 posts since
Jan 13, 2004
Hello,

Yes this is abnormal. I would correlate those to your SAN logs and see if there is anything that sticks out to you. You can also use the vmkerrcode to decode the 0xbad error.


Best regards,
Edward L. Haletky
VMware Communities User Moderator, VMware vExpert 2009
====
Author of the book 'VMWare ESX Server in the Enterprise: Planning and Securing Virtualization Servers', Copyright 2008 Pearson Education.
Blue Gears and SearchVMware Pro Blogs -- Top Virtualization Security Links -- Virtualization Security Round Table Podcast

Re: Checking logs for a VM that locked up

4. Mar 31, 2009 7:12 AM in response to: jaygriffin
Click to view ZaWizZ's profile Expert
ZaWizZ
268 posts since
Jul 27, 2007
Indeed, definitely a storage IO problem in the SAN connection.

-Arnim van Lieshout

Blogging: http://www.van-lieshout.com
Twitter: http://www.twitter.com/avlieshout

If you find this information useful, please award points for "correct" or "helpful".

Re: Checking logs for a VM that locked up

5. Mar 31, 2009 8:35 AM in response to: jaygriffin
Click to view petedr's profile Master
petedr
1,408 posts since
Mar 18, 2006

Jay,

Even though it may not be a backup issue have you contacted our support group. They may be able to go through the logs and offer some assistance.

Pete@esXpress

www.phdvirtual.com, makers of esXpress

Re: Checking logs for a VM that locked up

6. Mar 31, 2009 8:36 AM in response to: petedr
Click to view jaygriffin's profile Hot Shot
jaygriffin
165 posts since
May 3, 2006

Peter,

Yes, I have.

Thanks.

Re: Checking logs for a VM that locked up

7. Mar 31, 2009 8:54 AM in response to: jaygriffin
Click to view petedr's profile Master
petedr
1,408 posts since
Mar 18, 2006

Thanks Jay,

I'll check wuth the support group on what you sent and post back and observations I may have.

www.phdvirtual.com, makers of esXpress

Re: Checking logs for a VM that locked up

8. Mar 31, 2009 9:18 AM in response to: petedr
Click to view petedr's profile Master
petedr
1,408 posts since
Mar 18, 2006

It is interesting as our support group indicated nothing jumps out in the vmware logs as to what occurred. As was posted here storage could definitely be a cause.

It does not look anything specific to esXpress that I can see that is causing an issue.

On the snapshot removal I see in hostd it did fail with file busy errors.

2009-03-26 15:34:14.077 'BaseLibs' 38304688 info DISKLIB-LIB : Failed to open '/vmfs/volumes/4909f986-4c2b05da-cb29-00215ad8d792/DDsql/DDsql-000001-delta.vmdk' with flags 0x11 (Device or resource busy).

That usually indicated a vmware process hung which could just be an off shoot of the original problem.

www.phdvirtual.com, makers of esXpress

Re: Checking logs for a VM that locked up

9. Mar 31, 2009 9:21 AM in response to: petedr
Click to view jaygriffin's profile Hot Shot
jaygriffin
165 posts since
May 3, 2006
That is probably a side affect -- the problem happened about 15:07.

Thanks for checking!

Re: Checking logs for a VM that locked up

10. Mar 31, 2009 9:33 AM in response to: jaygriffin
Click to view petedr's profile Master
petedr
1,408 posts since
Mar 18, 2006
If we find anything else we will follow up with you off line through our support group.


www.phdvirtual.com, makers of esXpress

Actions

VMware Developer

SDKs, APIs, Videos, Learn and much more in the Developer community.

Learn More

Developer Sample Code

Increase your developer productivity with VMware API sample code.

Learn More

VMworld Sessions & Labs

Online access to the latest VMworld Sessions & Labs and online services.

Learn more

Purchase PSO Credits Online

Purchase credits to redeem training and consulting services online.

Buy Now

Community Hardware Software

View reported configurations or report your own.

Learn More

VMware vSphere

Come witness the next giant leap in virtualization.

Register Today

Communities