search

phpseclib / phpseclib

PHP Secure Communications Library
http://phpseclib.com/
MIT License
5.35k stars 888 forks source link

SFTP error with LiveDrive SFTP server #1479

Closed dnutbourne2 closed 4 years ago

dnutbourne2 commented 4 years ago

Hi,

We are experiencing an issue with uploading to LiveDrive SFTP servers.

When connected to the LiveDrive SFTP server (sftp.livedrive.com), attempting to create a directory with mkdir() will result in subsequent calls failing with the same error. This does not occur with other SFTP servers.

For example, we have the attached test script: phpseclibtest.zip

This test connects to the server, creates a new directory, moves into the directory, calls nlist() and outputs the errors array. It then moves back to the original directory and attempts the same process (this time with the pre-existing directory).

Normally, the output is as follows:

[02-Jun-2020 14:43:47 UTC] creating a new directory
[02-Jun-2020 14:43:47 UTC] chdir: 1
[02-Jun-2020 14:43:47 UTC] pwd: /dnutbourne
[02-Jun-2020 14:43:48 UTC] mkdir: 1
[02-Jun-2020 14:43:48 UTC] chdir: 1
[02-Jun-2020 14:43:48 UTC] pwd: /dnutbourne/test
[02-Jun-2020 14:43:48 UTC] nlist: Array
(
    [0] => .
    [1] => ..
)

[02-Jun-2020 14:43:48 UTC] Array
(
)

[02-Jun-2020 14:43:48 UTC] attempt to create an existing directory
[02-Jun-2020 14:43:48 UTC] pwd: /dnutbourne
[02-Jun-2020 14:43:48 UTC] mkdir: 
[02-Jun-2020 14:43:48 UTC] chdir: 1
[02-Jun-2020 14:43:49 UTC] nlist: Array
(
    [0] => .
    [1] => ..
)

[02-Jun-2020 14:43:49 UTC] Array
(
    [0] => NET_SFTP_STATUS_FAILURE: Failure
)

The final error array contains NET_SFTP_STATUS_FAILURE: Failure from the second mkdir call, and the second nlist call succeeds.

However, for the LiveDrive server:

[02-Jun-2020 17:35:25 UTC] creating a new directory
[02-Jun-2020 17:35:25 UTC] chdir: 1
[02-Jun-2020 17:35:25 UTC] pwd: /backup1
[02-Jun-2020 17:35:25 UTC] mkdir: 1
[02-Jun-2020 17:35:25 UTC] chdir: 1
[02-Jun-2020 17:35:25 UTC] pwd: /backup1/test
[02-Jun-2020 17:35:25 UTC] nlist: Array
(
    [0] => .
    [1] => ..
)

[02-Jun-2020 17:35:25 UTC] errors: Array
(
)

[02-Jun-2020 17:35:25 UTC] attempt to create the same directory
[02-Jun-2020 17:35:25 UTC] pwd: /backup1
[02-Jun-2020 17:35:25 UTC] mkdir: 
[02-Jun-2020 17:35:25 UTC] chdir: 1
[02-Jun-2020 17:35:26 UTC] nlist: 
[02-Jun-2020 17:35:26 UTC] errors: Array
(
    [0] => NET_SFTP_STATUS_FILE_ALREADY_EXISTS: 
    [1] => NET_SFTP_STATUS_FILE_ALREADY_EXISTS: 
)

The second nlist call fails with the same NET_SFTP_STATUS_FILE_ALREADY_EXISTS error logged.

Any advice on this would be greatly appreciated.

Dee

terrafrost commented 4 years ago

Honestly, it sounds like a bug in LiveDrive - that maybe the best thing to do would be to report the issue to LiveDrive. But before that's done... can you post the SFTP logs? You can get them by doing define('NET_SFTP_LOGGING', 2) at the top and then echo $sftp->getSFTPLog() at the very end. Do it for both servers and post the results.

dnutbourne2 commented 4 years ago

Hi, thanks sorry about the delay.

Results for our test server:

