open-vm-tools-devel

vcpu-0| GuestMsg: Unknown protocol magic number.

[Florian F. <fl...@de...>]

Hi,

running open-vm-tools 2008.11.18-130226 on Debian Lenny within ESX 2.5.4
build-119703 produces the following error msgs about every 30s in the
vmware.log files of the virtual machines:

Jul 03 00:56:31: vcpu-0| GuestMsg: Unknown protocol magic number.
Jul 03 00:56:59: vcpu-0| GuestMsg: Unknown protocol magic number.
Jul 03 00:57:01: vcpu-0| GuestMsg: Unknown protocol magic number.

Do you have any hints how to further debug or come around this problem?

-Florian

Re: vcpu-0| GuestMsg: Unknown protocol magic number.

[Marcelo V. <mv...@vm...>]

Hi Florian,

Florian Fuessl wrote:
> running open-vm-tools 2008.11.18-130226 on Debian Lenny within ESX 2.5.4
> build-119703 produces the following error msgs about every 30s in the
> vmware.log files of the virtual machines:

First, a disclaimer: the version of ESX you're running is really old (even if 
the build is recent, the 2.5.x line is really old). One of the issues we have 
with Tools is that they're not really certified to run on a lot of different 
VMware platforms; so while it's very probably that they will work on recent 
VMware products, we don't make any guarantees about older versions.

That being said...

 > Jul 03 00:56:31: vcpu-0| GuestMsg: Unknown protocol magic number.
 > Jul 03 00:56:59: vcpu-0| GuestMsg: Unknown protocol magic number.
 > Jul 03 00:57:01: vcpu-0| GuestMsg: Unknown protocol magic number.

This is pretty interesting, because the magic numbers it's talking about haven't 
changed. My best guess without going into the code too much is that something 
changed slightly in the protocol that Tools uses to talk to the host (something 
other than the magic number) and it's causing that...

If you have a more recent VMware product around where you can test it, it would 
be useful to know if you still see it there, to rule out any compilation issue 
or any patches you may have (it's not clear whether you're compiling Tools 
yourself or using the Debian packages, if they exist).

> Do you have any hints how to further debug or come around this problem?

You could enable Tools logging so that we have an idea of what Tools are doing 
when those messages show up on the host. With that particular release of 
open-vm-tools, I think adding these two lines to /etc/vmware-tools/tools.conf 
should do it:

log = "TRUE"
log.file = "/path/to/log/file"

-- 
- Marcelo

RE: vcpu-0| GuestMsg: Unknown protocol magic number.

[Florian F. <fl...@de...>]

Hi Marcelo,

thanks for your message and sorry for the late reply: it's been a busy week
here ;)

> -----Original Message-----
> From: Marcelo Vanzin [mailto:mv...@vm...]
> Subject: Re: vcpu-0| GuestMsg: Unknown protocol magic number.
> 
> Hi Florian,
> 
> Florian Fuessl wrote:
> > running open-vm-tools 2008.11.18-130226 on Debian Lenny within ESX
> 2.5.4
> > build-119703 produces the following error msgs about every 30s in the
> > vmware.log files of the virtual machines:
> 
> First, a disclaimer: the version of ESX you're running is really old
> (even if
> the build is recent, the 2.5.x line is really old). One of the issues
> we have
> with Tools is that they're not really certified to run on a lot of
> different
> VMware platforms; so while it's very probably that they will work on
> recent
> VMware products, we don't make any guarantees about older versions.
> 
> That being said...

Yes I know. The next upcoming hardware will run a newer ESX version for sure
:)

> 
>  > Jul 03 00:56:31: vcpu-0| GuestMsg: Unknown protocol magic number.
>  > Jul 03 00:56:59: vcpu-0| GuestMsg: Unknown protocol magic number.
>  > Jul 03 00:57:01: vcpu-0| GuestMsg: Unknown protocol magic number.
> 
> This is pretty interesting, because the magic numbers it's talking
> about haven't
> changed. My best guess without going into the code too much is that
> something
> changed slightly in the protocol that Tools uses to talk to the host
> (something
> other than the magic number) and it's causing that...
> 
> If you have a more recent VMware product around where you can test it,
> it would
> be useful to know if you still see it there, to rule out any
> compilation issue
> or any patches you may have (it's not clear whether you're compiling
> Tools
> yourself or using the Debian packages, if they exist).
> 
> > Do you have any hints how to further debug or come around this
> problem?
> 
> You could enable Tools logging so that we have an idea of what Tools
> are doing
> when those messages show up on the host. With that particular release
> of
> open-vm-tools, I think adding these two lines to /etc/vmware-
> tools/tools.conf
> should do it:
> 
> log = "TRUE"
> log.file = "/path/to/log/file"

