I run VMWare server 1.07 on Centos 5. Last night I left a Windows 2000 virtual machine doing a ClamWin scan of drive M: when I went to bed around midnight. Drive M: is actually a volume on the Centos 5 host, mounted via Samba. It has about 40Gb of photos on it, plus a few other things. I had the VM up visible in the VMWare Server Console running under KDE on display 8 (X session #1), my usual configuration.
This morning when I looked in on it the screen was not responsive. The keyboard seemed to be working (num lock would go on and off, though sometimes with some delay). There was some disk activity showing on the hard drive light. Nothing I did would cause any video to appear. I finally his Ctl+Alt+1 (nothing happened) then I pressed just Ctrl, and the monitor light turned green. I got a console login prompt! When I tried to go back to one of the GUI consoles the computer locked up again. I went to another computer on the network and logged into the VMWare server from it. It showed both the Windows 2000 machine and also the IPCop VM (which had also been running) were both shut down. I restarted them both successfully. I again could not get any response from the host machine.
Eventually I hit a key combination that got me back to console 1 command line. I went back to the other computer, shut down both of the VMs that were running, logged in, and did a Ctl-Alt-Del. I breathed a sigh of relief as the shutdown messages started scrolling across the screen.
After the reboot, things seem pretty normal. However, I found this in /var/log/messages, and wonder what they mean, especially the one at 04:02:08 about debug info.
Jan 17 01:27:44 office2 kernel: NVRM: Xid (0005:00): 3, C 00000001 SC 00000003 M 000002fc Data 00000003 Jan 17 01:27:44 office2 kernel: NVRM: Xid (0005:00): 3, C 00000001 SC 00000003 M 000002fc Data 00000001 Jan 17 01:27:44 office2 last message repeated 6 times Jan 17 03:37:35 office2 smbd[4771]: [2009/01/17 03:37:35, 0] smbd/open.c:open_directory(2060) Jan 17 03:37:35 office2 smbd[4771]: open_directory: TED/Alabanza/Sony_KP-43T90_TV/hv cable removal_anyone: TechLore.com_files is a stream name! Jan 17 03:37:35 office2 smbd[4771]: [2009/01/17 03:37:35, 0] smbd/open.c:open_directory(2060) Jan 17 03:37:35 office2 smbd[4771]: open_directory: TED/Alabanza/Sony_KP-43T90_TV/hv cable removal_anyone: TechLore.com_files is a stream name! Jan 17 03:37:36 office2 smbd[4771]: [2009/01/17 03:37:36, 0] smbd/open.c:open_directory(2060) Jan 17 03:37:36 office2 smbd[4771]: open_directory: TED/Alabanza/Sony_KP-43T90_TV/hv cable removal_anyone: TechLore.com_files/iframe_data is a stream name! Jan 17 03:37:36 office2 smbd[4771]: [2009/01/17 03:37:36, 0] smbd/open.c:open_directory(2060) Jan 17 03:37:36 office2 smbd[4771]: open_directory: TED/Alabanza/Sony_KP-43T90_TV/hv cable removal_anyone: TechLore.com_files/iframe_data is a stream name! Jan 17 03:37:36 office2 smbd[4771]: [2009/01/17 03:37:36, 0] smbd/open.c:open_directory(2060) Jan 17 03:37:36 office2 smbd[4771]: open_directory: TED/Alabanza/Sony_KP-43T90_TV/hv cable removal_anyone: TechLore.com_files/minimall_data is a stream name! Jan 17 03:37:37 office2 smbd[4771]: [2009/01/17 03:37:37, 0] smbd/open.c:open_directory(2060) Jan 17 03:37:37 office2 smbd[4771]: open_directory: TED/Alabanza/Sony_KP-43T90_TV/hv cable removal_anyone: TechLore.com_files/minimall_data is a stream name! Jan 17 03:37:41 office2 smbd[4771]: [2009/01/17 03:37:41, 0] smbd/open.c:open_directory(2060) Jan 17 03:37:41 office2 smbd[4771]: open_directory: TED/Alabanza/Sony_KP-43T90_TV/hv cable removal_anyone: TechLore.com_files/iframe_data_002 is a stream name! Jan 17 03:37:41 office2 smbd[4771]: [2009/01/17 03:37:41, 0] smbd/open.c:open_directory(2060) Jan 17 03:37:41 office2 smbd[4771]: open_directory: TED/Alabanza/Sony_KP-43T90_TV/hv cable removal_anyone: TechLore.com_files/iframe_data_002 is a stream name! Jan 17 03:37:42 office2 smbd[4771]: [2009/01/17 03:37:42, 0] smbd/open.c:open_directory(2060) Jan 17 03:37:42 office2 smbd[4771]: open_directory: TED/Alabanza/Sony_KP-43T90_TV/hv cable removal_anyone: TechLore.com_files/iframe_data_003 is a stream name! Jan 17 03:37:42 office2 smbd[4771]: [2009/01/17 03:37:42, 0] smbd/open.c:open_directory(2060) Jan 17 03:37:42 office2 smbd[4771]: open_directory: TED/Alabanza/Sony_KP-43T90_TV/hv cable removal_anyone: TechLore.com_files/iframe_data_003 is a stream name! Jan 17 03:37:42 office2 smbd[4771]: [2009/01/17 03:37:42, 0] smbd/open.c:open_directory(2060) Jan 17 03:37:42 office2 smbd[4771]: open_directory: TED/Alabanza/Sony_KP-43T90_TV/hv cable removal_anyone: TechLore.com_files/iframe_data_003/ads_data is a stream name! Jan 17 03:37:42 office2 smbd[4771]: [2009/01/17 03:37:42, 0] smbd/open.c:open_directory(2060) Jan 17 03:37:42 office2 smbd[4771]: open_directory: TED/Alabanza/Sony_KP-43T90_TV/hv cable removal_anyone: TechLore.com_files/iframe_data_003/ads_data is a stream name! Jan 17 03:56:46 office2 kernel: device eth1 left promiscuous mode Jan 17 03:56:46 office2 kernel: audit(1232182606.512:5): dev=eth1 prom=0 old_prom=256 auid=4294967295 ses=4294967295 Jan 17 03:56:46 office2 kernel: bridge-eth1: disabled promiscuous mode Jan 17 03:56:46 office2 kdm[3925]: X server for display :1 terminated unexpectedly Jan 17 03:56:46 office2 kernel: device eth0 left promiscuous mode Jan 17 03:56:46 office2 kernel: audit(1232182606.897:6): dev=eth0 prom=0 old_prom=256 auid=4294967295 ses=4294967295 Jan 17 03:56:46 office2 kernel: bridge-eth0: disabled promiscuous mode Jan 17 03:57:05 office2 kdm_greet[14492]: Can't open default user face Jan 17 04:02:08 office2 nmbd[3710]: [2009/01/17 04:02:08, 0] nmbd/nmbd.c:process(559) Jan 17 04:02:08 office2 nmbd[3710]: Got SIGHUP dumping debug info. Jan 17 04:02:08 office2 nmbd[3710]: [2009/01/17 04:02:08, 0] nmbd/nmbd_workgroupdb.c:dump_workgroups(282) Jan 17 04:02:08 office2 nmbd[3710]: dump_workgroups() Jan 17 04:02:08 office2 nmbd[3710]: dump workgroup on subnet 10.41.65.2: netmask= 255.255.255.0: Jan 17 04:02:08 office2 nmbd[3710]: MILLER(1) current master browser = OFFICE2 Jan 17 04:02:08 office2 nmbd[3710]: OFFICE2 40849a03 (Office2) Jan 17 04:15:53 office2 smbd[4771]: [2009/01/17 04:15:53, 0] lib/util_sock.c:read_data(534) Jan 17 04:15:53 office2 smbd[4771]: read_data: read failure for 4 bytes to client 10.41.65.251. Error = No route to host Jan 17 04:47:01 office2 ntpd[3543]: synchronized to 69.26.112.120, stratum 3 Jan 17 04:48:04 office2 ntpd[3543]: synchronized to LOCAL(0), stratum 10 Jan 17 10:48:08 office2 xinetd[3522]: START: vmware-authd pid=17407 from=10.41.65.254 Jan 17 10:48:08 office2 xinetd[3522]: EXIT: vmware-authd status=0 pid=17407 duration=0(sec) Jan 17 10:48:44 office2 kernel: device eth1 entered promiscuous mode Jan 17 10:48:44 office2 kernel: audit(1232207324.327:7): dev=eth1 prom=256 old_prom=0 auid=4294967295 ses=4294967295 Jan 17 10:48:44 office2 kernel: bridge-eth1: enabled promiscuous mode Jan 17 10:48:44 office2 kernel: device eth0 entered promiscuous mode Jan 17 10:48:44 office2 kernel: audit(1232207324.327:8): dev=eth0 prom=256 old_prom=0 auid=4294967295 ses=4294967295 Jan 17 10:48:44 office2 kernel: bridge-eth0: enabled promiscuous mode Jan 17 10:48:44 office2 xinetd[3522]: START: vmware-authd pid=17425 from=10.41.65.254
Here is the /var/log/vmware/vmware-serverd-0.log entries from that time period, starting back when the Win2K VM was started and running through my remote connection this morning (when I found all VMs powered off):
Jan 16 18:37:07: app| Adding to list of running vms: /vmware/Win2K-T1/Win2K-T1.vmx Jan 16 18:37:07: app| Attempting to launch vmx : /vmware/Win2K-T1/Win2K-T1.vmx Jan 16 18:37:07: app| New connection on socket server-vmxvmdb from host localhost (ip address: local) , user: tmiller Jan 16 18:37:07: app| Connection from : /vmware/Win2K-T1/Win2K-T1.vmx Jan 16 18:37:07: app| Setting up autoDetect info. Jan 16 18:37:07: app| VMServerdConnect: connecting to /vmware/Win2K-T1/Win2K-T1.vmx Jan 16 18:37:09: app| Connected to /vmware/Win2K-T1/Win2K-T1.vmx Jan 16 18:37:09: app| Trimming event log for /vmware/Win2K-T1/Win2K-T1.vmx by 3 lines... Jan 16 18:37:09: app| SP: Retrieved username: tmiller Jan 16 18:37:09: app| VM suddenly changed state: poweredOn. Jan 16 18:37:09: app| SP: Retrieved username: tmiller Jan 16 18:37:09: app| SP: Retrieved username: tmiller Jan 16 18:37:10: app| cleanup: cleaned up 2 objects Jan 16 18:37:41: app| VmsdRegister: Config file has changed: /vmware/Win2K-T1/Win2K-T1.vmx Jan 17 03:56:46: app| vmdbPipe_Streams Couldn't read: OVL_STATUS_EOF Jan 17 03:56:46: app| VMHS: Connection to VM broken: cfg: /vmware/IPCop-01/IPCop-01.vmx; error: Pipe: Read failed; state: 3 Jan 17 03:56:46: app| VMServerd IPC closed the connection with thread /vmware/IPCop-01/IPCop-01.vmx (0x9522af0) Jan 17 03:56:46: app| Lost connection to /vmware/IPCop-01/IPCop-01.vmx (/vmware/IPCop-01/IPCop-01.vmx) unexpectedly. Jan 17 03:56:46: app| vmdbPipe_Streams Couldn't read: OVL_STATUS_EOF Jan 17 03:56:46: app| VMHS: Connection to VM broken: cfg: /vmware/Win2K-T1/Win2K-T1.vmx; error: Pipe: Read failed; state: 3 Jan 17 03:56:47: app| VMServerd IPC closed the connection with thread /vmware/Win2K-T1/Win2K-T1.vmx (0x9522b6c) Jan 17 03:56:47: app| Lost connection to /vmware/Win2K-T1/Win2K-T1.vmx (/vmware/Win2K-T1/Win2K-T1.vmx) unexpectedly. Jan 17 03:56:47: app| OvlHostStartIo: errno 104 Jan 17 03:56:47: app| vmdbPipe_Streams: Couldn't read Jan 17 03:56:47: app| VM suddenly changed state: poweredOff. Jan 17 03:56:47: app| VM suddenly changed state: poweredOff. Jan 17 03:56:47: app| VM suddenly changed state: poweredOff. Jan 17 03:56:47: app| SP: Deleting user session: 0 username: tmiller Jan 17 03:56:47: app| VM suddenly changed state: poweredOff. Jan 17 03:56:47: app| VM suddenly changed state: poweredOff. Jan 17 03:56:47: app| VM suddenly changed state: poweredOff. Jan 17 10:48:18: app| New connection on socket server-vmdb from host 10.41.65.254 (ip address: 10.41.65.254) , user: tmiller
I thing the "event" happened at 03:56:46, when: the the VMWare server lost the connection to both VMs within 2 seconds device eth1 left promiscuous mode
I do note that it showed the connection to the IPCop machine broken first, so that may be where the problem started.
If it helps any, the IPCop VM uses both eth0 (LAN) and eth1 (DSL modem). Win2K only uses eth0.
Anyone have any insight as to what might have happened?
Any recommendations besides that I should probably upgrade the server to the latest version?
Ted Miller Indiana