-> NET_SFTP_INIT (0.0003s) 00000000 00:00:00:03 .... <- NET_SFTP_VERSION (0.0948s) 00000000 00:00:00:03:00:00:00:18:70:6f:73:69:78:2d:72:65 ........posix-re 00000010 6e:61:6d:65:40:6f:70:65:6e:73:73:68:2e:63:6f:6d name@openssh.com 00000020 00:00:00:01:31:00:00:00:13:73:74:61:74:76:66:73 ....1....statvfs 00000030 40:6f:70:65:6e:73:73:68:2e:63:6f:6d:00:00:00:01 @openssh.com.... 00000040 32:00:00:00:14:66:73:74:61:74:76:66:73:40:6f:70 2....fstatvfs@op 00000050 65:6e:73:73:68:2e:63:6f:6d:00:00:00:01:32:00:00 enssh.com....2.. 00000060 00:14:68:61:72:64:6c:69:6e:6b:40:6f:70:65:6e:73 ..hardlink@opens 00000070 73:68:2e:63:6f:6d:00:00:00:01:31:00:00:00:11:66 sh.com....1....f 00000080 73:79:6e:63:40:6f:70:65:6e:73:73:68:2e:63:6f:6d sync@openssh.com 00000090 00:00:00:01:31 ....1 -> NET_SFTP_REALPATH (0.0002s) 00000000 00:00:00:01:2e ..... <- NET_SFTP_NAME (0.1001s) 00000000 00:00:00:01:00:00:00:01:2f:00:00:00:01:2f:00:00 ......../..../.. 00000010 00:00 .. -> NET_SFTP_OPENDIR (0.0002s) 00000000 00:00:00:0b:2f:64:6e:75:74:62:6f:75:72:6e:65 ..../dnutbourne <- NET_SFTP_HANDLE (0.0986s) 00000000 00:00:00:04:00:00:00:00 ........ -> NET_SFTP_CLOSE (0.0002s) 00000000 00:00:00:04:00:00:00:00 ........ <- NET_SFTP_STATUS (0.0933s) 00000000 00:00:00:00:00:00:00:07:53:75:63:63:65:73:73:00 ........Success. 00000010 00:00:00 ... -> NET_SFTP_MKDIR (0.0002s) 00000000 00:00:00:10:2f:64:6e:75:74:62:6f:75:72:6e:65:2f ..../dnutbourne/ 00000010 74:65:73:74:00:00:00:00 test.... <- NET_SFTP_STATUS (0.0944s) 00000000 00:00:00:00:00:00:00:07:53:75:63:63:65:73:73:00 ........Success. 00000010 00:00:00 ... -> NET_SFTP_OPENDIR (0.0002s) 00000000 00:00:00:10:2f:64:6e:75:74:62:6f:75:72:6e:65:2f ..../dnutbourne/ 00000010 74:65:73:74 test <- NET_SFTP_HANDLE (0.1019s) 00000000 00:00:00:04:00:00:00:00 ........ -> NET_SFTP_CLOSE (0.0002s) 00000000 00:00:00:04:00:00:00:00 ........ <- NET_SFTP_STATUS (0.1003s) 00000000 00:00:00:00:00:00:00:07:53:75:63:63:65:73:73:00 ........Success. 00000010 00:00:00 ... -> NET_SFTP_OPENDIR (0.0003s) 00000000 00:00:00:10:2f:64:6e:75:74:62:6f:75:72:6e:65:2f ..../dnutbourne/ 00000010 74:65:73:74 test <- NET_SFTP_HANDLE (0.093s) 00000000 00:00:00:04:00:00:00:00 ........ -> NET_SFTP_READDIR (0.0002s) 00000000 00:00:00:04:00:00:00:00 ........ <- NET_SFTP_NAME (0.1034s) 00000000 00:00:00:02:00:00:00:01:2e:00:00:00:39:64:72:77 ............9drw 00000010 78:72:2d:78:72:2d:78:20:20:20:20:32:20:31:30:30 xr-xr-x 2 100 00000020 31:20:20:20:20:20:31:30:30:32:20:20:20:20:20:20 1 1002 00000030 20:20:20:34:30:39:36:20:4a:75:6e:20:31:31:20:31 4096 Jun 11 1 00000040 31:3a:33:32:20:2e:00:00:00:0f:00:00:00:00:00:00 1:32 ........... 00000050 10:00:00:00:03:e9:00:00:03:ea:00:00:41:ed:5e:e2 ............A.^. 00000060 16:58:5e:e2:16:58:00:00:00:02:2e:2e:00:00:00:3a .X^..X.........: 00000070 64:72:77:78:2d:2d:2d:2d:2d:2d:20:20:20:20:33:20 drwx------ 3 00000080 31:30:30:31:20:20:20:20:20:31:30:30:32:20:20:20 1001 1002 00000090 20:20:20:20:31:30:36:34:39:36:20:4a:75:6e:20:31 106496 Jun 1 000000a0 31:20:31:31:3a:33:32:20:2e:2e:00:00:00:0f:00:00 1 11:32 ........ 000000b0 00:00:00:01:a0:00:00:00:03:e9:00:00:03:ea:00:00 ................ 000000c0 41:c0:58:ae:ef:2a:5e:e2:16:58 A.X..*^..X -> NET_SFTP_READDIR (0.0002s) 00000000 00:00:00:04:00:00:00:00 ........ <- NET_SFTP_STATUS (0.1004s) 00000000 00:00:00:01:00:00:00:0b:45:6e:64:20:6f:66:20:66 ........End of f 00000010 69:6c:65:00:00:00:00 ile.... -> NET_SFTP_CLOSE (0.0002s) 00000000 00:00:00:04:00:00:00:00 ........ <- NET_SFTP_STATUS (0.0993s) 00000000 00:00:00:00:00:00:00:07:53:75:63:63:65:73:73:00 ........Success. 00000010 00:00:00 ... -> NET_SFTP_MKDIR (0.0002s) 00000000 00:00:00:10:2f:64:6e:75:74:62:6f:75:72:6e:65:2f ..../dnutbourne/ 00000010 74:65:73:74:00:00:00:00 test.... <- NET_SFTP_STATUS (0.0941s) 00000000 00:00:00:04:00:00:00:07:46:61:69:6c:75:72:65:00 ........Failure. 00000010 00:00:00 ... -> NET_SFTP_OPENDIR (0.0003s) 00000000 00:00:00:10:2f:64:6e:75:74:62:6f:75:72:6e:65:2f ..../dnutbourne/ 00000010 74:65:73:74 test <- NET_SFTP_HANDLE (0.0935s) 00000000 00:00:00:04:00:00:00:00 ........ -> NET_SFTP_READDIR (0.0002s) 00000000 00:00:00:04:00:00:00:00 ........ <- NET_SFTP_NAME (0.0931s) 00000000 00:00:00:02:00:00:00:01:2e:00:00:00:39:64:72:77 ............9drw 00000010 78:72:2d:78:72:2d:78:20:20:20:20:32:20:31:30:30 xr-xr-x 2 100 00000020 31:20:20:20:20:20:31:30:30:32:20:20:20:20:20:20 1 1002 00000030 20:20:20:34:30:39:36:20:4a:75:6e:20:31:31:20:31 4096 Jun 11 1 00000040 31:3a:33:32:20:2e:00:00:00:0f:00:00:00:00:00:00 1:32 ........... 00000050 10:00:00:00:03:e9:00:00:03:ea:00:00:41:ed:5e:e2 ............A.^. 00000060 16:58:5e:e2:16:58:00:00:00:02:2e:2e:00:00:00:3a .X^..X.........: 00000070 64:72:77:78:2d:2d:2d:2d:2d:2d:20:20:20:20:33:20 drwx------ 3 00000080 31:30:30:31:20:20:20:20:20:31:30:30:32:20:20:20 1001 1002 00000090 20:20:20:20:31:30:36:34:39:36:20:4a:75:6e:20:31 106496 Jun 1 000000a0 31:20:31:31:3a:33:32:20:2e:2e:00:00:00:0f:00:00 1 11:32 ........ 000000b0 00:00:00:01:a0:00:00:00:03:e9:00:00:03:ea:00:00 ................ 000000c0 41:c0:58:ae:ef:2a:5e:e2:16:58 A.X..*^..X -> NET_SFTP_READDIR (0.0002s) 00000000 00:00:00:04:00:00:00:00 ........ <- NET_SFTP_STATUS (0.1001s) 00000000 00:00:00:01:00:00:00:0b:45:6e:64:20:6f:66:20:66 ........End of f 00000010 69:6c:65:00:00:00:00 ile.... -> NET_SFTP_CLOSE (0.0002s) 00000000 00:00:00:04:00:00:00:00 ........ <- NET_SFTP_STATUS (0.0929s) 00000000 00:00:00:00:00:00:00:07:53:75:63:63:65:73:73:00 ........Success. 00000010 00:00:00 ...

