Skip to content

High CPU usage and log file growing up #606

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

Closed
Leproide opened this issue Mar 24, 2017 · 40 comments
Closed

High CPU usage and log file growing up #606

Leproide opened this issue Mar 24, 2017 · 40 comments
Milestone

Comments

@Leproide
Copy link

Leproide commented Mar 24, 2017

OpenSSH for Windows latest version v0.0.10.0

OS details
Windows 7 Pro x64 sp1

-High CPU usage
-Log file growing up

3236 23:21:28 692 debug2: signal() sig:2, handler:00000001
3236 23:21:28 694 debug1: socket:420, socktype:1, io:00531B70, fd:3 
3236 23:21:28 694 debug3: w32_fcntl fd:3
3236 23:21:28 694 debug2: fd 3 setting O_NONBLOCK
3236 23:21:28 694 debug3: w32_fcntl fd:3
3236 23:21:28 694 debug3: w32_fcntl fd:3
3236 23:21:28 694 debug3: w32_setsockopt fd:3
3236 23:21:28 694 debug1: Bind to port 22 on 0.0.0.0.
3236 23:21:28 694 debug3: w32_bind fd:3
3236 23:21:28 694 debug3: w32_listen fd:3
3236 23:21:28 699 Server listening on 0.0.0.0 port 22.
3236 23:21:28 699 debug2: signal() sig:6, handler:01265A20
3236 23:21:28 699 debug2: signal() sig:3, handler:01265B40
3236 23:21:28 699 debug2: signal() sig:8, handler:01265B30
3236 23:21:28 699 debug2: signal() sig:7, handler:01265B30
3236 23:21:28 699 error: Couldn't create pid file "./sshd.pid": Permission denied
3236 23:21:28 699 debug3: w32_select fd:3
3236 23:21:28 699 debug3: Total in fds:1
3236 23:21:28 699 debug2: on_select - io:00531B70 type:1 rd:1
3236 23:21:28 699 debug3: acceptEx - io:00531B70
3236 23:21:28 700 debug1: acceptEx - AcceptEx() ERROR:22, io:00531B70
3236 23:21:28 700 debug3: wait() on 0 events and 0 children
3236 23:21:28 700 debug3: select - returning 1
3236 23:21:28 700 debug3: w32_accept fd:3
3236 23:21:28 700 debug3: accept - io:00531B70
3236 23:21:28 700 debug1: accept - ERROR: async io completed with error: -9978, io:00531B70
3236 23:21:28 700 error: accept: Unknown error
3236 23:21:28 700 debug3: w32_select fd:3
3236 23:21:28 700 debug3: Total in fds:1
3236 23:21:28 700 debug2: on_select - io:00531B70 type:1 rd:1
3236 23:21:28 700 debug3: acceptEx - io:00531B70
3236 23:21:28 700 debug1: acceptEx - AcceptEx() ERROR:22, io:00531B70
3236 23:21:28 700 debug3: wait() on 0 events and 0 children
3236 23:21:28 700 debug3: select - returning 1
3236 23:21:28 700 debug3: w32_accept fd:3
3236 23:21:28 700 debug3: accept - io:00531B70
3236 23:21:28 700 debug1: accept - ERROR: async io completed with error: -9978, io:00531B70
3236 23:21:28 700 error: accept: Unknown error
@bagajjal
Copy link
Collaborator

Try changing the sshd_config as mentioned in this issue #493.

If you still have the issue then please share the sshd_config.

@Leproide
Copy link
Author

Hi, thanks for the fast reply
No more pid error but:

7632 23:36:29 209 debug2: signal() sig:2, handler:00000001
7632 23:36:29 211 debug1: socket:420, socktype:1, io:00351B70, fd:3 
7632 23:36:29 211 debug3: w32_fcntl fd:3
7632 23:36:29 211 debug2: fd 3 setting O_NONBLOCK
7632 23:36:29 211 debug3: w32_fcntl fd:3
7632 23:36:29 211 debug3: w32_fcntl fd:3
7632 23:36:29 211 debug3: w32_setsockopt fd:3
7632 23:36:29 211 debug1: Bind to port 22 on 0.0.0.0.
7632 23:36:29 211 debug3: w32_bind fd:3
7632 23:36:29 212 debug3: w32_listen fd:3
7632 23:36:29 217 Server listening on 0.0.0.0 port 22.
7632 23:36:29 217 debug2: signal() sig:6, handler:01135A20
7632 23:36:29 217 debug2: signal() sig:3, handler:01135B40
7632 23:36:29 217 debug2: signal() sig:8, handler:01135B30
7632 23:36:29 217 debug2: signal() sig:7, handler:01135B30
7632 23:36:29 217 debug3: w32_select fd:3
7632 23:36:29 217 debug3: Total in fds:1
7632 23:36:29 217 debug2: on_select - io:00351B70 type:1 rd:1
7632 23:36:29 217 debug3: acceptEx - io:00351B70
7632 23:36:29 218 debug1: acceptEx - AcceptEx() ERROR:22, io:00351B70
7632 23:36:29 218 debug3: wait() on 0 events and 0 children
7632 23:36:29 218 debug3: select - returning 1
7632 23:36:29 218 debug3: w32_accept fd:3
7632 23:36:29 218 debug3: accept - io:00351B70
7632 23:36:29 218 debug1: accept - ERROR: async io completed with error: -9978, io:00351B70
7632 23:36:29 218 error: accept: Unknown error
7632 23:36:29 218 debug3: w32_select fd:3
7632 23:36:29 218 debug3: Total in fds:1
7632 23:36:29 219 debug2: on_select - io:00351B70 type:1 rd:1
7632 23:36:29 219 debug3: acceptEx - io:00351B70
7632 23:36:29 219 debug1: acceptEx - AcceptEx() ERROR:22, io:00351B70
7632 23:36:29 219 debug3: wait() on 0 events and 0 children
7632 23:36:29 219 debug3: select - returning 1
7632 23:36:29 219 debug3: w32_accept fd:3
7632 23:36:29 219 debug3: accept - io:00351B70
7632 23:36:29 219 debug1: accept - ERROR: async io completed with error: -9978, io:00351B70
7632 23:36:29 219 error: accept: Unknown error

