[BUG] sftp issue
hasechris opened this issue · 7 comments
Hi,
i updated to your newest version 1.5.4 from 1.3.7. Now im getting the following errors when i trigger a backup.
minecraft-designworld | [14:15:10] [Server thread/INFO]: [DriveBackupV2] Scheduling a backup to run at 05:00 AM every and Monday
minecraft-designworld | [14:15:10] [Server thread/INFO]: [DriveBackupV2] Config reloaded!
minecraft-designworld | [14:15:15] [Server thread/INFO]: [DriveBackupV2] Forcing a backup
minecraft-designworld | [14:15:15] [Thread-69/INFO]: Generating random seed from SecureRandom.
minecraft-designworld | [14:15:15] [Thread-69/INFO]: Client identity string: SSH-2.0-SSHJ_0.29.0
minecraft-designworld | [14:15:15] [Thread-69/INFO]: Server identity string: SSH-2.0-OpenSSH_8.4p1 Debian-5
minecraft-designworld | [14:15:19] [Thread-69/INFO]: Will request `sftp` subsystem
minecraft-designworld | [14:15:19] [Thread-69/WARN]: net.schmizz.sshj.sftp.SFTPException: EOF while reading packet
minecraft-designworld | [14:15:19] [Thread-69/WARN]: at net.schmizz.sshj.sftp.PacketReader.readIntoBuffer(PacketReader.java:54)
minecraft-designworld | [14:15:19] [Thread-69/WARN]: at net.schmizz.sshj.sftp.PacketReader.getPacketLength(PacketReader.java:59)
minecraft-designworld | [14:15:19] [Thread-69/WARN]: at net.schmizz.sshj.sftp.PacketReader.readPacket(PacketReader.java:75)
minecraft-designworld | [14:15:19] [Thread-69/WARN]: at net.schmizz.sshj.sftp.SFTPEngine.init(SFTPEngine.java:84)
minecraft-designworld | [14:15:19] [Thread-69/WARN]: at net.schmizz.sshj.SSHClient.newSFTPClient(SSHClient.java:722)
minecraft-designworld | [14:15:19] [Thread-69/WARN]: at ratismal.drivebackup.uploaders.ftp.SFTPUploader.connect(SFTPUploader.java:124)
minecraft-designworld | [14:15:19] [Thread-69/WARN]: at ratismal.drivebackup.uploaders.ftp.SFTPUploader.<init>(SFTPUploader.java:51)
minecraft-designworld | [14:15:19] [Thread-69/WARN]: at ratismal.drivebackup.uploaders.ftp.FTPUploader.<init>(FTPUploader.java:67)
minecraft-designworld | [14:15:19] [Thread-69/WARN]: at ratismal.drivebackup.UploadThread.run(UploadThread.java:210)
minecraft-designworld | [14:15:19] [Thread-69/WARN]: at java.lang.Thread.run(Thread.java:748)
minecraft-designworld | [14:15:19] [Thread-69/WARN]: Exception in thread "Thread-69" java.lang.NullPointerException
minecraft-designworld | [14:15:19] [Thread-69/WARN]: at ratismal.drivebackup.uploaders.ftp.FTPUploader.isAuthenticated(FTPUploader.java:147)
minecraft-designworld | [14:15:19] [Thread-69/WARN]: at ratismal.drivebackup.UploadThread.ensureMethodsAuthenticated(UploadThread.java:304)
minecraft-designworld | [14:15:19] [Thread-69/WARN]: at ratismal.drivebackup.UploadThread.run(UploadThread.java:213)
minecraft-designworld | [14:15:19] [Thread-69/WARN]: at java.lang.Thread.run(Thread.java:748)
minecraft-designworld | [14:15:38] [RCON Client /192.168.0.1 #3/INFO]: Thread RCON Client /192.168.0.1 shutting down
My config.yml looks like this:
#
# DriveBackupV2 - by Max Maeder (MaxTheGinus)
delay: -1
backup-thread-priority: 1
keep-count: 5
local-keep-count: 2
backups-require-players: false
restart-after-backup: false
scheduled-backups: true
backup-schedule-list:
- days:
- monday
time: 05:00
backup-list:
- path: .
format: '''Backup-world-''yyyy-M-d--HH-mm''.zip'''
create: true
blacklist:
- logs/**
- plugins/dynmap/**
- crash-reports/**
- backups/**
- serverhub/**
- serverhub_the_end/**
- serverhub_nether/**
- designworld/**
- designworld_the_end/**
- designworld_nether/**
- hase-survival/**
- hase-survival_the_end/**
- hase-survival_nether/***
googledrive:
enabled: false
onedrive:
enabled: false
ftp:
enabled: true
hostname: <redacted>
port: <redacted>
sftp: true
ftps: false
username: backupminecraft
sftp-public-key: ../../backup_key_mgtsrv001
working-dir: /data_hdd/minecraft_designworld_backup
messages:
send-in-chat: true
prefix: '&6[&4DriveBackupV2&6] '
default-color: '&3'
advanced:
metrics: true
update-check: true
suppress-errors: false
date-language: en
ftp-file-separator: /
date-timezone: +02:00
dropbox: {}
webdav: {}
version: 2
local-save-directory: backups
remote-save-directory: backups
Greetings
hasechris
Found this issue on (maybe) the library:
hierynomus/sshj#750
Maybe it is linked - the drive backup should do file renaming/moving/deletion in my situation. There are alot of old backups lying on disk which should never have been left to rot there.
Sorry for the delay. I suspect you're right but since I can't reproduce this error, I cannot verify this. Try out this new build which uses sshj 0.32.0 to see if that fixes it: https://transfer.sh/P4NRoe/DriveBackupV2.jar
Hi @rhld16,
no offense taken, thanks for trying to help me :) I downloaded the new version and restartet my my MC server.
version output
Output on server console (mcrcon)
minecraft-designworld | [20:36:53] [Server thread/INFO]: CPUMiner issued server command: /drivebackup test ftp
minecraft-designworld | [20:36:53] [Thread-32/INFO]: Creating new SecureRandom.
minecraft-designworld | [20:36:53] [Thread-32/INFO]: Client identity string: SSH-2.0-SSHJ_0.32.0
minecraft-designworld | [20:36:53] [Thread-32/INFO]: Server identity string: SSH-2.0-OpenSSH_8.4p1 Debian-5
minecraft-designworld | [20:36:57] [Thread-32/INFO]: Will request `sftp` subsystem
minecraft-designworld | [20:36:57] [Thread-32/WARN]: net.schmizz.sshj.sftp.SFTPException: EOF while reading packet
minecraft-designworld | [20:36:57] [Thread-32/WARN]: at net.schmizz.sshj.sftp.PacketReader.readIntoBuffer(PacketReader.java:55)
minecraft-designworld | [20:36:57] [Thread-32/WARN]: at net.schmizz.sshj.sftp.PacketReader.getPacketLength(PacketReader.java:60)
minecraft-designworld | [20:36:57] [Thread-32/WARN]: at net.schmizz.sshj.sftp.PacketReader.readPacket(PacketReader.java:76)
minecraft-designworld | [20:36:57] [Thread-32/WARN]: at net.schmizz.sshj.sftp.SFTPEngine.init(SFTPEngine.java:84)
minecraft-designworld | [20:36:57] [Thread-32/WARN]: at net.schmizz.sshj.SSHClient.newSFTPClient(SSHClient.java:722)
minecraft-designworld | [20:36:57] [Thread-32/WARN]: at ratismal.drivebackup.uploaders.ftp.SFTPUploader.connect(SFTPUploader.java:124)
minecraft-designworld | [20:36:57] [Thread-32/WARN]: at ratismal.drivebackup.uploaders.ftp.SFTPUploader.<init>(SFTPUploader.java:51)
minecraft-designworld | [20:36:57] [Thread-32/WARN]: at ratismal.drivebackup.uploaders.ftp.FTPUploader.<init>(FTPUploader.java:63)
minecraft-designworld | [20:36:57] [Thread-32/WARN]: at ratismal.drivebackup.TestThread.testUploadMethod(TestThread.java:149)
minecraft-designworld | [20:36:57] [Thread-32/WARN]: at ratismal.drivebackup.TestThread.run(TestThread.java:90)
minecraft-designworld | [20:36:57] [Thread-32/WARN]: at java.lang.Thread.run(Thread.java:748)
minecraft-designworld | [20:36:57] [Thread-32/INFO]: [DriveBackupV2] Beginning the test on (S)FTP
minecraft-designworld | [20:36:57] [Thread-32/WARN]: java.lang.NullPointerException
minecraft-designworld | [20:36:57] [Thread-32/WARN]: at ratismal.drivebackup.uploaders.ftp.FTPUploader.resetWorkingDirectory(FTPUploader.java:387)
minecraft-designworld | [20:36:57] [Thread-32/WARN]: at ratismal.drivebackup.uploaders.ftp.FTPUploader.test(FTPUploader.java:181)
minecraft-designworld | [20:36:57] [Thread-32/WARN]: at ratismal.drivebackup.TestThread.testUploadMethod(TestThread.java:181)
minecraft-designworld | [20:36:57] [Thread-32/WARN]: at ratismal.drivebackup.TestThread.run(TestThread.java:90)
minecraft-designworld | [20:36:57] [Thread-32/WARN]: at java.lang.Thread.run(Thread.java:748)
minecraft-designworld | [20:36:57] [Thread-32/INFO]: [DriveBackupV2] The (S)FTP test was unsuccessful, please check the config.yml
minecraft-designworld | [20:36:57] [Thread-32/WARN]: java.lang.NullPointerException
minecraft-designworld | [20:36:57] [Thread-32/WARN]: at ratismal.drivebackup.uploaders.ftp.FTPUploader.close(FTPUploader.java:160)
minecraft-designworld | [20:36:57] [Thread-32/WARN]: at ratismal.drivebackup.TestThread.testUploadMethod(TestThread.java:194)
minecraft-designworld | [20:36:57] [Thread-32/WARN]: at ratismal.drivebackup.TestThread.run(TestThread.java:90)
minecraft-designworld | [20:36:57] [Thread-32/WARN]: at java.lang.Thread.run(Thread.java:748)
Can i make the sftp part more verbose via the config.yml?
Unfortunately sshj doesn't allow me to change it's logging level. Since the issue you linked refers to v0.32.0 I'll assume this issue still persists in the updated version. Are you able to provide ssh server logs at the point where the plugin attempts to connect?
Mär 06 22:19:02 mgtsrv001 sshd[443489]: debug1: Forked child 449282.
Mär 06 22:19:02 mgtsrv001 sshd[449282]: debug1: Set /proc/self/oom_score_adj to 0
Mär 06 22:19:02 mgtsrv001 sshd[449282]: debug1: rexec start in 5 out 5 newsock 5 pipe 7 sock 8
Mär 06 22:19:02 mgtsrv001 sshd[449282]: debug1: inetd sockets after dupping: 4, 4
Mär 06 22:19:02 mgtsrv001 sshd[449282]: Connection from 2.59.133.176 port 9913 on 192.168.42.25 port 22 rdomain ""
Mär 06 22:19:02 mgtsrv001 sshd[449282]: debug1: Local version string SSH-2.0-OpenSSH_8.4p1 Debian-5
Mär 06 22:19:02 mgtsrv001 sshd[449282]: debug1: Remote protocol version 2.0, remote software version SSHJ_0.32.0
Mär 06 22:19:02 mgtsrv001 sshd[449282]: debug1: no match: SSHJ_0.32.0
Mär 06 22:19:02 mgtsrv001 sshd[449282]: debug1: permanently_set_uid: 106/65534 [preauth]
Mär 06 22:19:02 mgtsrv001 sshd[449282]: debug1: list_hostkey_types: rsa-sha2-512,rsa-sha2-256,ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
Mär 06 22:19:02 mgtsrv001 sshd[449282]: debug1: SSH2_MSG_KEXINIT sent [preauth]
Mär 06 22:19:02 mgtsrv001 sshd[449282]: debug1: SSH2_MSG_KEXINIT received [preauth]
Mär 06 22:19:02 mgtsrv001 sshd[449282]: debug1: kex: algorithm: curve25519-sha256 [preauth]
Mär 06 22:19:02 mgtsrv001 sshd[449282]: debug1: kex: host key algorithm: ssh-ed25519 [preauth]
Mär 06 22:19:02 mgtsrv001 sshd[449282]: debug1: kex: client->server cipher: [email protected] MAC: <implicit> compression: none [preauth]
Mär 06 22:19:02 mgtsrv001 sshd[449282]: debug1: kex: server->client cipher: [email protected] MAC: <implicit> compression: none [preauth]
Mär 06 22:19:02 mgtsrv001 sshd[449282]: debug1: expecting SSH2_MSG_KEX_ECDH_INIT [preauth]
Mär 06 22:19:02 mgtsrv001 sshd[449282]: debug1: rekey out after 134217728 blocks [preauth]
Mär 06 22:19:02 mgtsrv001 sshd[449282]: debug1: SSH2_MSG_NEWKEYS sent [preauth]
Mär 06 22:19:02 mgtsrv001 sshd[449282]: debug1: Sending SSH2_MSG_EXT_INFO [preauth]
Mär 06 22:19:02 mgtsrv001 sshd[449282]: debug1: expecting SSH2_MSG_NEWKEYS [preauth]
Mär 06 22:19:02 mgtsrv001 sshd[449282]: debug1: SSH2_MSG_NEWKEYS received [preauth]
Mär 06 22:19:02 mgtsrv001 sshd[449282]: debug1: rekey in after 134217728 blocks [preauth]
Mär 06 22:19:02 mgtsrv001 sshd[449282]: debug1: KEX done [preauth]
Mär 06 22:19:02 mgtsrv001 sshd[449282]: debug1: userauth-request for user backupminecraft service ssh-connection method password [preauth]
Mär 06 22:19:02 mgtsrv001 sshd[449282]: debug1: attempt 0 failures 0 [preauth]
Mär 06 22:19:02 mgtsrv001 sshd[449282]: debug1: PAM: initializing for "backupminecraft"
Mär 06 22:19:02 mgtsrv001 sshd[449282]: debug1: PAM: setting PAM_RHOST to "2.59.133.176"
Mär 06 22:19:02 mgtsrv001 sshd[449282]: debug1: PAM: setting PAM_TTY to "ssh"
Mär 06 22:19:02 mgtsrv001 sshd[449282]: pam_unix(sshd:auth): authentication failure; logname= uid=0 euid=0 tty=ssh ruser= rhost=2.59.133.176 user=backupminecraft
Mär 06 22:19:04 mgtsrv001 sshd[449282]: debug1: PAM: password authentication failed for backupminecraft: Authentication failure
Mär 06 22:19:04 mgtsrv001 sshd[449282]: Failed password for backupminecraft from 2.59.133.176 port 9913 ssh2
Mär 06 22:19:05 mgtsrv001 sshd[449282]: debug1: userauth-request for user backupminecraft service ssh-connection method publickey [preauth]
Mär 06 22:19:05 mgtsrv001 sshd[449282]: debug1: attempt 1 failures 1 [preauth]
Mär 06 22:19:05 mgtsrv001 sshd[449282]: debug1: userauth_pubkey: test pkalg rsa-sha2-512 pkblob RSA SHA256:jdr0K5mnhgebEAHBI/36HohxteJu2C67klYoqpskKSs [preauth]
Mär 06 22:19:05 mgtsrv001 sshd[449282]: debug1: temporarily_use_uid: 1002/1003 (e=0/0)
Mär 06 22:19:05 mgtsrv001 sshd[449282]: debug1: trying public key file /home/backupminecraft/.ssh/authorized_keys
Mär 06 22:19:05 mgtsrv001 sshd[449282]: debug1: fd 5 clearing O_NONBLOCK
Mär 06 22:19:05 mgtsrv001 sshd[449282]: debug1: /home/backupminecraft/.ssh/authorized_keys:1: matching key found: RSA SHA256:jdr0K5mnhgebEAHBI/36HohxteJu2C67klYoqpskKSs
Mär 06 22:19:05 mgtsrv001 sshd[449282]: debug1: /home/backupminecraft/.ssh/authorized_keys:1: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
Mär 06 22:19:05 mgtsrv001 sshd[449282]: Accepted key RSA SHA256:jdr0K5mnhgebEAHBI/36HohxteJu2C67klYoqpskKSs found at /home/backupminecraft/.ssh/authorized_keys:1
Mär 06 22:19:05 mgtsrv001 sshd[449282]: debug1: restore_uid: 0/0
Mär 06 22:19:05 mgtsrv001 sshd[449282]: Postponed publickey for backupminecraft from 2.59.133.176 port 9913 ssh2 [preauth]
Mär 06 22:19:05 mgtsrv001 sshd[449282]: debug1: userauth-request for user backupminecraft service ssh-connection method publickey [preauth]
Mär 06 22:19:05 mgtsrv001 sshd[449282]: debug1: attempt 2 failures 1 [preauth]
Mär 06 22:19:05 mgtsrv001 sshd[449282]: debug1: temporarily_use_uid: 1002/1003 (e=0/0)
Mär 06 22:19:05 mgtsrv001 sshd[449282]: debug1: trying public key file /home/backupminecraft/.ssh/authorized_keys
Mär 06 22:19:05 mgtsrv001 sshd[449282]: debug1: fd 5 clearing O_NONBLOCK
Mär 06 22:19:05 mgtsrv001 sshd[449282]: debug1: /home/backupminecraft/.ssh/authorized_keys:1: matching key found: RSA SHA256:jdr0K5mnhgebEAHBI/36HohxteJu2C67klYoqpskKSs
Mär 06 22:19:05 mgtsrv001 sshd[449282]: debug1: /home/backupminecraft/.ssh/authorized_keys:1: key options: agent-forwarding port-forwarding pty user-rc x11-forwarding
Mär 06 22:19:05 mgtsrv001 sshd[449282]: Accepted key RSA SHA256:jdr0K5mnhgebEAHBI/36HohxteJu2C67klYoqpskKSs found at /home/backupminecraft/.ssh/authorized_keys:1
Mär 06 22:19:05 mgtsrv001 sshd[449282]: debug1: restore_uid: 0/0
Mär 06 22:19:05 mgtsrv001 sshd[449282]: debug1: auth_activate_options: setting new authentication options
Mär 06 22:19:05 mgtsrv001 sshd[449282]: debug1: do_pam_account: called
Mär 06 22:19:05 mgtsrv001 sshd[449282]: Accepted publickey for backupminecraft from 2.59.133.176 port 9913 ssh2: RSA SHA256:jdr0K5mnhgebEAHBI/36HohxteJu2C67klYoqpskKSs
Mär 06 22:19:05 mgtsrv001 sshd[449282]: debug1: monitor_child_preauth: backupminecraft has been authenticated by privileged process
Mär 06 22:19:05 mgtsrv001 sshd[449282]: debug1: auth_activate_options: setting new authentication options [preauth]
Mär 06 22:19:05 mgtsrv001 sshd[449282]: debug1: monitor_read_log: child log fd closed
Mär 06 22:19:05 mgtsrv001 sshd[449282]: debug1: PAM: establishing credentials
Mär 06 22:19:05 mgtsrv001 sshd[449282]: debug1: PAM: pam_setcred(): Failure setting user credentials
Mär 06 22:19:05 mgtsrv001 sshd[449282]: pam_unix(sshd:session): session opened for user backupminecraft(uid=1002) by (uid=0)
Mär 06 22:19:05 mgtsrv001 sshd[449282]: User child is on pid 450244
Mär 06 22:19:08 mgtsrv001 sshd[443489]: debug1: Forked child 452245.
Mär 06 22:19:08 mgtsrv001 sshd[452245]: debug1: Set /proc/self/oom_score_adj to 0
Mär 06 22:19:08 mgtsrv001 sshd[452245]: debug1: rexec start in 5 out 5 newsock 5 pipe 7 sock 8
Mär 06 22:19:08 mgtsrv001 sshd[452245]: debug1: inetd sockets after dupping: 4, 4
Mär 06 22:19:08 mgtsrv001 sshd[452245]: Connection from 106.15.109.130 port 55976 on 192.168.42.25 port 22 rdomain ""
Mär 06 22:19:08 mgtsrv001 sshd[452245]: debug1: Local version string SSH-2.0-OpenSSH_8.4p1 Debian-5
Mär 06 22:19:09 mgtsrv001 sshd[452245]: debug1: Remote protocol version 2.0, remote software version libssh-0.2
Mär 06 22:19:09 mgtsrv001 sshd[452245]: debug1: no match: libssh-0.2
Mär 06 22:19:09 mgtsrv001 sshd[452245]: debug1: permanently_set_uid: 106/65534 [preauth]
Mär 06 22:19:09 mgtsrv001 sshd[452245]: debug1: list_hostkey_types: rsa-sha2-512,rsa-sha2-256,ssh-rsa,ecdsa-sha2-nistp256,ssh-ed25519 [preauth]
Mär 06 22:19:09 mgtsrv001 sshd[452245]: debug1: SSH2_MSG_KEXINIT sent [preauth]
Mär 06 22:19:09 mgtsrv001 sshd[452245]: Connection closed by 106.15.109.130 port 55976 [preauth]
Mär 06 22:19:09 mgtsrv001 sshd[452245]: debug1: do_cleanup [preauth]
Mär 06 22:19:09 mgtsrv001 sshd[452245]: debug1: monitor_read_log: child log fd closed
Mär 06 22:19:09 mgtsrv001 sshd[452245]: debug1: do_cleanup
Mär 06 22:19:09 mgtsrv001 sshd[452245]: debug1: Killing privsep child 452246
Mär 06 22:19:09 mgtsrv001 sshd[452245]: debug1: audit_event: unhandled event 12
Mär 06 22:19:09 mgtsrv001 sshd[443489]: debug1: main_sigchld_handler: Child exited
Another thing i just found. The sftp test leaves sshd Process open on my target server:
root 438128 0.0 0.0 14728 8564 ? Ss 22:16 0:00 sshd: backupminecraft [priv]
backupm+ 438368 0.0 0.0 14728 6036 ? S 22:16 0:00 \_ sshd: backupminecraft@notty
root 439850 0.0 0.0 14728 8356 ? Ss 22:17 0:00 sshd: backupminecraft [priv]
backupm+ 439900 0.0 0.0 14728 5788 ? S 22:17 0:00 \_ sshd: backupminecraft@notty
root 443489 0.0 0.0 13292 7616 ? Ss 22:17 0:00 sshd: /usr/sbin/sshd -D [listener] 0 of 10-100 startups
root 445829 0.0 0.0 14724 8396 ? Ss 22:18 0:00 \_ sshd: backupminecraft [priv]
backupm+ 445872 0.0 0.0 14724 5872 ? S 22:18 0:00 | \_ sshd: backupminecraft@notty
root 449282 0.0 0.0 14724 8556 ? Ss 22:19 0:00 \_ sshd: backupminecraft [priv]
backupm+ 450244 0.0 0.0 14724 6108 ? S 22:19 0:00 | \_ sshd: backupminecraft@notty
root 486651 0.0 0.0 14724 8544 ? Ss 22:27 0:00 \_ sshd: backupminecraft [priv]
backupm+ 486701 0.0 0.0 14724 5956 ? S 22:27 0:00 | \_ sshd: backupminecraft@notty
root 496079 0.0 0.0 14724 8460 ? Ss 22:29 0:00 \_ sshd: backupminecraft [priv]
backupm+ 496347 0.0 0.0 14724 5836 ? S 22:29 0:00 | \_ sshd: backupminecraft@notty
root 503073 0.0 0.0 14724 8324 ? Ss 22:30 0:00 \_ sshd: backupminecraft [priv]
backupm+ 503112 0.0 0.0 14724 5920 ? S 22:30 0:00 \_ sshd: backupminecraft@notty
ARGH... I found the problem. My ssh user (backupminecraft) had "/bin/false" as shell, as "all the howto's" suggest for sftp users in google.
Changed it to /bin/bash, now the sftp test is working again. I guess I changed this setting sometime the last few weeks. Im really sorry for all the fuss.