Client waiting forever - new container installation on server side

Thierry · September 24, 2021, 9:48pm

Hi, I have change my home server. Brand new one with debian 11, installation with docker-compose. Client side (windows), I have fully uninstalled and reinstalled the client and the status stays at “waiting” (in french).
I have disabled firewalls both sides, checked with telnet that I could connect to all urbackup tcp ports both sides, the UI on port 55414 works (from my windows pc) and shows no activity. I have checked from inside the container that I could write the mapped disks, and it works.
So the question is why backup does not start?
Thanks for your help.

The docker compose file :

version: ‘2’

services:
urbackup:
image: uroni/urbackup-server:latest
container_name: urbackup
restart: unless-stopped
environment:
- PUID=1000 # Enter the UID of the user who should own the files here
- PGID=100 # Enter the GID of the user who should own the files here
- TZ=Europe/Paris # Enter your timezone
volumes:
- /var/urbackup:/var/urbackup
- /data/pc-backup:/backups
# Uncomment the next line if you want to bind-mount the www-folder
#- /path/to/wwwfolder:/usr/share/urbackup
network_mode: “host”
# Activate the following two lines for BTRFS support
#cap_add:
# - SYS_ADMIN

Server log :

2021-09-24 23:20:58: Starting HTTP-Server on port 55414
2021-09-24 23:20:58: HTTP: Server started up successfully!
2021-09-24 23:20:58: SQLite: recovered 138 frames from WAL file /var/urbackup/backup_server.db-wal code: 283
2021-09-24 23:20:58: SQLite: recovered 8 frames from WAL file /var/urbackup/backup_server_link_journal.db-wal code: 283
2021-09-24 23:20:58: SQLite: recovered 51 frames from WAL file /var/urbackup/backup_server_settings.db-wal code: 283
2021-09-24 23:20:58: SQLite: recovered 138 frames from WAL file /var/urbackup/backup_server.db-wal code: 283
2021-09-24 23:20:58: SQLite: recovered 51 frames from WAL file /var/urbackup/backup_server_settings.db-wal code: 283
2021-09-24 23:20:58: SQLite: recovered 8 frames from WAL file /var/urbackup/backup_server_link_journal.db-wal code: 283
2021-09-24 23:20:58: Started UrBackup…
2021-09-24 23:20:58: Removing temporary files…
2021-09-24 23:20:58: Recreating temporary folder…
2021-09-24 23:20:58: Image mounting disabled: TEST FAILED: guestmount is missing (libguestfs-tools)
2021-09-24 23:20:58: Backup destination cannot handle subvolumes and snapshots. Snapshots disabled.
2021-09-24 23:20:58: Reflink ioctl failed. errno=95
2021-09-24 23:20:58: Broadcasting on ipv4 interface enp2s0 addr 192.168.0.18
2021-09-24 23:20:58: Broadcasting on ipv4 interface docker0 addr 172.17.0.1
2021-09-24 23:20:58: Broadcasting on ipv4 interface br-b99b510aad2c addr 172.18.0.1
2021-09-24 23:20:58: Broadcasting on ipv6 interface enp2s0 addr 2a03:4980:152:9c00:8639:4cff:fe00:d6e1
2021-09-24 23:20:58: Broadcasting on ipv6 interface enp2s0 addr fe80::8639:4cff:fe00:d6e1
2021-09-24 23:20:58: UrBackup Server start up complete.
2021-09-24 23:20:58: Server started up successfully!
2021-09-24 23:20:58: Looking for old Sessions… 0 sessions
2021-09-24 23:20:59: Downloading version file…
2021-09-24 23:21:01: Downloading version file…
2021-09-24 23:21:01: Downloading server version info…
2021-09-24 23:21:01: Downloading dataplan database…

Client log :

