Facebook
Twitter
Konstantin Elstner
New Pleskian
Hello,
we detected a critical bug in the backup command routine of Plesk 12.5 on Debian when storing backups to an external FTP server.
We had the issue, that our remote server disk runs out of memory during backup on 30th of August, so the last created TAR archive could not be finalised. Afterwards we cleaned up our backup server to get free disk space.
Every automated backup after 30th of August triggered the following critical issue:
At start of backup the last created TAR archive will be loaded from remote server and the backup process tries to open the TAR archive. If the TAR archive structure is broken the backup process will run into an endless loop of tries to open the broken TAR archive.
This try will be repeated thousands of times a second and every fail will be written to log file with a log like this:
[2016-09-02 22:37:06.917|25022] INFO: ArchiveStreamReader::ReadFile. Break 1
The current implementation will retry and update the log file until the disk memory exceeds.
I saw this issue 3 times, every time the backup.log file had a size of 127GB, which is stored at this file path pattern:
/var/log/plesk/PMM/backup-2016-MM-d-h-m-s-xxx
Please implement a check of file integrity of loaded TAR file before starting such endless retry loop.
In general it is a common programming practice to check remote file integrity before starting similar processes.
Example log of this issue:
[24978]: 2016-09-02 22:37:05.071 DEBUG Domain 'clients.example.de': BackupSizeCalculator::getDomainCustomButtonsSize finished. Size is 0 bytes.
[24978]: 2016-09-02 22:37:05.071 DEBUG Get backup size for domain 'clients.example.de' finished. Size is 368640 bytes.
[24978]: 2016-09-02 22:37:05.071 DEBUG Get backup size for domain 'demo-domain.de'
[24978]: 2016-09-02 22:37:05.071 DEBUG Domain 'demo-domain.de': BackupSizeCalculator::getDomainCustomButtonsSize started.
[24978]: 2016-09-02 22:37:05.071 DEBUG Domain 'demo-domain.de': BackupSizeCalculator::getDomainCustomButtonsSize finished. Size is 0 bytes.
[24978]: 2016-09-02 22:37:05.071 DEBUG Get backup size for domain 'demo-domain.de' finished. Size is 254050304 bytes.
[24978]: 2016-09-02 22:37:05.071 DEBUG Get backup size for server settings
[24978]: 2016-09-02 22:37:05.084 DEBUG Retrieve size of '/var/www/vhosts/.skel/0': 245898 bytes
[24978]: 2016-09-02 22:37:05.084 DEBUG Server: BackupSizeCalculator::getServerSettingsKeysSize started.
[24978]: 2016-09-02 22:37:05.084 DEBUG getServerSettingsBackupSize: Found sw key repository: /etc/sw/keys
[24978]: 2016-09-02 22:37:05.084 DEBUG getServerSettingsBackupSize: Load keys from '/etc/sw/keys/keys'
[24978]: 2016-09-02 22:37:05.087 DEBUG Retrieve size of '/etc/sw/keys/keys/XXXXXXXX': 11838 bytes
[24978]: 2016-09-02 22:37:05.087 DEBUG Server: BackupSizeCalculator::getServerSettingsKeysSize finished. Size is 11838 bytes.
[24978]: 2016-09-02 22:37:05.087 DEBUG Server: BackupSizeCalculator::getServerSettingsAppPackagesSize started.
[24978]: 2016-09-02 22:37:05.087 DEBUG Server: BackupSizeCalculator::getServerSettingsAppPackagesSize finished. Size is 0 bytes.
[24978]: 2016-09-02 22:37:05.088 DEBUG Server: BackupSizeCalculator::getServerCustomButtonsSize started.
[24978]: 2016-09-02 22:37:05.088 DEBUG Server: BackupSizeCalculator::getServerCustomButtonsSize finished. Size is 0 bytes.
[24978]: 2016-09-02 22:37:05.089 DEBUG Get backup size of server settings finished. Size is 257736 bytes.
[24978]: 2016-09-02 22:37:05.089 DEBUG Get backup size finished. Backup size of selected objects is 26465193672 bytes
[2016-09-02 22:37:05.866|25019] INFO: pmm-ras started : /opt/psa/admin/sbin/pmm-ras --get-incremental-base --dump-storage=ftp://[email protected]/clients.example.de/ --dump-prefix=backup --type=server --guid=xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxx --use-ftp-passive-mode --session-path=/opt/psa/PMM/sessions/2016-09-02-223702.333
[2016-09-02 22:37:05.867|25019] INFO: Repository 'ftp://xxx.xxx.xxx.xxx/clients.example.de/': Initializing...
[2016-09-02 22:37:05.867|25019] INFO: Curl version: 0x72300
[2016-09-02 22:37:05.868|25019] INFO: Repository 'ftp://xxx.xxx.xxx.xxx/clients.example.de/': Initialized
[2016-09-02 22:37:05.868|25019] INFO: Ftp init url ftp://xxx.xxx.xxx.xxx/clients.example.de/
[2016-09-02 22:37:06.072|25019] INFO: Repository 'ftp://xxx.xxx.xxx.xxx/clients.example.de/': Get packed backup info from file backup_1608312237.tar
[2016-09-02 22:37:06.072|25019] INFO: ArchiveStreamReader::ReadFile. Break 1
[2016-09-02 22:37:06.072|25019] INFO: ArchiveStreamReader::GetNextTarEntry. Error 2. Unable to read expected size. Readed 0, expected 512 (TAR_BLOCK_SIZE)
[2016-09-02 22:37:06.072|25019] INFO: Unable to read first entry from archive.
[2016-09-02 22:37:06.072|25019] INFO: Repository 'ftp://xxx.xxx.xxx.xxx/clients.example.de/': Get backup info from file backup_1608312237.tar
[2016-09-02 22:37:06.072|25019] INFO: Repository 'ftp://xxx.xxx.xxx.xxx/clients.example.de/': Get packed backup info from file backup_1608302237.tar
[2016-09-02 22:37:06.072|25019] INFO: Ftp init url ftp://xxx.xxx.xxx.xxx/clients.example.de/backup_1608302237.tar
[2016-09-02 22:37:06.276|25019] INFO: pmm-ras finished. Exit code: 0
[2016-09-02 22:37:06.287|25022] INFO: pmm-ras started : /opt/psa/admin/sbin/pmm-ras --extract-index --dump-storage=ftp://[email protected]/clients.example.de/ --dump-file-specification=backup_1608302237.tar --out-dir=/tmp/iZZsyao --use-ftp-passive-mode --session-path=/opt/psa/PMM/sessions/2016-09-02-223702.333
[2016-09-02 22:37:06.287|25022] INFO: Repository 'ftp://xxx.xxx.xxx.xxx/clients.example.de/': Initializing...
[2016-09-02 22:37:06.287|25022] INFO: Curl version: 0x72300
[2016-09-02 22:37:06.289|25022] INFO: Repository 'ftp://xxx.xxx.xxx.xxx/clients.example.de/': Initialized
[2016-09-02 22:37:06.289|25022] INFO: Ftp init url ftp://xxx.xxx.xxx.xxx/clients.example.de/
[2016-09-02 22:37:06.695|25022] INFO: Ftp init url ftp://xxx.xxx.xxx.xxx/clients.example.de/backup_1608302237.tar
[2016-09-02 22:37:06.917|25022] INFO: ArchiveStreamReader::ReadFile. Break 1
[2016-09-02 22:37:06.917|25022] INFO: ArchiveStreamReader::ReadFile. Break 1
[2016-09-02 22:37:06.917|25022] INFO: ArchiveStreamReader::ReadFile. Break 1
[2016-09-02 22:37:06.917|25022] INFO: ArchiveStreamReader::ReadFile. Break 1
[2016-09-02 22:37:06.917|25022] INFO: ArchiveStreamReader::ReadFile. Break 1
[2016-09-02 22:37:06.917|25022] INFO: ArchiveStreamReader::ReadFile. Break 1
[2016-09-02 22:37:06.917|25022] INFO: ArchiveStreamReader::ReadFile. Break 1
[2016-09-02 22:37:06.917|25022] INFO: ArchiveStreamReader::ReadFile. Break 1
we detected a critical bug in the backup command routine of Plesk 12.5 on Debian when storing backups to an external FTP server.
We had the issue, that our remote server disk runs out of memory during backup on 30th of August, so the last created TAR archive could not be finalised. Afterwards we cleaned up our backup server to get free disk space.
Every automated backup after 30th of August triggered the following critical issue:
At start of backup the last created TAR archive will be loaded from remote server and the backup process tries to open the TAR archive. If the TAR archive structure is broken the backup process will run into an endless loop of tries to open the broken TAR archive.
This try will be repeated thousands of times a second and every fail will be written to log file with a log like this:
[2016-09-02 22:37:06.917|25022] INFO: ArchiveStreamReader::ReadFile. Break 1
The current implementation will retry and update the log file until the disk memory exceeds.
I saw this issue 3 times, every time the backup.log file had a size of 127GB, which is stored at this file path pattern:
/var/log/plesk/PMM/backup-2016-MM-d-h-m-s-xxx
Please implement a check of file integrity of loaded TAR file before starting such endless retry loop.
In general it is a common programming practice to check remote file integrity before starting similar processes.
Example log of this issue:
[24978]: 2016-09-02 22:37:05.071 DEBUG Domain 'clients.example.de': BackupSizeCalculator::getDomainCustomButtonsSize finished. Size is 0 bytes.
[24978]: 2016-09-02 22:37:05.071 DEBUG Get backup size for domain 'clients.example.de' finished. Size is 368640 bytes.
[24978]: 2016-09-02 22:37:05.071 DEBUG Get backup size for domain 'demo-domain.de'
[24978]: 2016-09-02 22:37:05.071 DEBUG Domain 'demo-domain.de': BackupSizeCalculator::getDomainCustomButtonsSize started.
[24978]: 2016-09-02 22:37:05.071 DEBUG Domain 'demo-domain.de': BackupSizeCalculator::getDomainCustomButtonsSize finished. Size is 0 bytes.
[24978]: 2016-09-02 22:37:05.071 DEBUG Get backup size for domain 'demo-domain.de' finished. Size is 254050304 bytes.
[24978]: 2016-09-02 22:37:05.071 DEBUG Get backup size for server settings
[24978]: 2016-09-02 22:37:05.084 DEBUG Retrieve size of '/var/www/vhosts/.skel/0': 245898 bytes
[24978]: 2016-09-02 22:37:05.084 DEBUG Server: BackupSizeCalculator::getServerSettingsKeysSize started.
[24978]: 2016-09-02 22:37:05.084 DEBUG getServerSettingsBackupSize: Found sw key repository: /etc/sw/keys
[24978]: 2016-09-02 22:37:05.084 DEBUG getServerSettingsBackupSize: Load keys from '/etc/sw/keys/keys'
[24978]: 2016-09-02 22:37:05.087 DEBUG Retrieve size of '/etc/sw/keys/keys/XXXXXXXX': 11838 bytes
[24978]: 2016-09-02 22:37:05.087 DEBUG Server: BackupSizeCalculator::getServerSettingsKeysSize finished. Size is 11838 bytes.
[24978]: 2016-09-02 22:37:05.087 DEBUG Server: BackupSizeCalculator::getServerSettingsAppPackagesSize started.
[24978]: 2016-09-02 22:37:05.087 DEBUG Server: BackupSizeCalculator::getServerSettingsAppPackagesSize finished. Size is 0 bytes.
[24978]: 2016-09-02 22:37:05.088 DEBUG Server: BackupSizeCalculator::getServerCustomButtonsSize started.
[24978]: 2016-09-02 22:37:05.088 DEBUG Server: BackupSizeCalculator::getServerCustomButtonsSize finished. Size is 0 bytes.
[24978]: 2016-09-02 22:37:05.089 DEBUG Get backup size of server settings finished. Size is 257736 bytes.
[24978]: 2016-09-02 22:37:05.089 DEBUG Get backup size finished. Backup size of selected objects is 26465193672 bytes
[2016-09-02 22:37:05.866|25019] INFO: pmm-ras started : /opt/psa/admin/sbin/pmm-ras --get-incremental-base --dump-storage=ftp://[email protected]/clients.example.de/ --dump-prefix=backup --type=server --guid=xxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxx --use-ftp-passive-mode --session-path=/opt/psa/PMM/sessions/2016-09-02-223702.333
[2016-09-02 22:37:05.867|25019] INFO: Repository 'ftp://xxx.xxx.xxx.xxx/clients.example.de/': Initializing...
[2016-09-02 22:37:05.867|25019] INFO: Curl version: 0x72300
[2016-09-02 22:37:05.868|25019] INFO: Repository 'ftp://xxx.xxx.xxx.xxx/clients.example.de/': Initialized
[2016-09-02 22:37:05.868|25019] INFO: Ftp init url ftp://xxx.xxx.xxx.xxx/clients.example.de/
[2016-09-02 22:37:06.072|25019] INFO: Repository 'ftp://xxx.xxx.xxx.xxx/clients.example.de/': Get packed backup info from file backup_1608312237.tar
[2016-09-02 22:37:06.072|25019] INFO: ArchiveStreamReader::ReadFile. Break 1
[2016-09-02 22:37:06.072|25019] INFO: ArchiveStreamReader::GetNextTarEntry. Error 2. Unable to read expected size. Readed 0, expected 512 (TAR_BLOCK_SIZE)
[2016-09-02 22:37:06.072|25019] INFO: Unable to read first entry from archive.
[2016-09-02 22:37:06.072|25019] INFO: Repository 'ftp://xxx.xxx.xxx.xxx/clients.example.de/': Get backup info from file backup_1608312237.tar
[2016-09-02 22:37:06.072|25019] INFO: Repository 'ftp://xxx.xxx.xxx.xxx/clients.example.de/': Get packed backup info from file backup_1608302237.tar
[2016-09-02 22:37:06.072|25019] INFO: Ftp init url ftp://xxx.xxx.xxx.xxx/clients.example.de/backup_1608302237.tar
[2016-09-02 22:37:06.276|25019] INFO: pmm-ras finished. Exit code: 0
[2016-09-02 22:37:06.287|25022] INFO: pmm-ras started : /opt/psa/admin/sbin/pmm-ras --extract-index --dump-storage=ftp://[email protected]/clients.example.de/ --dump-file-specification=backup_1608302237.tar --out-dir=/tmp/iZZsyao --use-ftp-passive-mode --session-path=/opt/psa/PMM/sessions/2016-09-02-223702.333
[2016-09-02 22:37:06.287|25022] INFO: Repository 'ftp://xxx.xxx.xxx.xxx/clients.example.de/': Initializing...
[2016-09-02 22:37:06.287|25022] INFO: Curl version: 0x72300
[2016-09-02 22:37:06.289|25022] INFO: Repository 'ftp://xxx.xxx.xxx.xxx/clients.example.de/': Initialized
[2016-09-02 22:37:06.289|25022] INFO: Ftp init url ftp://xxx.xxx.xxx.xxx/clients.example.de/
[2016-09-02 22:37:06.695|25022] INFO: Ftp init url ftp://xxx.xxx.xxx.xxx/clients.example.de/backup_1608302237.tar
[2016-09-02 22:37:06.917|25022] INFO: ArchiveStreamReader::ReadFile. Break 1
[2016-09-02 22:37:06.917|25022] INFO: ArchiveStreamReader::ReadFile. Break 1
[2016-09-02 22:37:06.917|25022] INFO: ArchiveStreamReader::ReadFile. Break 1
[2016-09-02 22:37:06.917|25022] INFO: ArchiveStreamReader::ReadFile. Break 1
[2016-09-02 22:37:06.917|25022] INFO: ArchiveStreamReader::ReadFile. Break 1
[2016-09-02 22:37:06.917|25022] INFO: ArchiveStreamReader::ReadFile. Break 1
[2016-09-02 22:37:06.917|25022] INFO: ArchiveStreamReader::ReadFile. Break 1
[2016-09-02 22:37:06.917|25022] INFO: ArchiveStreamReader::ReadFile. Break 1
