search

vmware / open-vm-tools

Official repository of VMware open-vm-tools project
http://sourceforge.net/projects/open-vm-tools/
2.23k stars 425 forks source link

open-vm-tools core dump on debian 10. #575

Open Girish-Chilukuri opened 2 years ago

Girish-Chilukuri commented 2 years ago

Describe the bug

We are blocked with open-vm-tools core dump issue and we are not able to deliver our product. Please consider this issue with priority.

We are seeing the below open-vm-tools(version: 10.3.10) core dump on debian 10(amd 64). We have also upgraded open-vm-tools to 11.2.5 and still face the same issue.

systemctl status open-vm-tools.service ● open-vm-tools.service - Service for virtual machines hosted on VMware Loaded: loaded (/lib/systemd/system/open-vm-tools.service; enabled; vendor preset: enabled) Active: failed (Result: core-dump) since Tue 2022-03-01 08:32:44 UTC; 26min ago Docs: http://open-vm-tools.sourceforge.net/about.php Process: 441 ExecStart=/usr/bin/vmtoolsd (code=dumped, signal=SEGV) Main PID: 441 (code=dumped, signal=SEGV)

Mar 01 08:27:11 systemd[1]: Started Service for virtual machines hosted on VMware. Mar 01 08:32:44 systemd[1]: open-vm-tools.service: Main process exited, code=dumped, st Mar 01 08:32:44 systemd[1]: open-vm-tools.service: Failed with result 'core-dump'.

Core file was generated and below is the segmentation fault information from core dump file:

Using host libthread_db library "/usr/lib/x86_64-linux-gnu/libthread_db.so.1". Core was generated by `/usr/bin/vmtoolsd'. Program terminated with signal SIGSEGV, Segmentation fault.

0 __strlen_avx2 () at ../sysdeps/x86_64/multiarch/strlen-avx2.S:65

65 ../sysdeps/x86_64/multiarch/strlen-avx2.S: No such file or directory.

Reproduction steps

1. Create the VM with debian 10 on ESXi host. 
2. Try to find the all the vm's using the methods from in VC.
3. When trying to fetch the information core dump is observed.

Expected behavior

VM tools should run successfully.

Additional context

No response

zhoumgh commented 2 years ago

Could you post the complete back-trace of the core? https://github.com/vmware/open-vm-tools/issues/378 is a similar issue that was fixed OVT 11.0.5.

Girish-Chilukuri commented 2 years ago

Hi @zhoumgh, Complete backtrace of core dump: Using host libthread_db library "/usr/lib/x86_64-linux-gnu/libthread_db.so.1". Core was generated by `/usr/bin/vmtoolsd'. Program terminated with signal SIGSEGV, Segmentation fault.

0 __strlen_sse2 () at ../sysdeps/x86_64/multiarch/../strlen.S:120

120 ../sysdeps/x86_64/multiarch/../strlen.S: No such file or directory. [Current thread is 1 (Thread 0x7fe590a95780 (LWP 441))] (gdb) bt

0 __strlen_sse2 () at ../sysdeps/x86_64/multiarch/../strlen.S:120

1 0x00007fe590f6b475 in __GI___fputs_unlocked (str=0x7fe58fcf7ac8 <error: Cannot access memory at address 0x7fe58fcf7ac8>,

fp=fp@entry=0x5645ba53b000) at iofputs_u.c:34

2 0x00007fe590fe4868 in __GI___vsyslog_chk (pri=, flag=1, fmt=0x7fe5907c083c "%s.", ap=0x7ffd823b7880)

at ../misc/syslog.c:205

3 0x00007fe590fe4dff in __syslog_chk (pri=, flag=, fmt=)

at ../misc/syslog.c:129

4 0x00007fe5907bb1db in Audit_EventV () from /lib/libvgauth.so.0

5 0x00007fe5907bb2a4 in Audit_Event () from /lib/libvgauth.so.0

6 0x00007fe5907b7f95 in VGAuth_AuditEvent () from /lib/libvgauth.so.0

7 0x00007fe5907b6d05 in VGAuth_ValidateUsernamePassword () from /lib/libvgauth.so.0

8 0x00007fe5907d1cf1 in ?? () from /usr/lib/open-vm-tools/plugins/common/libvix.so

9 0x00007fe5907d22e3 in ?? () from /usr/lib/open-vm-tools/plugins/common/libvix.so

10 0x00007fe5907d25d9 in ?? () from /usr/lib/open-vm-tools/plugins/common/libvix.so

11 0x00007fe5907d81f6 in ?? () from /usr/lib/open-vm-tools/plugins/common/libvix.so

12 0x00007fe5907cf2cb in ?? () from /usr/lib/open-vm-tools/plugins/common/libvix.so

13 0x00007fe59345f664 in RpcChannel_Dispatch () from /lib/libvmtools.so.0

14 0x00007fe5934611de in ?? () from /lib/libvmtools.so.0

15 0x00007fe593461aa4 in ?? () from /lib/libvmtools.so.0

16 0x00007fe5932dfe98 in g_main_context_dispatch () from /lib/x86_64-linux-gnu/libglib-2.0.so.0

17 0x00007fe5932e0288 in ?? () from /lib/x86_64-linux-gnu/libglib-2.0.so.0

18 0x00007fe5932e0582 in g_main_loop_run () from /lib/x86_64-linux-gnu/libglib-2.0.so.0

19 0x00005645ba2e7bb6 in ?? ()

20 0x00005645ba2e6cc7 in main ()

Thanks, Girish

zhoumgh commented 2 years ago

From the backtrace, the memory address at fault seems to be 0x7fe58fcf7ac8.

Could you get us these gdb command outputs:

frame 2 p ap p ap[0].reg_save_area+ap[0].gp_offset x /s \<address printed by the previous line>

zhoumgh commented 2 years ago

Please also send us outputs of commands:

apt list --installed | egrep -i "open-vm-tools|glib" cat /etc/apt/sources.list

We also need VMware Tools logs.

zhoumgh commented 2 years ago

What is the glibc version in your VM?

johnwvmw commented 2 years ago

@Girish-Chilukuri The stack trace that you provided has a number of engineers scratching their heads. The string address that is being flagged as invalid, should be the string that syslog() would have just created.

Our presumption is that they are using the Debian provided OVT packages.

Debian 10 (buster) was released with OVT 10.3.10. That is what is in the buster (oldstable) repository. OVT 11.2.5 is available in the buster-backports repository.

Please help us get a better picture of the situation here by collecting the following information/files from you Debian 10 VM. output of:

Girish-Chilukuri commented 2 years ago