That's the respond every 30s:

Jul 12 17:11:45.327: [vmsvc]: Daemon: Setting option 'broadcastIP' to '1'
Jul 12 17:11:45.328: [vmsvc]: Rpci: Sending request='info-set guestinfo.ip
xxx.xxx.xxx.90'
Jul 12 17:11:45.329: [vmsvc]: Rpci: Sent request='info-set guestinfo.ip
xxx.xxx.xxx.90', reply='', len=0, status=1
Jul 12 17:11:46.626: [vmsvc]: Entered guest info gather.
Jul 12 17:11:46.627: [vmsvc]: Entered update vmdb.
Jul 12 17:11:46.627: [vmsvc]: Rpci: Sending request='SetGuestInfo  4
build-130226'
Jul 12 17:11:46.629: [vmsvc]: Rpci: Sent request='SetGuestInfo  4
build-130226', reply='Invalid guest information type.', len=31, status=0
Jul 12 17:11:46.629: [vmsvc]: SetGuestInfo: Error sending rpc message:
Invalid guest information type.
Jul 12 17:11:46.629: [vmsvc]: Failed to update key/value pair for type 4.
Jul 12 17:11:46.629: [vmsvc]: Failed to update VMDB with tools version.
Jul 12 17:11:46.657: [vmsvc]: ReadDistroFile: could not open
file/etc/redhat-release: 2
Jul 12 17:11:46.658: [vmsvc]: ReadDistroFile: could not open
file/etc/redhat_version: 2
Jul 12 17:11:46.658: [vmsvc]: ReadDistroFile: could not open
file/etc/sun-release: 2
Jul 12 17:11:46.658: [vmsvc]: ReadDistroFile: could not open
file/etc/SuSE-release: 2
Jul 12 17:11:46.659: [vmsvc]: ReadDistroFile: could not open
file/etc/novell-release: 2
Jul 12 17:11:46.659: [vmsvc]: ReadDistroFile: could not open
file/etc/sles-release: 2
Jul 12 17:11:46.659: [vmsvc]: Entered update vmdb.
Jul 12 17:11:46.660: [vmsvc]: Rpci: Sending request='SetGuestInfo  5
Linux2.6.26-10-p4-debian-vm 5.0.2'
Jul 12 17:11:46.664: [vmsvc]: Rpci: Sent request='SetGuestInfo  5
Linux2.6.26-10-p4-debian-vm 5.0.2', reply='Invalid guest information type.',
len=31, status=0
Jul 12 17:11:46.664: [vmsvc]: SetGuestInfo: Error sending rpc message:
Invalid guest information type.
Jul 12 17:11:46.665: [vmsvc]: Failed to update key/value pair for type 5.
Jul 12 17:11:46.665: [vmsvc]: Failed to update VMDB
Jul 12 17:11:46.665: [vmsvc]: Entered update vmdb.
Jul 12 17:11:46.665: [vmsvc]: Rpci: Sending request='SetGuestInfo  6
other26xlinux'
Jul 12 17:11:46.667: [vmsvc]: Rpci: Sent request='SetGuestInfo  6
other26xlinux', reply='Invalid guest information type.', len=31, status=0
Jul 12 17:11:46.668: [vmsvc]: SetGuestInfo: Error sending rpc message:
Invalid guest information type.
Jul 12 17:11:46.668: [vmsvc]: Failed to update key/value pair for type 6.
Jul 12 17:11:46.668: [vmsvc]: Failed to update VMDB
Jul 12 17:11:46.669: [vmsvc]: Entered update vmdb.
Jul 12 17:11:46.670: [vmsvc]: GuestInfo: number of disks has changed
Jul 12 17:11:46.670: [vmsvc]: sizeof request is 254
Jul 12 17:11:46.670: [vmsvc]: Rpci: Sending request='SetGuestInfo  3 '
Jul 12 17:11:46.676: [vmsvc]: Rpci: Sent request='SetGuestInfo  3 ',
reply='Error, unknown guest information type', len=37, status=0
Jul 12 17:11:46.676: [vmsvc]: Failed to update disk information.
Jul 12 17:11:46.676: [vmsvc]: Failed to update VMDB
Jul 12 17:11:46.677: [vmsvc]: Entered update vmdb.
Jul 12 17:11:46.677: [vmsvc]: Value unchanged for infotype 1.
Jul 12 17:11:46.677: [vmsvc]: GuestInfo: Returning after updating guest
information
Jul 12 17:11:46.678: [vmsvc]: Nic info not changed.
Jul 12 17:11:46.679: [vmsvc]: Setting guest uptime to '125700686'
Jul 12 17:11:46.679: [vmsvc]: Entered update vmdb.
Jul 12 17:11:46.679: [vmsvc]: Rpci: Sending request='SetGuestInfo  7
125700686'
Jul 12 17:11:46.680: [vmsvc]: Rpci: Sent request='SetGuestInfo  7
125700686', reply='Invalid guest information type.', len=31, status=0
Jul 12 17:11:46.681: [vmsvc]: SetGuestInfo: Error sending rpc message:
Invalid guest information type.
Jul 12 17:11:46.681: [vmsvc]: Failed to update key/value pair for type 7.
Jul 12 17:11:46.681: [vmsvc]: Failed to update VMDB with uptime.
Jul 12 17:11:46.683: [vmsvc]: Entered update vmdb.
Jul 12 17:11:46.683: [vmsvc]: GuestInfo: Sending GuestMemInfo message.
Jul 12 17:11:46.683: [vmsvc]: Rpci: Sending request='SetGuestInfo  8 '
Jul 12 17:11:46.686: [vmsvc]: Rpci: Sent request='SetGuestInfo  8 ',
reply='Invalid guest information type.', len=31, status=0
Jul 12 17:11:46.686: [vmsvc]: Error sending GuestMemInfo.
Jul 12 17:11:46.686: [vmsvc]: Failed to send vmstats.