2021-09-24 00:51:55: Loaded -fileserv- plugin
2021-09-24 00:51:55: Loaded -fsimageplugin- plugin
2021-09-24 00:51:55: Loaded -cryptoplugin- plugin
2021-09-24 00:51:55: SQLite: recovered 24 frames from WAL file C:\Program Files\UrBackup\urbackup\backup_client.db-wal code: 283
2021-09-24 00:51:55: urbackupserver: Server started up successfully!
2021-09-24 00:51:55: FileSrv: Backup privileges set successfully
2021-09-24 00:51:55: Started UrBackupClient Backend…
2021-09-24 00:51:55: FileSrv: Backup privileges set successfully (SE_SECURITY_NAME)
2021-09-24 00:51:55: FileSrv: Backup privileges set successfully (SE_RESTORE_NAME)
2021-09-24 00:51:55: Filesystem. Vol="\?\Volume{b8333ef8-5f7e-46f8-985a-7c79792e87a7}" Name=“acer” Type=“ntfs” VPaths=1 Size=126830505984
2021-09-24 00:51:55: Filesystem is System partition. Skipping…
2021-09-24 00:51:55: FileSrv: Binding UDP socket at port 35622…
2021-09-24 00:51:55: FileSrv: done.
2021-09-24 00:51:55: FileSrv: Disabling new behavior…
2021-09-24 00:51:55: Filesystem. Vol="\?\Volume{b669820a-ee5b-4bf9-9bed-db7bf4adcb12}" Name=“recovery” Type=“ntfs” VPaths=0 Size=1073737728
2021-09-24 00:51:55: FileSrv: Binding ipv6 UDP socket at port 35622…
2021-09-24 00:51:55: FileSrv: done.
2021-09-24 00:51:55: FileSrv: Disabling new behavior…
2021-09-24 00:51:55: FileSrv: Servername: -LAPTOP-POBFFN7E-
2021-09-24 00:51:55: GPT formated hard disk encountered. No bootable flag. Attributes = -9223372036854775807
2021-09-24 00:51:55: Do not automount is set
2021-09-24 00:51:55: System partition is set
2021-09-24 00:51:55: Bootable flag set for volume
2021-09-24 00:51:55: FileSrv: Server started up successfully
2021-09-24 00:51:55: Found potential candidate: \?\Volume{b669820a-ee5b-4bf9-9bed-db7bf4adcb12}\ Score: 3
2021-09-24 00:51:55: FileSrv: UDP Thread started
2021-09-24 00:51:55: Filesystem. Vol="\?\Volume{be10deb1-ed20-11e9-a96c-fc777489aa25}" Name="" Type=“fat32” VPaths=1 Size=250389102592
2021-09-24 00:51:55: Bootable flag not set for volume
2021-09-24 00:51:55: Filesystem. Vol="\?\Volume{4f6ba7eb-341f-452d-87d3-d84712a038c3}" Name=“esp” Type=“fat32” VPaths=0 Size=100663296
2021-09-24 00:51:55: GPT formated hard disk encountered. No bootable flag. Attributes = -9223372036854775808
2021-09-24 00:51:55: Do not automount is set
2021-09-24 00:51:55: Bootable flag not set for volume
2021-09-24 00:51:55: Found potential candidate: \?\Volume{4f6ba7eb-341f-452d-87d3-d84712a038c3}\ Score: 3
2021-09-24 00:51:55: Selected volume \?\Volume{b669820a-ee5b-4bf9-9bed-db7bf4adcb12}
2021-09-24 00:51:55: System dir: C:\WINDOWS
2021-09-24 00:51:55: Volpath: \.\C:
2021-09-24 00:51:55: EFI partition with type UUID {C12A7328-F81F-11D2-BA4B-00A0C93EC93B}
2021-09-24 00:51:55: EFI System Partition is at \?\GLOBALROOT\Device\Harddisk0\Partition1
2021-09-24 00:51:55: urbackupserver: No available slots… starting new Worker
2021-09-24 00:51:55: ClientService cmd: STATUS DETAIL#pw=GPhGtnfjVQgKYOd5xaf4aMqincaxjX
2021-09-24 00:51:55: ClientService cmd: STATUS#pw=GPhGtnfjVQgKYOd5xaf4aMqincaxjX
2021-09-24 00:51:55: ClientService cmd: STATUS DETAIL#pw=GPhGtnfjVQgKYOd5xaf4aMqincaxjX
2021-09-24 00:51:55: ClientService cmd: STATUS#pw=GPhGtnfjVQgKYOd5xaf4aMqincaxjX
2021-09-24 00:51:56: Looking for old Sessions… 0 sessions
2021-09-24 00:51:56: Internet mode not enabled
2021-09-24 00:51:56: ClientService cmd: STATUS DETAIL#pw=GPhGtnfjVQgKYOd5xaf4aMqincaxjX
2021-09-24 00:51:57: ClientService cmd: STATUS DETAIL#pw=GPhGtnfjVQgKYOd5xaf4aMqincaxjX
2021-09-24 00:51:58: ClientService cmd: STATUS DETAIL#pw=GPhGtnfjVQgKYOd5xaf4aMqincaxjX
2021-09-24 00:51:59: ClientService cmd: STATUS DETAIL#pw=GPhGtnfjVQgKYOd5xaf4aMqincaxjX
2021-09-24 00:52:00: ClientService cmd: STATUS DETAIL#pw=GPhGtnfjVQgKYOd5xaf4aMqincaxjX
2021-09-24 00:52:01: ClientService cmd: STATUS DETAIL#pw=GPhGtnfjVQgKYOd5xaf4aMqincaxjX
2021-09-24 00:52:02: ClientService cmd: STATUS DETAIL#pw=GPhGtnfjVQgKYOd5xaf4aMqincaxjX
2021-09-24 00:52:03: ClientService cmd: STATUS DETAIL#pw=GPhGtnfjVQgKYOd5xaf4aMqincaxjX
2021-09-24 00:52:04: ClientService cmd: STATUS DETAIL#pw=GPhGtnfjVQgKYOd5xaf4aMqincaxjX
2021-09-24 00:52:05: ClientService cmd: STATUS DETAIL#pw=GPhGtnfjVQgKYOd5xaf4aMqincaxjX
2021-09-24 00:52:06: ClientService cmd: STATUS DETAIL#pw=GPhGtnfjVQgKYOd5xaf4aMqincaxjX
2021-09-24 00:52:07: ClientService cmd: STATUS DETAIL#pw=GPhGtnfjVQgKYOd5xaf4aMqincaxjX
2021-09-24 00:52:08: ClientService cmd: STATUS DETAIL#pw=GPhGtnfjVQgKYOd5xaf4aMqincaxjX
2021-09-24 00:52:09: ClientService cmd: STATUS DETAIL#pw=GPhGtnfjVQgKYOd5xaf4aMqincaxjX
2021-09-24 00:52:10: ClientService cmd: STATUS DETAIL#pw=GPhGtnfjVQgKYOd5xaf4aMqincaxjX
2021-09-24 00:52:11: ClientService cmd: STATUS DETAIL#pw=GPhGtnfjVQgKYOd5xaf4aMqincaxjX
2021-09-24 00:52:12: ClientService cmd: STATUS DETAIL#pw=GPhGtnfjVQgKYOd5xaf4aMqincaxjX
2021-09-24 00:52:13: ClientService cmd: STATUS DETAIL#pw=GPhGtnfjVQgKYOd5xaf4aMqincaxjX
2021-09-24 00:52:14: ClientService cmd: STATUS DETAIL#pw=GPhGtnfjVQgKYOd5xaf4aMqincaxjX
2021-09-24 00:52:15: ClientService cmd: STATUS DETAIL#pw=GPhGtnfjVQgKYOd5xaf4aMqincaxjX
2021-09-24 00:52:16: ClientService cmd: STATUS DETAIL#pw=GPhGtnfjVQgKYOd5xaf4aMqincaxjX
2021-09-24 00:52:17: ClientService cmd: STATUS DETAIL#pw=GPhGtnfjVQgKYOd5xaf4aMqincaxjX
2021-09-24 00:52:18: ClientService cmd: STATUS DETAIL#pw=GPhGtnfjVQgKYOd5xaf4aMqincaxjX
2021-09-24 00:52:19: ClientService cmd: STATUS DETAIL#pw=GPhGtnfjVQgKYOd5xaf4aMqincaxjX

