Probably bug. Web interface unreachable after mount raw image from web. Full report

Server: UrBackup 2.4.12, debian 10.3 64bit / Linux 4.19.0-8-amd64);
Storage file system: btrfs.

Issue (Bug):

Web interface unreachable after mount raw image from web.

  • Mount image from web;

  • Web interface becomes unreachable;

  • Restart UrBackup service;

  • Mount same image again from web;

  • Now web interface works fine, but we have an error:
    Mounting image failed. Please see server log file for details.
    Guestmount...

  • Reload web page with this image backup;

  • It’s fine! Now we see files which in the mounted image.

As far as I understand this is due to error:

Apr 22 21:54:24 urbackupsrv kernel: [855598.905596] mnt image[31818]: segfault at 7f54945990ce ip 0000000000af171b sp 00007f54737fc140 error 6 in urbackupsrv[400000+97d000]
Apr 22 21:54:24 urbackupsrv kernel: [855598.905785] Code: 8d 3c 28 75 3a 0f b6 06 48 8d 1d 40 7c 50 00 88 07 49 8b 07 48 8d 50 e8 48 39 da 74 8d 66 90 c7 40 f8 00 00 00 00 4c 89 60 e8 <42> c6 04 20 00 48 83 c4 28 5b 5d 41 5c 41 5d 41 5e 41 5f c3 90 48

The process of installing image mount support:

#  apt-get install libguestfs-tools qemu-utils
#  libguestfs-test-tool
...
===== TEST FINISHED OK =====
#  urbackup_mount_helper test
MOUNT TEST OK

# reboot

Full report:
Last log strings before (/var/log/urbackup.log):

2020-04-22 20:52:06: ERROR: Error while downloading version info from http://update.urbackup.org/2.4.x/version_linux.txt: Couldn't connect to server(ec=7), Failed to connect to update.urbackup.org port 80: Connection timed out
2020-04-22 20:52:37: ERROR: Error downloading server version information: Couldn't connect to server(ec=7), Failed to connect to update.urbackup.org port 80: Connection timed out
2020-04-22 20:53:09: ERROR: Error downloading dataplan database: Couldn't connect to server(ec=7), Failed to connect to update.urbackup.org port 80: Connection timed out

Mount image.

Web interface becomes unreachable.

I checked log (/var/log/urbackup.log), nothing was changed.

Syslog:

Apr 22 21:54:24 urbackupsrv kernel: [855598.905596] mnt image[31818]: segfault at 7f54945990ce ip 0000000000af171b sp 00007f54737fc140 error 6 in urbackupsrv[400000+97d000]
Apr 22 21:54:24 urbackupsrv kernel: [855598.905785] Code: 8d 3c 28 75 3a 0f b6 06 48 8d 1d 40 7c 50 00 88 07 49 8b 07 48 8d 50 e8 48 39 da 74 8d 66 90 c7 40 f8 00 00 00 00 4c 89 60 e8 <42> c6 04 20 00 48 83 c4 28 5b 5d 41 5c 41 5d 41 5e 41 5f c3 90 48

Despite the fact that the syslog error is “mnt image [31818]: segfault”, the image has been successfully mounted.

# df -h
Filesystem                          Size  Used Avail Use% Mounted on
udev                                981M     0  981M   0% /dev
tmpfs                               200M   18M  182M  10% /run
/dev/mapper/debian10test--vg-root    18G  4.1G   13G  25% /
tmpfs                               998M     0  998M   0% /dev/shm
tmpfs                               5.0M     0  5.0M   0% /run/lock
tmpfs                               998M     0  998M   0% /sys/fs/cgroup
/dev/sda1                           236M   87M  138M  39% /boot
/dev/mapper/vgurbackup-lvurbackup1  190G  109G   79G  58% /media/BACKUP/urbackup
tmpfs                               200M     0  200M   0% /run/user/0
/dev/fuse                            70G   23G   47G  33% /media/BACKUP/urbackup/UpBackupPC1/200229-0010_Image_C_mnt0

At the same time, the urbackupsrv service is active.