@Leproide
Copy link
Author

Config:


#	$OpenBSD: sshd_config,v 1.84 2011/05/23 03:30:07 djm Exp $

# This is the sshd server system-wide configuration file.  See
# sshd_config(5) for more information.

# This sshd was compiled with PATH=/usr/bin:/bin:/usr/sbin:/sbin

# The strategy used for options in the default sshd_config shipped with
# OpenSSH is to specify options with their default value where
# possible, but leave them commented.  Uncommented options override the
# default value.

Port 22
AddressFamily inet
#ListenAddress 0.0.0.0
#ListenAddress ::

# The default requires explicit activation of protocol 1
Protocol 2

# HostKey for protocol version 1
#HostKey /etc/ssh/ssh_host_key
# HostKeys for protocol version 2
#HostKey /etc/ssh/ssh_host_rsa_key
#HostKey /etc/ssh/ssh_host_dsa_key
#HostKey /etc/ssh/ssh_host_ecdsa_key

# Lifetime and size of ephemeral version 1 server key
#KeyRegenerationInterval 1h
#ServerKeyBits 1024

# Logging
# obsoletes QuietMode and FascistLogging
#SyslogFacility AUTH
LogLevel DEBUG3

# Authentication:

#LoginGraceTime 2m
#PermitRootLogin yes
#StrictModes yes
#MaxAuthTries 6
#MaxSessions 10

#RSAAuthentication yes
#PubkeyAuthentication yes

# The default is to check both .ssh/authorized_keys and .ssh/authorized_keys2
# but this is overridden so installations will only check .ssh/authorized_keys
AuthorizedKeysFile	.ssh/authorized_keys

# For this to work you will also need host keys in /etc/ssh/ssh_known_hosts
#RhostsRSAAuthentication no
# similar for protocol version 2
#HostbasedAuthentication no
# Change to yes if you don't trust ~/.ssh/known_hosts for
# RhostsRSAAuthentication and HostbasedAuthentication
#IgnoreUserKnownHosts no
# Don't read the user's ~/.rhosts and ~/.shosts files
#IgnoreRhosts yes

# To disable tunneled clear text passwords, change to no here!
#PasswordAuthentication yes
#PermitEmptyPasswords no

# Change to no to disable s/key passwords
#ChallengeResponseAuthentication yes

# Kerberos options
#KerberosAuthentication no
#KerberosOrLocalPasswd yes
#KerberosTicketCleanup yes
#KerberosGetAFSToken no

# GSSAPI options
#GSSAPIAuthentication no
#GSSAPICleanupCredentials yes

# Set this to 'yes' to enable PAM authentication, account processing, 
# and session processing. If this is enabled, PAM authentication will 
# be allowed through the ChallengeResponseAuthentication and
# PasswordAuthentication.  Depending on your PAM configuration,
# PAM authentication via ChallengeResponseAuthentication may bypass
# the setting of "PermitRootLogin without-password".
# If you just want the PAM account and session checks to run without
# PAM authentication, then enable this but set PasswordAuthentication
# and ChallengeResponseAuthentication to 'no'.
#UsePAM no

#AllowAgentForwarding yes
#AllowTcpForwarding yes
#GatewayPorts no
#X11Forwarding no
#X11DisplayOffset 10
#X11UseLocalhost yes
#PrintMotd yes
#PrintLastLog yes
#TCPKeepAlive yes
#UseLogin no
#UsePrivilegeSeparation yes
#PermitUserEnvironment no
#Compression delayed
#ClientAliveInterval 0
#ClientAliveCountMax 3
#UseDNS yes
PidFile C:\openssh\sshd.pid
#MaxStartups 10
#PermitTunnel no
#ChrootDirectory none

# no default banner path
Banner C:\openssh\Banner.txt

# override default of no subsystems
Subsystem	sftp	C:\openssh\sftp-server.exe

# Example of overriding settings on a per-user basis
#Match User anoncvs
#	X11Forwarding no
#	AllowTcpForwarding no
#	ForceCommand cvs server
PubkeyAcceptedKeyTypes ssh-ed25519*,ssh-rsa*,ssh-dss*,ecdsa-sha2*