auanasgheps · September 27, 2021, 10:21am

Are you sure server and client are in the same IP Subnet? If not, you’ll have to enable Internet backup.
Also doublecheck when the client is allowed to make backups, maybe you haven’t specified a backup winbdow.

Thierry · September 27, 2021, 10:09pm

Hi, yes both client and server are on the same subnet.
Server is always up and running.
Client is configured as follows (as found in the log file) :

backup_window_full_file=1-7/0-24
backup_window_full_image=1-7/0-24
backup_window_incr_file=1-7/0-24
backup_window_incr_image=1-7/0-24
computername=LAPTOP-POBFFN7E
exclude_files=C:\ProgramData\Microsoft\Network\Downloader*;C:\WINDOWS\system32\LogFiles\WMI\RtBackup:.:;C:\Users\thier\index.dat;C:\WINDOWS\Minidump*;:\Pagefile.sys;:\System Volume Information\MountPointManagerRemoteDatabase;C:\WINDOWS\netlogon.chg;:\hiberfil.sys;:\System Volume Information\Heat*.;C:\Users\thier\AppData\Local\Temp*;:\System Volume Information*{3808876B-C176-4e48-B7AE-04046E6CC752};:\System Volume Information:.{7cc467ef-6865-4831-853f-2a4817fd1bca}ALT;:\System Volume Information:.{7cc467ef-6865-4831-853f-2a4817fd1bca}DB;C:\ProgramData\Microsoft\Windows\WER*;C:\WINDOWS\softwaredistribution*.;:\System Volume Information\FVE2.{e40ad34d-dae9-4bc7-95bd-b16218c10f72}.:;:\System Volume Information\FVE2.{c9ca54a3-6983-46b7-8684-a7e5e23499e3};:\System Volume Information\FVE2.{24e6f0ae-6a00-4f73-984b-75ce9942852d};:\System Volume Information\FVE2.{9ef82dfa-1239-4a30-83e6-3b3e9b8fed08};:\System Volume Information\FVE2.{aff97bac-a69b-45da-aba1-2cfbce434750}.:;:\System Volume Information\FVE2.{9ef82dfa-1239-4a30-83e6-3b3e9b8fed08}.:;:\System Volume Information\FVE.{e40ad34d-dae9-4bc7-95bd-b16218c10f72}.:;:\System Volume Information\FVE.{c9ca54a3-6983-46b7-8684-a7e5e23499e3};:\System Volume Information\FVE.{9ef82dfa-1239-4a30-83e6-3b3e9b8fed08};C:\Windows\system32\MSDtc\MSDTC.LOG;C:\Users:\AppData\Local\Temp;C:\Users:\AppData\Local\Microsoft\Windows\Temporary Internet Files;C:\Users:\AppData\Local\Google\Chrome\User Data\Default\Cache;C:\Users:\AppData\Local\Google\Chrome\User Data\Default\Media Cache;C:\Users:\AppData\Local\Microsoft\Windows\Explorer\thumbcache*;C:\Users:\AppData\Local\Microsoft\Terminal Server Client\Cache;C:\Users:\AppData\Local\Mozilla\Firefox\Profiles:\cache2;C:\Users:\AppData\Local\Mozilla\Firefox\Profiles:\cache;C:\Windows\Temp;:$$Recycle.Bin;:\System Volume Information;C:\Windows.old;C:$$Windows.~BT;C:\ProgramData\Microsoft\Windows Defender\Scans\mpcache-*
image_letters=C
include_files=C:\Users:\Documents*;C:\Users:\Pictures*;C:\Users:\Music*;C:\Users:\Videos*;C:\Users:\Desktop*
internet_authkey=
internet_compress=true
internet_encrypt=true
internet_full_file_backups=false
internet_image_backups=false
internet_mode_enabled=false
internet_server=
internet_server_port=55415
internet_server_proxy=
internet_speed=-1
local_speed=-1
max_file_full=10
max_file_incr=50
max_image_full=0
max_image_incr=0
min_file_full=2
min_file_incr=30
min_image_full=0
min_image_incr=0
startup_backup_delay=0
update_freq_full=2592000
update_freq_image_full=-5184000
update_freq_image_full_orig=5184000
update_freq_image_incr=-604800
update_freq_incr=86400
client_set_settings=true
client_set_settings_time=1632426083
default_dirs=C:\Users
#pw=KlOcT725f16MMphCVsn9PtsIgoUvHM
2021-09-24 20:48:00: rc=0 hasError=true state=0

