Topic "authenticated but can't login to FreeBSD 10.2 OpenSSH_6.6.1p1"

Author Message
Guest




I can't login via scp into my FreeBSD 10.2 server using a key. I get these messages:

Code:
Searching for host...
Connecting to host...
Authenticating...
Using username "johnsmith".
Authenticating with public key "imported-openssh-key".
Authenticated.
Starting the session...


And this is where the process stops.

"Optimize connection buffer size" is disabled in Advanced Site Settings > Connection.

Doing a 'sshd -v' in FreeBSD gives me:

Code:
OpenSSH_6.6.1p1, OpenSSL 1.0.1p-freebsd 9 Jul 2015


What am I missing here?

Oh, here is my WinSCP log:

Code:
. 2015-08-19 05:59:08.031 --------------------------------------------------------------------------
. 2015-08-19 05:59:08.031 WinSCP Version 5.7.5 (Build 5665) (OS 5.1.2600 Service Pack 3 - Microsoft Windows XP)
. 2015-08-19 05:59:08.031 Configuration: .\winscp\WinSCP.ini
. 2015-08-19 05:59:08.031 Log level: Debug 2
. 2015-08-19 05:59:08.031 Local account: johnsmithPC\johnsmith
. 2015-08-19 05:59:08.031 Working directory: .\winscp
. 2015-08-19 05:59:08.031 Process ID: 756
. 2015-08-19 05:59:08.031 Command-line: ".\winscp\WinSCP.exe"
. 2015-08-19 05:59:08.031 Time zone: Current: GMT+3, Standard: GMT+2 (GTB Standard Time), DST: GMT+3 (GTB Standard Time), DST Start: 3/29/2015, DST End: 10/25/2015
. 2015-08-19 05:59:08.031 Login time: Wednesday, August 19, 2015 5:59:08 AM
. 2015-08-19 05:59:08.031 --------------------------------------------------------------------------
. 2015-08-19 05:59:08.031 Session name: johnsmith@10.0.0.3 (FreeBSD - SSH) (Site)
. 2015-08-19 05:59:08.031 Host name: 10.0.0.3 (Port: 22)
. 2015-08-19 05:59:08.031 User name: johnsmith (Password: Yes, Key file: Yes)
. 2015-08-19 05:59:08.031 Tunnel: No
. 2015-08-19 05:59:08.031 Transfer Protocol: SCP
. 2015-08-19 05:59:08.031 Ping type: -, Ping interval: 30 sec; Timeout: 15 sec
. 2015-08-19 05:59:08.031 Disable Nagle: No
. 2015-08-19 05:59:08.031 Proxy: none
. 2015-08-19 05:59:08.031 Send buffer: 0
. 2015-08-19 05:59:08.031 SSH protocol version: 2; Compression: No
. 2015-08-19 05:59:08.031 Bypass authentication: No
. 2015-08-19 05:59:08.031 Try agent: Yes; Agent forwarding: No; TIS/CryptoCard: No; KI: No; GSSAPI: No
. 2015-08-19 05:59:08.031 Ciphers: aes,blowfish,3des,WARN,arcfour,des; Ssh2DES: No
. 2015-08-19 05:59:08.031 KEX: rsa,dh-gex-sha1,dh-group14-sha1,dh-group1-sha1,WARN
. 2015-08-19 05:59:08.031 SSH Bugs: A,A,A,A,A,A,A,A,A,A,A,A
. 2015-08-19 05:59:08.031 Simple channel: No
. 2015-08-19 05:59:08.031 Return code variable: Autodetect; Lookup user groups: A
. 2015-08-19 05:59:08.031 Shell: default
. 2015-08-19 05:59:08.031 EOL: 0, UTF: 2
. 2015-08-19 05:59:08.031 Clear aliases: Yes, Unset nat.vars: Yes, Resolve symlinks: Yes
. 2015-08-19 05:59:08.031 LS: ls -la, Ign LS warn: Yes, Scp1 Comp: No
. 2015-08-19 05:59:08.031 Local directory: default, Remote directory: home, Update: Yes, Cache: Yes
. 2015-08-19 05:59:08.031 Cache directory changes: Yes, Permanent: Yes
. 2015-08-19 05:59:08.031 DST mode: 1;Timezone offset: 0h 0m
. 2015-08-19 05:59:08.031 --------------------------------------------------------------------------
. 2015-08-19 05:59:08.078 Looking up host "10.0.0.3"
. 2015-08-19 05:59:08.078 Connecting to 10.0.0.3 port 22
. 2015-08-19 05:59:08.078 Selecting events 63 for socket 824
. 2015-08-19 05:59:08.125 Waiting for the server to continue with the initialization
. 2015-08-19 05:59:08.125 Looking for incoming data
. 2015-08-19 05:59:08.125 Looking for network events
. 2015-08-19 05:59:08.125 Detected network event
. 2015-08-19 05:59:08.125 Enumerating network events for socket 824
. 2015-08-19 05:59:08.125 Enumerated 19 network events making 19 cumulative events for socket 824
. 2015-08-19 05:59:08.125 Handling network read event on socket 824 with error 0
. 2015-08-19 05:59:08.125 Server version: SSH-2.0-OpenSSH_6.6.1_hpn13v11 FreeBSD-20140420
. 2015-08-19 05:59:08.125 Using SSH protocol version 2
. 2015-08-19 05:59:08.125 We claim version: SSH-2.0-WinSCP_release_5.7.5
. 2015-08-19 05:59:08.125 Handling network write event on socket 824 with error 0
. 2015-08-19 05:59:08.125 Handling network connect event on socket 824 with error 0
. 2015-08-19 05:59:08.125 Waiting for the server to continue with the initialization
. 2015-08-19 05:59:08.125 Looking for incoming data
. 2015-08-19 05:59:08.125 Looking for network events
. 2015-08-19 05:59:08.140 Detected network event
. 2015-08-19 05:59:08.140 Enumerating network events for socket 824
. 2015-08-19 05:59:08.140 Enumerated 1 network events making 1 cumulative events for socket 824
. 2015-08-19 05:59:08.140 Handling network read event on socket 824 with error 0
. 2015-08-19 05:59:08.140 Doing Diffie-Hellman group exchange
. 2015-08-19 05:59:08.140 Waiting for the server to continue with the initialization
. 2015-08-19 05:59:08.140 Looking for incoming data
. 2015-08-19 05:59:08.140 Looking for network events
. 2015-08-19 05:59:08.250 Detected network event
. 2015-08-19 05:59:08.250 Enumerating network events for socket 824
. 2015-08-19 05:59:08.250 Enumerated 1 network events making 1 cumulative events for socket 824
. 2015-08-19 05:59:08.250 Handling network read event on socket 824 with error 0
. 2015-08-19 05:59:08.250 Doing Diffie-Hellman key exchange with hash SHA-256
. 2015-08-19 05:59:08.656 Waiting for the server to continue with the initialization
. 2015-08-19 05:59:08.656 Looking for incoming data
. 2015-08-19 05:59:08.656 Looking for network events
. 2015-08-19 05:59:08.671 Detected network event
. 2015-08-19 05:59:08.671 Enumerating network events for socket 824
. 2015-08-19 05:59:08.671 Enumerated 1 network events making 1 cumulative events for socket 824
. 2015-08-19 05:59:08.671 Handling network read event on socket 824 with error 0
. 2015-08-19 05:59:09.125 Verifying host key rsa2 0x10001,0xb59a3e27710509e5 594332ab5f0efd57 5173baa0c04c27ec f53c9ceecd213e8d 5e61e57bcb7b8c50 d31d92403a5cfba4 3e6a60bd286b4f6b e234f6c760c09f90 dce78c1b4f9f608a 2f810fb267c35b87 d7c41b831a875227 1deeec45025aa596 ee46d36f28864cc3 0ae3e6e1501c1575 edddf5562cc7010b 88d39d7a50e8520f f0c5afab96f665c3 53049245cdee0e74 789b2c5b9d7fcf25 c19e3aeee6913d83 63286b41a9ba1c54 971cfc2b149fc8e4 1c25ca8d0863d4dd 00d9ce110979bc5b 5c61606c27df57b3 ba7327a15188878d a2aa4ef42703d4d7 2c383fd16cbb7a05 20565da500a2f1aa 0e046f19a3dc4cf4 95601a1f9fe24fc7 4dee2308c4aaf835  with fingerprint ssh-rsa 2048 8e:88:f4:ba:af:98:1a:87:78:10:c0:25:95:8c:b5:d3
. 2015-08-19 05:59:09.156 Host key matches cached key
. 2015-08-19 05:59:09.156 Selecting events 63 for socket 824
. 2015-08-19 05:59:09.156 Host key fingerprint is:
. 2015-08-19 05:59:09.156 ssh-rsa 2048 8e:88:f4:ba:af:98:1a:87:78:10:c0:25:95:8c:b5:d3
. 2015-08-19 05:59:09.156 Initialised AES-256 SDCTR client->server encryption
. 2015-08-19 05:59:09.156 Initialised HMAC-SHA-256 client->server MAC algorithm
. 2015-08-19 05:59:09.156 Initialised AES-256 SDCTR server->client encryption
. 2015-08-19 05:59:09.156 Initialised HMAC-SHA-256 server->client MAC algorithm
. 2015-08-19 05:59:09.156 Waiting for the server to continue with the initialization
. 2015-08-19 05:59:09.156 Looking for incoming data
. 2015-08-19 05:59:09.156 Looking for network events
. 2015-08-19 05:59:09.250 Detected network event
. 2015-08-19 05:59:09.250 Enumerating network events for socket 824
. 2015-08-19 05:59:09.250 Enumerated 1 network events making 1 cumulative events for socket 824
. 2015-08-19 05:59:09.250 Handling network read event on socket 824 with error 0
. 2015-08-19 05:59:09.250 Reading private key file ".\winscp\keys\freebsd.prv.ppk"
! 2015-08-19 05:59:09.250 Using username "johnsmith".
. 2015-08-19 05:59:09.296 Waiting for the server to continue with the initialization
. 2015-08-19 05:59:09.296 Looking for incoming data
. 2015-08-19 05:59:09.296 Looking for network events
. 2015-08-19 05:59:09.312 Detected network event
. 2015-08-19 05:59:09.312 Enumerating network events for socket 824
. 2015-08-19 05:59:09.312 Enumerated 1 network events making 1 cumulative events for socket 824
. 2015-08-19 05:59:09.312 Handling network read event on socket 824 with error 0
. 2015-08-19 05:59:09.312 Offered public key
. 2015-08-19 05:59:09.312 Waiting for the server to continue with the initialization
. 2015-08-19 05:59:09.312 Looking for incoming data
. 2015-08-19 05:59:09.312 Looking for network events
. 2015-08-19 05:59:09.312 Detected network event
. 2015-08-19 05:59:09.312 Enumerating network events for socket 824
. 2015-08-19 05:59:09.312 Enumerated 1 network events making 1 cumulative events for socket 824
. 2015-08-19 05:59:09.312 Handling network read event on socket 824 with error 0
. 2015-08-19 05:59:09.312 Offer of public key accepted
! 2015-08-19 05:59:09.312 Authenticating with public key "imported-openssh-key"
. 2015-08-19 05:59:09.484 Sent public key signature
. 2015-08-19 05:59:09.484 Waiting for the server to continue with the initialization
. 2015-08-19 05:59:09.484 Looking for incoming data
. 2015-08-19 05:59:09.484 Looking for network events
. 2015-08-19 05:59:09.484 Detected network event
. 2015-08-19 05:59:09.484 Enumerating network events for socket 824
. 2015-08-19 05:59:09.484 Enumerated 1 network events making 1 cumulative events for socket 824
. 2015-08-19 05:59:09.484 Handling network read event on socket 824 with error 0
. 2015-08-19 05:59:09.484 Access granted
. 2015-08-19 05:59:09.484 Opening session as main channel
. 2015-08-19 05:59:09.484 Waiting for the server to continue with the initialization
. 2015-08-19 05:59:09.484 Looking for incoming data
. 2015-08-19 05:59:09.484 Looking for network events
. 2015-08-19 05:59:09.500 Detected network event
. 2015-08-19 05:59:09.500 Enumerating network events for socket 824
. 2015-08-19 05:59:09.500 Enumerated 1 network events making 1 cumulative events for socket 824
. 2015-08-19 05:59:09.500 Handling network read event on socket 824 with error 0
. 2015-08-19 05:59:09.500 Opened main channel
. 2015-08-19 05:59:09.500 Waiting for the server to continue with the initialization
. 2015-08-19 05:59:09.500 Looking for incoming data
. 2015-08-19 05:59:09.500 Looking for network events
. 2015-08-19 05:59:09.500 Detected network event
. 2015-08-19 05:59:09.500 Enumerating network events for socket 824
. 2015-08-19 05:59:09.500 Enumerated 1 network events making 1 cumulative events for socket 824
. 2015-08-19 05:59:09.500 Handling network read event on socket 824 with error 0
. 2015-08-19 05:59:09.500 Started a shell/command
. 2015-08-19 05:59:09.500 --------------------------------------------------------------------------
. 2015-08-19 05:59:09.500 Using SCP protocol.
. 2015-08-19 05:59:09.500 Doing startup conversation with host.
. 2015-08-19 05:59:09.500 Session upkeep
. 2015-08-19 05:59:09.500 Looking for network events
. 2015-08-19 05:59:09.500 Detected network event
. 2015-08-19 05:59:09.500 Enumerating network events for socket 824
. 2015-08-19 05:59:09.500 Enumerated 1 network events making 1 cumulative events for socket 824
. 2015-08-19 05:59:09.500 Handling network read event on socket 824 with error 0
. 2015-08-19 05:59:09.500 Received 84 bytes (0)
. 2015-08-19 05:59:09.500 Received 127 bytes (0)
. 2015-08-19 05:59:09.546 Skipping host startup message (if any).
> 2015-08-19 05:59:09.546 echo "WinSCP: this is end-of-file:0"
. 2015-08-19 05:59:09.546 Sent 37 bytes
. 2015-08-19 05:59:09.546 There are 0 bytes remaining in the send buffer
. 2015-08-19 05:59:09.546 Looking for network events
. 2015-08-19 05:59:09.546 Timeout waiting for network events
. 2015-08-19 05:59:09.546 Read 49 bytes (162 pending)
< 2015-08-19 05:59:09.546 Warning: no access to tty (Bad file descriptor).
. 2015-08-19 05:59:09.546 Read 35 bytes (127 pending)
< 2015-08-19 05:59:09.546 Thus no job control in this shell.
. 2015-08-19 05:59:09.546 Read 72 bytes (55 pending)
< 2015-08-19 05:59:09.546 Need to see the calendar for this month? Simply type "cal".  To see the
. 2015-08-19 05:59:09.546 Read 27 bytes (28 pending)
< 2015-08-19 05:59:09.546 whole year, type "cal -y".
. 2015-08-19 05:59:09.546 Read 28 bytes (0 pending)
< 2015-08-19 05:59:09.546       -- Dru <genesis@istar.ca>
. 2015-08-19 05:59:09.546 Waiting for another 1 bytes
. 2015-08-19 05:59:09.546 Looking for incoming data
. 2015-08-19 05:59:09.546 Looking for network events
. 2015-08-19 05:59:09.546 Detected network event
. 2015-08-19 05:59:09.546 Enumerating network events for socket 824
. 2015-08-19 05:59:09.546 Enumerated 1 network events making 1 cumulative events for socket 824
. 2015-08-19 05:59:09.546 Handling network read event on socket 824 with error 0
. 2015-08-19 05:59:09.546 Received 30 bytes (0)
. 2015-08-19 05:59:09.546 Read 1 bytes (29 pending)
. 2015-08-19 05:59:09.546 Read 29 bytes (0 pending)
< 2015-08-19 05:59:09.546 WinSCP: this is end-of-file:0
. 2015-08-19 05:59:09.562 Detecting variable containing return code of last command.
. 2015-08-19 05:59:09.562 Trying "$status".
> 2015-08-19 05:59:09.562 echo "$status" ; echo "WinSCP: this is end-of-file:0"
. 2015-08-19 05:59:09.562 Sent 54 bytes
. 2015-08-19 05:59:09.562 There are 0 bytes remaining in the send buffer
. 2015-08-19 05:59:09.562 Looking for network events
. 2015-08-19 05:59:09.562 Timeout waiting for network events
. 2015-08-19 05:59:09.562 Waiting for another 1 bytes
. 2015-08-19 05:59:09.562 Looking for incoming data
. 2015-08-19 05:59:09.562 Looking for network events
. 2015-08-19 05:59:09.562 Detected network event
. 2015-08-19 05:59:09.562 Enumerating network events for socket 824
. 2015-08-19 05:59:09.562 Enumerated 1 network events making 1 cumulative events for socket 824
. 2015-08-19 05:59:09.562 Handling network read event on socket 824 with error 0
. 2015-08-19 05:59:09.562 Received 2 bytes (0)
. 2015-08-19 05:59:09.562 Received 30 bytes (0)
. 2015-08-19 05:59:09.562 Read 1 bytes (31 pending)
. 2015-08-19 05:59:09.562 Read 1 bytes (30 pending)
< 2015-08-19 05:59:09.562 0
. 2015-08-19 05:59:09.562 Read 30 bytes (0 pending)
< 2015-08-19 05:59:09.562 WinSCP: this is end-of-file:0
. 2015-08-19 05:59:09.562 Return code variable "$status" selected.
> 2015-08-19 05:59:09.562 echo $LANG ; echo "WinSCP: this is end-of-file:$status"
. 2015-08-19 05:59:09.562 Sent 56 bytes
. 2015-08-19 05:59:09.562 There are 0 bytes remaining in the send buffer
. 2015-08-19 05:59:09.562 Looking for network events
. 2015-08-19 05:59:09.562 Timeout waiting for network events
. 2015-08-19 05:59:09.562 Waiting for another 1 bytes
. 2015-08-19 05:59:09.562 Looking for incoming data
. 2015-08-19 05:59:09.562 Looking for network events
. 2015-08-19 05:59:09.562 Detected network event
. 2015-08-19 05:59:09.562 Enumerating network events for socket 824
. 2015-08-19 05:59:09.562 Enumerated 1 network events making 1 cumulative events for socket 824
. 2015-08-19 05:59:09.562 Handling network read event on socket 824 with error 0
. 2015-08-19 05:59:09.562 Received 26 bytes (1)
! 2015-08-19 05:59:09.562 LANG: Undefined variable.
. 2015-08-19 05:59:09.562 Waiting for another 1 bytes
. 2015-08-19 05:59:09.562 Looking for incoming data
. 2015-08-19 05:59:09.562 Looking for network events
. 2015-08-19 05:59:24.578 Timeout waiting for network events
. 2015-08-19 05:59:24.578 Waiting for data timed out, asking user what to do.
. 2015-08-19 05:59:24.578 Asking user:
. 2015-08-19 05:59:24.578 **Host is not communicating for 15 seconds.
. 2015-08-19 05:59:24.578
. 2015-08-19 05:59:24.578 Wait for another 15 seconds?** ()
. 2015-08-19 05:59:25.078 Pooling for data in case they finally arrives
. 2015-08-19 05:59:25.078 Looking for network events
. 2015-08-19 05:59:25.078 Timeout waiting for network events
. 2015-08-19 05:59:25.578 Pooling for data in case they finally arrives
. 2015-08-19 05:59:25.578 Looking for network events
. 2015-08-19 05:59:25.578 Timeout waiting for network events
. 2015-08-19 05:59:26.078 Pooling for data in case they finally arrives
. 2015-08-19 05:59:26.078 Looking for network events
. 2015-08-19 05:59:26.078 Timeout waiting for network events
. 2015-08-19 05:59:26.468 Attempt to close connection due to fatal exception:
* 2015-08-19 05:59:26.468 **Terminated by user.**
. 2015-08-19 05:59:26.468 Closing connection.
. 2015-08-19 05:59:26.468 Sending special code: 12
. 2015-08-19 05:59:26.468 Sent EOF message
. 2015-08-19 05:59:26.468 Selecting events 0 for socket 824
* 2015-08-19 05:59:26.531 (EFatal) **Terminated by user.**
Advertisements
swapjim
[View user's profile]

Joined: 2015-08-19
Posts: 9
Oh my, I forgot to login! That was me.
swapjim
[View user's profile]

Joined: 2015-08-19
Posts: 9
Something? Anything I can try?
martin
[View user's profile]
Site Admin
Joined: 2002-12-10
Posts: 24530
Location: Prague, Czechia
Can you try to connect with PuTTY with Connection > SSH > TTY > Don't allocate a pseudo-terminal turned on?
Then try to type echo $LANG and let me know what the output is.
Then repeat the same with printenv LANG
swapjim
[View user's profile]

Joined: 2015-08-19
Posts: 9
In putty, I can't login if I turn on 'Don't allocate a pseudo-terminal'.

Here is LANG:

Code:
user@freebsd:~$ echo $LANG
LANG: Undefined variable.
user@freebsd:~$ printenv LANG
user@freebsd:~$


However, somehow the problem got solved! I created a new session and although I've already done that a couple of times, this time I managed to login with WinSCP.

What do you think was causing this?
swapjim
[View user's profile]

Joined: 2015-08-19
Posts: 9
It stopped working :-/

So I'm back with the problem.
martin
[View user's profile]
Site Admin
Joined: 2002-12-10
Posts: 24530
Location: Prague, Czechia
swapjim wrote:
In putty, I can't login if I turn on 'Don't allocate a pseudo-terminal'.

What happens exactly?

Quote:
Here is LANG:

Code:
user@freebsd:~$ echo $LANG
LANG: Undefined variable.
user@freebsd:~$ printenv LANG
user@freebsd:~$


Thanks. Can you try also
echo $LANG ; echo blah
and
printenv LANG ; echo blah
swapjim
[View user's profile]

Joined: 2015-08-19
Posts: 9
Wait, my mistake. When I enabled 'Don't allocate a pseudo-terminal', I couldn't login. Putty became unresponsive and I got this message:

Quote:
Warning: no access to tty (Bad file descriptor). Thus no job control in this shell.


Here it is: https://i.imgur.com/whMWj8L.png

The output that I told you it gave me was when I logged in normally, with 'Don't allocate a pseudo-terminal' disabled.

Edit:

I just noticed that by setting LANG on ~/.csh (csh is my default shell), I can login normally:

Code:
setenv LANG     en_US.UTF-8


For now it seems to work. Is this what you though caused the problem?
martin
[View user's profile]
Site Admin
Joined: 2002-12-10
Posts: 24530
Location: Prague, Czechia
swapjim wrote:
I just noticed that by setting LANG on ~/.csh (csh is my default shell), I can login normally:

Code:
setenv LANG     en_US.UTF-8


For now it seems to work. Is this what you though caused the problem?

Yes, that's the culprit.
But as it seems like a default behavior in FreeBSD, I want to make WinSCP be able to handle it.

So can you please try

echo $LANG ; echo blah

and

printenv LANG ; echo blah
swapjim
[View user's profile]

Joined: 2015-08-19
Posts: 9
The output is from PuttyPortable 0.63-t022.

With $LANG set in csh:

Quote:
user@freebsd:~$ echo $LANG ; echo blah
en_US.UTF-8
blah
user@freebsd:~$ printenv LANG ; echo blah
en_US.UTF-8
blah


Without $LANG set in csh:

Quote:
user@freebsd:~$ echo $LANG ; echo blah
LANG: Undefined variable.
user@freebsd:~$ printenv LANG ; echo blah
blah


It seems that with printenv, you get the 'blah' but not with echo.

Without $LANG set in sh (that's /bin/sh, the default shell):

Code:
$ echo $LANG ; echo blah

blah
$ printenv LANG ; echo blah
blah


Strangely, with sh as the default shell, I don't need to have $LANG defined to login!
martin
[View user's profile]
Site Admin
Joined: 2002-12-10
Posts: 24530
Location: Prague, Czechia
Thanks.

This issue has been added to the tracker:
http://winscp.net/tracker/show_bug.cgi?id=1354

I'm sending you an email with a development version of WinSCP to address you have used to register on this forum.
Please send me a log file with the default settings (Auto).
Advertisements

You can post new topics in this forum






Search Site

What is WinSCP?

It is award-winning SFTP client, SCP client, FTPS client and FTP client integrated into one software program for file transfer to FTP server or secure SFTP server. [More]

And it's free!

Donate

About donations

$9   $19   $49   $99

About donations

Recommend

WinSCP Privacy Policy

WinSCP License