@bagajjal
Copy link
Collaborator

Try commenting "AddressFamily inet" line and restart the sshd..

@Leproide
Copy link
Author

8224 23:48:59 183 debug2: signal() sig:2, handler:00000001
8224 23:48:59 183 debug1: socket:356, socktype:1, io:00201BF0, fd:3
8224 23:48:59 183 debug3: w32_fcntl fd:3
8224 23:48:59 183 debug2: fd 3 setting O_NONBLOCK
8224 23:48:59 183 debug3: w32_fcntl fd:3
8224 23:48:59 183 debug3: w32_fcntl fd:3
8224 23:48:59 183 debug3: w32_setsockopt fd:3
8224 23:48:59 183 debug3: sock_set_v6only: set socket 3 IPV6_V6ONLY
8224 23:48:59 183 debug3: w32_setsockopt fd:3
8224 23:48:59 184 debug1: Bind to port 22 on ::.
8224 23:48:59 184 debug3: w32_bind fd:3
8224 23:48:59 184 debug3: w32_listen fd:3
8224 23:48:59 189 Server listening on :: port 22.
8224 23:48:59 189 debug1: socket:428, socktype:1, io:00201C70, fd:4
8224 23:48:59 189 debug3: w32_fcntl fd:4
8224 23:48:59 189 debug2: fd 4 setting O_NONBLOCK
8224 23:48:59 189 debug3: w32_fcntl fd:4
8224 23:48:59 189 debug3: w32_fcntl fd:4
8224 23:48:59 189 debug3: w32_setsockopt fd:4
8224 23:48:59 189 debug1: Bind to port 22 on 0.0.0.0.
8224 23:48:59 189 debug3: w32_bind fd:4
8224 23:48:59 189 debug3: w32_listen fd:4
8224 23:48:59 194 Server listening on 0.0.0.0 port 22.
8224 23:48:59 194 debug2: signal() sig:6, handler:003A5A20
8224 23:48:59 194 debug2: signal() sig:3, handler:003A5B40
8224 23:48:59 194 debug2: signal() sig:8, handler:003A5B30
8224 23:48:59 194 debug2: signal() sig:7, handler:003A5B30
8224 23:48:59 195 debug3: w32_select fd:3
8224 23:48:59 195 debug3: w32_select fd:4
8224 23:48:59 195 debug3: Total in fds:2
8224 23:48:59 195 debug2: on_select - io:00201BF0 type:1 rd:1
8224 23:48:59 195 debug3: acceptEx - io:00201BF0
8224 23:48:59 195 debug2: on_select - io:00201C70 type:1 rd:1
8224 23:48:59 195 debug3: acceptEx - io:00201C70
8224 23:48:59 195 debug1: acceptEx - AcceptEx() ERROR:22, io:00201C70
8224 23:48:59 195 debug3: wait() on 0 events and 0 children
8224 23:48:59 195 debug3: select - returning 1
8224 23:48:59 195 debug3: w32_accept fd:4
8224 23:48:59 195 debug3: accept - io:00201C70
8224 23:48:59 195 debug1: accept - ERROR: async io completed with error: -9978, io:00201C70
8224 23:48:59 195 error: accept: Unknown error
8224 23:48:59 195 debug3: w32_select fd:3
8224 23:48:59 195 debug3: w32_select fd:4
8224 23:48:59 195 debug3: Total in fds:2
8224 23:48:59 195 debug2: on_select - io:00201BF0 type:1 rd:1
8224 23:48:59 195 debug2: on_select - io:00201C70 type:1 rd:1
8224 23:48:59 195 debug3: acceptEx - io:00201C70
8224 23:48:59 195 debug1: acceptEx - AcceptEx() ERROR:22, io:00201C70
8224 23:48:59 195 debug3: wait() on 0 events and 0 children
8224 23:48:59 195 debug3: select - returning 1
8224 23:48:59 195 debug3: w32_accept fd:4
8224 23:48:59 195 debug3: accept - io:00201C70
8224 23:48:59 195 debug1: accept - ERROR: async io completed with error: -9978, io:00201C70
8224 23:48:59 195 error: accept: Unknown error
8224 23:48:59 195 debug3: w32_select fd:3
8224 23:48:59 195 debug3: w32_select fd:4
8224 23:48:59 195 debug3: Total in fds:2
8224 23:48:59 195 debug2: on_select - io:00201BF0 type:1 rd:1
8224 23:48:59 195 debug2: on_select - io:00201C70 type:1 rd:1
8224 23:48:59 195 debug3: acceptEx - io:00201C70
8224 23:48:59 195 debug1: acceptEx - AcceptEx() ERROR:22, io:00201C70
8224 23:48:59 195 debug3: wait() on 0 events and 0 children
8224 23:48:59 195 debug3: select - returning 1
8224 23:48:59 195 debug3: w32_accept fd:4
8224 23:48:59 195 debug3: accept - io:00201C70
8224 23:48:59 195 debug1: accept - ERROR: async io completed with error: -9978, io:00201C70
8224 23:48:59 195 error: accept: Unknown error
8224 23:48:59 195 debug3: w32_select fd:3
8224 23:48:59 195 debug3: w32_select fd:4
8224 23:48:59 195 debug3: Total in fds:2
8224 23:48:59 195 debug2: on_select - io:00201BF0 type:1 rd:1
8224 23:48:59 195 debug2: on_select - io:00201C70 type:1 rd:1
8224 23:48:59 195 debug3: acceptEx - io:00201C70
8224 23:48:59 195 debug1: acceptEx - AcceptEx() ERROR:22, io:00201C70
8224 23:48:59 195 debug3: wait() on 0 events and 0 children
8224 23:48:59 195 debug3: select - returning 1
8224 23:48:59 195 debug3: w32_accept fd:4
8224 23:48:59 195 debug3: accept - io:00201C70
8224 23:48:59 195 debug1: accept - ERROR: async io completed with error: -9978, io:00201C70
8224 23:48:59 195 error: accept: Unknown error
8224 23:48:59 195 debug3: w32_select fd:3
8224 23:48:59 195 debug3: w32_select fd:4
8224 23:48:59 195 debug3: Total in fds:2
8224 23:48:59 195 debug2: on_select - io:00201BF0 type:1 rd:1
8224 23:48:59 195 debug2: on_select - io:00201C70 type:1 rd:1
8224 23:48:59 195 debug3: acceptEx - io:00201C70
8224 23:48:59 196 debug1: acceptEx - AcceptEx() ERROR:22, io:00201C70
8224 23:48:59 196 debug3: wait() on 0 events and 0 children
8224 23:48:59 196 debug3: select - returning 1
8224 23:48:59 196 debug3: w32_accept fd:4
8224 23:48:59 196 debug3: accept - io:00201C70
8224 23:48:59 196 debug1: accept - ERROR: async io completed with error: -9978, io:00201C70
8224 23:48:59 196 error: accept: Unknown error
8224 23:48:59 196 debug3: w32_select fd:3
8224 23:48:59 196 debug3: w32_select fd:4
8224 23:48:59 196 debug3: Total in fds:2

