Hello,
I am using LFTP Version 4.4.8 on Linux to connect and download/upload files
to a 3rd party's SFTP site via a bash script. Every so often, LFTP "sees"
the file(s) on the remote SFTP folder, but does not download them. It then
inexplicably delete(s) them from the remote SFTP folder (without
downloading first). I am using the following lftp values and the "mget"
command with the "-E" option (delete after successful download):
set net:timeout 5
set net:max-retries 3
set net:reconnect-interval-multiplier 1
set net:reconnect-interval-base 5
set net:connection-limit 1
mget -a -E /out/AG*.O
Here is a snippet of the LFTP/SFTP log from the "client" side that
initiates the connection. Notice that it "sees" the file /out/AG022608.O,
but then does not download it. Next, it complains "NoSuchFileException":
2021-12-27 08:01:02 ---- Running connect program (ssh -a -x -s -l userid -p
22 xxx.xxx.xxx.xxx sftp)
2021-12-27 08:01:02 ---> sending a packet, length=5, type=1(INIT), id=0
2021-12-27 08:01:03 <--- Password authentication
2021-12-27 08:01:03 <--- Password: XXXX
2021-12-27 08:01:03 <--- got a packet, length=545, type=2(VERSION), id=0
2021-12-27 08:01:03 ---- protocol version set to 6
2021-12-27 08:01:03 ---> sending a packet, length=10, type=16(REALPATH),
id=1
2021-12-27 08:01:04 <--- got a packet, length=20, type=104(NAME), id=1
2021-12-27 08:01:04 ---- home set to /
2021-12-27 08:01:04 ---- path on wire is `/out'
2021-12-27 08:01:04 ---> sending a packet, length=13, type=11(OPENDIR), id=2
2021-12-27 08:01:04 <--- got a packet, length=41, type=102(HANDLE), id=2
2021-12-27 08:01:04 ---- got file handle
3030623038653532663530653235643365643462386237343564316633323566 (32)
2021-12-27 08:01:04 ---> sending a packet, length=41, type=12(READDIR), id=3
2021-12-27 08:01:04 <--- got a packet, length=296, type=104(NAME), id=3
2021-12-27 08:01:04 ---- file name count=5
2021-12-27 08:01:04 ---- eof
2021-12-27 08:01:04 ---> sending a packet, length=41, type=4(CLOSE), id=4
2021-12-27 08:01:04 <--- got a packet, length=17, type=101(STATUS), id=4
2021-12-27 08:01:04 ---- status code=0(OK), message=
2021-12-27 08:01:04 ---- path on wire is `/out/AG022608.O'
2021-12-27 08:01:04 ---> sending a packet, length=37, type=3(OPEN), id=5
2021-12-27 08:01:04 <--- got a packet, length=96, type=101(STATUS), id=5
2021-12-27 08:01:04 ---- status code=2(No such file),
message=java.nio.file.NoSuchFileException:
/WEB/aida/data/sftproot/userid/out/AG022608.O
I asked the 3rd party to provide the logs on the "server" side, and here is
what they provided. Notice that there are two session ids for some reason:
49686 and 63478. The 1st session id "sees" the file, the 2nd one deletes
it, and when the 1st one tries to download the file, it does not find it:
2021-12-27 20:21:02,887 ERROR dataflow.sftp.server.config.ServerConfig -
Request auth (PublicKey) for username=userid (RSA): FAIL
2021-12-27 20:21:02,887 INFO
dataflow.sftp.server.CustomPublicKeyAuthenticator - Failed authentication
attempt for user 'userid' on server 'xxx.xxx.xxx.xxx' on session
ServerSessionImpl[null@/64.78.239.116:49686]
2021-12-27 20:21:02,908 INFO
dataflow.sftp.server.eventhandling.SessionEventListener - Session event
Authenticated ServerSessionImpl[userid@/xx.xx.xxx.xxx:63478]
2021-12-27 20:21:02,908 INFO
dataflow.sftp.server.eventhandling.SessionEventListener - SessionMap added
ServerSessionImpl[userid@/xx.xx.xxx.xxx:63478]
2021-12-27 20:21:02,908 INFO
org.apache.sshd.server.session.ServerUserAuthService - Session
userid@/xx.xx.xxx.xxx:63478
authenticated
2021-12-27 20:21:03,120 INFO
dataflow.sftp.server.eventhandling.SessionEventListener - Session event
Authenticated ServerSessionImpl[userid@/xx.xx.xxx.xxx:49686]
2021-12-27 20:21:03,120 INFO
dataflow.sftp.server.eventhandling.SessionEventListener - SessionMap added
ServerSessionImpl[userid@/xx.xx.xxx.xxx:49686]
2021-12-27 20:21:03,120 INFO
org.apache.sshd.server.session.ServerUserAuthService - Session
userid@/xx.xx.xxx.xxx:49686
authenticated
2021-12-27 20:21:03,142 INFO
org.apache.sshd.server.subsystem.sftp.SftpSubsystem -
doInit(ServerSessionImpl[userid@/xx.xx.xxx.xxx:63478])[id=6] SSH_FXP_INIT
(version=6)
2021-12-27 20:21:03,142 INFO
dataflow.sftp.server.eventhandling.SessionEventListener - initialized
ServerSessionImpl[userid@/xx.xx.xxx.xxx:63478] : SFTP protocol v6
2021-12-27 20:21:03,353 INFO
org.apache.sshd.server.subsystem.sftp.SftpSubsystem -
doInit(ServerSessionImpl[userid@/xx.xx.xxx.xxx:49686])[id=6] SSH_FXP_INIT
(version=6)
2021-12-27 20:21:03,353 INFO
dataflow.sftp.server.eventhandling.SessionEventListener - initialized
ServerSessionImpl[userid@/xx.xx.xxx.xxx:49686] : SFTP protocol v6
2021-12-27 20:21:03,538 INFO
dataflow.sftp.server.eventhandling.SessionEventListener - open
ServerSessionImpl[userid@/xx.xx.xxx.xxx:63478]: /out
2021-12-27 20:21:03,740 INFO
dataflow.sftp.server.eventhandling.SessionEventListener - open
ServerSessionImpl[userid@/xx.xx.xxx.xxx:49686]: /out
2021-12-27 20:21:03,782 INFO
dataflow.sftp.server.eventhandling.SessionEventListener - close
ServerSessionImpl[userid@/xx.xx.xxx.xxx:63478]: /out
2021-12-27 20:21:03,899 INFO
org.apache.sshd.server.subsystem.sftp.SftpSubsystem -
doOpen(ServerSessionImpl[userid@/xx.xx.xxx.xxx:63478])[id=5] SSH_FXP_OPEN
2021-12-27 20:21:03,899 INFO
org.apache.sshd.server.subsystem.sftp.SftpSubsystem -
doOpen(ServerSessionImpl[userid@/xx.xx.xxx.xxx:63478])[id=5] SSH_FXP_OPEN
(path=/out/AG022608.O, access=0x81, pflags=0x2, attrs={isOther=true})
2021-12-27 20:21:03,901 INFO
dataflow.sftp.server.eventhandling.SessionEventListener - open
ServerSessionImpl[userid@/xx.xx.xxx.xxx:63478]: /out/AG022608.O
2021-12-27 20:21:03,977 INFO
dataflow.sftp.server.eventhandling.SessionEventListener - close
ServerSessionImpl[userid@/xx.xx.xxx.xxx:49686]: /out
2021-12-27 20:21:04,093 INFO
org.apache.sshd.server.subsystem.sftp.SftpSubsystem -
doOpen(ServerSessionImpl[userid@/xx.xx.xxx.xxx:49686])[id=5] SSH_FXP_OPEN
2021-12-27 20:21:04,093 INFO
org.apache.sshd.server.subsystem.sftp.SftpSubsystem -
doOpen(ServerSessionImpl[userid@/xx.xx.xxx.xxx:49686])[id=5] SSH_FXP_OPEN
(path=/out/AG022608.O, access=0x81, pflags=0x2, attrs={isOther=true})
2021-12-27 20:21:04,093 INFO
dataflow.sftp.server.eventhandling.SessionEventListener - open
ServerSessionImpl[userid@/xx.xx.xxx.xxx:49686]: /out/AG022608.O
2021-12-27 20:21:04,134 INFO
org.apache.sshd.server.subsystem.sftp.SftpSubsystem -
doRead(ServerSessionImpl[userid@/xx.xx.xxx.xxx:63478])[id=7](d77953e7907a055795dc3c18812ce134)[offset=0]
- req=32768, max=73728, effective=32768
2021-12-27 20:21:04,134 INFO
org.apache.sshd.server.subsystem.sftp.SftpSubsystem -
doRead(ServerSessionImpl[userid@/xx.xx.xxx.xxx:63478])[id=8](d77953e7907a055795dc3c18812ce134)[offset=32768]
- req=32768, max=73728, effective=32768
2021-12-27 20:21:04,250 INFO
org.apache.sshd.server.subsystem.sftp.SftpSubsystem -
doRead(ServerSessionImpl[userid@/xx.xx.xxx.xxx:63478])[id=9](d77953e7907a055795dc3c18812ce134)[offset=1731]
- req=31037, max=73728, effective=31037
2021-12-27 20:21:04,327 INFO
org.apache.sshd.server.subsystem.sftp.SftpSubsystem -
doRead(ServerSessionImpl[userid@/xx.xx.xxx.xxx:49686])[id=7](bdbbe85fb694627279d319a835db2493)[offset=0]
- req=32768, max=73728, effective=32768
2021-12-27 20:21:04,327 INFO
org.apache.sshd.server.subsystem.sftp.SftpSubsystem -
doRead(ServerSessionImpl[userid@/xx.xx.xxx.xxx:49686])[id=8](bdbbe85fb694627279d319a835db2493)[offset=32768]
- req=32768, max=73728, effective=32768
2021-12-27 20:21:04,366 INFO
dataflow.sftp.server.eventhandling.SessionEventListener - close
ServerSessionImpl[userid@/xx.xx.xxx.xxx:63478]: /out/AG022608.O
2021-12-27 20:21:04,367 INFO
dataflow.sftp.server.eventhandling.SessionEventListener - removed
ServerSessionImpl[userid@/xx.xx.xxx.xxx:63478]: /out/AG022608.O
2021-12-27 20:21:04,443 INFO
org.apache.sshd.server.subsystem.sftp.SftpSubsystem -
doRead(ServerSessionImpl[userid@/xx.xx.xxx.xxx:49686])[id=9](bdbbe85fb694627279d319a835db2493)[offset=1731]
- req=31037, max=73728, effective=31037
2021-12-27 20:21:04,540 INFO dataflow.sftp.server.MySshServerStats -
Sessions 4 - SessionCloseHandlers 0
2021-12-27 20:21:04,540 INFO dataflow.sftp.server.MySshServerStats -
session 0: ServerSessionImpl[userid@/xx.xx.xxx.xxx:49686]
2021-12-27 20:21:04,540 INFO dataflow.sftp.server.MySshServerStats -
session 1: ServerSessionImpl[userid@/xx.xx.xxx.xxx:63478]
This is just bizarre. Also note that this happens intermittently and not
all the time. Any ideas as to why this may be happening sporadically?
Note that there was only 1 connection session active from the "client"
side, so I am not sure why the "server" side reports 2 sessions.
Thanks
_______________________________________________
lftp mailing list
lftp@uniyar.ac.ru
http://univ.uniyar.ac.ru/mailman/listinfo/lftp