Results for the livedrive server:

-> NET_SFTP_INIT (0.0002s) 00000000 00:00:00:03 .... <- NET_SFTP_VERSION (0.0577s) 00000000 00:00:00:03:00:00:00:07:6e:65:77:6c:69:6e:65:00 ........newline. 00000010 00:00:02:0d:0a:00:00:00:09:73:75:70:70:6f:72:74 .........support 00000020 65:64:00:00:01:0d:80:00:ff:ff:00:00:0f:ff:00:00 ed.............. 00000030 0f:f9:00:1f:01:ff:00:00:00:00:00:00:00:07:6e:65 ..............ne 00000040 77:6c:69:6e:65:00:00:00:13:6e:65:77:6c:69:6e:65 wline....newline 00000050 40:76:61:6e:64:79:6b:65:2e:63:6f:6d:00:00:00:0e @vandyke.com.... 00000060 76:65:72:73:69:6f:6e:2d:73:65:6c:65:63:74:00:00 version-select.. 00000070 00:1c:66:69:6c:65:6e:61:6d:65:2d:74:72:61:6e:73 ..filename-trans 00000080 6c:61:74:69:6f:6e:2d:63:6f:6e:74:72:6f:6c:00:00 lation-control.. 00000090 00:09:74:65:78:74:2d:73:65:65:6b:00:00:00:09:76 ..text-seek....v 000000a0 65:6e:64:6f:72:2d:69:64:00:00:00:0a:63:68:65:63 endor-id....chec 000000b0 6b:2d:66:69:6c:65:00:00:00:0f:73:70:61:63:65:2d k-file....space- 000000c0 61:76:61:69:6c:61:62:6c:65:00:00:00:0e:68:6f:6d available....hom 000000d0 65:2d:64:69:72:65:63:74:6f:72:79:00:00:00:09:63 e-directory....c 000000e0 6f:70:79:2d:66:69:6c:65:00:00:00:09:63:6f:70:79 opy-file....copy 000000f0 2d:64:61:74:61:00:00:00:0f:67:65:74:2d:74:65:6d -data....get-tem 00000100 70:2d:66:6f:6c:64:65:72:00:00:00:10:6d:61:6b:65 p-folder....make 00000110 2d:74:65:6d:70:2d:66:6f:6c:64:65:72:00:00:00:13 -temp-folder.... 00000120 73:74:61:74:76:66:73:40:6f:70:65:6e:73:73:68:2e statvfs@openssh. 00000130 63:6f:6d:00:00:00:08:76:65:72:73:69:6f:6e:73:00 com....versions. 00000140 00:00:07:33:2c:34:2c:35:2c:36:00:00:00:09:76:65 ...3,4,5,6....ve 00000150 6e:64:6f:72:2d:69:64:00:00:00:2b:00:00:00:05:45 ndor-id...+....E 00000160 6c:64:6f:53:00:00:00:0e:53:65:63:75:72:65:42:6c ldoS....SecureBl 00000170 61:63:6b:62:6f:78:00:00:00:04:31:35:2e:31:00:0f ackbox....15.1.. 00000180 00:01:01:2b:00:00 ...+.. -> NET_SFTP_REALPATH (0.0002s) 00000000 00:00:00:01:2e ..... <- NET_SFTP_NAME (0.0163s) 00000000 00:00:00:01:00:00:00:01:2f:00:00:00:01:2f:00:00 ......../..../.. 00000010 00:00 .. -> NET_SFTP_OPENDIR (0.0002s) 00000000 00:00:00:08:2f:62:61:63:6b:75:70:31 ..../backup1 <- NET_SFTP_HANDLE (0.0301s) 00000000 00:00:00:04:00:00:00:00 ........ -> NET_SFTP_CLOSE (0.0002s) 00000000 00:00:00:04:00:00:00:00 ........ <- NET_SFTP_STATUS (0.0178s) 00000000 00:00:00:00:00:00:00:00:00:00:00:04:00:00:00:00 ................ -> NET_SFTP_MKDIR (0.0002s) 00000000 00:00:00:0d:2f:62:61:63:6b:75:70:31:2f:74:65:73 ..../backup1/tes 00000010 74:00:00:00:00 t.... <- NET_SFTP_STATUS (0.0239s) 00000000 00:00:00:00:00:00:00:00:00:00:00:04:00:00:00:00 ................ -> NET_SFTP_OPENDIR (0.0002s) 00000000 00:00:00:0d:2f:62:61:63:6b:75:70:31:2f:74:65:73 ..../backup1/tes 00000010 74 t <- NET_SFTP_HANDLE (0.0195s) 00000000 00:00:00:04:00:00:00:00 ........ -> NET_SFTP_CLOSE (0.0002s) 00000000 00:00:00:04:00:00:00:00 ........ <- NET_SFTP_STATUS (0.0158s) 00000000 00:00:00:00:00:00:00:00:00:00:00:04:00:00:00:00 ................ -> NET_SFTP_OPENDIR (0.0003s) 00000000 00:00:00:0d:2f:62:61:63:6b:75:70:31:2f:74:65:73 ..../backup1/tes 00000010 74 t <- NET_SFTP_HANDLE (0.0175s) 00000000 00:00:00:04:00:00:00:00 ........ -> NET_SFTP_READDIR (0.0002s) 00000000 00:00:00:04:00:00:00:00 ........ <- NET_SFTP_NAME (0.0246s) 00000000 00:00:00:02:00:00:00:01:2e:00:00:00:39:64:72:77 ............9drw 00000010 78:72:77:78:72:77:78:20:20:20:31:20:75:73:65:72 xrwxrwx 1 user 00000020 20:20:20:20:20:67:72:6f:75:70:20:20:20:20:30:30 group 00 00000030 30:30:30:30:30:30:20:20:4a:75:6e:20:31:31:20:31 000000 Jun 11 1 00000040 31:3a:33:36:20:2e:00:00:00:0d:00:00:00:00:00:00 1:36 ........... 00000050 00:00:00:00:41:ff:5e:e2:17:44:5e:e2:17:44:00:00 ....A.^..D^..D.. 00000060 00:02:2e:2e:00:00:00:3a:64:72:77:78:72:77:78:72 .......:drwxrwxr 00000070 77:78:20:20:20:31:20:75:73:65:72:20:20:20:20:20 wx 1 user 00000080 67:72:6f:75:70:20:20:20:20:30:30:30:30:30:30:30 group 0000000 00000090 30:20:20:4a:75:6e:20:31:31:20:31:31:3a:33:36:20 0 Jun 11 11:36 000000a0 2e:2e:00:00:00:0d:00:00:00:00:00:00:00:00:00:00 ................ 000000b0 41:ff:5e:e2:17:44:5e:e2:17:44 A.^..D^..D -> NET_SFTP_READDIR (0.0002s) 00000000 00:00:00:04:00:00:00:00 ........ <- NET_SFTP_STATUS (0.0181s) 00000000 00:00:00:01:00:00:00:08:4e:6f:20:66:69:6c:65:73 ........No files 00000010 00:00:00:0c:00:00:00:08:4e:6f:20:66:69:6c:65:73 ........No files -> NET_SFTP_CLOSE (0.0002s) 00000000 00:00:00:04:00:00:00:00 ........ <- NET_SFTP_STATUS (0.0151s) 00000000 00:00:00:00:00:00:00:00:00:00:00:04:00:00:00:00 ................ -> NET_SFTP_MKDIR (0.0002s) 00000000 00:00:00:0d:2f:62:61:63:6b:75:70:31:2f:74:65:73 ..../backup1/tes 00000010 74:00:00:00:00 t.... <- NET_SFTP_STATUS (0.0184s) 00000000 00:00:00:0b:00:00:00:00:00:00:00:04:00:00:00:00 ................ -> NET_SFTP_OPENDIR (0.0002s) 00000000 00:00:00:0d:2f:62:61:63:6b:75:70:31:2f:74:65:73 ..../backup1/tes 00000010 74 t <- NET_SFTP_STATUS (0.0179s) 00000000 00:00:00:0b:00:00:00:00:00:00:00:04:00:00:00:00 ................
terrafrost commented 4 years ago

Normally the log output has new lines in it. eg. https://pastebin.com/fwNxiyiK . phpseclib detects the SAPI being used (CLI, Apache2, whatever) and should add <pre> tags if it's Apache2. Anyway, that's neither here nor there, I suppose.

Anyway, yah, this looks like a bug in LiveDrive. You should be able to reproduce it using WinSCP or FileZilla or whatever. I'd say create a bug report with them!

dnutbourne2 commented 4 years ago

Hi,

Thanks very much. I'll get in touch with them