Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[BUG] govmomi/guest/toolbox.Download() returning stream error: failing with stream ID 1; NO_ERROR; received from peer #3635

Open
mjb2k opened this issue Dec 4, 2024 · 3 comments
Open

[BUG] govmomi/guest/toolbox.Download() returning stream error: failing with stream ID 1; NO_ERROR; received from peer #3635

mjb2k opened this issue Dec 4, 2024 · 3 comments

Comments

@mjb2k
Copy link

mjb2k commented Dec 4, 2024

Describe the bug
Sometimes, after some amount of uses, the toolbox.Download() endpoint is returning this error: stream error: failing with stream ID 1; NO_ERROR; received from peer. This happens after about 50 seconds of trying to load the file. I also can verify it's not a network issue with my computer and the VM as they are on the same network.

My hunch is this might be an error with VMWare Tools, but I'd figure I'd ask here since it was caused when I used the govmomi library, and at the very least might be able to add some useful documentation for this error to the Github.

To Reproduce
Steps to reproduce the behavior:

  1. Create Toolbox session with VM
  2. Run `toolbox.Client.Download(ctx, src)

Expected behavior
An io.ReadCloser return type

Affected version
v0.37.3

Screenshots/Debug Output
I also have a log of host.d of ESXi in addition to the error passed by the toolbox method.

2024-12-04T21:35:05.487Z In(166) Hostd[2098866]: [Originator@6876 sub=Guestsvc.GuestFileTransfer] StoreAndReturnToken: Generated token: 52fefac9-6c16-2478-4794-b7c340110cd11357
2024-12-04T21:35:05.488Z Db(167) Hostd[2098866]: [Originator@6876 sub=Vigor.Vmsvc.vm:/vmfs/volumes/67408e59-ec6f2742-d9aa-3cecef1f15c8/python-windows-10-ssd/python-windows-10-ssd.vmx] Initiate file transfer from guest translated error to success
2024-12-04T21:35:05.488Z In(166) Hostd[2098900]: [Originator@6876 sub=Vimsvc.ha-eventmgr] Event 73312 : Guest operation Initiate File Transfer From Guest performed on Virtual machine python-windows-10-ssd.
2024-12-04T21:35:05.489Z In(166) Hostd[2098900]: [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/67408e59-ec6f2742-d9aa-3cecef1f15c8/python-windows-10-ssd/python-windows-10-ssd.vmx] State Transition (VM_STATE_GUEST_OPERATION -> VM_STATE_ON)
2024-12-04T21:35:05.491Z In(166) Hostd[2098867]: [Originator@6876 sub=Hbrsvc] Replicator: powerstate change VM: 1357 Old: 1 New: 1
2024-12-04T21:35:05.503Z In(166) Hostd[2098898]: [Originator@6876 sub=Guestsvc.GuestFileHandler] GetGuestFileTransferParameters, token is 52fefac9-6c16-2478-4794-b7c340110cd11357
2024-12-04T21:35:05.503Z In(166) Hostd[2098898]: [Originator@6876 sub=Guestsvc.GuestFileHandler] GetGuestFileTransferParameters: vmmoid is 1357
2024-12-04T21:35:05.503Z In(166) Hostd[2098898]: [Originator@6876 sub=Guestsvc.GuestFileHandler] Guest File Path is C:\Users\edrsilencer\get_ui_elements.json
2024-12-04T21:35:05.587Z Db(167) Hostd[2098893]: [Originator@6876 sub=Vigor.Vmsvc.vm:/vmfs/volumes/67408e59-ec6f2742-d9aa-3cecef1f15c8/python-windows-10-ssd/python-windows-10-ssd.vmx] Copy file send packet translated error to success
2024-12-04T21:35:05.587Z In(166) Hostd[2098896]: [Originator@6876 sub=Libs] HGFileCopyCreateSessionCB: Successfully created the session.
2024-12-04T21:35:05.635Z Db(167) Hostd[2098894]: [Originator@6876 sub=Vigor.Vmsvc.vm:/vmfs/volumes/67408e59-ec6f2742-d9aa-3cecef1f15c8/python-windows-10-ssd/python-windows-10-ssd.vmx] Copy file send packet translated error to success
2024-12-04T21:35:05.731Z Db(167) Hostd[2098894]: [Originator@6876 sub=Vigor.Vmsvc.vm:/vmfs/volumes/67408e59-ec6f2742-d9aa-3cecef1f15c8/python-windows-10-ssd/python-windows-10-ssd.vmx] Copy file send packet translated error to success
2024-12-04T21:35:05.828Z Db(167) Hostd[2098879]: [Originator@6876 sub=Vigor.Vmsvc.vm:/vmfs/volumes/67408e59-ec6f2742-d9aa-3cecef1f15c8/python-windows-10-ssd/python-windows-10-ssd.vmx] Copy file send packet translated error to success
2024-12-04T21:35:05.925Z Db(167) Hostd[2098878]: [Originator@6876 sub=Vigor.Vmsvc.vm:/vmfs/volumes/67408e59-ec6f2742-d9aa-3cecef1f15c8/python-windows-10-ssd/python-windows-10-ssd.vmx] Copy file send packet translated error to success
2024-12-04T21:35:05.972Z Db(167) Hostd[2098887]: [Originator@6876 sub=Vigor.Vmsvc.vm:/vmfs/volumes/67408e59-ec6f2742-d9aa-3cecef1f15c8/python-windows-10-ssd/python-windows-10-ssd.vmx] Copy file send packet translated error to success
2024-12-04T21:35:06.052Z Db(167) Hostd[2098884]: [Originator@6876 sub=Vigor.Vmsvc.vm:/vmfs/volumes/67408e59-ec6f2742-d9aa-3cecef1f15c8/python-windows-10-ssd/python-windows-10-ssd.vmx] Copy file send packet translated error to success
2024-12-04T21:35:06.148Z Db(167) Hostd[2098868]: [Originator@6876 sub=Vigor.Vmsvc.vm:/vmfs/volumes/67408e59-ec6f2742-d9aa-3cecef1f15c8/python-windows-10-ssd/python-windows-10-ssd.vmx] Copy file send packet translated error to success
2024-12-04T21:35:06.197Z Db(167) Hostd[2098874]: [Originator@6876 sub=Vigor.Vmsvc.vm:/vmfs/volumes/67408e59-ec6f2742-d9aa-3cecef1f15c8/python-windows-10-ssd/python-windows-10-ssd.vmx] Copy file send packet translated error to success
2024-12-04T21:35:06.276Z Db(167) Hostd[2098866]: [Originator@6876 sub=Vigor.Vmsvc.vm:/vmfs/volumes/67408e59-ec6f2742-d9aa-3cecef1f15c8/python-windows-10-ssd/python-windows-10-ssd.vmx] Copy file send packet translated error to success
2024-12-04T21:35:06.325Z Db(167) Hostd[2098883]: [Originator@6876 sub=Vigor.Vmsvc.vm:/vmfs/volumes/67408e59-ec6f2742-d9aa-3cecef1f15c8/python-windows-10-ssd/python-windows-10-ssd.vmx] Copy file send packet translated error to success
2024-12-04T21:35:06.372Z Db(167) Hostd[2098868]: [Originator@6876 sub=Vigor.Vmsvc.vm:/vmfs/volumes/67408e59-ec6f2742-d9aa-3cecef1f15c8/python-windows-10-ssd/python-windows-10-ssd.vmx] Copy file send packet translated error to success
2024-12-04T21:35:06.421Z Db(167) Hostd[2098878]: [Originator@6876 sub=Vigor.Vmsvc.vm:/vmfs/volumes/67408e59-ec6f2742-d9aa-3cecef1f15c8/python-windows-10-ssd/python-windows-10-ssd.vmx] Copy file send packet translated error to success
2024-12-04T21:35:06.499Z Db(167) Hostd[2098899]: [Originator@6876 sub=Vigor.Vmsvc.vm:/vmfs/volumes/67408e59-ec6f2742-d9aa-3cecef1f15c8/python-windows-10-ssd/python-windows-10-ssd.vmx] Copy file send packet translated error to success
2024-12-04T21:35:06.547Z Db(167) Hostd[2098888]: [Originator@6876 sub=Vigor.Vmsvc.vm:/vmfs/volumes/67408e59-ec6f2742-d9aa-3cecef1f15c8/python-windows-10-ssd/python-windows-10-ssd.vmx] Copy file send packet translated error to success
2024-12-04T21:35:06.595Z Db(167) Hostd[2098889]: [Originator@6876 sub=Vigor.Vmsvc.vm:/vmfs/volumes/67408e59-ec6f2742-d9aa-3cecef1f15c8/python-windows-10-ssd/python-windows-10-ssd.vmx] Copy file send packet translated error to success
2024-12-04T21:35:11.192Z In(166) Hostd[2098894]: [Originator@6876 sub=Solo.HttpSvc.HTTPService.HttpConnection] HTTP Connection read failed while waiting for further requests; <io_obj p:0x0000005aa0834168, h:-1, <TCP '127.0.0.1 : 8309'>, <TCP '127.0.0.1 : 15269'>>, N7Vmacore16TimeoutExceptionE(Operation timed out: Stream: <io_obj p:0x0000005aa0834168, h:-1, <TCP '127.0.0.1 : 8309'>, <TCP '127.0.0.1 : 15269'>>, duration: 00:00:47.964199 (hh:mm:ss.us))
2024-12-04T21:35:11.193Z In(166) Hostd[2098844]: --> [context]zKq7AVICAgAAAP////8JaG9zdGQAAANZQWxpYnZtYWNvcmUuc28AAI4PNwCieicA0HsnAI4xKACwTCgAS9lJAYJ6AGxpYnB0aHJlYWQuc28uMAAC7y4PbGliYy5zby42AA==[/context]
2024-12-04T21:35:11.193Z In(166) Hostd[2098871]: [Originator@6876 sub=Solo.HttpSvc.HTTPService.HttpConnection] HTTP Connection read failed while waiting for further requests; <io_obj p:0x0000005aa06b4d08, h:-1, <TCP '127.0.0.1 : 8309'>, <TCP '0.0.0.0 : 0'>>, N7Vmacore16TimeoutExceptionE(Operation timed out: Stream: <io_obj p:0x0000005aa06b4d08, h:-1, <TCP '127.0.0.1 : 8309'>, <TCP '0.0.0.0 : 0'>>, duration: 00:00:46.675947 (hh:mm:ss.us))
2024-12-04T21:35:11.194Z In(166) Hostd[2098844]: --> [context]zKq7AVICAgAAAP////8JaG9zdGQAAANZQWxpYnZtYWNvcmUuc28AAI4PNwCieicA0HsnAI4xKACwTCgAS9lJAYJ6AGxpYnB0aHJlYWQuc28uMAAC7y4PbGliYy5zby42AA==[/context]
2024-12-04T21:35:11.192Z In(166) Hostd[2098872]: [Originator@6876 sub=Solo.HttpSvc.HTTPService.HttpConnection] HTTP Connection read failed while waiting for further requests; <io_obj p:0x0000005a9c282b08, h:-1, <TCP '127.0.0.1 : 8309'>, <TCP '0.0.0.0 : 0'>>, N7Vmacore16TimeoutExceptionE(Operation timed out: Stream: <io_obj p:0x0000005a9c282b08, h:-1, <TCP '127.0.0.1 : 8309'>, <TCP '0.0.0.0 : 0'>>, duration: 00:00:46.685835 (hh:mm:ss.us))
2024-12-04T21:35:11.196Z In(166) Hostd[2098844]: --> [context]zKq7AVICAgAAAP////8JaG9zdGQAAANZQWxpYnZtYWNvcmUuc28AAI4PNwCieicA0HsnAI4xKACwTCgAS9lJAYJ6AGxpYnB0aHJlYWQuc28uMAAC7y4PbGliYy5zby42AA==[/context]
2024-12-04T21:35:11.193Z In(166) Hostd[2098873]: [Originator@6876 sub=Solo.HttpSvc.HTTPService.HttpConnection] HTTP Connection read failed while waiting for further requests; <io_obj p:0x0000005aa07f24e8, h:-1, <TCP '127.0.0.1 : 8309'>, <TCP '0.0.0.0 : 0'>>, N7Vmacore16TimeoutExceptionE(Operation timed out: Stream: <io_obj p:0x0000005aa07f24e8, h:-1, <TCP '127.0.0.1 : 8309'>, <TCP '0.0.0.0 : 0'>>, duration: 00:00:46.675637 (hh:mm:ss.us))
2024-12-04T21:35:11.197Z In(166) Hostd[2098844]: --> [context]zKq7AVICAgAAAP////8JaG9zdGQAAANZQWxpYnZtYWNvcmUuc28AAI4PNwCieicA0HsnAI4xKACwTCgAS9lJAYJ6AGxpYnB0aHJlYWQuc28uMAAC7y4PbGliYy5zby42AA==[/context]
2024-12-04T21:35:11.192Z In(166) Hostd[2098866]: [Originator@6876 sub=Solo.HttpSvc.HTTPService.HttpConnection] HTTP Connection read failed while waiting for further requests; <io_obj p:0x0000005aa01fdca8, h:-1, <TCP '127.0.0.1 : 8309'>, <TCP '0.0.0.0 : 0'>>, N7Vmacore16TimeoutExceptionE(Operation timed out: Stream: <io_obj p:0x0000005aa01fdca8, h:-1, <TCP '127.0.0.1 : 8309'>, <TCP '0.0.0.0 : 0'>>, duration: 00:00:46.686267 (hh:mm:ss.us))
2024-12-04T21:35:11.199Z In(166) Hostd[2098844]: --> [context]zKq7AVICAgAAAP////8JaG9zdGQAAANZQWxpYnZtYWNvcmUuc28AAI4PNwCieicA0HsnAI4xKACwTCgAS9lJAYJ6AGxpYnB0aHJlYWQuc28uMAAC7y4PbGliYy5zby42AA==[/context]
2024-12-04T21:35:11.193Z In(166) Hostd[2098876]: [Originator@6876 sub=Solo.HttpSvc.HTTPService.HttpConnection] HTTP Connection read failed while waiting for further requests; <io_obj p:0x0000005aa0813198, h:-1, <TCP '127.0.0.1 : 8309'>, <TCP '127.0.0.1 : 36622'>>, N7Vmacore16TimeoutExceptionE(Operation timed out: Stream: <io_obj p:0x0000005aa0813198, h:-1, <TCP '127.0.0.1 : 8309'>, <TCP '127.0.0.1 : 36622'>>, duration: 00:00:46.676113 (hh:mm:ss.us))
2024-12-04T21:35:11.201Z In(166) Hostd[2098844]: --> [context]zKq7AVICAgAAAP////8JaG9zdGQAAANZQWxpYnZtYWNvcmUuc28AAI4PNwCieicA0HsnAI4xKACwTCgAS9lJAYJ6AGxpYnB0aHJlYWQuc28uMAAC7y4PbGliYy5zby42AA==[/context]
2024-12-04T21:35:11.212Z In(166) Hostd[2098868]: [Originator@6876 sub=Solo.HTTP server /host user=root] Sent OK response for GET /host/hostd.log
2024-12-04T21:35:16.196Z In(166) Hostd[2098866]: [Originator@6876 sub=Solo.HttpSvc.HTTPService.HttpConnection] HTTP Connection read failed while waiting for further requests; <io_obj p:0x0000005aa0b161d8, h:-1, <TCP '127.0.0.1 : 8309'>, <TCP '0.0.0.0 : 0'>>, N7Vmacore16TimeoutExceptionE(Operation timed out: Stream: <io_obj p:0x0000005aa0b161d8, h:-1, <TCP '127.0.0.1 : 8309'>, <TCP '0.0.0.0 : 0'>>, duration: 00:00:48.085773 (hh:mm:ss.us))
2024-12-04T21:35:16.197Z In(166) Hostd[2098844]: --> [context]zKq7AVICAgAAAP////8JaG9zdGQAAANZQWxpYnZtYWNvcmUuc28AAI4PNwCieicA0HsnAI4xKACwTCgAS9lJAYJ6AGxpYnB0aHJlYWQuc28uMAAC7y4PbGliYy5zby42AA==[/context]
2024-12-04T21:35:16.196Z In(166) Hostd[2098891]: [Originator@6876 sub=Solo.HttpSvc.HTTPService.HttpConnection] HTTP Connection read failed while waiting for further requests; <io_obj p:0x0000005a9c677818, h:-1, <TCP '127.0.0.1 : 8309'>, <TCP '0.0.0.0 : 0'>>, N7Vmacore16TimeoutExceptionE(Operation timed out: Stream: <io_obj p:0x0000005a9c677818, h:-1, <TCP '127.0.0.1 : 8309'>, <TCP '0.0.0.0 : 0'>>, duration: 00:00:48.086225 (hh:mm:ss.us))
2024-12-04T21:35:16.198Z In(166) Hostd[2098844]: --> [context]zKq7AVICAgAAAP////8JaG9zdGQAAANZQWxpYnZtYWNvcmUuc28AAI4PNwCieicA0HsnAI4xKACwTCgAS9lJAYJ6AGxpYnB0aHJlYWQuc28uMAAC7y4PbGliYy5zby42AA==[/context]
2024-12-04T21:35:16.196Z In(166) Hostd[2098889]: [Originator@6876 sub=Solo.HttpSvc.HTTPService.HttpConnection] HTTP Connection read failed while waiting for further requests; <io_obj p:0x0000005a47e6a608, h:-1, <TCP '127.0.0.1 : 8309'>, <TCP '127.0.0.1 : 45916'>>, N7Vmacore16TimeoutExceptionE(Operation timed out: Stream: <io_obj p:0x0000005a47e6a608, h:-1, <TCP '127.0.0.1 : 8309'>, <TCP '127.0.0.1 : 45916'>>, duration: 00:00:48.086330 (hh:mm:ss.us))
2024-12-04T21:35:16.200Z In(166) Hostd[2098844]: --> [context]zKq7AVICAgAAAP////8JaG9zdGQAAANZQWxpYnZtYWNvcmUuc28AAI4PNwCieicA0HsnAI4xKACwTCgAS9lJAYJ6AGxpYnB0aHJlYWQuc28uMAAC7y4PbGliYy5zby42AA==[/context]
2024-12-04T21:35:16.196Z In(166) Hostd[2098883]: [Originator@6876 sub=Solo.HttpSvc.HTTPService.HttpConnection] HTTP Connection read failed while waiting for further requests; <io_obj p:0x0000005aa0a31308, h:-1, <TCP '127.0.0.1 : 8309'>, <TCP '127.0.0.1 : 50360'>>, N7Vmacore16TimeoutExceptionE(Operation timed out: Stream: <io_obj p:0x0000005aa0a31308, h:-1, <TCP '127.0.0.1 : 8309'>, <TCP '127.0.0.1 : 50360'>>, duration: 00:00:48.085898 (hh:mm:ss.us))
2024-12-04T21:35:16.201Z In(166) Hostd[2098844]: --> [context]zKq7AVICAgAAAP////8JaG9zdGQAAANZQWxpYnZtYWNvcmUuc28AAI4PNwCieicA0HsnAI4xKACwTCgAS9lJAYJ6AGxpYnB0aHJlYWQuc28uMAAC7y4PbGliYy5zby42AA==[/context]
2024-12-04T21:35:16.196Z In(166) Hostd[2098875]: [Originator@6876 sub=Solo.HttpSvc.HTTPService.HttpConnection] HTTP Connection read failed while waiting for further requests; <io_obj p:0x0000005aa0a5a698, h:-1, <TCP '127.0.0.1 : 8309'>, <TCP '127.0.0.1 : 52698'>>, N7Vmacore16TimeoutExceptionE(Operation timed out: Stream: <io_obj p:0x0000005aa0a5a698, h:-1, <TCP '127.0.0.1 : 8309'>, <TCP '127.0.0.1 : 52698'>>, duration: 00:00:45.704481 (hh:mm:ss.us))
2024-12-04T21:35:16.203Z In(166) Hostd[2098844]: --> [context]zKq7AVICAgAAAP////8JaG9zdGQAAANZQWxpYnZtYWNvcmUuc28AAI4PNwCieicA0HsnAI4xKACwTCgAS9lJAYJ6AGxpYnB0aHJlYWQuc28uMAAC7y4PbGliYy5zby42AA==[/context]
2024-12-04T21:35:26.202Z In(166) Hostd[2098898]: [Originator@6876 sub=SoapAdapter.HTTPService.HttpConnection] HTTP Connection read failed while waiting for further requests; <io_obj p:0x0000005aa084e6d8, h:-1, <TCP '127.0.0.1 : 8307'>, <TCP '127.0.0.1 : 58272'>>, N7Vmacore16TimeoutExceptionE(Operation timed out: Stream: <io_obj p:0x0000005aa084e6d8, h:-1, <TCP '127.0.0.1 : 8307'>, <TCP '127.0.0.1 : 58272'>>, duration: 00:00:48.278362 (hh:mm:ss.us))
2024-12-04T21:35:26.203Z In(166) Hostd[2098844]: --> [context]zKq7AVICAgAAAP////8JaG9zdGQAAANZQWxpYnZtYWNvcmUuc28AAI4PNwCieicA0HsnAI4xKACwTCgAS9lJAYJ6AGxpYnB0aHJlYWQuc28uMAAC7y4PbGliYy5zby42AA==[/context]
2024-12-04T21:35:31.205Z In(166) Hostd[2098883]: [Originator@6876 sub=Solo.HttpSvc.HTTPService.HttpConnection] HTTP Connection read failed while waiting for further requests; <io_obj p:0x0000005aa04f1d28, h:-1, <TCP '127.0.0.1 : 8309'>, <TCP '0.0.0.0 : 0'>>, N7Vmacore16TimeoutExceptionE(Operation timed out: Stream: <io_obj p:0x0000005aa04f1d28, h:-1, <TCP '127.0.0.1 : 8309'>, <TCP '0.0.0.0 : 0'>>, duration: 00:00:46.514746 (hh:mm:ss.us))
2024-12-04T21:35:31.207Z In(166) Hostd[2098844]: --> [context]zKq7AVICAgAAAP////8JaG9zdGQAAANZQWxpYnZtYWNvcmUuc28AAI4PNwCieicA0HsnAI4xKACwTCgAS9lJAYJ6AGxpYnB0aHJlYWQuc28uMAAC7y4PbGliYy5zby42AA==[/context]
@github-actions GitHub Actions
Copy link
Contributor

github-actions bot commented Dec 4, 2024

Howdy 🖐   mjb2k ! Thank you for your interest in this project. We value your feedback and will respond soon.

If you want to contribute to this project, please make yourself familiar with the CONTRIBUTION guidelines.

@mjb2k
Copy link
Author

mjb2k commented Dec 12, 2024

I encountered this error again today and this time I recorded some metrics from the VM. Notably, the CPU usage spikes massively when the error occurs.

exported

The last two spikes were two separate runs of my process, which immediately errored with the above error.

The group of spikes before that is another run that worked for some time before also failing.

@dougm
Copy link
Member

dougm commented Dec 19, 2024

Haven't seen that error before. Are you sure the connection is being closed after each download? You can check connections to the host using:

% host=$(govc collect -s vm/your-vm-name summary.runtime.host)
% govc host.esxcli -host $host network ip connection list

Can you reproduce using govc guest.download ?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@dougm @mjb2k