vcenter 问题排查--vcenter api上传文件至虚拟机报500错误

末蓝、 2023-06-23 13:14 20阅读 0赞

## vcenter 问题排查–vcenter api上传文件至虚拟机报500错误 ##

### 文章目录 ###

*   *  vcenter 问题排查--vcenter api上传文件至虚拟机报500错误
     *   *  1. 问题背景
         *  2. 问题排查记录

### 1. 问题背景 ###

> vcenter由5.5升级到6.0后，向esxi下的windows10虚拟机上传文件，vcenter api反馈500，但向同esxi下的windows7虚拟机上传文件是成功的。

### 2. 问题排查记录 ###

*  1.问题定位
    
     *  500错误首先可以排除上传脚本本身问题，上传文件是通过vcenter api获取上传文件的url，然后以POST方式将文件上传至虚拟机中。
     *  上传文件的url为：`https://1.1.1.159:443/guestFile?id=83&token=52a90eee-5c9e-004f-7cba-4ae79949830c83`其中`1.1.1.159`为esxi IP，所以初步定位是esxi内的服务发生了错误。
 *  2.进入esxi中进一步排查
    
     *  登录esxi，打开ssh远程连接选项  
        !\[avatar\]\[open\_ssh\_of\_esxi\]
     *  ssh进入esxi中，尝试用`netstat -apn | grep 443`查找出服务信息，但esxi中没有`netstat`命令，查看常见的web服务进程`ps | grep nginx`, `ps | grep apache`, `ps | grep http`, 发现一个http代理进程：
        
            [root@localhost:~] ps | grep  http
            33904   33890  rhttpproxy-work
            33905   33890  rhttpproxy-work
            33914   33890  rhttpproxy-poll
            34452   33890  rhttpproxy-work
            35247   33890  rhttpproxy-work
     *  查看`/etc/init.d/rhttpproxy`文件，发现存在日志路径：`/var/log/vmware`
        
            #!/bin/sh                   
            # chkconfig: on 18 82         
                      
            export PATH=/bin:/sbin         
            RHTTPPROXY_UPGRADE_CONFIG=/usr/lib/vmware/rhttpproxy/bin/upgrade-config.py  
            RHTTPPROXY_TAG=rhttpproxy
            RHTTPPROXY_LOGDIR=/var/log/vmware
            RHTTPPROXY_SRV_NAME="VMware HTTP reverse proxy"
            RHTTPPROXY_KILL_SIGNAL=15                  
            ISRUNNING="${RHTTPPROXY_SRV_NAME} is running."
            ISNOTRUNNING="${RHTTPPROXY_SRV_NAME} is not running."
            RHTTPPROXY_PID="$(pidof -s $RHTTPPROXY_TAG)"
        
        但`/var/log/vmware`为一空目录，同时发现`/var/log/`目录下存在`rhttpproxy.log`:
        
            [root@localhost:/var/log] ls -l
            total 292
            lrwxrwxrwx    1 root     root            21 May  9 08:40 Xorg.log -> /scratch/log/Xorg.log
            lrwxrwxrwx    1 root     root            21 May  9 08:40 auth.log -> /scratch/log/auth.log
            -rw-rw-rw-    1 root     root         51407 May  9 08:40 boot.gz
            lrwxrwxrwx    1 root     root            22 May  9 08:40 clomd.log -> /scratch/log/clomd.log
            -rw-r--r--    1 root     root         23206 May  9 08:49 configRP.log
            lrwxrwxrwx    1 root     root            25 May  9 08:40 dhclient.log -> /scratch/log/dhclient.log
            lrwxrwxrwx    1 root     root            20 May  9 08:40 epd.log -> /scratch/log/epd.log
            -rw-r--r--    1 root     root             0 May  9 08:40 esxcli.log
            lrwxrwxrwx    1 root     root            26 May  9 08:40 esxupdate.log -> /scratch/log/esxupdate.log
            lrwxrwxrwx    1 root     root            20 May  9 08:40 fdm.log -> /scratch/log/fdm.log
            -rw-r--r--    1 root     root         19512 May 14 09:43 hostd-live-34084-0001.dmp
            lrwxrwxrwx    1 root     root            28 May  9 08:40 hostd-probe.log -> /scratch/log/hostd-probe.log
            lrwxrwxrwx    1 root     root            22 May  9 08:40 hostd.log -> /scratch/log/hostd.log
            lrwxrwxrwx    1 root     root            33 May  9 08:40 hostprofiletrace.log -> /scratch/log/hostprofiletrace.log
            lrwxrwxrwx    1 root     root            28 May  9 08:40 iofiltervpd.log -> /scratch/log/iofiltervpd.log
            drwxr-xr-x    1 root     root           512 May  9 08:41 ipmi
            -rw-r--r--    1 root     root          3118 May  9 08:40 jumpstart-stdout.log
            lrwxrwxrwx    1 root     root            21 May  9 08:40 lacp.log -> /scratch/log/lacp.log
            lrwxrwxrwx    1 root     root            21 May  9 08:40 nfcd.log -> /scratch/log/nfcd.log
            lrwxrwxrwx    1 root     root            22 May  9 08:40 osfsd.log -> /scratch/log/osfsd.log
            lrwxrwxrwx    1 root     root            30 May  9 08:40 rabbitmqproxy.log -> /scratch/log/rabbitmqproxy.log
            lrwxrwxrwx    1 root     root            27 May  9 08:40 rhttpproxy.log -> /scratch/log/rhttpproxy.log
            lrwxrwxrwx    1 root     root            29 May  9 08:40 sdrsinjector.log -> /scratch/log/sdrsinjector.log
            lrwxrwxrwx    1 root     root            22 May  9 08:40 shell.log -> /scratch/log/shell.log
            -rw-------    1 root     root          3599 May 14 09:45 smbios.bin
            lrwxrwxrwx    1 root     root            26 May  9 08:40 storagerm.log -> /scratch/log/storagerm.log
            lrwxrwxrwx    1 root     root            25 May  9 08:40 swapobjd.log -> /scratch/log/swapobjd.log
            -rw-------    1 root     root          9361 May  9 08:40 sysboot.log
            lrwxrwxrwx    1 root     root            23 May  9 08:40 syslog.log -> /scratch/log/syslog.log
            -rw-------    1 root     root         32064 May 14 09:50 tallylog
            lrwxrwxrwx    1 root     root            20 May  9 08:40 usb.log -> /scratch/log/usb.log
            lrwxrwxrwx    1 root     root            24 May  9 08:40 vmauthd.log -> /scratch/log/vmauthd.log
            lrwxrwxrwx    1 root     root            26 May  9 08:40 vmkdevmgr.log -> /scratch/log/vmkdevmgr.log
            lrwxrwxrwx    1 root     root            25 May  9 08:40 vmkernel.log -> /scratch/log/vmkernel.log
            lrwxrwxrwx    1 root     root            26 May  9 08:40 vmkeventd.log -> /scratch/log/vmkeventd.log
            lrwxrwxrwx    1 root     root            27 May  9 08:40 vmksummary.log -> /scratch/log/vmksummary.log
            lrwxrwxrwx    1 root     root            27 May  9 08:40 vmkwarning.log -> /scratch/log/vmkwarning.log
            drwxr-xr-x    1 root     root           512 May 14 09:43 vmware
            lrwxrwxrwx    1 root     root            21 May  9 08:40 vobd.log -> /scratch/log/vobd.log
            lrwxrwxrwx    1 root     root            23 May  9 08:40 vprobe.log -> /scratch/log/vprobe.log
            lrwxrwxrwx    1 root     root            24 May  9 08:40 vprobed.log -> /scratch/log/vprobed.log
            lrwxrwxrwx    1 root     root            21 May  9 08:40 vpxa.log -> /scratch/log/vpxa.log
            lrwxrwxrwx    1 root     root            24 May  9 08:40 vsanvpd.log -> /scratch/log/vsanvpd.log
            lrwxrwxrwx    1 root     root            22 May  9 08:40 vvold.log -> /scratch/log/vvold.log
     *  观察`rhttpproxy.log`,发现在上传成功和上传失败时的日志不同点：
        
         *  上传文件至windows10时失败的日志：
            
                2019-05-14T08:57:31.285Z verbose rhttpproxy[32D40B70] [Originator@6876 sub=Proxy Req 41558] New proxy client <SSL(<io_obj p:0xffb13e4c, h:24, <TCP '1.1.1.159:443'>, <TCP '1.1.1.31:57193'>>)>
                2019-05-14T08:57:31.288Z verbose rhttpproxy[32F40B70] [Originator@6876 sub=Proxy Req 41558] Resolved endpoint : [N7Vmacore4Http16LocalServiceSpecE:0xffaa22b0] _serverNamespace = /guestFile _isRedirect = false _port = 8309
                2019-05-14T08:57:31.289Z verbose rhttpproxy[32D40B70] [Originator@6876 sub=Proxy Req 41558] Connected to localhost : 8309 over <io_obj p:0xffc9f2fc, h:25, <TCP '127.0.0.1:32429'>, <TCP '127.0.0.1:8309'>>
                2019-05-14T08:57:31.291Z verbose rhttpproxy[32D40B70] [Originator@6876 sub=Proxy Req 41558] Server localhost : 8309 disconnected
                2019-05-14T08:57:32.857Z verbose rhttpproxy[FFE02B70] [Originator@6876 sub=Proxy Req 01743] Resolved endpoint : [N7Vmacore4Http16LocalServiceSpecE:0x32c40820] _serverNamespace = /sdk _isRedirect = true _port = 8307
         *  上传文件至windows7时成功的日志：
            
                2019-05-14T08:59:31.280Z verbose rhttpproxy[32F40B70] [Originator@6876 sub=Proxy Req 41572] New proxy client <SSL(<io_obj p:0xffc04234, h:24, <TCP '1.1.1.159:443'>, <TCP '1.1.1.31:57322'>>)>
                2019-05-14T08:59:31.283Z verbose rhttpproxy[32D40B70] [Originator@6876 sub=Proxy Req 41572] Resolved endpoint : [N7Vmacore4Http16LocalServiceSpecE:0xffaa22b0] _serverNamespace = /guestFile _isRedirect = false _port = 8309
                2019-05-14T08:59:31.283Z verbose rhttpproxy[32F40B70] [Originator@6876 sub=Proxy Req 41572] Connected to localhost : 8309 over <io_obj p:0xffb1ce1c, h:25, <TCP '127.0.0.1:41733'>, <TCP '127.0.0.1:8309'>>
                2019-05-14T08:59:31.287Z verbose rhttpproxy[32D40B70] [Originator@6876 sub=Proxy Req 01743] Resolved endpoint : [N7Vmacore4Http16LocalServiceSpecE:0x32c40820] _serverNamespace = /sdk _isRedirect = true _port = 8307
                2019-05-14T08:59:31.289Z verbose rhttpproxy[32F40B70] [Originator@6876 sub=Proxy Req 01743] Resolved endpoint : [N7Vmacore4Http16LocalServiceSpecE:0x32c40820] _serverNamespace = /sdk _isRedirect = true _port = 8307
                2019-05-14T08:59:31.389Z verbose rhttpproxy[32F40B70] [Originator@6876 sub=Proxy Req 41572] The client closed the stream, not unexpectedly.
                2019-05-14T08:59:32.917Z verbose rhttpproxy[FFE02B70] [Originator@6876 sub=Proxy Req 01743] Resolved endpoint : [N7Vmacore4Http16LocalServiceSpecE:0x32c40820] _serverNamespace = /sdk _isRedirect = true _port = 8307
        
        可以看到在上传文件时是与esxi上的8309端口服务建立的连接，但上传失败时该连接disconnect了，并且日志中没有反馈出具体的错误原因；
     *  观察`/var/log`目录发现，`rhttpproxy.log`为`/scratch/log/rhttpproxy.log`的软链，同时`/var/log`还存在大量`/scratch/log/`目录下的日志软链，可推断出这些日志属于同一个服务，当前使用背景是向虚拟机中上传文件，将观察重点放在以下三个日志中：
        
            lrwxrwxrwx    1 root     root            28 May  9 08:40 hostd-probe.log -> /scratch/log/hostd-probe.log
            lrwxrwxrwx    1 root     root            22 May  9 08:40 hostd.log -> /scratch/log/hostd.log
            lrwxrwxrwx    1 root     root            33 May  9 08:40 hostprofiletrace.log -> /scratch/log/hostprofiletrace.log
        
        再次试验上传文件，在`hostd.log`中发现了相关日志：
        
         *  上传文件至windows10时失败的日志：
            
                2019-05-14T09:23:20.325Z info hostd[809F2B70] [Originator@6876 sub=Guestsvc.GuestFileHandler] GetGuestFileTransferParameters, token is 529424a0-7820-1b3a-ca99-2ff0a6dcfed383
                2019-05-14T09:23:20.325Z info hostd[809F2B70] [Originator@6876 sub=Guestsvc.GuestFileHandler] GetGuestFileTransferParameters: vmmoid is 83
                2019-05-14T09:23:20.325Z info hostd[809F2B70] [Originator@6876 sub=Guestsvc.GuestFileHandler] Guest File Path is C:\123.py
                2019-05-14T09:23:20.326Z info hostd[809F2B70] [Originator@6876 sub=Libs] HGFileCopy_TransferFileUsingReader: Error, cannot convert C:\123.py to CPName
                2019-05-14T09:23:20.326Z info hostd[809F2B70] [Originator@6876 sub=Libs] Vix: [34484 vmGuestOps.cpp:5377]: Error VIX_E_FAIL in CopyFileDoneCallback(): Unknown error
                2019-05-14T09:23:20.326Z error hostd[809F2B70] [Originator@6876 sub=Guestsvc.GuestFileHandler] GuestFileCompleteFunc() job failed with 22
                2019-05-14T09:23:20.326Z error hostd[809F2B70] [Originator@6876 sub=Guestsvc.GuestFileHandler] GuestFileCompleteFunc() throwing InternalServerError
                2019-05-14T09:23:57.819Z info hostd[82381B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5b863a1c-9c2eda01-7eba-20040fe62a62/6saVXPY8U9O2/6saVXPY8U9O2.vmx opID=5f1409c4-bb-0f4b user=vpxuser:Administrator] State Transition (VM_STATE_ON -> VM_STATE_GUEST_OPERATION)
                2019-05-14T09:23:57.894Z info hostd[82880B70] [Originator@6876 sub=Vimsvc.ha-eventmgr] Event 1481 : Guest operation Start Program performed on Virtual machine 6saVXPY8U9O2.
                2019-05-14T09:23:57.896Z info hostd[82880B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5b863a1c-9c2eda01-7eba-20040fe62a62/6saVXPY8U9O2/6saVXPY8U9O2.vmx] State Transition (VM_STATE_GUEST_OPERATION -> VM_STATE_ON)
         *  上传文件至windows7时成功的日志：
            
                2019-05-14T09:36:42.961Z info hostd[82181B70] [Originator@6876 sub=Guestsvc.GuestFileHandler] GetGuestFileTransferParameters, token is 52b097a7-eb63-1efe-914c-703cfef0aa6a78
                2019-05-14T09:36:42.961Z info hostd[82181B70] [Originator@6876 sub=Guestsvc.GuestFileHandler] GetGuestFileTransferParameters: vmmoid is 78
                2019-05-14T09:36:42.961Z info hostd[82181B70] [Originator@6876 sub=Guestsvc.GuestFileHandler] Guest File Path is C:\123.py
                2019-05-14T09:36:43.004Z info hostd[821C2B70] [Originator@6876 sub=Libs] HGFileCopyCreateSessionCB: Successfully created the session.
                2019-05-14T09:36:49.335Z info hostd[82340B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5b863a1c-9c2eda01-7eba-20040fe62a62/windows7_test/windows7_test.vmx opID=5a367cb8-24-1fa5 user=vpxuser:Administrator] State Transition (VM_STATE_ON -> VM_STATE_GUEST_OPERATION)
                2019-05-14T09:36:49.351Z info hostd[821C2B70] [Originator@6876 sub=Vimsvc.ha-eventmgr] Event 1514 : Guest operation List Files performed on Virtual machine windows7_test.
                2019-05-14T09:36:49.352Z info hostd[821C2B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/5b863a1c-9c2eda01-7eba-20040fe62a62/windows7_test/windows7_test.vmx] State Transition (VM_STATE_GUEST_OPERATION -> VM_STATE_ON)
         *  可以看到，成功向windows7虚拟机上传文件时，日志显示
            
                HGFileCopyCreateSessionCB: Successfully created the session.
         *  上传到windows10失败时显示
            
                GuestFileCompleteFunc() job failed with 22
         *  显然esxi上8309端口的服务尝试与windows10虚拟机通过22端口创建连接上传文件，因此失败。
     *  查看虚拟机信息：  
        !\[avatar\]\[failed\_win10\_open\]  
        ![avatar][]  
        可以看到上传文件失败的win10在开启和关闭电源的情况下，都未正确识别出操作系统，同时虚拟机模板也是未能正确识别出操作系统。但win7虚拟机是正确识别出操作系统的。
     *  重新创建虚拟机，要求虚拟机在开启和关闭电源的情况下都正确识别出操作系统：  
        ![avatar][]  
        ![avatar][]
     *  向正确识别操作系统的虚拟机上传文件，上传成功；
 *  vcenter5.5中创建虚拟机不支持选择windows10系统，但vcenter6.0中支持将虚拟机设定为windows10系统：  
    ![avatar][]

[avatar]: