When restoring backups within the Virtualmin interface I have the following issue. The backup gets to extracting tar and stops. I've tested this on two separate virtual servers, one in AWS and another on my private network. They are running different versions of FreeBSD, that being 10.2 and 10.3 and I have tested it across multiple versions of Webmin and Virtualmin over the last 5 months. So far I have not been able to get past this issue.
This issue only arrises once I upload a website to an account. If I just create an empty Virtual Server the backup the restore works perfectly fine, things come apart when I install a website, in this case via the WordPress script. Then you get without fail it stopping in extract tar. This also occurs whether you use .gz or .bz2 so I am assuming the issue lies with the tar and not the compression used.
The issue also occurs whether the restore is done via the web interface or via the command line. I have also run it from the root user to rule out permissions as follows:
Running:
virtualmin restore-domain --source /home/mytestaccount/virtualmin-backup/mytestaccount.tar.gz --domain mytestaccount --all-features
Produces:
Checking for missing features ..
.. WARNING - The following features were enabled for one or more
domains in the backup, but do not exist on this system. Some
functions of the restored domains may not work : Mail for domain
Checking for errors in backup ..
.. no errors found
Starting restore..
Extracting backup archive file ..
.. done
Restoring backup for virtual server mytestaccount ..
Restoring virtual server password, quota and other details ..
.. done
Updating administration password and quotas ..
.. done
Restoring Cron jobs ..
.. done
Extracting TAR file of home directory ..
The following appears to be running. If I kill it the restores completes, though the extract is incomplete.
44344 0 I+ 0:00.01 /bin/sh -c (cd \\/home\\/mytestaccount && cat \\/home\\/mytestaccount\\/virtualmin\\-backup\\/mytestaccount\\.tar\\.gz | gunzip -c | /usr/bin/tar xvfX - /tmp/.webmin/156112_443
Also a correspecting entry within the debug log is as follows:
44313 [03/Apr/2016 17:07:49.042921] - - virtual-server CMD "cmd=cd \/home\/mytestaccount && cat \/home\/mytestaccount\/virtualmin\-backup\/mytestaccount\.tar\.gz | gunzip -c | /usr/bin/tar xvfX - /tmp/.webmin/156112_44313_4_restore-domain.pl"
Interestingly if I manually run:
cd \/home\/mytestaccount && cat \/home\/mytestaccount\/virtualmin\-backup\/mytestaccount\.tar\.gz | gunzip -c | /usr/bin/tar xvfX - /tmp/.webmin/156112_44313_4_restore-domain.pl
It appears to extract the archive without error.
Also I ran a trace via the truss command which produces the following:
truss virtualmin restore-domain --source /home/mytestaccount/virtualmin-backup/mytestaccount.tar.gz --domain mytestaccount --all-features
Below is some of the end of the output of this command:
igaction(SIGPIPE,{ 0x280780f0 SA_SIGINFO ss_t },{ SIG_IGN 0x0 ss_t }) = 0 (0x0)
sigprocmask(SIG_SETMASK,{ },0x0) = 0 (0x0)
stat("/etc/nsswitch.conf",{ mode=-rw-r--r-- ,inode=481627,size=360,blksize=32768 }) = 0 (0x0)
sigprocmask(SIG_SETMASK,{ SIGHUP|SIGINT|SIGQUIT|SIGILL|SIGTRAP|SIGABRT|SIGEMT|SIGFPE|SIGKILL|SIGBUS|SIGSEGV|SIGSYS|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2 },{ }) = 0 (0x0)
sigaction(SIGPIPE,{ SIG_IGN 0x0 ss_t },{ 0x280780f0 SA_SIGINFO ss_t }) = 0 (0x0)
sigprocmask(SIG_SETMASK,{ },0x0) = 0 (0x0)
poll({ 6/POLLIN|POLLPRI },1,-1) = 1 (0x1)
read(6,"01\^B\^A\^Ce\a\n",8) = 8 (0x8)
read(6,"\^A\0\^D\0\^D\0\240#0!\^D\^V1.2."...,43) = 43 (0x2b)
stat("/usr/local/etc/nss_ldap.conf",{ mode=-rw-r--r-- ,inode=802684,size=9963,blksize=32768 }) = 0 (0x0)
getpid() = 4987 (0x137b)
geteuid() = 0 (0x0)
getsockname(6,{ AF_INET int_ip-1:14141 },0xbfbfcf14) = 0 (0x0)
getpeername(6,{ AF_INET int_ip-2:389 },0xbfbfcf10) = 0 (0x0)
sigprocmask(SIG_SETMASK,{ SIGHUP|SIGINT|SIGQUIT|SIGILL|SIGTRAP|SIGABRT|SIGEMT|SIGFPE|SIGKILL|SIGBUS|SIGSEGV|SIGSYS|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2 },{ }) = 0 (0x0)
sigaction(SIGPIPE,{ 0x280780f0 SA_SIGINFO ss_t },{ SIG_IGN 0x0 ss_t }) = 0 (0x0)
sigprocmask(SIG_SETMASK,{ },0x0) = 0 (0x0)
stat("/etc/nsswitch.conf",{ mode=-rw-r--r-- ,inode=481627,size=360,blksize=32768 }) = 0 (0x0)
close(8) = 0 (0x0)
sigprocmask(SIG_SETMASK,{ SIGHUP|SIGINT|SIGQUIT|SIGILL|SIGTRAP|SIGABRT|SIGEMT|SIGFPE|SIGKILL|SIGBUS|SIGSEGV|SIGSYS|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2 },{ }) = 0 (0x0)
sigaction(SIGPIPE,{ SIG_IGN 0x0 ss_t },{ 0x280780f0 SA_SIGINFO ss_t }) = 0 (0x0)
sigprocmask(SIG_SETMASK,{ },0x0) = 0 (0x0)
sigprocmask(SIG_SETMASK,{ SIGHUP|SIGINT|SIGQUIT|SIGILL|SIGTRAP|SIGABRT|SIGEMT|SIGFPE|SIGKILL|SIGBUS|SIGSEGV|SIGSYS|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2 },{ }) = 0 (0x0)
sigaction(SIGPIPE,{ 0x280780f0 SA_SIGINFO ss_t },{ SIG_IGN 0x0 ss_t }) = 0 (0x0)
sigprocmask(SIG_SETMASK,{ },0x0) = 0 (0x0)
__sysctl(0xbfbfe974,0x2,0xbfbfe970,0xbfbfe97c,0x0,0x0) = 0 (0x0)
Currently the system is running FreeBSD 10.3 with Webmin 1.791 and Virtualmin 5.0. This is a showstopper issue as I wish to allow this feature for my clients. I have tried .zip archives however they appear to need to extraordinary amount of free disk space to work.
Comments
Submitted by JamieCameron on Sat, 04/02/2016 - 23:07 Comment #1
What happens if you run
trusson thetarcommand? From your description, it looks like Virtualmin is waiting ontarto complete, but it is hung up on something..Submitted by benh on Sun, 04/03/2016 - 19:40 Comment #2
I think I've stumbled on something when trying out your request. So far I have been running the commands that appear in the debug log. I noticed that the command appears slightly different within the PS output.
When I run ps the process in question comes up as follows (note the double "\"s):
/bin/sh -c (cd \\/home\\/mytestaccount && cat \\/home\\/mytestaccount\\/virtualmin\\-backup\\/mytestaccount\\.tar\\.gz | gunzip -c | /usr/bin/tar xvfX - /tmp/.webmin/298847_61945_4_restore-domain.pl)If I run the above command as is I get:
cat: \/home\/mytestaccount\/virtualmin\-backup\/mytestaccount\.tar\.gz: No such file or directorygunzip: (stdin): unexpected end of file
If I remove the extract "\"s it runs fine. I'm wondering if this is what is causing the issue. Is there a way I can remove these extra "\"s in the perl code to test this theory?
As requested I have also run it via truss. This time it is the command that appears in the debug log file which doesn't have the extra "\"s.
truss -o debug cd \/home\/mytestaccount && cat \/home\/mytestaccount\/virtualmin\-backup\/mytestaccount\.tar\.gz | gunzip -c | /usr/bin/tar xvfX - /tmp/.webmin/298847_61945_4_restore-domain.plDebug Output
cat debug
mmap(0x0,32768,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 671608832 (0x2807f000)
issetugid() = 0 (0x0)
lstat("/etc",{ mode=drwxr-xr-x ,inode=481536,size=2560,blksize=32768 }) = 0 (0x0)
lstat("/etc/libmap.conf",{ mode=-rw-r--r-- ,inode=481631,size=109,blksize=32768 }) = 0 (0x0)
openat(AT_FDCWD,"/etc/libmap.conf",O_CLOEXEC,00) = 3 (0x3)
fstat(3,{ mode=-rw-r--r-- ,inode=481631,size=109,blksize=32768 }) = 0 (0x0)
mmap(0x0,109,PROT_READ,MAP_PRIVATE,3,0x0) = 671641600 (0x28087000)
close(3) = 0 (0x0)
lstat("/usr",{ mode=drwxr-xr-x ,inode=642048,size=512,blksize=32768 }) = 0 (0x0)
lstat("/usr/local",{ mode=drwxr-xr-x ,inode=642052,size=512,blksize=32768 }) = 0 (0x0)
lstat("/usr/local/etc",{ mode=drwxr-xr-x ,inode=818963,size=1024,blksize=32768 }) = 0 (0x0)
lstat("/usr/local/etc/libmap.d",0xbfbfc9c0) ERR#2 'No such file or directory'
munmap(0x28087000,109) = 0 (0x0)
openat(AT_FDCWD,"/var/run/ld-elf.so.hints",O_CLOEXEC,00) = 3 (0x3)
read(3,"Ehnt\^A\0\0\0\M^@\0\0\0\M-*\0\0"...,128) = 128 (0x80)
lseek(3,0x80,SEEK_SET) = 128 (0x80)
read(3,"/lib:/usr/lib:/usr/lib/compat:/u"...,170) = 170 (0xaa)
close(3) = 0 (0x0)
access("/lib/libedit.so.7",F_OK) = 0 (0x0)
openat(AT_FDCWD,"/lib/libedit.so.7",O_CLOEXEC,00) = 3 (0x3)
fstat(3,{ mode=-r--r--r-- ,inode=2327459,size=132580,blksize=32768 }) = 0 (0x0)
mmap(0x0,4096,PROT_READ,MAP_PRIVATE|MAP_PREFAULT_READ,3,0x0) = 671641600 (0x28087000)
mmap(0x0,143360,PROT_NONE,MAP_PRIVATE|MAP_ANON|MAP_NOCORE,-1,0x0) = 671645696 (0x28088000)
mmap(0x28088000,126976,PROT_READ|PROT_EXEC,MAP_PRIVATE|MAP_FIXED|MAP_NOCORE|MAP_PREFAULT_READ,3,0x0) = 671645696 (0x28088000)
mmap(0x280a7000,8192,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_FIXED|MAP_PREFAULT_READ,3,0x1e000) = 671772672 (0x280a7000)
mmap(0x280a9000,8192,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_FIXED|MAP_ANON,-1,0x0) = 671780864 (0x280a9000)
munmap(0x28087000,4096) = 0 (0x0)
close(3) = 0 (0x0)
access("/lib/libncurses.so.8",F_OK) = 0 (0x0)
openat(AT_FDCWD,"/lib/libncurses.so.8",O_CLOEXEC,00) = 3 (0x3)
fstat(3,{ mode=-r--r--r-- ,inode=2327478,size=247760,blksize=32768 }) = 0 (0x0)
mmap(0x0,4096,PROT_READ,MAP_PRIVATE|MAP_PREFAULT_READ,3,0x0) = 671641600 (0x28087000)
mmap(0x0,249856,PROT_NONE,MAP_PRIVATE|MAP_ANON|MAP_NOCORE,-1,0x0) = 671789056 (0x280ab000)
mmap(0x280ab000,237568,PROT_READ|PROT_EXEC,MAP_PRIVATE|MAP_FIXED|MAP_NOCORE|MAP_PREFAULT_READ,3,0x0) = 671789056 (0x280ab000)
mmap(0x280e5000,12288,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_FIXED|MAP_PREFAULT_READ,3,0x3a000) = 672026624 (0x280e5000)
munmap(0x28087000,4096) = 0 (0x0)
close(3) = 0 (0x0)
access("/lib/libc.so.7",F_OK) = 0 (0x0)
openat(AT_FDCWD,"/lib/libc.so.7",O_CLOEXEC,00) = 3 (0x3)
fstat(3,{ mode=-r--r--r-- ,inode=2327426,size=1440192,blksize=32768 }) = 0 (0x0)
mmap(0x0,4096,PROT_READ,MAP_PRIVATE|MAP_PREFAULT_READ,3,0x0) = 671641600 (0x28087000)
mmap(0x0,1531904,PROT_NONE,MAP_PRIVATE|MAP_ANON|MAP_NOCORE,-1,0x0) = 672038912 (0x280e8000)
mmap(0x280e8000,1351680,PROT_READ|PROT_EXEC,MAP_PRIVATE|MAP_FIXED|MAP_NOCORE|MAP_PREFAULT_READ,3,0x0) = 672038912 (0x280e8000)
mmap(0x28232000,28672,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_FIXED|MAP_PREFAULT_READ,3,0x149000) = 673390592 (0x28232000)
mmap(0x28239000,151552,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_FIXED|MAP_ANON,-1,0x0) = 673419264 (0x28239000)
munmap(0x28087000,4096) = 0 (0x0)
close(3) = 0 (0x0)
munmap(0x28086000,4096) = 0 (0x0)
mmap(0x0,40960,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 673570816 (0x2825e000)
munmap(0x28261000,28672) = 0 (0x0)
mmap(0x0,69632,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 673583104 (0x28261000)
sysarch(I386_SET_GSBASE,0xbfbfe30c) = 0 (0x0)
sigprocmask(SIG_BLOCK,{ SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2 },{ }) = 0 (0x0)
sigprocmask(SIG_SETMASK,{ },0x0) = 0 (0x0)
readlink("/etc/malloc.conf",0xbfbfdaa7,1024) ERR#2 'No such file or directory'
issetugid() = 0 (0x0)
mmap(0x0,4194304,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 673652736 (0x28272000)
munmap(0x28272000,4194304) = 0 (0x0)
mmap(0x0,8384512,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 673652736 (0x28272000)
munmap(0x28272000,1630208) = 0 (0x0)
munmap(0x28800000,2560000) = 0 (0x0)
sigprocmask(SIG_BLOCK,{ SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2 },{ }) = 0 (0x0)
sigprocmask(SIG_SETMASK,{ },0x0) = 0 (0x0)
sigprocmask(SIG_BLOCK,{ SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2 },{ }) = 0 (0x0)
sigprocmask(SIG_SETMASK,{ },0x0) = 0 (0x0)
sigprocmask(SIG_BLOCK,{ SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2 },{ }) = 0 (0x0)
sigprocmask(SIG_SETMASK,{ },0x0) = 0 (0x0)
sigprocmask(SIG_BLOCK,{ SIGHUP|SIGINT|SIGQUIT|SIGKILL|SIGPIPE|SIGALRM|SIGTERM|SIGURG|SIGSTOP|SIGTSTP|SIGCONT|SIGCHLD|SIGTTIN|SIGTTOU|SIGIO|SIGXCPU|SIGXFSZ|SIGVTALRM|SIGPROF|SIGWINCH|SIGINFO|SIGUSR1|SIGUSR2 },{ }) = 0 (0x0)
sigprocmask(SIG_SETMASK,{ },0x0) = 0 (0x0)
getpid() = 62045 (0xf25d)
geteuid() = 0 (0x0)
getppid() = 62044 (0xf25c)
mmap(0x0,4194304,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANON,-1,0x0) = 679477248 (0x28800000)
getuid() = 0 (0x0)
geteuid() = 0 (0x0)
getgid() = 0 (0x0)
getegid() = 0 (0x0)
openat(AT_FDCWD,"/usr/bin/cd",O_CLOEXEC,00) = 3 (0x3)
fcntl(3,F_DUPFD_CLOEXEC,0xa) = 10 (0xa)
close(3) = 0 (0x0)
sigaction(SIGINT,0x0,{ SIG_DFL SA_RESTART ss_t }) = 0 (0x0)
sigaction(SIGINT,{ 0x805fb40 0x0 ss_t },0x0) = 0 (0x0)
sigaction(SIGQUIT,0x0,{ SIG_DFL SA_RESTART ss_t }) = 0 (0x0)
sigaction(SIGQUIT,{ 0x805fb40 0x0 ss_t },0x0) = 0 (0x0)
sigaction(SIGTERM,0x0,{ SIG_DFL 0x0 ss_t }) = 0 (0x0)
sigaction(SIGTERM,{ SIG_DFL 0x0 ss_t },0x0) = 0 (0x0)
stat(".",{ mode=drwxr-xr-x ,inode=883586,size=512,blksize=4096 }) = 0 (0x0)
stat("/home/mytestaccount",{ mode=drwxr-xr-x ,inode=883586,size=512,blksize=4096 }) = 0 (0x0)
read(10,"#!/bin/sh\n# $FreeBSD: releng/10"...,1024) = 162 (0xa2)
stat("/home/mytestaccount",{ mode=drwxr-xr-x ,inode=883586,size=512,blksize=4096 }) = 0 (0x0)
lstat("/home",{ mode=drwxr-xr-x ,inode=827951,size=512,blksize=4096 }) = 0 (0x0)
lstat("/home/mytestaccount",{ mode=drwxr-xr-x ,inode=883586,size=512,blksize=4096 }) = 0 (0x0)
chdir("/home/mytestaccount") = 0 (0x0)
madvise(0x28805000,0x1000,0x5) = 0 (0x0)
madvise(0x2880d000,0x1000,0x5) = 0 (0x0)
read(10,0x80666c0,1024) = 0 (0x0)
process exit, rval = 0
Submitted by benh on Sun, 04/03/2016 - 21:41 Comment #3
I believe I have found a way around the issue. In the below code you have the "&execute_command" function being initiated.
It appears that if you have the "\$err" argument the command pauses indefinitely. If you remove it the restore appears to work. When I print to the console the contents of $err it appears to be empty. Maybe there lies the problem.
I've got a linux box somewhere that's running Virtualmin so will have a look at the output on that.
feature-dir.pl
671 if ($key && $homefmt) {
672 $catter = &backup_decryption_command($key)." ".$q;
673 }
674 else {
675 $catter = "cat $q";
676 }
677 if ($cf == 4) {
678 # Unzip command does un-compression and un-archiving
679 # XXX ZIP doesn't support excludes of paths :-(
680 &execute_command("cd $qh && unzip -o $q", undef, \$out, \$out);
681 }
682 else {
683 local $comp = $cf == 1 ? "gunzip -c" :
684 $cf == 2 ? "uncompress -c" :
685 $cf == 3 ? &get_bunzip2_command()." -c" : "cat";
686 local $tarcmd = &make_tar_command("xvfX", "-", $xtemp);
687 local $reader = $catter." | ".$comp;
688 if ($asd) {
689 # Run as domain owner - disabled, as this prevents some files
690 # from being written to by tar
691 $tarcmd = &command_as_user($d->{'user'}, 0, $tarcmd);
692 }
693
694 #&execute_command("cd $qh && $reader | $tarcmd", undef, \$out, \$err);
695 &execute_command("cd $qh && $reader | $tarcmd", undef, \$out);
Submitted by JamieCameron on Mon, 04/04/2016 - 22:42 Comment #4
Thanks for finding this - I see the cause (buffering of IO causes a deadlock) and will fix it in the next Virtualmin release.
Submitted by JamieCameron on Mon, 04/04/2016 - 22:43 Comment #5