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

SFTP failing with "Unable to fulfill channel request" #1271

Open
DavidAnderson684 opened this issue May 12, 2018 · 14 comments
Open

SFTP failing with "Unable to fulfill channel request" #1271

DavidAnderson684 opened this issue May 12, 2018 · 14 comments

Comments

@DavidAnderson684
Copy link
Contributor

I have an SFTP server (openssh) to which phpseclib (1.0.11), running as part of a test setup, daily sends a backup mid-morning.

Starting from yesterday, this began failing. Using openssh/sftp from the command line manually still works and does not throw any warnings/errors. The server logs show no clues.

During the night before, the server had received an automatic update to openssh/sshd (as part of the whole batch of updates for CentOS 7.5). So, I suspect this is related. I have restarted sshd and all other services that had old libraries loaded in memory (using the needs-restarting tool). This has made no difference.

The error happens most of the time, but not every time. It has been tried from 3 different clients, and they all show the same behaviour. (The same clients have also been tested manually with a different server (one on Fedora, the other I think Ubuntu), which has worked. So that strengthens the suspicion that the server openssh upgrade is involved).

These are the PHP notices generated when the failure occurs:

Messages:
* PHP event: code E_NOTICE: Undefined offset: 256 (line 489, wp-content/plugins/updraftplus/vendor/phpseclib/phpseclib/phpseclib/Net/SFTP.php)
* PHP event: code E_USER_NOTICE: Unable to fulfill channel request (line 3844, wp-content/plugins/updraftplus/vendor/phpseclib/phpseclib/phpseclib/Net/SSH2.php)
* PHP event: code E_NOTICE: Undefined offset: 256 (line 4060, wp-content/plugins/updraftplus/vendor/phpseclib/phpseclib/phpseclib/Net/SSH2.php)
* PHP event: code E_USER_NOTICE: Connection closed prematurely (line 3318, wp-content/plugins/updraftplus/vendor/phpseclib/phpseclib/phpseclib/Net/SSH2.php)
* PHP event: code E_USER_NOTICE: Connection closed by server (line 3690, wp-content/plugins/updraftplus/vendor/phpseclib/phpseclib/phpseclib/Net/SSH2.php)
* PHP event: code E_NOTICE: Undefined offset: 256 (line 4072, wp-content/plugins/updraftplus/vendor/phpseclib/phpseclib/phpseclib/Net/SSH2.php)
* PHP event: code E_NOTICE: Undefined offset: 256 (line 4073, wp-content/plugins/updraftplus/vendor/phpseclib/phpseclib/phpseclib/Net/SSH2.php)
* PHP event: code E_NOTICE: Undefined offset: 256 (line 4080, wp-content/plugins/updraftplus/vendor/phpseclib/phpseclib/phpseclib/Net/SSH2.php)
* PHP event: code E_NOTICE: Undefined offset: 256 (line 4084, wp-content/plugins/updraftplus/vendor/phpseclib/phpseclib/phpseclib/Net/SSH2.php)
* PHP event: code E_USER_NOTICE: Connection closed prematurely (line 3924, wp-content/plugins/updraftplus/vendor/phpseclib/phpseclib/phpseclib/Net/SSH2.php)

This is the contents of the debug log:

00000000  53:53:48:2d:32:2e:30:2d:4f:70:65:6e:53:53:48:5f  SSH-2.0-OpenSSH_
00000010  37:2e:34:0d:0a                                   7.4..

->
00000000  53:53:48:2d:32:2e:30:2d:70:68:70:73:65:63:6c:69  SSH-2.0-phpsecli
00000010  62:5f:31:2e:30:20:28:6f:70:65:6e:73:73:6c:2c:20  b_1.0 (openssl, 
00000020  67:6d:70:29:0d:0a                                gmp)..

