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.

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

x/crypto/ssh: failed to interact with Windows Powershell OpenSSH server #18901

Closed
olegdunkan opened this issue Feb 2, 2017 · 12 comments
Closed

x/crypto/ssh: failed to interact with Windows Powershell OpenSSH server #18901

olegdunkan opened this issue Feb 2, 2017 · 12 comments

Comments

@olegdunkan
Copy link

@olegdunkan olegdunkan commented Feb 2, 2017

Please answer these questions before submitting your issue. Thanks!

What version of Go are you using (go version)?

1.8

What operating system and processor architecture are you using (go env)?

amd64 windows

What did you do?

	config := &ssh.ClientConfig{
		User: "user",
		Auth: []ssh.AuthMethod{
			ssh.Password("password"),
		},
	}
	client, err := ssh.Dial("tcp", "*.*.*.*:22", config)
	if err != nil {
		log.Fatal("Failed to connect to server: " + err.Error())
	}
	session, err := client.NewSession()
	if err != nil {
		log.Fatal("Failed to create session: " + err.Error())
	}
	defer session.Close()
	buf, err := session.CombinedOutput("echo ok")
	if err != nil {
		log.Println(err)
	}
	log.Println(string(buf))

What did you expect to see?

Output in console: Ok

What did you see instead?

Nothing

The other side of ssh channel is open-ssh https://github.com/PowerShell/Win32-OpenSSH
v0.0.8.0

This is normal output when we run program as is (no ok in console):

2017/02/02 16:19:58 send global(1): ssh.channelOpenMsg{ChanType:"session", PeersId:0x1, PeersWindow:0x200000, MaxPacketSize:0x8000, TypeSpecificData:[]uint8(nil)}
2017/02/02 16:19:58 decoding(1): 80 &ssh.globalRequestMsg{Type:"hostkeys-00@openssh.com", WantReply:false, Data:[]uint8{...}} - 912 bytes
2017/02/02 16:19:59 decoding(1): 91 &ssh.channelOpenConfirmMsg{PeersId:0x1, MyId:0x0, MyWindow:0x0, MaxPacketSize:0x8000, TypeSpecificData:[]uint8{}} - 17 bytes
2017/02/02 16:19:59 send(1): ssh.channelRequestMsg{PeersId:0x0, Request:"exec", WantReply:true, RequestSpecificData:[]uint8{0x0, 0x0, 0x0, 0x7, 0x65, 0x63, 0x68, 0x6f, 0x20, 0x6f, 0x6b}}
2017/02/02 16:19:59 decoding(1): 93 &ssh.windowAdjustMsg{PeersId:0x1, AdditionalBytes:0x200000} - 9 bytes
2017/02/02 16:19:59 decoding(1): 99 &ssh.channelRequestSuccessMsg{PeersId:0x1} - 5 bytes
2017/02/02 16:19:59 send(1): ssh.channelEOFMsg{PeersId:0x0}
2017/02/02 16:19:59 decoding(1): 96 &ssh.channelEOFMsg{PeersId:0x1} - 5 bytes
2017/02/02 16:19:59 decoding(1): 98 &ssh.channelRequestMsg{PeersId:0x1, Request:"exit-status", WantReply:false, RequestSpecificData:[]uint8{0x0, 0x0, 0x0, 0x0}} - 25 bytes
2017/02/02 16:19:59 decoding(1): 97 &ssh.channelCloseMsg{PeersId:0x1} - 5 bytes
2017/02/02 16:19:59 send(1): ssh.channelCloseMsg{PeersId:0x0}
2017/02/02 16:19:59 
2017/02/02 16:19:59 send(1): ssh.channelCloseMsg{PeersId:0x0}

This is interrupted (debugged via breakpoint, check it out by time stamp) output of the same program (we can see we received additional data packet and output is what I have expected),:

2017/02/02 16:22:56 send global(1): ssh.channelOpenMsg{ChanType:"session", PeersId:0x1, PeersWindow:0x200000, MaxPacketSize:0x8000, TypeSpecificData:[]uint8(nil)}
2017/02/02 16:22:56 decoding(1): 80 &ssh.globalRequestMsg{Type:"hostkeys-00@openssh.com", WantReply:false, Data:[]uint8{...}} - 912 bytes
2017/02/02 16:22:56 decoding(1): 91 &ssh.channelOpenConfirmMsg{PeersId:0x1, MyId:0x0, MyWindow:0x0, MaxPacketSize:0x8000, TypeSpecificData:[]uint8{}} - 17 bytes
2017/02/02 16:23:08 send(1): ssh.channelRequestMsg{PeersId:0x0, Request:"exec", WantReply:true, RequestSpecificData:[]uint8{0x0, 0x0, 0x0, 0x7, 0x65, 0x63, 0x68, 0x6f, 0x20, 0x6f, 0x6b}}
2017/02/02 16:23:08 decoding(1): 93 &ssh.windowAdjustMsg{PeersId:0x1, AdditionalBytes:0x200000} - 9 bytes
2017/02/02 16:23:16 decoding(1): 99 &ssh.channelRequestSuccessMsg{PeersId:0x1} - 5 bytes
2017/02/02 16:23:23 decoding(1): data packet - 13 bytes
2017/02/02 16:23:23 send(1): ssh.channelEOFMsg{PeersId:0x0}
2017/02/02 16:23:23 decoding(1): 96 &ssh.channelEOFMsg{PeersId:0x1} - 5 bytes
2017/02/02 16:23:23 decoding(1): 98 &ssh.channelRequestMsg{PeersId:0x1, Request:"exit-status", WantReply:false, RequestSpecificData:[]uint8{0x0, 0x0, 0x0, 0x0}} - 25 bytes
2017/02/02 16:23:23 decoding(1): 97 &ssh.channelCloseMsg{PeersId:0x1} - 5 bytes
2017/02/02 16:23:23 send(1): ssh.channelCloseMsg{PeersId:0x0}
2017/02/02 16:23:23 send(1): ssh.windowAdjustMsg{PeersId:0x0, AdditionalBytes:0x4}
2017/02/02 16:23:23 ok