x /s @zhoumgh Here is info about the gdb commands Reading symbols from /usr/bin/vmtoolsd...Reading symbols from /usr/lib/debug/.build-id/0c/b56603853dcbb2a52cedaf3fce7bd481da6d02.debug...done. done. [New LWP 429] [New LWP 541] [Thread debugging using libthread_db enabled] Using host libthread_db library "/usr/lib/x86_64-linux-gnu/libthread_db.so.1". Core was generated by `/usr/bin/vmtoolsd'. Program terminated with signal SIGSEGV, Segmentation fault.

0 __strlen_sse2 () at ../sysdeps/x86_64/multiarch/../strlen.S:120

120 ../sysdeps/x86_64/multiarch/../strlen.S: No such file or directory. [Current thread is 1 (Thread 0x7f4d563fb780 (LWP 429))] (gdb) bt

0 0x00007f4d568ef206 in __strlen_sse2 () at ../sysdeps/x86_64/multiarch/../strlen.S:120

1 0x00007f4d568d1475 in __GI___fputs_unlocked

(str=0x7f4d55658ac8 <error: Cannot access memory at address 0x7f4d55658ac8>, fp=fp@entry=0x556450f316d0) at iofputs_u.c:34

2 0x00007f4d5694a868 in __GI___vsyslog_chk (pri=, flag=1, fmt=0x7f4d5612683c "%s.", ap=0x7fff492d6d20)

at ../misc/syslog.c:205

3 0x00007f4d5694adff in __syslog_chk (pri=, flag=flag@entry=1, fmt=fmt@entry=0x7f4d5612683c "%s.")

at ../misc/syslog.c:129

4 0x00007f4d561211db in syslog (fmt=0x7f4d5612683c "%s.", pri=)

at /usr/include/x86_64-linux-gnu/bits/syslog.h:31

5 0x00007f4d561211db in Audit_EventV (isSuccess=, fmt=, args=)

at ../common/audit.c:205

6 0x00007f4d561212a4 in Audit_Event (isSuccess=isSuccess@entry=1, fmt=fmt@entry=0x7f4d56124b34 "%s: %s")

at ../common/audit.c:139

7 0x00007f4d5611df95 in VGAuth_AuditEvent

(ctx=ctx@entry=0x556450f34490, isSuccess=isSuccess@entry=1, fmt=) at common.c:655

8 0x00007f4d5611cd05 in VGAuth_ValidateUsernamePassword

(ctx=0x556450f34490, userName=0x556450f2ca90 "admin", password=0x556450f2c700 "admin!", numExtraParams=numExtraParams@entry=0, extraParams=extraParams@entry=0x0, handle=handle@entry=0x7fff492d7040) at auth.c:587

9 0x00007f4d56137cf1 in GuestAuthPasswordAuthenticateImpersonate

(obfuscatedNamePassword=obfuscatedNamePassword@entry=0x556450f33bf1 "YWRtaW4AYWRtaW4hAA==", userToken=userToken@entry=0x7fff492d7260) at vixTools.c:11579

10 0x00007f4d561382e3 in VixToolsImpersonateUserImplEx

(credentialTypeStr=credentialTypeStr@entry=0x0, credentialType=, obfuscatedNamePassword=obfuscatedNamePassword@entry=0x556450f33bf1 "YWRtaW4AYWRtaW4hAA==", userToken=userToken@entry=0x7fff492d7260) at vixTools.c:7992

11 0x00007f4d561385d9 in VixToolsImpersonateUser

(requestMsg=requestMsg@entry=0x556450f33b78, userToken=userToken@entry=0x7fff492d7260) at vixTools.c:7752

12 0x00007f4d5613e1f6 in VixToolsInitiateFileTransferFromGuest (result=0x7fff492d7240, requestMsg=0x556450f33b78)

at vixTools.c:4805

13 0x00007f4d5613e1f6 in VixTools_ProcessVixCommand

(requestMsg=requestMsg@entry=0x556450f33b78, requestName=requestName@entry=0x556450f32910 "4d3cb130cb2c506", maxResultBufferSize=maxResultBufferSize@entry=65444, confDictRef=confDictRef@entry=0x556450ede050, eventQueue=eventQueue@entry=0x556450ee6b30, resultBuffer=resultBuffer@entry=0x7fff492d7368, resultLen=0x7fff492d7370, deleteResultBufferResult=0x7fff49--Type for more, q to quit, c to continue without paging--c 2d7367 "") at vixTools.c:10962

14 0x00007f4d561352cb in ToolsDaemonTcloReceiveVixCommand (data=0x7fff492d74b0) at foundryToolsDaemon.c:1248

15 0x00007f4d58dc5664 in RpcChannel_Dispatch () at /lib/libvmtools.so.0

16 0x00007f4d58dc71de in () at /lib/libvmtools.so.0

17 0x00007f4d58dc7aa4 in () at /lib/libvmtools.so.0

18 0x00007f4d58c45e98 in g_main_context_dispatch () at /lib/x86_64-linux-gnu/libglib-2.0.so.0

19 0x00007f4d58c46288 in () at /lib/x86_64-linux-gnu/libglib-2.0.so.0

20 0x00007f4d58c46582 in g_main_loop_run () at /lib/x86_64-linux-gnu/libglib-2.0.so.0

21 0x000055644f0bebb6 in ToolsCoreRunLoop (state=0x55644f0c7540 ) at mainLoop.c:369

22 0x000055644f0bebb6 in ToolsCoreRunLoop (state=0x55644f0c7540 ) at mainLoop.c:301

23 0x000055644f0bdcc7 in main (argc=1, argv=, envp=0x7fff492d7858) at mainPosix.c:283

**(gdb) frame 2

2 0x00007f4d5694a868 in __GI___vsyslog_chk (pri=, flag=1, fmt=0x7f4d5612683c "%s.", ap=0x7fff492d6d20)

at ../misc/syslog.c:205 205 ../misc/syslog.c: No such file or directory. (gdb) p ap $1 = (struct __va_list_tag ) 0x7fff492d6d20 (gdb) p ap[0].reg_save_area+ap[0].gp_offset $2 = (void ) 0x7fff492d6d58 (gdb) x /s 0x7fff492d6d58 0x7fff492d6d58: "\200g\363PdU"** (gdb)

Girish-Chilukuri commented 2 years ago

Hi @zhoumgh @johnwvmw,

Below is the information asked in above comments. Also attached the vmware logs and complete backtrace of core debug mode. apt list --installed | egrep -i "open-vm-tools|glib"

gir1.2-glib-2.0/oldstable,now 1.58.3-2 amd64 [installed,automatic] glib-networking-common/oldstable,now 2.58.0-2+deb10u2 all [installed,automatic] glib-networking-services/oldstable,now 2.58.0-2+deb10u2 amd64 [installed,automatic] glib-networking/oldstable,now 2.58.0-2+deb10u2 amd64 [installed,automatic] libglib2.0-0/oldstable,now 2.58.3-2+deb10u3 amd64 [installed,automatic] libglib2.0-bin/oldstable,now 2.58.3-2+deb10u3 amd64 [installed,automatic] libglib2.0-data/oldstable,now 2.58.3-2+deb10u3 all [installed,automatic] libglib2.0-dev-bin/oldstable,now 2.58.3-2+deb10u3 amd64 [installed,automatic] libglib2.0-dev/oldstable,now 2.58.3-2+deb10u3 amd64 [installed,automatic] libglibmm-2.4-1v5/oldstable,now 2.58.0-2 amd64 [installed,automatic] libglibmm-2.4-dev/oldstable,now 2.58.0-2 amd64 [installed,automatic] libjson-glib-1.0-0/oldstable,now 1.4.4-2 amd64 [installed,automatic] libjson-glib-1.0-common/oldstable,now 1.4.4-2 all [installed,automatic] libtaglibs-standard-impl-java/oldstable,now 1.2.5-2 all [installed,automatic] libtaglibs-standard-spec-java/oldstable,now 1.2.5-2 all [installed,automatic] open-vm-tools-dbgsym/now 2:10.3.10-1+deb10u2 amd64 [installed,local] open-vm-tools/oldstable,now 2:10.3.10-1+deb10u2 amd64 [installed]

cat /etc/apt/sources.list deb http://deb.debian.org/debian-debug/ buster-debug main deb http://deb.debian.org/debian buster main contrib non-free deb-src http://deb.debian.org/debian buster main contrib non-free deb http://deb.debian.org/debian buster-updates main contrib non-free deb-src http://deb.debian.org/debian buster-updates main contrib non-free deb http://security.debian.org/debian-security/ buster/updates main contrib non-free deb-src http://security.debian.org/debian-security/ buster/updates main contrib non-free

ldd --version ldd (Debian GLIBC 2.28-10) 2.28 Copyright (C) 2018 Free Software Foundation, Inc. This is free software; see the source for copying conditions. There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. Written by Roland McGrath and Ulrich Drepper.

uname -a Linux 0x5d9926ec41aea35f-vm1 4.19.0-18-amd64 #1 SMP Debian 4.19.208-1 (2021-09-29) x86_64 GNU/Linux

ESXI version: VMware ESXi, 6.7.0, 15160138 Host: Debian 10(buster)

Debug_backtrace.txt vmware_logs.tar.gz

Thanks, Girish

zhoumgh commented 2 years ago

Girish, thanks a lot for providing the info.

I carefully checked the backtrace, tools logs, glibc-2.28 & OVT source code, I can't figure out why syslog crashed. I saw user & password are validated to be correct, the message to syslog() was "vmtoolsd: Username and password successfully validated for '*****'".

1 0x00007ffff5a83475 in __GI___fputs_unlocked (str=0x7ffff51ddac8 <error: Cannot access memory at address 0x7ffff51ddac8>, fp=fp@entry=0x5555555de1e0) at iofputs_u.c:34

here str should point to constant string "VGAuth", no idea why it was not.

Could you help dump out these static variables from the core? Thanks!

glibc-2.28/misc/syslog.c

static int LogType = SOCK_DGRAM; / type of socket connection / static int LogFile = -1; / fd for log / static int connected; / have done connect / static int LogStat; / status bits, set by openlog() / static const char LogTag; / string to tag the entry with / static int LogFacility = LOG_USER; / default facility code / static int LogMask = 0xff; / mask of priorities to be logged / extern char __progname; / Program name, from crt0. /

open-vm-tools-10.3.10-12406962\vgauth\common\audit.c

static gboolean doLogSuccess = TRUE; static gboolean auditInited = FALSE;

Girish-Chilukuri commented 2 years ago

Hi @zhoumgh, Below is the information about static variables from the core glibc-2.28/misc/syslog.c (gdb) frame 2

2 0x00007f321f5e4868 in __GI___vsyslog_chk (pri=, flag=1, fmt=0x7f321edc083c "%s.", ap=0x7ffd36e1eda0)

at ../misc/syslog.c:205

205 ../misc/syslog.c: No such file or directory. (gdb) p LogType $1 = 2 (gdb) p LogFile $2 = -1 (gdb) p connected $3 = 0 (gdb) p LogStat $4 = 1 (gdb) p LogTag $5 = 0x7f321e2f7ac8 <error: Cannot access memory at address 0x7f321e2f7ac8> (gdb) p LogFacility $6 = 80 (gdb) p LogMask $7 = 255 (gdb) p __progname $8 = 0x7ffd36e1ff48 "vmtoolsd" (gdb) frame 3

3 0x00007f321f5e4dff in __syslog_chk (pri=, flag=flag@entry=1, fmt=fmt@entry=0x7f321edc083c "%s.")

at ../misc/syslog.c:129

129 in ../misc/syslog.c (gdb) p LogType $9 = 2 (gdb) p LogFile $10 = -1 (gdb) p connected $11 = 0 (gdb) p LogStat $12 = 1 (gdb) p LogTag $13 = 0x7f321e2f7ac8 <error: Cannot access memory at address 0x7f321e2f7ac8> (gdb) p LogFacility $14 = 80 (gdb) p LogMask $15 = 255 (gdb) p __progname $16 = 0x7ffd36e1ff48 "vmtoolsd" (gdb)

open-vm-tools-10.3.10-12406962\vgauth\common\audit.c

(gdb) frame 6

6 0x00007f321edbb2a4 in Audit_Event (isSuccess=isSuccess@entry=1, fmt=fmt@entry=0x7f321edbeb34 "%s: %s")

at ../common/audit.c:139

139 ../common/audit.c: No such file or directory. (gdb) p doLogSuccess $17 = 1 (gdb) p auditInited $18 = (gdb) frame 5

5 Audit_EventV (isSuccess=, fmt=, args=) at ../common/audit.c:205

205 in ../common/audit.c (gdb) p doLogSuccess $19 = 1 (gdb) p auditInited $20 = (gdb)

Thanks, Girish

zhoumgh commented 2 years ago

Hi Girish,

This seems not from the same core as shown in Debug_backtrace.txt.

Could you use the core that generated Debug_backtrace.txt?

Thanks, Ming Hua

zhoumgh commented 2 years ago

I created a new VM with OS/Linux/Debian/10/10.11/10.11.0/GA/debian-10.11.0-amd64-DVD-1.iso

$ uname -a Linux debian-Tester 4.19.0-19-amd64 #1 SMP Debian 4.19.232-1 (2022-03-07) x86_64 GNU/Linux <=== Newer than yours

$ ldd --version ldd (Debian GLIBC 2.28-10) 2.28

After installed open-vm-tools, performed guest operation InitiateFileTransferFromGuest, I did not see any issue.

/var/log/vmware-vmsvc.log

[2022-03-09T19:24:16.302Z] [ message] [vmsvc] Log caching is enabled with maxCacheEntries=4096. [2022-03-09T19:24:16.302Z] [ message] [vmsvc] Core dump limit set to -1 [2022-03-09T19:24:16.302Z] [ message] [vmtoolsd] Tools Version: 10.3.10.10540 (build-12406962) ... [2022-03-09T19:24:16.470Z] [ message] [vmtoolsd] Plugin 'vmbackup' initialized. [2022-03-09T19:24:16.797Z] [ message] [powerops] Executing script: '/etc/vmware-tools/poweron-vm-default' [2022-03-09T19:24:16.958Z] [ message] [powerops] Script exit code: 0, success = 1 [2022-03-09T19:24:17.472Z] [ message] [vix] VixTools_ProcessVixCommand: command 62 [2022-03-09T19:43:56.794Z] [ message] [vix] VixTools_ProcessVixCommand: command 188 [2022-03-09T19:43:56.795Z] [ message] [VCGA] Pref_Init: Using '/etc/vmware-tools/vgauth.conf' as preferences filepath [2022-03-09T19:43:56.796Z] [ message] [VCGA] VGAuth 'build-12406962' initialized for application 'vmtoolsd'. Context created at 0x557512fb7190 [2022-03-09T19:43:56.799Z] [ message] [VCGA] PAM up and running. [2022-03-09T19:43:56.836Z] [ message] [vix] VixToolsInitiateFileTransferFromGuest: opcode 188 returning 0 [2022-03-09T19:43:58.193Z] [ message] [vix] VixTools_ProcessVixCommand: command 84 [2022-03-09T19:43:58.225Z] [ message] [vix] VixTools_ProcessVixCommand: command 84 [2022-03-09T19:43:58.245Z] [ message] [vix] VixTools_ProcessVixCommand: command 84 [2022-03-09T19:43:58.278Z] [ message] [vix] VixTools_ProcessVixCommand: command 84 [2022-03-09T19:43:58.301Z] [ message] [vix] VixTools_ProcessVixCommand: command 84 [2022-03-09T19:43:58.331Z] [ message] [vix] VixTools_ProcessVixCommand: command 84

/var/log/syslog

... Mar 9 11:24:17 debian-Tester VGAuthService[2807]: Pref_Init: Using '/etc/vmware-tools/vgauth.conf' as preferences filepath Mar 9 11:24:17 debian-Tester VGAuthService[2807]: Core dump limit set to -1 Mar 9 11:24:17 debian-Tester VGAuthService[2807]: Cannot load message catalog for domain 'VGAuthService', language 'C', catalog dir '.'. Mar 9 11:24:17 debian-Tester VGAuthService[2807]: INIT SERVICE Mar 9 11:24:17 debian-Tester VGAuthService[2807]: Using '/var/lib/vmware/VGAuth/aliasStore' for alias store root directory Mar 9 11:24:17 debian-Tester VGAuthService[2807]: LoadCatalogAndSchema: Using '/etc/vmware-tools/vgauth/schemas' for SAML schemas Mar 9 11:24:17 debian-Tester systemd[1]: Reloading. Mar 9 11:24:17 debian-Tester VGAuthService[2807]: LoadPrefs: Allowing 300 of clock skew for SAML date validation Mar 9 11:24:17 debian-Tester VGAuthService[2807]: SAML_Init: Using xmlsec1 1.2.27 for XML signature support Mar 9 11:24:17 debian-Tester VGAuthService[2807]: ServiceNetworkCreateSocketDir: Created socket directory '/var/run/vmware' Mar 9 11:24:17 debian-Tester VGAuthService[2807]: BEGIN SERVICE ...

/var/log/auth.log

Mar 9 11:43:56 debian-Tester VGAuth[2719]: vmtoolsd: Username and password successfully validated for 'Tester'. Mar 9 11:43:58 debian-Tester VGAuth[2719]: vmtoolsd: Username and password successfully validated for 'Tester'. Mar 9 11:43:58 debian-Tester VGAuth[2719]: vmtoolsd: Username and password successfully validated for 'Tester'. Mar 9 11:43:58 debian-Tester VGAuth[2719]: vmtoolsd: Username and password successfully validated for 'Tester'. Mar 9 11:43:58 debian-Tester VGAuth[2719]: vmtoolsd: Username and password successfully validated for 'Tester'. Mar 9 11:43:58 debian-Tester VGAuth[2719]: vmtoolsd: Username and password successfully validated for 'Tester'. Mar 9 11:43:58 debian-Tester VGAuth[2719]: vmtoolsd: Username and password successfully validated for 'Tester'.

I'm not sure if syslog is working properly on your system.

Girish-Chilukuri commented 2 years ago

Hi Ming Hua, Thanks for the analysis, I think the issue is with syslog. Checking syslog is working properly or not.

Thanks, Girish