File restore fails with permission error

Restore
1

I’m having the same Issue!
One thing not mentioned above - the restored file is created with a size of 0 bytes.
Also, client debug log shows the following:

2018-11-05 20:52:33: WARNING: No permission to open "((client path to file))" for writing. Not restoring file.
2018-11-05 21:10:49: ERROR: Error loading "((client path to file))" CANNOT_OPEN_FILE (code: 3)
2018-11-05 21:10:49: ERROR: Error while downloading files during restore

Server is Fedora 28, client is Windows 7
server-confirm does not help
Running client service as my user does not help

2

2.2.x takes into account the permissions of the user starting the restore. So it could be correct? How are you starting the restore?

Does it work if you login as admin on the server and start the restore this way?

3

Can you please check if client backup path is in place and whether client service is running and also is server_idents file contains the server key.

4

Also check whether client and server services are running from user having administrative rights.

5

I have tried both restoring from the context menu and from the web UI as admin. Same result.

6

The backup path exists, all I am doing is deleting a single file then restoring it. The client service is running and backups work fine for all clients. The file gets created with size 0 (P.S. after the restore fails, I get a UAC prompt when deleting the 0 byte file).
server_idents looks fine to me as far as I can tell.

As for admin rights, on the client I have tested both defaults (Local System) and my own user (has admin rights but UAC is enabled). On the server, the default configuration is used (a user called urbackup) and the permissions for the backed up data are correct (777).

One other thing to note is that downloading the files from the web UI works, too.

7

I have tested on another client running Windows 10 - same result

8

Ok, we don’t have the same problem, so there is probably something different about your setup…

What client version are you using?

To solve the problem the client (debug) log would be useful.
If possible, could you post it or send it?

This post describes how to change the client to debug logging, where it is stored and where to send it to if posting is not possible: Having problems with UrBackup? Please read before posting

Thanks!

9

debug.log (12.5 KB)

10

Server log: (not sure if I’ve succeeded in enabling debug logging)
urbackup.log (2.7 KB)

11

Seems to be at info level. Maybe you could get it to debug level?

12

I think I got it right this time
urbackup_debug.log (8.1 KB)

13

Looks like it indeed cannot open the file:

2018-11-07 15:23:33: FileSrv: Sending file (normal) clientdl0/VSC_MP1.ISO metadata_id=1
2018-11-07 15:23:33: FileSrv: Mapped name: /mnt/mdata/Dank-PC/181107-0042/Archive/VSC_MP1.ISO
2018-11-07 15:23:33: FileSrv: Info: Couldn't open file

Unfortunately it doesn’t print why… I guess you could run it in strace (with strace -f urbackupsrv run -v debug) to see why it cannot open the file (or it is obvious from the path).

14

The path exists and I can access it as a user.
If it helps, /mnt/mdata is a mergerfs volume
The strace log is too big (26.8MiB), here is the interesting part:

3152  stat("/mnt/mdata/Dank-PC/181107-0042/Archive/VSC_MP1.ISO",  <unfinished ...>
3148  stat("/mnt/mdata/Dank-PC/181107-0042/Archive/VSC_MP1.ISO",  <unfinished ...>
3152  <... stat resumed> {st_mode=S_IFREG|0777, st_size=57065472, ...}) = 0
3152  lstat("/mnt/mdata/Dank-PC/181107-0042/Archive/VSC_MP1.ISO", {st_mode=S_IFREG|0777, st_size=57065472, ...}) = 0
3152  stat("/mnt/mdata/Dank-PC/181107-0042/.hashes/Archive/VSC_MP1.ISO",  <unfinished ...>
3148  <... stat resumed> {st_mode=S_IFREG|0777, st_size=57065472, ...}) = 0
3148  openat(AT_FDCWD, "/mnt/mdata/Dank-PC/181107-0042/Archive/VSC_MP1.ISO", O_RDONLY|O_NOATIME|O_CLOEXEC) = -1 EPERM (Operation not permitted)
3148  stat("/mnt/mdata/Dank-PC/181107-0042/Archive/", {st_mode=S_IFDIR|0777, st_size=4096, ...}) = 0
3152  <... stat resumed> {st_mode=S_IFREG|0777, st_size=394, ...}) = 0
3152  openat(AT_FDCWD, "/mnt/mdata/Dank-PC/181107-0042/.hashes/Archive/VSC_MP1.ISO", O_RDONLY|O_CLOEXEC <unfinished ...>
3148  poll([{fd=52, events=POLLOUT}], 1, 300000) = 1 ([{fd=52, revents=POLLOUT}])
3148  sendto(52, "\0", 1, MSG_NOSIGNAL, NULL, 0 <unfinished ...>
3152  <... openat resumed> )            = 80
3152  lseek(80, 0, SEEK_SET <unfinished ...>
3148  <... sendto resumed> )            = 1
3152  <... lseek resumed> )             = 0
3148  stat("/etc/localtime",  <unfinished ...>
3152  read(80,  <unfinished ...>
3148  <... stat resumed> {st_mode=S_IFREG|0644, st_size=2265, ...}) = 0
3141  <... poll resumed> )              = 1 ([{fd=79, revents=POLLIN}])
3153  <... poll resumed> )              = 1 ([{fd=77, revents=POLLIN}])
3152  <... read resumed> "\377\377\377\377\377\377\377\377", 8) = 8
3148  write(1, "2018-11-07 15:46:52: FileSrv: In"..., 55 <unfinished ...>
3141  recvfrom(79,  <unfinished ...>
3153  poll([{fd=77, events=POLLIN}], 1, 60000 <unfinished ...>
3152  read(80,  <unfinished ...>
3141  <... recvfrom resumed> "4\0\0\0LOG 5-2-Error while download"..., 8192, MSG_NOSIGNAL, NULL, NULL) = 83
3141  futex(0x55adfa6fca78, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
3153  <... poll resumed> )              = 1 ([{fd=77, revents=POLLIN}])
3152  <... read resumed> "\177\0\0\0AN\360\244", 8) = 8
3148  <... write resumed> )             = 55
15

My guess is the O_NOATIME is causing this. I’ll fix it by removing that. It probably works if you run the server as root user…

16

Running the server as root does fix the issue, thanks for the help!