# systemctl status urbackupsrv
urbackupsrv.service - LSB: Server for doing backups
   Loaded: loaded (/etc/init.d/urbackupsrv; generated)
   Active: active (running) since Wed 2020-04-22 20:51:00 MSK; 1h 17min ago

After restart service the web interface starts working.
systemctl restart urbackupsrv

After restarting the service, the image in df -h is no longer mounted.

# df -h
Filesystem                          Size  Used Avail Use% Mounted on
udev                                981M     0  981M   0% /dev
tmpfs                               200M   18M  182M  10% /run
/dev/mapper/debian10test--vg-root    18G  4.1G   13G  25% /
tmpfs                               998M     0  998M   0% /dev/shm
tmpfs                               5.0M     0  5.0M   0% /run/lock
tmpfs                               998M     0  998M   0% /sys/fs/cgroup
/dev/sda1                           236M   87M  138M  39% /boot
/dev/mapper/vgurbackup-lvurbackup1  190G  109G   79G  58% /media/BACKUP/urbackup
tmpfs                               200M     0  200M   0% /run/user/0

Syslog:

Apr 22 22:11:34 urbackupsrv systemd[1]: Stopping LSB: Server for doing backups...
Apr 22 22:11:34 urbackupsrv systemd[1]: urbackupsrv.service: Succeeded.
Apr 22 22:11:34 urbackupsrv systemd[1]: Stopped LSB: Server for doing backups.
Apr 22 22:11:34 urbackupsrv systemd[1]: urbackupsrv.service: Found left-over process 1296 (qemu-system-x86) in control group while starting unit. Ignoring.
Apr 22 22:11:34 urbackupsrv systemd[1]: This usually indicates unclean termination of a previous run, or service implementation deficiencies.
Apr 22 22:11:34 urbackupsrv systemd[1]: urbackupsrv.service: Found left-over process 1309 (guestmount) in control group while starting unit. Ignoring.
Apr 22 22:11:34 urbackupsrv systemd[1]: This usually indicates unclean termination of a previous run, or service implementation deficiencies.
Apr 22 22:11:34 urbackupsrv systemd[1]: Starting LSB: Server for doing backups...
Apr 22 22:11:34 urbackupsrv systemd[1]: Started LSB: Server for doing backups.
Apr 22 22:11:36 urbackupsrv systemd[1779]: media-BACKUP-urbackup-UpBackupPC1-200229\x2d0010_Image_C_mnt0.mount: Succeeded.
Apr 22 22:11:36 urbackupsrv systemd[1]: media-BACKUP-urbackup-UpBackupPC1-200229\x2d0010_Image_C_mnt0.mount: Succeeded.

Try mount this image again.

In that time web interface works fine, but we have an error:

Mounting image failed. Please see server log file for details.
Guestmount... 

Check df -h

# df -h
Filesystem                          Size  Used Avail Use% Mounted on
udev                                981M     0  981M   0% /dev
tmpfs                               200M   18M  182M  10% /run
/dev/mapper/debian10test--vg-root    18G  4.1G   13G  25% /
tmpfs                               998M     0  998M   0% /dev/shm
tmpfs                               5.0M     0  5.0M   0% /run/lock
tmpfs                               998M     0  998M   0% /sys/fs/cgroup
/dev/sda1                           236M   87M  138M  39% /boot
/dev/mapper/vgurbackup-lvurbackup1  190G  109G   79G  58% /media/BACKUP/urbackup
tmpfs                               200M     0  200M   0% /run/user/0
/dev/fuse                            70G   23G   47G  33% /media/BACKUP/urbackup/UpBackupPC1/200229-0010_Image_C_mnt0

As we see the image mounted successfully.

Goto previous page

Then open this image backup again

Now we see files in the mounted image.

UrBackup log:

2020-04-22 22:11:36: ERROR: Image mounting failed: Mountpoint: /media/BACKUP/urbackup/Win7x64-Test1/200422-2034_Image_C_mnt0
Guestunmount...
guestunmount: /media/BACKUP/urbackup/Win7x64-Test1/200422-2034_Image_C_mnt0 is not mounted: fusermount: entry for /media/BACKUP/urbackup/Win7x64-Test1/200422-2034_Image_C_mnt0 not found in /etc/mtab
Unmounting "/media/BACKUP/urbackup/Win7x64-Test1/200422-2034_Image_C_mnt0" failed.

