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