Do you have any idea how to come around this problem?

> 
> --
> - Marcelo

Thx. for your help,
- Florian

Re: vcpu-0| GuestMsg: Unknown protocol magic number.

[Marcelo V. <mv...@vm...>]

Hi Florian,

Florian Fuessl wrote:
> That's the respond every 30s:
> Jul 12 17:11:46.627: [vmsvc]: Rpci: Sending request='SetGuestInfo  4
> build-130226'
> Jul 12 17:11:46.629: [vmsvc]: Rpci: Sent request='SetGuestInfo  4
> build-130226', reply='Invalid guest information type.', len=31, status=0
> Jul 12 17:11:46.629: [vmsvc]: SetGuestInfo: Error sending rpc message:
> Invalid guest information type.

Without really digging in the code, it seems that an invalid RPC (for your 
version of ESX) is causing the "magic number" error to show up on the host logs; 
if other Tools features are working (for example, time synchronization) then I 
wouldn't worry about the error.

Since you said the logs just show up on the host every 30s (which is how often 
the code that logs the messages above runs), it's a good indication that other 
features seem to be working. For example, a few lines before that on the logs 
you get a successful RPC:

> Jul 12 17:11:45.329: [vmsvc]: Rpci: Sent request='info-set guestinfo.ip
> xxx.xxx.xxx.90', reply='', len=0, status=1

-- 
- Marcelo

RE: vcpu-0| GuestMsg: Unknown protocol magic number.

[Florian F. <fl...@de...>]

Hi Marcelo,

thx. for the info:
Indeed everything we need seems to be working without any problems.

To prevent the log files grow and exhaust all the disk space I've added the
following line to the .vmx configuration file of the affected virtual
machines:

log.rotateSize = 1048576

-Florian

> -----Original Message-----
> From: Marcelo Vanzin [mailto:mvanzin@...]
> Sent: Saturday, July 18, 2009 3:29 AM
> To: Florian Fuessl
> Cc: 'open-vm-tools development'
> Subject: Re: vcpu-0| GuestMsg: Unknown protocol magic number.
> 
> Hi Florian,
> 
> Florian Fuessl wrote:
> > That's the respond every 30s:
> > Jul 12 17:11:46.627: [vmsvc]: Rpci: Sending request='SetGuestInfo  4
> > build-130226'
> > Jul 12 17:11:46.629: [vmsvc]: Rpci: Sent request='SetGuestInfo  4
> > build-130226', reply='Invalid guest information type.', len=31,
> status=0
> > Jul 12 17:11:46.629: [vmsvc]: SetGuestInfo: Error sending rpc
> message:
> > Invalid guest information type.
> 
> Without really digging in the code, it seems that an invalid RPC (for
> your
> version of ESX) is causing the "magic number" error to show up on the
> host logs;
> if other Tools features are working (for example, time synchronization)
> then I
> wouldn't worry about the error.
> 
> Since you said the logs just show up on the host every 30s (which is
> how often
> the code that logs the messages above runs), it's a good indication
> that other
> features seem to be working. For example, a few lines before that on
> the logs
> you get a successful RPC:
> 
> > Jul 12 17:11:45.329: [vmsvc]: Rpci: Sent request='info-set
> guestinfo.ip
> > xxx.xxx.xxx.90', reply='', len=0, status=1
> 
> --
> - Marcelo