2020-04-22 22:11:36: ERROR: Unmounting image backup id 8 path "/media/BACKUP/urbackup/Win7x64-Test1/200422-2034_Image_C/Image_C_200422-2034.raw" mounted 23m 39s ago failed: Mountpoint: /media/BACKUP/urbackup/Win7x64-Test1/200422-2034_Image_C_mnt0
Guestunmount...
guestunmount: /media/BACKUP/urbackup/Win7x64-Test1/200422-2034_Image_C_mnt0 is not mounted: fusermount: entry for /media/BACKUP/urbackup/Win7x64-Test1/200422-2034_Image_C_mnt0 not found in /etc/mtab
Unmounting "/media/BACKUP/urbackup/Win7x64-Test1/200422-2034_Image_C_mnt0" failed.

Syslog:

Apr 22 22:11:34 urbackupsrv systemd[1]: Stopping LSB: Server for doing backups...
Apr 22 22:11:34 urbackupsrv systemd[1]: urbackupsrv.service: Succeeded.
Apr 22 22:11:34 urbackupsrv systemd[1]: Stopped LSB: Server for doing backups.
Apr 22 22:11:34 urbackupsrv systemd[1]: urbackupsrv.service: Found left-over process 1296 (qemu-system-x86) in control group while starting unit. Ignoring.
Apr 22 22:11:34 urbackupsrv systemd[1]: This usually indicates unclean termination of a previous run, or service implementation deficiencies.
Apr 22 22:11:34 urbackupsrv systemd[1]: urbackupsrv.service: Found left-over process 1309 (guestmount) in control group while starting unit. Ignoring.
Apr 22 22:11:34 urbackupsrv systemd[1]: This usually indicates unclean termination of a previous run, or service implementation deficiencies.
Apr 22 22:11:34 urbackupsrv systemd[1]: Starting LSB: Server for doing backups...
Apr 22 22:11:34 urbackupsrv systemd[1]: Started LSB: Server for doing backups.
Apr 22 22:11:36 urbackupsrv systemd[1779]: media-BACKUP-urbackup-UpBackupPC1-200229\x2d0010_Image_C_mnt0.mount: Succeeded.
Apr 22 22:11:36 urbackupsrv systemd[1]: media-BACKUP-urbackup-UpBackupPC1-200229\x2d0010_Image_C_mnt0.mount: Succeeded.

kern.log:

Apr 22 20:45:13 urbackupsrv kernel: [851448.479656] loop: module loaded
Apr 22 20:45:23 urbackupsrv kernel: [851458.389112] fuse init (API version 7.27)
Apr 22 20:45:23 urbackupsrv kernel: [851458.395518] mnt image[28547]: segfault at 7fea725950ce ip 0000000000af171b sp 00007feaccff7140 error 6 in urbackupsrv[400000+97d000]
Apr 22 20:45:23 urbackupsrv kernel: [851458.395523] Code: 8d 3c 28 75 3a 0f b6 06 48 8d 1d 40 7c 50 00 88 07 49 8b 07 48 8d 50 e8 48 39 da 74 8d 66 90 c7 40 f8 00 00 00 00 4c 89 60 e8 <42> c6 04 20 00 48 83 c4 28 5b 5d 41 5c 41 5d 41 5e 41 5f c3 90 48
Apr 22 21:54:24 urbackupsrv kernel: [855598.905596] mnt image[31818]: segfault at 7f54945990ce ip 0000000000af171b sp 00007f54737fc140 error 6 in urbackupsrv[400000+97d000]
Apr 22 21:54:24 urbackupsrv kernel: [855598.905785] Code: 8d 3c 28 75 3a 0f b6 06 48 8d 1d 40 7c 50 00 88 07 49 8b 07 48 8d 50 e8 48 39 da 74 8d 66 90 c7 40 f8 00 00 00 00 4c 89 60 e8 <42> c6 04 20 00 48 83 c4 28 5b 5d 41 5c 41 5d 41 5e 41 5f c3 90 48

Full logs attached!

logs.zip (8.8 KB)