-> NET_SSH2_MSG_KEXINIT (since last: 0.4758, network: 0.0001s)
00000000  a4:11:1e:84:6d:52:fe:55:51:3c:84:5a:15:79:08:37  ....mR.UQ..Z.y.7
00000010  00:00:00:7e:64:69:66:66:69:65:2d:68:65:6c:6c:6d  ...~diffie-hellm
00000020  61:6e:2d:67:72:6f:75:70:31:2d:73:68:61:31:2c:64  an-group1-sha1,d
00000030  69:66:66:69:65:2d:68:65:6c:6c:6d:61:6e:2d:67:72  iffie-hellman-gr
00000040  6f:75:70:31:34:2d:73:68:61:31:2c:64:69:66:66:69  oup14-sha1,diffi
00000050  65:2d:68:65:6c:6c:6d:61:6e:2d:67:72:6f:75:70:2d  e-hellman-group-
00000060  65:78:63:68:61:6e:67:65:2d:73:68:61:31:2c:64:69  exchange-sha1,di
00000070  66:66:69:65:2d:68:65:6c:6c:6d:61:6e:2d:67:72:6f  ffie-hellman-gro
00000080  75:70:2d:65:78:63:68:61:6e:67:65:2d:73:68:61:32  up-exchange-sha2
00000090  35:36:00:00:00:0f:73:73:68:2d:72:73:61:2c:73:73  56....ssh-rsa,ss
000000a0  68:2d:64:73:73:00:00:00:e9:61:72:63:66:6f:75:72  h-dss....arcfour
000000b0  32:35:36:2c:61:72:63:66:6f:75:72:31:32:38:2c:61  256,arcfour128,a
000000c0  65:73:31:32:38:2d:63:74:72:2c:61:65:73:31:39:32  es128-ctr,aes192
000000d0  2d:63:74:72:2c:61:65:73:32:35:36:2d:63:74:72:2c  -ctr,aes256-ctr,
000000e0  74:77:6f:66:69:73:68:31:32:38:2d:63:74:72:2c:74  twofish128-ctr,t
000000f0  77:6f:66:69:73:68:31:39:32:2d:63:74:72:2c:74:77  wofish192-ctr,tw
00000100  6f:66:69:73:68:32:35:36:2d:63:74:72:2c:61:65:73  ofish256-ctr,aes
00000110  31:32:38:2d:63:62:63:2c:61:65:73:31:39:32:2d:63  128-cbc,aes192-c
00000120  62:63:2c:61:65:73:32:35:36:2d:63:62:63:2c:74:77  bc,aes256-cbc,tw
00000130  6f:66:69:73:68:31:32:38:2d:63:62:63:2c:74:77:6f  ofish128-cbc,two
00000140  66:69:73:68:31:39:32:2d:63:62:63:2c:74:77:6f:66  fish192-cbc,twof
00000150  69:73:68:32:35:36:2d:63:62:63:2c:74:77:6f:66:69  ish256-cbc,twofi
00000160  73:68:2d:63:62:63:2c:62:6c:6f:77:66:69:73:68:2d  sh-cbc,blowfish-
00000170  63:74:72:2c:62:6c:6f:77:66:69:73:68:2d:63:62:63  ctr,blowfish-cbc
00000180  2c:33:64:65:73:2d:63:74:72:2c:33:64:65:73:2d:63  ,3des-ctr,3des-c
00000190  62:63:00:00:00:e9:61:72:63:66:6f:75:72:32:35:36  bc....arcfour256
000001a0  2c:61:72:63:66:6f:75:72:31:32:38:2c:61:65:73:31  ,arcfour128,aes1
000001b0  32:38:2d:63:74:72:2c:61:65:73:31:39:32:2d:63:74  28-ctr,aes192-ct
000001c0  72:2c:61:65:73:32:35:36:2d:63:74:72:2c:74:77:6f  r,aes256-ctr,two
000001d0  66:69:73:68:31:32:38:2d:63:74:72:2c:74:77:6f:66  fish128-ctr,twof
000001e0  69:73:68:31:39:32:2d:63:74:72:2c:74:77:6f:66:69  ish192-ctr,twofi
000001f0  73:68:32:35:36:2d:63:74:72:2c:61:65:73:31:32:38  sh256-ctr,aes128
00000200  2d:63:62:63:2c:61:65:73:31:39:32:2d:63:62:63:2c  -cbc,aes192-cbc,
00000210  61:65:73:32:35:36:2d:63:62:63:2c:74:77:6f:66:69  aes256-cbc,twofi
00000220  73:68:31:32:38:2d:63:62:63:2c:74:77:6f:66:69:73  sh128-cbc,twofis
00000230  68:31:39:32:2d:63:62:63:2c:74:77:6f:66:69:73:68  h192-cbc,twofish
00000240  32:35:36:2d:63:62:63:2c:74:77:6f:66:69:73:68:2d  256-cbc,twofish-
00000250  63:62:63:2c:62:6c:6f:77:66:69:73:68:2d:63:74:72  cbc,blowfish-ctr
00000260  2c:62:6c:6f:77:66:69:73:68:2d:63:62:63:2c:33:64  ,blowfish-cbc,3d
00000270  65:73:2d:63:74:72:2c:33:64:65:73:2d:63:62:63:00  es-ctr,3des-cbc.
00000280  00:00:39:68:6d:61:63:2d:73:68:61:32:2d:32:35:36  ..9hmac-sha2-256
00000290  2c:68:6d:61:63:2d:73:68:61:31:2d:39:36:2c:68:6d  ,hmac-sha1-96,hm
000002a0  61:63:2d:73:68:61:31:2c:68:6d:61:63:2d:6d:64:35  ac-sha1,hmac-md5
000002b0  2d:39:36:2c:68:6d:61:63:2d:6d:64:35:00:00:00:39  -96,hmac-md5...9
000002c0  68:6d:61:63:2d:73:68:61:32:2d:32:35:36:2c:68:6d  hmac-sha2-256,hm
000002d0  61:63:2d:73:68:61:31:2d:39:36:2c:68:6d:61:63:2d  ac-sha1-96,hmac-
000002e0  73:68:61:31:2c:68:6d:61:63:2d:6d:64:35:2d:39:36  sha1,hmac-md5-96
000002f0  2c:68:6d:61:63:2d:6d:64:35:00:00:00:04:6e:6f:6e  ,hmac-md5....non
00000300  65:00:00:00:04:6e:6f:6e:65:00:00:00:00:00:00:00  e....none.......
00000310  00:00:00:00:00:00                                ......