auanasgheps · September 28, 2021, 10:12am

I’m not a super expert but everything looks correct. So I don’t know what could be wrong.
From the UrBackup GUI do you see the client ONLINE?

Thierry · September 28, 2021, 7:08pm

Thanks for trying to help, sometime we just miss a basic stuff and we don’t need a super expert to open our eyes. To answer your question, nothing is displayed in the UI, whatever the tab.

auanasgheps · September 29, 2021, 9:06am

So the Client is unable to find the server. This is suspicious.
But you can try to add the client manually (blue button).

Thierry · September 29, 2021, 10:23pm

I’ve added the client. It works and says the client is online. But the back up does not start. Here is a screenshot :

auanasgheps · September 30, 2021, 9:49pm

No it’s not. If the server does not show up in the upper part, it means the client is still unable to contact the server properly. It’s like not being able to download the correct settings.

Have you configured Server URL in General > Server?

I would also try Internet mode.
Go to General > Internet
Flag Enable internet mode
Enter your LAN address inInternet server name/IP.

You will have to reflect these changes to your client as there’s no server connection yet.

Let me know if then starts a backup.

Thierry · October 3, 2021, 7:52pm

So I’ve configured the internet on both sides (with the lan IP address of the server). The client said the server was not reachable for one hour. After one hour it said there was a server authentication issue. I’ve removed the internet config, restarted everything and the client was again in “waiting” mode. I’ve retried an internet config, and that time, it stayed in “server not reachable”. So I’ve removed again the internet config, restarted again everything and again the client was in “waiting mode”. And I gave up.
And yesterday night, the icon turned to white! Checking the admin interface, 3 full backups have been done (file backup, as defined). Tonight the icon is still white, some files have been modified on my pc, the client shows “waiting” mode and I don’t see any incremental backup starting.
Since no configuration has change (pc and server) all this is magic for me. If someone can explain!
Will see tomorrow if a backup starts meantime.

