Done tImeout while waiting for server to start backup


#1

HI

I just started using Urbackup, the feature list sounds great but I cant make this work on the client side.

Both of my client and the server are Debian Buster. Everything seems to work, I can login to the server see the settings even an active backup/indexing. My issue is that the indexing is never finished, it has been like a day already and no end to this. My backup is like 17gb. Seeing that, I restarted the server and used the urbackupclientbackend with debug. The I started

 /usr/local/bin/urbackupclientctl start -i
Waiting for server to start backup... done
Timeout while waiting for server to start backup

The client seems to be indexing files for couple mins (based on the console output) then it stops or seems to stop indexing files and start printing these or similar lines repeatedly without going back to indexing.

XK9qDt
2019-05-12 12:43:01: ClientService cmd: #IfrZFwSdsQCEmhIZXQFA3#2PING RUNNING pc_done=&status_id=5&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=rRq1kf9svxw4tRXK9qDt
2019-05-12 12:43:05: ClientService cmd: PONG
2019-05-12 12:43:11: ClientService cmd: #IfrZFwSdsQCEmhIZXQFA3#2PING RUNNING pc_done=&status_id=5&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=rRq1kf9svxw4tRXK9qDt
2019-05-12 12:43:21: ClientService cmd: #IfrZFwSdsQCEmhIZXQFA3#2PING RUNNING pc_done=&status_id=5&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=rRq1kf9svxw4tRXK9qDt
2019-05-12 12:43:31: ClientService cmd: #IfrZFwSdsQCEmhIZXQFA3#2PING RUNNING pc_done=&status_id=5&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=rRq1kf9svxw4tRXK9qDt
2019-05-12 12:43:41: ClientService cmd: #IfrZFwSdsQCEmhIZXQFA3#2PING RUNNING pc_done=&status_id=5&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=rRq1kf9svxw4tRXK9qDt
2019-05-12 12:43:51: ClientService cmd: #IfrZFwSdsQCEmhIZXQFA3#2PING RUNNING pc_done=&status_id=5&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=rRq1kf9svxw4tRXK9qDt
2019-05-12 12:44:01: ClientService cmd: #IfrZFwSdsQCEmhIZXQFA3#2PING RUNNING pc_done=&status_id=5&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=rRq1kf9svxw4tRXK9qDt
2019-05-12 12:44:05: ClientService cmd: PONG
2019-05-12 12:44:11: ClientService cmd: #IfrZFwSdsQCEmhIZXQFA3#2PING RUNNING pc_done=&status_id=5&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=rRq1kf9svxw4tRXK9qDt
2019-05-12 12:44:21: ClientService cmd: #IfrZFwSdsQCEmhIZXQFA3#2PING RUNNING pc_done=&status_id=5&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=rRq1kf9svxw4tRXK9qDt
2019-05-12 12:44:31: ClientService cmd: #IfrZFwSdsQCEmhIZXQFA3#2PING RUNNING pc_done=&status_id=5&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=rRq1kf9svxw4tRXK9qDt
2019-05-12 12:44:41: ClientService cmd: #IfrZFwSdsQCEmhIZXQFA3#2PING RUNNING pc_done=&status_id=5&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=rRq1kf9svxw4tRXK9qDt
2019-05-12 12:44:51: ClientService cmd: #IfrZFwSdsQCEmhIZXQFA3#2PING RUNNING pc_done=&status_id=5&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=rRq1kf9svxw4tRXK9qDt
2019-05-12 12:45:01: ClientService cmd: #IfrZFwSdsQCEmhIZXQFA3#2PING RUNNING pc_done=&status_id=5&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=rRq1kf9svxw4tRXK9qDt
2019-05-12 12:45:05: ClientService cmd: PONG
2019-05-12 12:45:11: ClientService cmd: #IfrZFwSdsQCEmhIZXQFA3#2PING RUNNING pc_done=&status_id=5&speed_bpms=0&total_bytes=-1&done_bytes=0&paused_fb=1#token=rRq1kf9svxw4tRXK9qDt

Then I check the server web panel, it seems to be backup running and indexing. However I feel like there is disconnect somewhere.


#2

Maybe by looking at those last lines you can get an idea where it gets stuck listing files/directories?


#3