<- NET_SSH2_MSG_KEXINIT (since last: 0.2271, network: 0.227s)
00000000  92:0a:c9:28:1b:74:9b:9d:47:b5:00:c0:fb:96:40:18  ...(.t..G.....@.
00000010  00:00:01:40:63:75:72:76:65:32:35:35:31:39:2d:73  ...@curve25519-s
00000020  68:61:32:35:36:2c:63:75:72:76:65:32:35:35:31:39  ha256,curve25519
00000030  2d:73:68:61:32:35:36:40:6c:69:62:73:73:68:2e:6f  -sha256@libssh.o
00000040  72:67:2c:65:63:64:68:2d:73:68:61:32:2d:6e:69:73  rg,ecdh-sha2-nis
00000050  74:70:32:35:36:2c:65:63:64:68:2d:73:68:61:32:2d  tp256,ecdh-sha2-
00000060  6e:69:73:74:70:33:38:34:2c:65:63:64:68:2d:73:68  nistp384,ecdh-sh
00000070  61:32:2d:6e:69:73:74:70:35:32:31:2c:64:69:66:66  a2-nistp521,diff
00000080  69:65:2d:68:65:6c:6c:6d:61:6e:2d:67:72:6f:75:70  ie-hellman-group
00000090  2d:65:78:63:68:61:6e:67:65:2d:73:68:61:32:35:36  -exchange-sha256
000000a0  2c:64:69:66:66:69:65:2d:68:65:6c:6c:6d:61:6e:2d  ,diffie-hellman-
000000b0  67:72:6f:75:70:31:36:2d:73:68:61:35:31:32:2c:64  group16-sha512,d
000000c0  69:66:66:69:65:2d:68:65:6c:6c:6d:61:6e:2d:67:72  iffie-hellman-gr
000000d0  6f:75:70:31:38:2d:73:68:61:35:31:32:2c:64:69:66  oup18-sha512,dif
000000e0  66:69:65:2d:68:65:6c:6c:6d:61:6e:2d:67:72:6f:75  fie-hellman-grou
000000f0  70:2d:65:78:63:68:61:6e:67:65:2d:73:68:61:31:2c  p-exchange-sha1,
00000100  64:69:66:66:69:65:2d:68:65:6c:6c:6d:61:6e:2d:67  diffie-hellman-g
00000110  72:6f:75:70:31:34:2d:73:68:61:32:35:36:2c:64:69  roup14-sha256,di
00000120  66:66:69:65:2d:68:65:6c:6c:6d:61:6e:2d:67:72:6f  ffie-hellman-gro
00000130  75:70:31:34:2d:73:68:61:31:2c:64:69:66:66:69:65  up14-sha1,diffie
00000140  2d:68:65:6c:6c:6d:61:6e:2d:67:72:6f:75:70:31:2d  -hellman-group1-
00000150  73:68:61:31:00:00:00:41:73:73:68:2d:72:73:61:2c  sha1...Assh-rsa,
00000160  72:73:61:2d:73:68:61:32:2d:35:31:32:2c:72:73:61  rsa-sha2-512,rsa
00000170  2d:73:68:61:32:2d:32:35:36:2c:65:63:64:73:61:2d  -sha2-256,ecdsa-
00000180  73:68:61:32:2d:6e:69:73:74:70:32:35:36:2c:73:73  sha2-nistp256,ss
00000190  68:2d:65:64:32:35:35:31:39:00:00:00:af:63:68:61  h-ed25519....cha
000001a0  63:68:61:32:30:2d:70:6f:6c:79:31:33:30:35:40:6f  cha20-poly1305@o
000001b0  70:65:6e:73:73:68:2e:63:6f:6d:2c:61:65:73:31:32  penssh.com,aes12
000001c0  38:2d:63:74:72:2c:61:65:73:31:39:32:2d:63:74:72  8-ctr,aes192-ctr
000001d0  2c:61:65:73:32:35:36:2d:63:74:72:2c:61:65:73:31  ,aes256-ctr,aes1
000001e0  32:38:2d:67:63:6d:40:6f:70:65:6e:73:73:68:2e:63  28-gcm@openssh.c
000001f0  6f:6d:2c:61:65:73:32:35:36:2d:67:63:6d:40:6f:70  om,aes256-gcm@op
00000200  65:6e:73:73:68:2e:63:6f:6d:2c:61:65:73:31:32:38  enssh.com,aes128
00000210  2d:63:62:63:2c:61:65:73:31:39:32:2d:63:62:63:2c  -cbc,aes192-cbc,
00000220  61:65:73:32:35:36:2d:63:62:63:2c:62:6c:6f:77:66  aes256-cbc,blowf
00000230  69:73:68:2d:63:62:63:2c:63:61:73:74:31:32:38:2d  ish-cbc,cast128-
00000240  63:62:63:2c:33:64:65:73:2d:63:62:63:00:00:00:af  cbc,3des-cbc....
00000250  63:68:61:63:68:61:32:30:2d:70:6f:6c:79:31:33:30  chacha20-poly130
00000260  35:40:6f:70:65:6e:73:73:68:2e:63:6f:6d:2c:61:65  5@openssh.com,ae
00000270  73:31:32:38:2d:63:74:72:2c:61:65:73:31:39:32:2d  s128-ctr,aes192-
00000280  63:74:72:2c:61:65:73:32:35:36:2d:63:74:72:2c:61  ctr,aes256-ctr,a
00000290  65:73:31:32:38:2d:67:63:6d:40:6f:70:65:6e:73:73  es128-gcm@openss
000002a0  68:2e:63:6f:6d:2c:61:65:73:32:35:36:2d:67:63:6d  h.com,aes256-gcm
000002b0  40:6f:70:65:6e:73:73:68:2e:63:6f:6d:2c:61:65:73  @openssh.com,aes
000002c0  31:32:38:2d:63:62:63:2c:61:65:73:31:39:32:2d:63  128-cbc,aes192-c
000002d0  62:63:2c:61:65:73:32:35:36:2d:63:62:63:2c:62:6c  bc,aes256-cbc,bl
000002e0  6f:77:66:69:73:68:2d:63:62:63:2c:63:61:73:74:31  owfish-cbc,cast1
000002f0  32:38:2d:63:62:63:2c:33:64:65:73:2d:63:62:63:00  28-cbc,3des-cbc.
00000300  00:00:d5:75:6d:61:63:2d:36:34:2d:65:74:6d:40:6f  ...umac-64-etm@o
00000310  70:65:6e:73:73:68:2e:63:6f:6d:2c:75:6d:61:63:2d  penssh.com,umac-
00000320  31:32:38:2d:65:74:6d:40:6f:70:65:6e:73:73:68:2e  128-etm@openssh.
00000330  63:6f:6d:2c:68:6d:61:63:2d:73:68:61:32:2d:32:35  com,hmac-sha2-25
00000340  36:2d:65:74:6d:40:6f:70:65:6e:73:73:68:2e:63:6f  6-etm@openssh.co
00000350  6d:2c:68:6d:61:63:2d:73:68:61:32:2d:35:31:32:2d  m,hmac-sha2-512-
00000360  65:74:6d:40:6f:70:65:6e:73:73:68:2e:63:6f:6d:2c  etm@openssh.com,
00000370  68:6d:61:63:2d:73:68:61:31:2d:65:74:6d:40:6f:70  hmac-sha1-etm@op
00000380  65:6e:73:73:68:2e:63:6f:6d:2c:75:6d:61:63:2d:36  enssh.com,umac-6
00000390  34:40:6f:70:65:6e:73:73:68:2e:63:6f:6d:2c:75:6d  4@openssh.com,um
000003a0  61:63:2d:31:32:38:40:6f:70:65:6e:73:73:68:2e:63  ac-128@openssh.c
000003b0  6f:6d:2c:68:6d:61:63:2d:73:68:61:32:2d:32:35:36  om,hmac-sha2-256
000003c0  2c:68:6d:61:63:2d:73:68:61:32:2d:35:31:32:2c:68  ,hmac-sha2-512,h
000003d0  6d:61:63:2d:73:68:61:31:00:00:00:d5:75:6d:61:63  mac-sha1....umac
000003e0  2d:36:34:2d:65:74:6d:40:6f:70:65:6e:73:73:68:2e  -64-etm@openssh.
000003f0  63:6f:6d:2c:75:6d:61:63:2d:31:32:38:2d:65:74:6d  com,umac-128-etm
00000400  40:6f:70:65:6e:73:73:68:2e:63:6f:6d:2c:68:6d:61  @openssh.com,hma
00000410  63:2d:73:68:61:32:2d:32:35:36:2d:65:74:6d:40:6f  c-sha2-256-etm@o
00000420  70:65:6e:73:73:68:2e:63:6f:6d:2c:68:6d:61:63:2d  penssh.com,hmac-
00000430  73:68:61:32:2d:35:31:32:2d:65:74:6d:40:6f:70:65  sha2-512-etm@ope
00000440  6e:73:73:68:2e:63:6f:6d:2c:68:6d:61:63:2d:73:68  nssh.com,hmac-sh
00000450  61:31:2d:65:74:6d:40:6f:70:65:6e:73:73:68:2e:63  a1-etm@openssh.c
00000460  6f:6d:2c:75:6d:61:63:2d:36:34:40:6f:70:65:6e:73  om,umac-64@opens
00000470  73:68:2e:63:6f:6d:2c:75:6d:61:63:2d:31:32:38:40  sh.com,umac-128@
00000480  6f:70:65:6e:73:73:68:2e:63:6f:6d:2c:68:6d:61:63  openssh.com,hmac
00000490  2d:73:68:61:32:2d:32:35:36:2c:68:6d:61:63:2d:73  -sha2-256,hmac-s
000004a0  68:61:32:2d:35:31:32:2c:68:6d:61:63:2d:73:68:61  ha2-512,hmac-sha
000004b0  31:00:00:00:15:6e:6f:6e:65:2c:7a:6c:69:62:40:6f  1....none,zlib@o
000004c0  70:65:6e:73:73:68:2e:63:6f:6d:00:00:00:15:6e:6f  penssh.com....no
000004d0  6e:65:2c:7a:6c:69:62:40:6f:70:65:6e:73:73:68:2e  ne,zlib@openssh.
000004e0  63:6f:6d:00:00:00:00:00:00:00:00:00:00:00:00:00  com.............

-> NET_SSH2_MSG_KEXDH_INIT (since last: 0.0062, network: 0s)
00000000  00:00:00:80:02:b5:5f:27:1d:0a:16:90:f1:9e:8d:53  ......_'.......S
00000010  d9:97:46:73:e4:84:3d:d2:f4:ae:4c:f3:9b:39:5a:5a  ..Fs..=...L..9ZZ
00000020  6c:70:fa:49:83:9e:88:7f:d2:64:5b:af:c8:9c:51:1a  lp.I.....d[...Q.
00000030  62:fd:22:ed:ea:2a:a2:de:78:f4:88:a3:37:12:42:bc  b."..*..x...7.B.
00000040  2a:85:1a:57:f7:2c:6d:d3:2c:4b:eb:03:dd:d0:d2:96  *..W.,m.,K......
00000050  4c:5b:a9:34:c6:04:c0:a3:f4:a6:67:85:b8:ae:dc:47  L[.4......g....G
00000060  67:26:ba:d2:0b:10:b4:a0:85:53:93:cd:33:f6:89:65  g&.......S..3..e
00000070  c1:01:ba:ff:b1:af:43:b4:2e:a7:09:fc:0a:e9:a1:93  ......C.........
00000080  a6:e2:ec:59                                      ...Y

<- NET_SSH2_MSG_KEXDH_REPLY (since last: 0.2921, network: 0.292s)
00000000  00:00:01:17:00:00:00:07:73:73:68:2d:72:73:61:00  ........ssh-rsa.
00000010  00:00:03:01:00:01:00:00:01:01:00:a3:f0:9f:8b:23  ...............#
00000020  46:b7:77:5a:17:7a:11:2d:74:4f:7f:80:66:82:bb:3b  F.wZ.z.-tO..f..;
00000030  33:ed:b8:77:30:5e:0d:a6:b4:55:9a:13:1d:fe:95:87  3..w0^...U......
00000040  75:ac:b7:c6:10:b4:d1:b0:8d:a9:8a:e8:0a:61:5d:40  u............a]@
00000050  8d:70:3e:79:f1:94:52:b2:4e:26:ce:53:7e:7f:2c:7d  .p>y..R.N&.S~.,}
00000060  cb:03:21:64:c7:42:65:73:d0:8b:1c:b4:f5:ba:d0:1b  ..!d.Bes........
00000070  0f:04:9c:e7:cc:f8:b8:d6:ec:20:fe:82:20:b6:73:8a  ......... .. .s.
00000080  bf:ef:4a:a5:6b:37:72:53:86:8c:a2:8e:66:88:72:32  ..J.k7rS....f.r2
00000090  35:dc:61:5a:c4:c7:b1:83:96:53:c9:4d:e8:07:32:ad  5.aZ.....S.M..2.
000000a0  36:77:16:d8:46:8a:ec:1c:6d:3d:73:da:0c:ba:4b:29  6w..F...m=s...K)
000000b0  a6:83:47:43:e2:15:a2:df:f4:d7:c0:eb:5b:f1:1a:1a  ..GC........[...
000000c0  c6:a0:8b:1e:ea:29:7a:e7:d2:e1:18:4a:90:30:cc:80  .....)z....J.0..
000000d0  ca:38:b5:c7:b1:d2:b2:b4:e1:ac:2a:fa:3b:d0:b0:da  .8........*.;...
000000e0  da:ce:82:51:a0:11:c8:8c:f8:32:1b:a3:f8:c3:b2:7d  ...Q.....2.....}
000000f0  03:40:89:c4:66:ab:ef:b2:4c:ed:8b:2b:1a:23:48:ed  .@..f...L..+.#H.
00000100  c4:ff:44:41:03:89:52:f7:24:9b:7f:0a:ca:59:72:dd  ..DA..R.$....Yr.
00000110  cc:fe:07:91:8d:d1:5b:75:e1:a6:83:00:00:00:80:30  ......[u.......0
00000120  40:c7:d8:11:63:cc:e2:89:72:45:a5:c2:83:bc:3d:71  @...c...rE....=q
00000130  dc:ea:b2:1b:4a:77:4c:e5:e8:68:5d:06:39:55:d9:2b  ....JwL..h].9U.+
00000140  b3:45:97:08:3d:41:ac:d0:43:99:51:06:29:36:b1:a5  .E..=A..C.Q.)6..
00000150  e4:3f:58:48:8f:4e:e5:d2:9f:72:78:0d:bf:9b:bb:86  .?XH.N...rx.....
00000160  7e:55:db:61:13:f0:3d:7d:1b:62:50:15:38:81:11:e7  ~U.a..=}.bP.8...
00000170  6f:fa:b0:51:18:cf:f0:7c:1d:9c:04:70:83:3d:61:fc  o..Q...|...p.=a.
00000180  9b:25:7a:28:09:6b:ed:94:a2:8e:4c:69:9c:1c:98:96  .%z(.k....Li....
00000190  16:2c:d3:9b:05:10:f9:e4:b2:5d:dd:2c:af:17:f7:00  .,.......].,....
000001a0  00:01:0f:00:00:00:07:73:73:68:2d:72:73:61:00:00  .......ssh-rsa..
000001b0  01:00:84:10:a9:ce:e2:cf:a8:8c:73:56:75:a2:1a:78  ..........sVu..x
000001c0  a9:20:1b:3a:57:b6:87:15:94:b0:6b:a8:45:7e:38:1e  . .:W.....k.E~8.
000001d0  47:8f:0a:4a:fe:08:d2:48:13:fa:ba:08:db:bc:f9:f4  G..J...H........
000001e0  8c:e7:d2:6d:84:3b:21:2e:ab:46:bd:ef:d0:9f:1e:5b  ...m.;!..F.....[
000001f0  1c:62:5d:9b:28:ef:a4:75:ff:69:39:2f:aa:72:93:ce  .b].(..u.i9/.r..
00000200  5b:c6:42:1f:cd:51:8b:6a:5e:ae:d9:69:76:d7:e8:38  [.B..Q.j^..iv..8
00000210  c5:24:c6:ed:c8:7d:e0:97:7b:25:9b:f6:06:70:26:2a  .$...}..{%...p&*
00000220  0b:56:a8:de:d5:db:a9:6d:ef:9a:86:b5:45:46:d2:93  .V.....m....EF..
00000230  5b:dc:e9:94:bb:e4:eb:4d:e0:b3:31:3f:bd:8c:75:4f  [......M..1?..uO
00000240  89:03:3c:e7:4f:fe:e6:0e:5c:2a:1b:eb:59:58:3d:c4  ....O...\*..YX=.
00000250  91:bf:f5:69:d5:11:76:65:61:0d:a7:21:5f:7a:3f:e3  ...i..vea..!_z?.
00000260  ac:7d:4b:60:db:01:ec:35:2a:ba:ca:b6:fd:14:01:b0  .}K`...5*.......
00000270  cb:09:15:8d:fd:6d:30:83:7f:9c:6d:a1:e7:44:c4:d0  .....m0...m..D..
00000280  71:2f:d0:d5:a1:7d:a8:91:e2:69:4f:f5:6f:d4:82:5d  q/...}...iO.o..]
00000290  2f:32:ff:98:41:66:12:6e:be:54:d3:72:d9:c3:7d:c0  /2..Af.n.T.r..}.
000002a0  aa:9d:57:97:94:1a:34:31:26:4c:2f:2b:5d:a3:a2:9f  ..W...41&L/+]...
000002b0  32:12                                            2.

-> NET_SSH2_MSG_NEWKEYS (since last: 0.0011, network: 0.0001s)
                                                 

<- NET_SSH2_MSG_NEWKEYS (since last: 0.0001, network: 0s)
                                                 

-> NET_SSH2_MSG_SERVICE_REQUEST (since last: 0.0041, network: 0s)
00000000  00:00:00:0c:73:73:68:2d:75:73:65:72:61:75:74:68  ....ssh-userauth

<- NET_SSH2_MSG_SERVICE_ACCEPT (since last: 0.4957, network: 0.4955s)
00000000  00:00:00:0c:73:73:68:2d:75:73:65:72:61:75:74:68  ....ssh-userauth

-> NET_SSH2_MSG_USERAUTH_REQUEST (since last: 0.0008, network: 0.0003s)
00000000  00:00:00:08:75:73:65:72:6e:61:6d:65:00:00:00:0e  ....username....
00000010  73:73:68:2d:63:6f:6e:6e:65:63:74:69:6f:6e:00:00  ssh-connection..
00000020  00:08:70:61:73:73:77:6f:72:64:00:00:00:00:08:70  ..password.....p
00000030  61:73:73:77:6f:72:64                             assword

<- NET_SSH2_MSG_USERAUTH_SUCCESS (since last: 0.3189, network: 0.3187s)
                                                 

-> NET_SSH2_MSG_CHANNEL_OPEN (since last: 0.0003, network: 0.0001s)
00000000  00:00:00:07:73:65:73:73:69:6f:6e:00:00:01:00:7f  ....session.....
00000010  ff:ff:ff:00:00:40:00                             .....@.

-> NET_SSH2_MSG_CHANNEL_REQUEST (since last: 14.5402, network: 0.0001s)
00000000  00:00:00:00:00:00:00:09:73:75:62:73:79:73:74:65  ........subsyste
00000010  6d:01:00:00:00:04:73:66:74:70                    m.....sftp

<- NET_SSH2_MSG_GLOBAL_REQUEST (since last: 10.7553, network: 0.0001s)
00000000  00:00:00:17:68:6f:73:74:6b:65:79:73:2d:30:30:40  ....hostkeys-00@
00000010  6f:70:65:6e:73:73:68:2e:63:6f:6d:00:00:00:01:17  openssh.com.....
00000020  00:00:00:07:73:73:68:2d:72:73:61:00:00:00:03:01  ....ssh-rsa.....
00000030  00:01:00:00:01:01:00:a3:f0:9f:8b:23:46:b7:77:5a  ...........#F.wZ
00000040  17:7a:11:2d:74:4f:7f:80:66:82:bb:3b:33:ed:b8:77  .z.-tO..f..;3..w
00000050  30:5e:0d:a6:b4:55:9a:13:1d:fe:95:87:75:ac:b7:c6  0^...U......u...
00000060  10:b4:d1:b0:8d:a9:8a:e8:0a:61:5d:40:8d:70:3e:79  .........a]@.p>y
00000070  f1:94:52:b2:4e:26:ce:53:7e:7f:2c:7d:cb:03:21:64  ..R.N&.S~.,}..!d
00000080  c7:42:65:73:d0:8b:1c:b4:f5:ba:d0:1b:0f:04:9c:e7  .Bes............
00000090  cc:f8:b8:d6:ec:20:fe:82:20:b6:73:8a:bf:ef:4a:a5  ..... .. .s...J.
000000a0  6b:37:72:53:86:8c:a2:8e:66:88:72:32:35:dc:61:5a  k7rS....f.r25.aZ
000000b0  c4:c7:b1:83:96:53:c9:4d:e8:07:32:ad:36:77:16:d8  .....S.M..2.6w..
000000c0  46:8a:ec:1c:6d:3d:73:da:0c:ba:4b:29:a6:83:47:43  F...m=s...K)..GC
000000d0  e2:15:a2:df:f4:d7:c0:eb:5b:f1:1a:1a:c6:a0:8b:1e  ........[.......
000000e0  ea:29:7a:e7:d2:e1:18:4a:90:30:cc:80:ca:38:b5:c7  .)z....J.0...8..
000000f0  b1:d2:b2:b4:e1:ac:2a:fa:3b:d0:b0:da:da:ce:82:51  ......*.;......Q
00000100  a0:11:c8:8c:f8:32:1b:a3:f8:c3:b2:7d:03:40:89:c4  .....2.....}.@..
00000110  66:ab:ef:b2:4c:ed:8b:2b:1a:23:48:ed:c4:ff:44:41  f...L..+.#H...DA
00000120  03:89:52:f7:24:9b:7f:0a:ca:59:72:dd:cc:fe:07:91  ..R.$....Yr.....
00000130  8d:d1:5b:75:e1:a6:83:00:00:00:68:00:00:00:13:65  ..[u......h....e
00000140  63:64:73:61:2d:73:68:61:32:2d:6e:69:73:74:70:32  cdsa-sha2-nistp2
00000150  35:36:00:00:00:08:6e:69:73:74:70:32:35:36:00:00  56....nistp256..
00000160  00:41:04:e5:df:54:61:ba:a4:77:a0:e4:0a:d3:86:26  .A...Ta..w.....&
00000170  1d:46:c7:8b:d8:12:3a:40:3f:90:65:76:20:fd:9a:91  .F....:@?.ev ...
00000180  54:c5:eb:d4:18:68:5f:f0:86:ba:3d:ee:8e:73:fd:36  T....h_...=..s.6
00000190  cb:99:2c:bd:5f:e8:7d:fe:42:18:79:4e:02:85:3e:94  ..,._.}.B.yN..>.
000001a0  8b:1f:5a:00:00:00:33:00:00:00:0b:73:73:68:2d:65  ..Z...3....ssh-e
000001b0  64:32:35:35:31:39:00:00:00:20:0f:62:03:b6:58:7c  d25519... .b..X|
000001c0  30:f4:d0:4e:3c:5b:2d:30:bc:95:2c:63:0e:39:ed:11  0..N.[-0..,c.9..
000001d0  4b:b2:80:e2:fd:4b:bf:9a:f6:a2                    K....K....

-> NET_SSH2_MSG_REQUEST_FAILURE (since last: 0.0002, network: 0.0001s)
                                                 

<- NET_SSH2_MSG_CHANNEL_OPEN_CONFIRMATION (since last: 0.0001, network: 0.0001s)
00000000  00:00:01:00:00:00:00:00:00:00:00:00:00:00:80:00  ................

-> NET_SSH2_MSG_DISCONNECT (since last: 0.0002, network: 0s)
00000000  00:00:00:0b:00:00:00:00:00:00:00:00              ............

@DavidAnderson684
Copy link
Contributor Author

DavidAnderson684 commented May 12, 2018

The server is openssh-7.4p1-16.el7.x86_64 on CentOS 7. The changelog items since the previous version (7.4p1-13) are:

= Friday Nov 24 2017 Jakub Jelen jjelen@redhat.com - 7.4p1-16 + 0.10.3-2 =

= Mon Nov 06 2017 Jakub Jelen jjelen@redhat.com - 7.4p1-15 + 0.10.3-2 =

  • Do not hang if SSH AuthorizedKeysCommand output is too large (#1496467)
  • Do not segfault pam_ssh_agent_auth if keyfile is missing (#1494268)
  • Do not segfault in audit code during cleanup (#1488083)
  • Add WinSCP 5.10+ compatibility (#1496808)
  • Clatch between ClientAlive and rekeying timeouts (#1480510)
  • Exclude dsa and ed25519 from default proposed keys in FIPS mode (#1456853)
  • Add enablement for openssl-ibmca and openssl-ibmpkcs11 (#1478035)

= Fri Nov 03 2017 Nikos Mavrogiannopoulos nmav@redhat.com - 7.4p1-14 + 0.10.3-2 =

  • Rebuilt for RHEL-7.5

@terrafrost
Copy link
Member

Are you able to reliably reproduce this?

This bit sticks out to me:

-> NET_SSH2_MSG_CHANNEL_OPEN (since last: 0.0003, network: 0.0001s)
00000000  00:00:00:07:73:65:73:73:69:6f:6e:00:00:01:00:7f  ....session.....
00000010  ff:ff:ff:00:00:40:00                             .....@.

-> NET_SSH2_MSG_CHANNEL_REQUEST (since last: 14.5402, network: 0.0001s)
00000000  00:00:00:00:00:00:00:09:73:75:62:73:79:73:74:65  ........subsyste
00000010  6d:01:00:00:00:04:73:66:74:70                    m.....sftp

In Net/SFTP.php there's this:

https://github.com/phpseclib/phpseclib/blob/1.0.11/phpseclib/Net/SFTP.php#L465

        $packet = pack(
            'CNa*N3',
            NET_SSH2_MSG_CHANNEL_OPEN,
            strlen('session'),
            'session',
            NET_SFTP_CHANNEL,
            $this->window_size,
            0x4000
        );
        if (!$this->_send_binary_packet($packet)) {
            return false;
        }
        $this->channel_status[NET_SFTP_CHANNEL] = NET_SSH2_MSG_CHANNEL_OPEN;
        $response = $this->_get_channel_packet(NET_SFTP_CHANNEL, true);
        if ($response === false) {
            return false;
        }

        $packet = pack(
            'CNNa*CNa*',
            NET_SSH2_MSG_CHANNEL_REQUEST,
            $this->server_channels[NET_SFTP_CHANNEL],
            strlen('subsystem'),
            'subsystem',
            1,
            strlen('sftp'),
            'sftp'
        );
        if (!$this->_send_binary_packet($packet)) {
            return false;
        }

So phpseclib is sending the channel open packet and then it's expecting a response from the server but 15s later it doesn't get one and then phpseclib sends the channel request packet.

Later, in SSH2::_get_channel_packet there's this:

https://github.com/phpseclib/phpseclib/blob/1.0.11/phpseclib/Net/SSH2.php#L3698

            if (!strlen($response)) {
                return '';
            }

I think that line is being hit. If you could maybe add an exit('this far'); there to confirm that'd be cool. That should probably be a return false; instead of a return ''; but that won't fix the issue either. Overall the server just ought not be sending empty packets. Maybe phpseclib ought to loop until it finds a non-empty packet. I'll research that.

@DavidAnderson684
Copy link
Contributor Author

Hi Jim,

Are you able to reliably reproduce this?

Yes, most of the time (succeeding happens sometimes, but less often).

I've tweaked the line as you suggested, and added an error_log() too for good measure. Nothing changed - execution continued (which was confirmed by adding another error_log() after as well).

N.B. You say:

That should probably be a return false; instead of a return '';

There's a fragment with precisely that (which can never be matched) immediately afterwards.

@terrafrost
Copy link
Member

Yes, most of the time (succeeding happens sometimes, but less often).

Would it be possible to give me access to the server?

I've tweaked the line as you suggested, and added an error_log() too for good measure. Nothing changed - execution continued (which was confirmed by adding another error_log() after as well).

Could you do var_dump on $response then, before the if (!strlen($response)) { check? The thing is... I'm not able to reproduce the problem with anything other than an empty string. It's like the server is timing out but it's not sending a '' because if it did that the output would be different. It's not sending out a false then if ($response === false) { would be met.

There's a fragment with precisely that (which can never be matched) immediately afterwards.

Good catch. That should definitely be removed. I'll try to do it as time permits.

Thanks!

@DavidAnderson684
Copy link
Contributor Author

Would it be possible to give me access to the server?

An SFTP login on the SFTP server that manifests the problem? Or something else? (As I say, from the client side, the same happens from any client).

@DavidAnderson684
Copy link
Contributor Author

P.S. If so... how to send you these login details?

@terrafrost
Copy link
Member

An SFTP login on the SFTP server that manifests the problem?

Yup.

P.S. If so... how to send you these login details?

You can email them to terrafrost@php.net.

Thanks!

@DavidAnderson684
Copy link
Contributor Author

If I log base64_encode($response) then the results of that is: WwAAAQAAAAAAAAAAAAAAgAA=

I've emailed you the login details now. They are tested and working with openssh/sftp - and also manifesting the problem.

It's been set up to be identical to our regular login that has the problem. In consequence, there's no shell on this account - it's SFTP only.

You cannot write in the default home directory - you need to go into the 'terrafrost' subdirectory.

David

@terrafrost
Copy link
Member

I was able to make it work with the latest commit and with this code:

include('Net/SFTP.php');

$sftp = new Net_SFTP(...);
$sftp->setTimeout(0);
$sftp->login('user', 'pass');

print_r($sftp->nlist());

The issue was this packet:

-> NET_SSH2_MSG_CHANNEL_OPEN (since last: 0.0009, network: 0.0002s)
00000000  00:00:00:07:73:65:73:73:69:6f:6e:00:00:01:00:7f  ....session.....
00000010  ff:ff:ff:00:00:40:00                             .....@.



<- NET_SSH2_MSG_GLOBAL_REQUEST (since last: 25.5383, network: 25.5235s)
00000000  00:00:00:17:68:6f:73:74:6b:65:79:73:2d:30:30:40  ....hostkeys-00@
00000010  6f:70:65:6e:73:73:68:2e:63:6f:6d:00:00:00:01:17  openssh.com.....
00000020  00:00:00:07:73:73:68:2d:72:73:61:00:00:00:03:01  ....ssh-rsa.....
00000030  00:01:00:00:01:01:00:a3:f0:9f:8b:23:46:b7:77:5a  ...........#F.wZ
00000040  17:7a:11:2d:74:4f:7f:80:66:82:bb:3b:33:ed:b8:77  .z.-tO..f..;3..w
00000050  30:5e:0d:a6:b4:55:9a:13:1d:fe:95:87:75:ac:b7:c6  0^...U......u...
00000060  10:b4:d1:b0:8d:a9:8a:e8:0a:61:5d:40:8d:70:3e:79  .........a]@.p>y
00000070  f1:94:52:b2:4e:26:ce:53:7e:7f:2c:7d:cb:03:21:64  ..R.N&.S~.,}..!d
00000080  c7:42:65:73:d0:8b:1c:b4:f5:ba:d0:1b:0f:04:9c:e7  .Bes............
00000090  cc:f8:b8:d6:ec:20:fe:82:20:b6:73:8a:bf:ef:4a:a5  ..... .. .s...J.
000000a0  6b:37:72:53:86:8c:a2:8e:66:88:72:32:35:dc:61:5a  k7rS....f.r25.aZ
000000b0  c4:c7:b1:83:96:53:c9:4d:e8:07:32:ad:36:77:16:d8  .....S.M..2.6w..
000000c0  46:8a:ec:1c:6d:3d:73:da:0c:ba:4b:29:a6:83:47:43  F...m=s...K)..GC
000000d0  e2:15:a2:df:f4:d7:c0:eb:5b:f1:1a:1a:c6:a0:8b:1e  ........[.......
000000e0  ea:29:7a:e7:d2:e1:18:4a:90:30:cc:80:ca:38:b5:c7  .)z....J.0...8..
000000f0  b1:d2:b2:b4:e1:ac:2a:fa:3b:d0:b0:da:da:ce:82:51  ......*.;......Q
00000100  a0:11:c8:8c:f8:32:1b:a3:f8:c3:b2:7d:03:40:89:c4  .....2.....}.@..
00000110  66:ab:ef:b2:4c:ed:8b:2b:1a:23:48:ed:c4:ff:44:41  f...L..+.#H...DA
00000120  03:89:52:f7:24:9b:7f:0a:ca:59:72:dd:cc:fe:07:91  ..R.$....Yr.....
00000130  8d:d1:5b:75:e1:a6:83:00:00:00:68:00:00:00:13:65  ..[u......h....e
00000140  63:64:73:61:2d:73:68:61:32:2d:6e:69:73:74:70:32  cdsa-sha2-nistp2
00000150  35:36:00:00:00:08:6e:69:73:74:70:32:35:36:00:00  56....nistp256..
00000160  00:41:04:e5:df:54:61:ba:a4:77:a0:e4:0a:d3:86:26  .A...Ta..w.....&
00000170  1d:46:c7:8b:d8:12:3a:40:3f:90:65:76:20:fd:9a:91  .F....:@?.ev ...
00000180  54:c5:eb:d4:18:68:5f:f0:86:ba:3d:ee:8e:73:fd:36  T....h_...=..s.6
00000190  cb:99:2c:bd:5f:e8:7d:fe:42:18:79:4e:02:85:3e:94  ..,._.}.B.yN..>.
000001a0  8b:1f:5a:00:00:00:33:00:00:00:0b:73:73:68:2d:65  ..Z...3....ssh-e
000001b0  64:32:35:35:31:39:00:00:00:20:0f:62:03:b6:58:7c  d25519... .b..X|
000001c0  30:f4:d0:4e:3c:5b:2d:30:bc:95:2c:63:0e:39:ed:11  0..N.[-0..,c.9..
000001d0  4b:b2:80:e2:fd:4b:bf:9a:f6:a2                    K....K....

phpseclib sends a NET_SSH2_MSG_CHANNEL_OPEN packet and then, 30 seconds later, the server responds with a NET_SSH2_MSG_GLOBAL_REQUEST packet. The problem is in the fact that the server took 30 seconds to respond. phpseclib, by default, times out after 10s so it assumes it won't be getting a response. Setting the timeout to 0 fixes that but only after this commit that I just made has been applied:

9b49d3c

The fact that that packet takes 30s to send is weird but I tested it with other SFTP clients and had similar delays. Quoting the logs from FlashFXP:

Like with FlashFXP... I tried it just now and got this:

[08:18:48] [R] SSH Connection open
[08:19:13] [R] Connection established with OpenSSH_7.4 (SFTP v3)

I tried connecting with PuTTY, too, but PuTTY doesn't appear to show timestamps in its logs.

@DavidAnderson684
Copy link
Contributor Author

Hi,

Thank you. Based on what you say, if I did...

```$sftp->setTimeout(35)``

... then in principle, ought that to work too? Obviously, I want to investigate + fix the server so that it doesn't time out, but given that the code is for distributing to users who may use it on all kinds of setups, I want to be able to work around it for them too.

David

@terrafrost
Copy link
Member

Yah - that should work. The only problem I could see is with PHP's max_execution_time and Apache timeout settings. For the former you could do set_time_limit(0); but there probably isn't much that can be done for the latter.

@DavidAnderson684
Copy link
Contributor Author

Thanks. Yes, setting the timeout either of those ways works for me.

Upon sticking a strace on the relevant sshd process, revealed that I had a problem with systemd-logind needing restarting after a certain other service has been restarted: https://serverfault.com/questions/707377/slow-ssh-login-activation-of-org-freedesktop-login1-timed-out.

@terrafrost
Copy link
Member

Interesting.

Thanks for the update!

@steventeo
Copy link

I thought I share my experience with this issue.
For me, I got a similar error message (Undefined offset: 256).

Then I noticed in my /var/log/secure the following line at the end of 25 or 30 seconds after each SSH login attemp.
pam_systemd(crond:session): Failed to create session: Failed to activate service 'org.freedesktop.login1': timed out

So it seems to be related to this issue.
https://bugs.launchpad.net/ubuntu/+source/systemd/+bug/1591411

I will just restart systemd-logind (systemctl restart systemd-logind) everytime I experience this issue.

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

No branches or pull requests

3 participants