2017/02/02 16:23:23 send(1): ssh.channelCloseMsg{PeersId:0x0}

I will create the same issue at https://github.com/PowerShell/Win32-OpenSSH.
Maybe the issue is not related entirely to this repo but I post this issue to this repo because it strange if we get the expected behavior while debugging program.

@odeke-em odeke-em changed the title Crypto failed interaction with openssh win x/crypto/ssh: failed to interact with Windows Powershell OpenSSH server Feb 2, 2017
@odeke-em
Copy link
Member

@odeke-em odeke-em commented Feb 2, 2017

/cc @hanwen

@hanwen
Copy link
Contributor

@hanwen hanwen commented Feb 2, 2017

what is the problem you observe?

2017/02/02 16:23:23 send(1): ssh.windowAdjustMsg{PeersId:0x0, AdditionalBytes:0x4}

looks suspect, since it shouldn't be happening after we send the channelClose.

@olegdunkan
Copy link
Author

@olegdunkan olegdunkan commented Feb 2, 2017

@hanwen Do you refer to second above log?
If so then this log from abnormal execution of program (interrupted by breakpoint) that give us right output (and it is strange).
The log of normal execution program is presented first, we didn't see ok in it.
Could you explain please why when do we interrupt program we get right result but in case of normal execution we doesn't?

@hanwen
Copy link
Contributor

@hanwen hanwen commented Feb 2, 2017

the remote end has a bug. You can see it wants to send something (it sends windowAdjust) but then it sends exit-status and closes the channel before sending the data.

2017/02/02 16:19:59 decoding(1): 93 &ssh.windowAdjustMsg{PeersId:0x1, AdditionalBytes:0x200000} - 9 bytes
2017/02/02 16:19:59 decoding(1): 99 &ssh.channelRequestSuccessMsg{PeersId:0x1} - 5 bytes
2017/02/02 16:19:59 send(1): ssh.channelEOFMsg{PeersId:0x0}
2017/02/02 16:19:59 decoding(1): 96 &ssh.channelEOFMsg{PeersId:0x1} - 5 bytes
2017/02/02 16:19:59 decoding(1): 98 &ssh.channelRequestMsg{PeersId:0x1, Request:"exit-status", WantReply:false, RequestSpecificData:[]uint8{0x0, 0x0, 0x0, 0x0}} - 25 bytes
2017/02/02 16:19:59 decoding(1): 97 &ssh.channelCloseMsg{PeersId:0x1} - 5 bytes

@hanwen
Copy link
Contributor

@hanwen hanwen commented Feb 2, 2017

Sorry, I think the windowAdjust is the remote end saying we can send more data. Nevertheless, the remote end kills the connection before flushing its data. So nothing prints.

@hanwen hanwen closed this Feb 2, 2017
@olegdunkan
Copy link
Author

@olegdunkan olegdunkan commented Feb 2, 2017

@hanwen ok, thanks.

@olegdunkan
Copy link
Author

@olegdunkan olegdunkan commented Feb 2, 2017

@hanwen one more addon, when we execute plink(ssh client) in windows console (cmd) then it works fine. But we execute plink in golang like so:

buf, err = exec.Command("plink", "-batch", "-i", `.\key.ppk`, "user@server", "echo", "ok").CombinedOutput()
	if err != nil {
		log.Println(err)
	}
	log.Println(string(buf))

then we have the same issue.

@hanwen
Copy link
Contributor

@hanwen hanwen commented Feb 6, 2017

Does this work differently with other SSH clients?

My suggestion is to write a little wrapper that flushes the output and sleeps for a bit so the data has the chance to get to the other side.

@olegdunkan
Copy link
Author

@olegdunkan olegdunkan commented Feb 6, 2017

@hanwen I don't know I have tried only putty. Golang too fast. It doesn't leave any chance to flash output to other side of connection))). Thanks for advice I will try.

@olegdunkan
Copy link
Author

@olegdunkan olegdunkan commented Feb 7, 2017

@hanwen Did you suggest wrapper around exec.Command?

@hanwen
Copy link
Contributor

@hanwen hanwen commented Feb 8, 2017

The wrapper has to run on the remote end, and be alive long enough to send the output.

@olegdunkan
Copy link
Author

@olegdunkan olegdunkan commented Feb 8, 2017

@hanwen Thanks. I think they (https://github.com/PowerShell/Win32-OpenSSH) have to resolve right order of messages because after 2017/02/02 16:19:59 decoding(1): 97 &ssh.channelCloseMsg{PeersId:0x1} we have to expect no data on closed channel. You are right it is a bug on the remote end.

@golang golang locked and limited conversation to collaborators Feb 8, 2018
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Linked pull requests

Successfully merging a pull request may close this issue.

None yet
4 participants
You can’t perform that action at this time.