Slow FILE_METADATA loading: wrong client token?

#1

After upgrading (1.4.14 -> 2.0.32) both client and server I’m having a problem with one of the clients: backup works ok until loading data stage. Then it is very slow in loading metadata.
What I see in server log is:

17/08/16 10:14 DEBUG Loading “urbackup/FILE_METADATA|Ppah6tpwcOR3Vea51e5D|1659”. Loaded 13.3516 MB at 11.36 KBit/s
17/08/16 10:15 DEBUG Loading “urbackup/FILE_METADATA|Ppah6tpwcOR3Vea51e5D|1659”. Loaded 13.4219 MB at 8.536 KBit/s
…
(one line every minute)

Client log is full of:

2016-08-17 10:17:07: ERROR: Token id for user not found
2016-08-17 10:17:07: ERROR: Token id for user not found
2016-08-17 10:17:07: ERROR: Token id for user not found
2016-08-17 10:17:07: ERROR: Token id for user not found
2016-08-17 10:17:07: ERROR: Token id for user not found
2016-08-17 10:17:07: ERROR: Token id for user not found
2016-08-17 10:17:07: ERROR: Token id for user not found
2016-08-17 10:17:07: ERROR: Token id for user not found
2016-08-17 10:17:07: ERROR: Token id for user not found
2016-08-17 10:17:07: ERROR: Token id for user not found
2016-08-17 10:17:07: ERROR: Token id for user not found
2016-08-17 10:17:07: ERROR: Token id for user not found
2016-08-17 10:17:07: ERROR: Token id for user not found
2016-08-17 10:17:07: ERROR: Token id for user not found
2016-08-17 10:17:07: ERROR: Token id for user not found
2016-08-17 10:17:07: ERROR: Token id for user not found
2016-08-17 10:17:07: ERROR: Token id for user not found
2016-08-17 10:17:07: ERROR: Token id for user not found
2016-08-17 10:17:07: ERROR: Token id for user not found

(as you see, many lines in a second)

Other clients don’t have this problem and their operations get completed in reasonable time (included metadata loading at 70/80 Mbit/s rates).

Already tried to reinstall client, to no avail.

Any ideas?

TIA

Loading urbackup/FILE_METADATA
#2

Could be you have many files with a deleted user.

Could you run

find / -nouser

and

find / -nogroup

?

#3

I found 500 files with no user. find / -nogroup is still running.
Meanwhile backup is giving an huge ETA (292487235 years 4 months 2 weeks 1 day 8 hours 10 minutes).

500 files are not few, but lines in urbackupclient.log are way more:

cat /var/log/urbackupclient.log | grep “Token id for user not found” | wc -l
64098

#4

Maybe you could attach strace to find out which files cause the error?

#5

I did a strace of urbackupclientbackend and what I see among the reported error is:

2016-08-18 10:23:02: ERROR: Error getting internal id for user with id 1058
2016-08-18 10:23:02: ERROR: Error getting internal id for group with id 102
2016-08-18 10:23:02: ERROR: Token id for user not found
2016-08-18 10:23:02: ERROR: Token id for user not found
2016-08-18 10:23:02: ERROR: Token id for user not found
2016-08-18 10:23:02: ERROR: Token id for user not found
2016-08-18 10:23:02: ERROR: Token id for user not found
2016-08-18 10:23:02: ERROR: Token id for user not found
2016-08-18 10:23:02: ERROR: Token id for user not found
2016-08-18 10:23:02: ERROR: Token id for user not found
2016-08-18 10:23:02: ERROR: Token id for user not found
2016-08-18 10:23:02: ERROR: Token id for user not found
2016-08-18 10:23:02: ERROR: Token id for user not found
2016-08-18 10:23:02: ERROR: Token id for user not found

user 1058 with group 102 is the user owning most of the files in the drive. Its id is resolved locally:

$ id 1058
uid=1058(coop) gid=102(coop) gruppi=102(coop)

The only strange thing I noticed is this:

$ getent passwd | grep 1058
coop:x:1058:102:My username:/home/coop:
coop:x:1058:102:My username,:/home/coop:/bin/bash

(two lines)
This is because this machine checks users against an LDAP tree and this user is both in /etc/passwd and in LDAP.
Can this harm somehow?

#6

Just to test: is there a way to prevent FILE_METADATA upload (so that the backup can get to end)?

#7

Currently it uses the file /etc/passwd to get a user list. This could be the problem. Could you do a grep 1058 /etc/passwd ?

#8

$ grep 1058 /etc/passwd
coop:x:1058:102:Username Surname,:/home/coop:/bin/bash

#9

Just to exclude upgrade problems, i did a fresh install of the server (writing to a new directory) and deleted clients configurations (/usr/local/var/urbackup) and reinstalled clients.
The problem with that client (token id for user/group not found) remains.

This time I’ll wait some day

Schermata.png1179×216 22.1 KB
to see if it comes to the end.

Otherwise i have to reinstall 1.4 version :frowning:

#10

So I did wait and it came to the end!
There was some troubles (i. e. I had to disable client logging, otherwise /var/log/syslog and /var/log/daemon.log filled up disk space [*] (these two log files were using > 8 GB)).
Yesterday evening full backup completed and after then it made two more incremental backups (it’s now completing the third).
Time and resources (urbackupclientbackend is using 50-60% CPU while working on this client) used to backup are much more compared to other clients, so I think the “error getting internal id for user 1058” has to be fixed.
I’ll investigate my passwd/LDAP architecture deeper, but I also wonder what’s the goal of retrieving internal id for user/group while backing up files.

[*] Btw, what is urbackupclient log facility? I tried to disable logging to syslog and daemon.log using “urbackup.none”, “urbackupclient.none”, “urbackupclientbackend.none” - to non avail. I had to completely disable client logging to prevent disk full problems.

#11

Thanks, it is used when a user on the machine accesses backups (via command line e.g. urbackupclientctl browse). As such it is not strictly neccessary if you only use a super user.

It logs to the specified log file and to stdout. And what happens with stdout is probably determined by systemd-journald.

#12

Is there a way to disable it? Maybe a config parameter in next version of the client?

Thanks in advance.