@Leproide
Copy link
Author

Leproide commented Mar 24, 2017

http://imgur.com/a/h2P0s
Quiet log level, idle on connecting, high cpu usage

(If can help, i use Comodo Firewall, but if i close it nothing changes)

@bagajjal
Copy link
Collaborator

commenting "AddressFamily inet" line in sshd_config didn't help?
Are you still getting the below error,
debug1: acceptEx - AcceptEx() ERROR:22, io:00201C70

@Leproide
Copy link
Author

Mmmh, no, nothing change (only disappeared 00201C70)

@DarwinJS
Copy link

@manojampalam - I was just noticing "Couldn't create pid file "./sshd.pid": Permission denied" in the first log posted in this thread.

I assume this trying to create a pid file next to sshd.exe?

AFAIK, Windows apps shouldn't try to save any state data next to an exe.

To me preventing storage of file based, machine-wide state data next to binaries is one of the security improvements of Windows over linux because it keeps the binaries more secure from malware.

Could ALL file based, machine-wide state data for ssh be pushed to %ProgramData%\openssh to follow Windows conventions - without requiring sshd_conf changes to do so? Actually examine and address the issue throughout the openssh code base?

D.

@Leproide
Copy link
Author

If need another info tell me
I need ssh on this machine :(

@manojampalam
Copy link
Contributor

manojampalam commented Mar 26, 2017

@DarwinJS, as we discussed before, all logging would be done under logs folder under ssh binary path. This is for simplicity, easy discoverability and having flexibility to host multiple versions of OpenSSH side by side (Production Vs Evaluation version for example)
The "Logs" folder will be owned by "Trusted Installer" and will be Writable only by admins and "NT Service/SSHD"

@manojampalam
Copy link
Contributor

@Leproide please provide us with network configuration of your machine (masking out any private info where applicable)

ipconfig /all
netstat -anop TCP

@DarwinJS
Copy link

DarwinJS commented Mar 26, 2017

@manojampalam - Yep - sorry I forgot that conversation.

I am not familiar with the model of ensuring something is owned by "Trusted Installer" unless it is explicitly under Windows Resource Protection (WRP). The ACLs for WRP protected resources actually LOCK OUT admin and system. There are also usually special AppCompat shims in place to lie to anything that tries to update resources owned by Trusted Installer. (These rules are created separately - they are not automatically enabled by the resource being owned by Trusted Installer). These last two attributes are what simultaneously [a] prevents updates to WRP resources - even by elevated setups and MSIs and [b] maintains compatibility so those setups don't' fail.

It's possible that the reason for having "Trusted Installer" own a resource has broadened since WRP was introduced in Windows 7 - if so I'd be interested in a pointer to the details!

@Leproide
Copy link
Author

Leproide commented Mar 26, 2017

netstat -anop TCP

Connessioni attive

  Proto  Indirizzo locale          Indirizzo esterno        Stato           PID
  TCP    0.0.0.0:21             0.0.0.0:0              LISTENING       8116
  TCP    0.0.0.0:135            0.0.0.0:0              LISTENING       632
  TCP    0.0.0.0:445            0.0.0.0:0              LISTENING       4
  TCP    0.0.0.0:554            0.0.0.0:0              LISTENING       728
  TCP    0.0.0.0:2869           0.0.0.0:0              LISTENING       4
  TCP    0.0.0.0:5170           0.0.0.0:0              LISTENING       1076
  TCP    0.0.0.0:5357           0.0.0.0:0              LISTENING       4
  TCP    0.0.0.0:7123           0.0.0.0:0              LISTENING       4776
  TCP    0.0.0.0:8091           0.0.0.0:0              LISTENING       8116
  TCP    0.0.0.0:10243          0.0.0.0:0              LISTENING       4
  TCP    0.0.0.0:27036          0.0.0.0:0              LISTENING       5624
  TCP    0.0.0.0:49152          0.0.0.0:0              LISTENING       796
  TCP    0.0.0.0:49153          0.0.0.0:0              LISTENING       1176
  TCP    0.0.0.0:49154          0.0.0.0:0              LISTENING       1288
  TCP    0.0.0.0:49159          0.0.0.0:0              LISTENING       876
  TCP    0.0.0.0:49160          0.0.0.0:0              LISTENING       856
  TCP    0.0.0.0:49316          0.0.0.0:0              LISTENING       1076
  TCP    127.0.0.1:5939         0.0.0.0:0              LISTENING       3484
  TCP    127.0.0.1:7122         0.0.0.0:0              LISTENING       3648
  TCP    127.0.0.1:25639        0.0.0.0:0              LISTENING       8880
  TCP    127.0.0.1:49156        0.0.0.0:0              LISTENING       2124
  TCP    127.0.0.1:53645        127.0.0.1:53646        ESTABLISHED     4360
  TCP    127.0.0.1:53646        127.0.0.1:53645        ESTABLISHED     4360
  TCP    127.0.0.1:53659        127.0.0.1:53660        ESTABLISHED     6908
  TCP    127.0.0.1:53660        127.0.0.1:53659        ESTABLISHED     6908
  TCP    127.0.0.1:63427        127.0.0.1:63428        ESTABLISHED     10936
  TCP    127.0.0.1:63428        127.0.0.1:63427        ESTABLISHED     10936
  TCP    169.254.244.77:139     0.0.0.0:0              LISTENING       4
  TCP    192.168.1.100:139      0.0.0.0:0              LISTENING       4
  TCP    192.168.1.100:888      0.0.0.0:0              LISTENING       2300
  TCP    192.168.1.100:53578    82.94.249.234:5222     ESTABLISHED     7628
  TCP    192.168.1.100:57340    52.28.222.112:443      CLOSE_WAIT      2016
  TCP    192.168.1.100:57341    52.28.222.112:443      CLOSE_WAIT      2016
  TCP    192.168.1.100:57408    149.202.24.2:443       ESTABLISHED     4360
  TCP    192.168.1.100:59075    136.243.74.100:443     ESTABLISHED     9488
  TCP    192.168.1.100:62603    35.162.207.140:443     ESTABLISHED     4360
  TCP    192.168.1.100:62619    52.29.0.144:443        CLOSE_WAIT      2016
  TCP    192.168.1.100:62620    52.57.38.158:443       CLOSE_WAIT      2016
  TCP    192.168.1.100:62649    212.47.227.58:80       ESTABLISHED     6932
  TCP    192.168.1.100:62698    136.243.74.100:443     ESTABLISHED     9488
  TCP    192.168.1.100:62703    212.47.227.58:8091     ESTABLISHED     4360
  TCP    192.168.1.100:63044    199.16.156.52:443      ESTABLISHED     12932
  TCP    192.168.1.100:63339    136.243.74.100:443     ESTABLISHED     9488
  TCP    192.168.1.100:63347    216.58.205.65:443      ESTABLISHED     8880
  TCP    192.168.1.100:63388    81.74.231.53:80        ESTABLISHED     12932
  TCP    192.168.1.100:63431    74.125.133.108:993     ESTABLISHED     10936
  TCP    192.168.1.100:63432    74.125.133.108:993     ESTABLISHED     10936
  TCP    192.168.1.100:63433    74.125.133.108:993     ESTABLISHED     10936
  TCP    192.168.1.100:63434    74.125.133.108:993     ESTABLISHED     10936
  TCP    192.168.1.100:63435    178.175.144.26:143     ESTABLISHED     10936
  TCP    192.168.1.100:63436    74.125.133.108:993     ESTABLISHED     10936
  TCP    192.168.1.100:63446    216.58.205.170:443     ESTABLISHED     10936
  TCP    192.168.1.100:63448    216.58.204.110:443     TIME_WAIT       0
  TCP    192.168.1.100:63453    74.125.133.108:993     ESTABLISHED     10936
  TCP    192.168.1.100:63456    74.125.133.108:993     ESTABLISHED     10936
  TCP    192.168.1.100:63457    104.25.25.5:443        TIME_WAIT       0
  TCP    192.168.1.100:63459    74.125.133.108:993     ESTABLISHED     10936
  TCP    192.168.1.100:63461    74.125.133.108:993     ESTABLISHED     10936
  TCP    192.168.1.100:63462    94.23.50.208:143       ESTABLISHED     10936
  TCP    192.168.1.100:63463    74.125.133.108:993     ESTABLISHED     10936
  TCP    192.168.1.100:63464    74.125.133.108:993     ESTABLISHED     10936
  TCP    192.168.1.100:63468    74.125.133.108:993     ESTABLISHED     10936
  TCP    192.168.1.100:63469    74.125.133.108:993     ESTABLISHED     10936
  TCP    192.168.1.100:63473    52.28.215.255:443      TIME_WAIT       0
  TCP    192.168.1.100:63474    52.28.215.255:443      TIME_WAIT       0
  TCP    192.168.1.100:63486    151.101.0.133:443      ESTABLISHED     4360
  TCP    192.168.1.100:63488    74.125.133.108:993     ESTABLISHED     10936
  TCP    192.168.1.100:63490    74.125.133.108:993     ESTABLISHED     10936
  TCP    192.168.1.100:63491    74.125.133.108:993     ESTABLISHED     10936
  TCP    192.168.1.100:63497    92.123.180.88:80       TIME_WAIT       0
  TCP    192.168.1.100:63504    192.30.253.124:443     ESTABLISHED     4360
  TCP    192.168.1.100:63508    212.47.227.58:8091     TIME_WAIT       0
  TCP    192.168.1.100:63511    192.30.253.113:443     TIME_WAIT       0
  TCP    192.168.1.100:63513    151.101.0.133:443      ESTABLISHED     4360
  TCP    192.168.1.100:63514    151.101.0.133:443      ESTABLISHED     4360
  TCP    192.168.1.100:63515    178.255.82.5:443       CLOSE_WAIT      1032
  TCP    192.168.1.100:63516    104.16.61.31:443       ESTABLISHED     1032
  TCP    192.168.1.100:63517    192.30.253.113:443     TIME_WAIT       0
  TCP    192.168.1.100:63523    212.47.227.58:8091     TIME_WAIT       0
  TCP    192.168.1.100:63524    81.74.231.52:80        ESTABLISHED     12932
  TCP    192.168.1.100:63527    212.47.227.58:8091     ESTABLISHED     4360
  TCP    192.168.1.100:63529    185.54.150.20:80       ESTABLISHED     12932
  TCP    192.168.1.100:63530    185.54.150.20:80       ESTABLISHED     12932

ipconfig /all

Configurazione IP di Windows

   Nome host . . . . . . . . . . . . . . : Nab******
   Suffisso DNS primario . . . . . . . . : 
   Tipo nodo . . . . . . . . . . . . . . : Ibrido
   Routing IP abilitato. . . . . . . . . : No
   Proxy WINS abilitato . . . . . . . .  : No

Scheda Ethernet Router:

   Suffisso DNS specifico per connessione: 
   Descrizione . . . . . . . . . . . . . : Realtek PCIe GBE Family Controller
   Indirizzo fisico. . . . . . . . . . . : 1C-6F-65-*******
   DHCP abilitato. . . . . . . . . . . . : No
   Configurazione automatica abilitata   : S
   Indirizzo IPv6 locale rispetto al collegamento . : fe80::459b:9b28:33ee:a6b2%21(Preferenziale) 
   Indirizzo IPv4. . . . . . . . . . . . : 192.168.1.100(Preferenziale) 
   Subnet mask . . . . . . . . . . . . . : 255.255.255.0
   Gateway predefinito . . . . . . . . . : fe80::781b:fff:fe5b:c171%21
                                           192.168.1.1
   IAID DHCPv6 . . . . . . . . . . . : 186412901
   DUID Client DHCPv6. . . . . . . . : 00-01-00-01-1E-E1-E4-16-1C-6F-65-CA-02-CD
   Server DNS . . . . . . . . . . . . .  : *******
                                           *******
   NetBIOS su TCP/IP . . . . . . . . . . : Attivato

Scheda Ethernet OpenVPN:

   Stato supporto. . . . . . . . . . . . : Supporto disconnesso
   Suffisso DNS specifico per connessione: 
   Descrizione . . . . . . . . . . . . . : TAP-Windows Adapter V9
   Indirizzo fisico. . . . . . . . . . . : 00-FF-1F-********
   DHCP abilitato. . . . . . . . . . . . : S
   Configurazione automatica abilitata   : S

Scheda Ethernet VBOX:

   Suffisso DNS specifico per connessione: 
   Descrizione . . . . . . . . . . . . . : VirtualBox Host-Only Ethernet Adapter
   Indirizzo fisico. . . . . . . . . . . : *******
   DHCP abilitato. . . . . . . . . . . . : S
   Configurazione automatica abilitata   : S
   Indirizzo IPv6 locale rispetto al collegamento . : fe80::59a6:706e:c3f2:f44d%13(Preferenziale) 
   Indirizzo IPv4 configurazione automatica : 169.254.244.77(Preferenziale) 
   Subnet mask . . . . . . . . . . . . . : 255.255.0.0
   Gateway predefinito . . . . . . . . . : 
   IAID DHCPv6 . . . . . . . . . . . : 453640231
   DUID Client DHCPv6. . . . . . . . : 00-01-00-01-1E-E1-E4-16-1C-6F-65-CA-02-CD
   Server DNS . . . . . . . . . . . . .  : fec0:0:0:ffff::1%1
                                           fec0:0:0:ffff::2%1
                                           fec0:0:0:ffff::3%1
   NetBIOS su TCP/IP . . . . . . . . . . : Attivato

Scheda Tunnel isatap.{637E4A28-1FEB-4483-8A3D-71BA3217FDD7}:

   Stato supporto. . . . . . . . . . . . : Supporto disconnesso
   Suffisso DNS specifico per connessione: 
   Descrizione . . . . . . . . . . . . . : Microsoft ISATAP Adapter
   Indirizzo fisico. . . . . . . . . . . : 00-00-00-00-00-00-00-E0
   DHCP abilitato. . . . . . . . . . . . : No
   Configurazione automatica abilitata   : S

Scheda Tunnel isatap.{08083AEA-49F6-4C13-8E5A-27B4346CC5D7}:

   Stato supporto. . . . . . . . . . . . : Supporto disconnesso
   Suffisso DNS specifico per connessione: 
   Descrizione . . . . . . . . . . . . . : Microsoft ISATAP Adapter #2
   Indirizzo fisico. . . . . . . . . . . : 00-00-00-00-00-00-00-E0
   DHCP abilitato. . . . . . . . . . . . : No
   Configurazione automatica abilitata   : S

Scheda Tunnel isatap.{1F7BD85A-247C-45FD-A572-F2853E76CEFB}:

   Stato supporto. . . . . . . . . . . . : Supporto disconnesso
   Suffisso DNS specifico per connessione: 
   Descrizione . . . . . . . . . . . . . : Microsoft ISATAP Adapter #3
   Indirizzo fisico. . . . . . . . . . . : 00-00-00-00-00-00-00-E0
   DHCP abilitato. . . . . . . . . . . . : No
   Configurazione automatica abilitata   : S

@manojampalam
Copy link
Contributor

@DarwinJS, clarified my previous response, I meant to imply that Logs folder will be created with appropriate permissions as part of the installation, just like any other system folder.

@manojampalam
Copy link
Contributor

@Leproide Please collect sshd and Winsock traces from the same run.

Steps to collect Winsock traces
https://msdn.microsoft.com/en-us/library/windows/desktop/bb892100(v=vs.85).aspx

  • Start tracing
    logman start -ets mywinsocksession -o winsocklogfile.etl -p Microsoft-Windows-Winsock-AFD
  • Stop tracing
    logman stop -ets mywinsocksession
  • decode traces
    tracerpt.exe <name of the .etl file> –o winsocktracelog.txt

@Leproide
Copy link
Author

Little problem:
etl file = 170 MB
winsocktracelog.txt = 2,12GB O.o

@manojampalam
Copy link
Contributor

Oops. How long did you leave Winsock tracing on? Can you try again shortening the interval?

@Leproide
Copy link
Author

30sec i think...
w8 i retry now

@Leproide
Copy link
Author

300mb log file in 6 second O.o
Compress to 1.80MB:
http://lara.monocul.us/~mauro/File/traccia.7z

@manojampalam
Copy link
Contributor

Still looking. Please attach the etl file too. Did you happen to have the corresponding sshd.log ?

@C-Duv
Copy link

C-Duv commented Mar 28, 2017

What do you call "high CPU usage"?
In #580 I get full core's CPU usage but no log (same OS, same OpenSSH version).

@Leproide
Copy link
Author

Leproide commented Mar 28, 2017

@C-Duv 80/90%, i7 2600k

@manojampalam In italy have 0.50 upload, 300mb log file is a suicide O.o
I try compress it

@manojampalam
Copy link
Contributor

manojampalam commented Mar 28, 2017

@Leproide, @C-Duv , @sterling

I just talked to a Winsock expert. Please follow these steps to collect some additional traces. These will unfortunately be much more verbose, so try keeping it as short as possible. Also share the corresponding sshd logs

New Tracing Steps

  • netsh trace start provider=Microsoft-Windows-Winsock-AFD provider=Microsoft-Windows-TCPIP provider={EB004A05-9B1A-11D4-9123-0050047759BC} provider={0C478C5B-0351-41B1-8C58-4A6737DA32E3} report=disabled ov=yes tracefile=nettrace.etl
  • Repro
  • netsh trace stop

Attach nettrace.etl

@Leproide
Copy link
Author

report=disabled give me error, i removed this.
netsh trace start provider=Microsoft-Windows-Winsock-AFD provider=Microsoft-Windows-TCPIP provider={EB004A05-9B1A-11D4-9123-0050047759BC} provider={0C478C5B-0351-41B1-8C58-4A6737DA32E3} ov=yes tracefile=nettrace.etl

nettrace.etl 63,5 MB
nettrace.zip 3,91 MB

nettrace.zip

@sterling
Copy link

Attached etl file and sshd log.

logs.zip

@m00tness
Copy link

I can confirm @manojampalam the referenced "AddressFamily inet" fix worked for me for this issue. THANK YOU

@C-Duv
Copy link

C-Duv commented Mar 30, 2017

Here are the .etl and .cab files in a single archive (no SSH logs because sshd.log stays empty...).

Win32-OpenSSH-bug_606-nettrace.zip

After setting AddressFamily inet in sshd_config CPU usage of sshd.exe is just fine (0%).

@Leproide
Copy link
Author

In my case AddressFamily inet not work

@manojampalam
Copy link
Contributor

@Leproide, @C-Duv , @sterling

Can you try out the attached package and see if it works (revert "AddressFamily inet" change in sshd_config)? This is with a private fix on top of March-End package.
OpenSSH-Win64.zip
OpenSSH-Win64_Symbols.zip

@sterling
Copy link

sterling commented Apr 5, 2017

This appears to have fixed the log spam for me. sshd starts up with just a few logs:

8176 18:58:19 186 Server listening on :: port 22.
8176 18:58:19 187 Server listening on 0.0.0.0 port 22.
8176 18:58:19 187 error: Couldn't create pid file "./sshd.pid": Permission denied

@Leproide
Copy link
Author

Leproide commented Apr 5, 2017

Work :D
Now i can uninstall the shitty bitvise ssh server :D
Thanks!

But, the problem is?

13064 03:32:49 188 debug3: socket:336, socktype:1, io:00000000004F2AF0, fd:3 
13064 03:32:49 188 debug2: fd 3 setting O_NONBLOCK
13064 03:32:49 188 debug3: sock_set_v6only: set socket 3 IPV6_V6ONLY
13064 03:32:49 188 debug1: Bind to port 27222 on ::.
13064 03:32:49 194 Server listening on :: port 27222.
13064 03:32:49 194 debug3: socket:408, socktype:1, io:00000000004F2BA0, fd:4 
13064 03:32:49 194 debug2: fd 4 setting O_NONBLOCK
13064 03:32:49 194 debug1: Bind to port 27222 on 0.0.0.0.
13064 03:32:49 200 Server listening on 0.0.0.0 port 27222.

@Leproide
Copy link
Author

Leproide commented Apr 5, 2017

Ah, this is my (orrible) update script if anyone need
https://pastebin.com/5T8MjDDt

@darkblaze69
Copy link

This is also my problem with up to 0.10 version - full 1 core load. Not sure about log file. I even don't see it. But private fix solved my problem. And now I can see log file.

@manojampalam
Copy link
Contributor

@Leproide do you see any other issues? Your logs seem OK to me.

Otherwise, I'll include this fix in April-Mid drop.

@Leproide
Copy link
Author

Leproide commented Apr 5, 2017

@manojampalam works like a charm

@Leproide
Copy link
Author

proprieta - sshd log

Latest release.
Unfortunately i not have a debug log for this issue, i changed now the configuration for future update about this problem.

@manojampalam
Copy link
Contributor

manojampalam commented Apr 16, 2017

IS this with the private I provided?

Please open a new issue.

@C-Duv
Copy link

C-Duv commented Apr 20, 2017

Tested plain new installation of v0.0.12.0 (via Chocolatey): Issue is gone, thanks. 👍

itnic added a commit to itnic/Win32-OpenSSH that referenced this issue Dec 2, 2017
Issue 787

There is a bug in the Microsoft POSIX compatibility layer used to
translate POSIX socket API to Windows socket API. The bug concerns the
emulated function accept() (socketio_accept() in the file socketio.c),
which may return an invalid socket and may lock the program in an
infinite loop.

A race is happening between the Windows kernel signaling a socket
issue to the POSIX compatibility layer. If a connection to the ssh
service is dropped before being fully handled by the POSIX
compatibility layer, that layer may reach a state where the Windows
kernel is aware of the dropped connection and update all the socket
states of the Windows socket API. However, the POSIX compatibility
layer is in the middle of the accept() function task and fails without
updating the local state of the emulated POSIX socket.

When the emulated accept() exits, the current socket state is not
updated and the emulated select() call would carry on detecting
activity (previously already detected) on the socket, triggering the
same exact error in the accept() call, running then in an infinite
loop.

This may not happen all the time: if the Windows kernel signals the
error before the compatibility POSIX layer has setup its accept()
state and returned successfully, other calls such as send() and recv()
will update the state of the socket and will handle the issue.

However, on a loaded machine where the synchronization between the
Windows socket API and the compatibility POSIX layer may be slower,
the emulated accept() call may finish before being notified by the
Windows kernel of a client disconnection. This may be triggered with
nmap, which makes two TCP connections in a row quickly: one to detect
an opened port, and a second to retrieve the ssh banner.

The fix proposed is to update the emulated accept() function to modify
the internal state of the compatibility POSIX layer as a regular POSIX
kernel would do. I personally had this issue and this patch fixed it.

Please note that we have identified other situations where it could
potentially happen (in particular the socketio_setsockopt() call). But
we haven't investigated this issue more deeply. Other issues such as
PowerShell#414 or PowerShell#606 may be related.
@itnic itnic mentioned this issue Dec 2, 2017
@manojampalam
Copy link
Contributor

This issue should be fixed by now. Reopen if you still see it.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

8 participants