I am not sure, these are the last lines it printed before going into that repeated line mode

Bear in mind I am backing up /home/USER, I have no idea how it jumped to /lib/systemd

019-05-12 12:40:28: Not following symlink "/lib/systemd/system/mountnfs-bootclean.service" because symlink target at "/dev/null" is excluded
2019-05-12 12:40:28: Not following symlink "/lib/systemd/system/mountnfs.service" because symlink target at "/dev/null" is excluded
2019-05-12 12:40:28: Not following symlink "/lib/systemd/system/nfs-common.service" because symlink target at "/dev/null" is excluded
2019-05-12 12:40:28: Not following symlink "/lib/systemd/system/rc.service" because symlink target at "/dev/null" is excluded     
2019-05-12 12:40:28: Not following symlink "/lib/systemd/system/rcS.service" because symlink target at "/dev/null" is excluded 
2019-05-12 12:40:28: Not following symlink "/lib/systemd/system/reboot.service" because symlink target at "/dev/null" is excluded
2019-05-12 12:40:28: Not following symlink "/lib/systemd/system/rmnologin.service" because symlink target at "/dev/null" is excluded
2019-05-12 12:40:28: Not following symlink "/lib/systemd/system/saned.service" because symlink target at "/dev/null" is excluded
2019-05-12 12:40:28: Not following symlink "/lib/systemd/system/screen-cleanup.service" because symlink target at "/dev/null" is excluded
2019-05-12 12:40:28: Not following symlink "/lib/systemd/system/sendsigs.service" because symlink target at "/dev/null" is excluded
2019-05-12 12:40:28: Not following symlink "/lib/systemd/system/single.service" because symlink target at "/dev/null" is excluded
2019-05-12 12:40:28: Not following symlink "/lib/systemd/system/stop-bootlogd-single.service" because symlink target at "/dev/null" is excluded                           
2019-05-12 12:40:28: Not following symlink "/lib/systemd/system/stop-bootlogd.service" because symlink target at "/dev/null" is excluded
2019-05-12 12:40:28: Not following symlink "/lib/systemd/system/sudo.service" because symlink target at "/dev/null" is excluded    
2019-05-12 12:40:28: Not following symlink "/lib/systemd/system/umountfs.service" because symlink target at "/dev/null" is excluded                                       
2019-05-12 12:40:28: Not following symlink "/lib/systemd/system/umountnfs.service" because symlink target at "/dev/null" is excluded                                      
2019-05-12 12:40:28: Not following symlink "/lib/systemd/system/umountroot.service" because symlink target at "/dev/null" is excluded    
2019-05-12 12:40:28: Not following symlink "/lib/systemd/system/x11-common.service" because symlink target at "/dev/null" is excluded                                     
2019-05-12 12:40:29: ClientService cmd: STATUS DETAIL#pw=hdQVbtR5u5RgQLGkbHfhpPxMDm7IZT                                                       
2019-05-12 12:40:29: rc=0 hasError=true state=0                                                                                                                           
2019-05-12 12:40:30: ClientService cmd: STATUS DETAIL#pw=hdQVbtR5u5RgQLGkbHfhpPxMDm7IZT                                                    
2019-05-12 12:40:30: rc=0 hasError=true state=0                                                                                                                           
2019-05-12 12:40:31: ClientService cmd: STATUS DETAIL#pw=hdQVbtR5u5RgQLGkbHfhpPxMDm7IZT                                                                                   
2019-05-12 12:40:31: rc=0 hasError=true state=0                                                                  

#4

What I have seen often is that people use wine and have a symlink to / in the .wine directory (or something similar).

Please check if one of the client threads is in D state (e.g. with htop). If not you could attach strace to see which syscall it hangs in. Or if you have debug symbols installed with https://urbackup.atlassian.net/wiki/spaces/US/pages/8323075/Debugging+with+gdb+on+Linux


#5

Can I disable following symlinks?


#6

See urbackupclientctl add --help.


#7

Thanks I will give it a try.


#8

Ok I removed the backup path and added a new one that does not follow symlinks. The issue is resolved, I am guessing that something funky was going on with the followed symlinks.

The backup was done quite happily. I am wondering why not disable symlinks by default? That seems to be the case for many sync and backup applications anyways.