auanasgheps · October 5, 2021, 8:11am

I don’t know what happened, I’m not that expert in UrBackup, but I’m glad it works for you now.

Thierry · October 6, 2021, 10:31pm

Well, I am not sure it is the end. The icon is red again, no back up since October 2sd. I tried to launch a backup from the UI and I got a “the launch of the backup has failed.” So back to the start point.

magnus_agnarsson · October 7, 2021, 1:57pm

I seem to have a very similiar problem. I can see that the container based urbackup problably only is scanning its subnet (170.0.0.0) and not at all on my subnet 192.2.168.0. Is there any way of making the urbackup scan my subnet instead? In my case I tried both with windows client and a raspberry (debian) client. Neither of them is starting backups. I also tried to change to internet backups with no success.

auanasgheps · October 7, 2021, 9:09pm

When you created your container you should have specified
network_mode: “host”
in the Docker Compose.
If this has been done, the container is running directly off your host network. Please recheck your config.

Thierry · October 7, 2021, 9:16pm

It’s good news and bad news. Bad because it’s affecting people, good because we are probably not alone and maybe the experts will have a look.
I can make a wire shark trace if someone tell me what to search for (what to filter).

Thierry · October 7, 2021, 10:20pm

I just made a trace to have a look. I’ve seen this :
30925 2559.377015 192.168.0.18 255.255.255.255 UDP 60 35623 → 35622 Len=1
30926 2559.388184 192.168.0.186 192.168.0.18 UDP 59 35622 → 35623 Len=17
This is a bit surprising to me because when you send a udp packet to a server, the source port should be random allocated by the IP stack. And when you have a firewall, by default it should “open” the way back. Anyway, I had reactivated the UFW server side, so I have added a rule to allow port 35623/udp and a backup started two minutes later.
I hope everything is now ok.

magnus_agnarsson · October 8, 2021, 12:02pm

Thanks. I rebuilt my docker container and with network host. Then all is working fine. From the start I had initiated urbackup as a docker service - then it created new server ID:s as well all the time, thus nothing working. Now the serverside seems to be working just fine and making backups from my wíndows client. Still have the raspberrys to solve. The client does not seem to start.