Hello all,
I have Urbackup server version 2.4.12. The server is working properly, but often during backup, the process freezes while downloading a list of files “urbackup/filelist.ub”. This status does not change, then I need to manually stop the backup and then start a new one manually. Recently I saw that when the backup is frozen and when I save the configuration without changing it, the process goes to the next stages. Below is a log from this backup process.
Thanks in advance for any help.
| 06.05.20 15:35 | DEBUG | pdcsrv: Waiting for filelist |
|---|---|---|
| 06.05.20 15:35 | DEBUG | pdcsrv: Connecting for filelist (async)… |
| 06.05.20 15:38 | WARNING | Restarting shadow copy of Q:\ because it was started by this server |
| 06.05.20 15:38 | INFO | Scanning for changed hard links on volume of “Q:”… |
| 06.05.20 15:38 | INFO | Indexing of “DRERYK” done. 1 filesystem lookups 0 db lookups and 0 db updates |
| 06.05.20 15:38 | DEBUG | pdcsrv: Doing backup without hashed transfer… |
| 06.05.20 15:38 | INFO | pdcsrv: Loading file list… |
| 06.05.20 15:40 | DEBUG | Loading “urbackup/filelist.ub”. 0% finished 0 bytes/1.66602 KB at 0 Bit/s |
| 06.05.20 15:42 | DEBUG | Loading “urbackup/filelist.ub”. 0% finished 0 bytes/1.66602 KB at 0 Bit/s |
| 06.05.20 15:44 | DEBUG | Loading “urbackup/filelist.ub”. 0% finished 0 bytes/1.66602 KB at 0 Bit/s |
| 06.05.20 15:46 | DEBUG | Loading “urbackup/filelist.ub”. 0% finished 0 bytes/1.66602 KB at 0 Bit/s |
| 06.05.20 15:48 | DEBUG | Loading “urbackup/filelist.ub”. 0% finished 0 bytes/1.66602 KB at 0 Bit/s |
| 06.05.20 15:50 | DEBUG | Loading “urbackup/filelist.ub”. 0% finished 0 bytes/1.66602 KB at 0 Bit/s |
| 06.05.20 15:52 | DEBUG | Loading “urbackup/filelist.ub”. 0% finished 0 bytes/1.66602 KB at 0 Bit/s |
| 06.05.20 15:54 | DEBUG | Loading “urbackup/filelist.ub”. 0% finished 0 bytes/1.66602 KB at 0 Bit/s |
| 06.05.20 15:56 | DEBUG | Loading “urbackup/filelist.ub”. 0% finished 0 bytes/1.66602 KB at 0 Bit/s |
| 06.05.20 15:58 | DEBUG | Loading “urbackup/filelist.ub”. 0% finished 0 bytes/1.66602 KB at 0 Bit/s |
| 06.05.20 16:00 | DEBUG | Loading “urbackup/filelist.ub”. 0% finished 0 bytes/1.66602 KB at 0 Bit/s |
| 06.05.20 16:02 | DEBUG | Loading “urbackup/filelist.ub”. 0% finished 0 bytes/1.66602 KB at 0 Bit/s |
| 06.05.20 16:04 | DEBUG | Loading “urbackup/filelist.ub”. 0% finished 0 bytes/1.66602 KB at 0 Bit/s |
| 06.05.20 16:06 | DEBUG | Loading “urbackup/filelist.ub”. 0% finished 0 bytes/1.66602 KB at 0 Bit/s |
| 06.05.20 16:08 | DEBUG | Loading “urbackup/filelist.ub”. 0% finished 0 bytes/1.66602 KB at 0 Bit/s |
| 06.05.20 16:10 | DEBUG | Loading “urbackup/filelist.ub”. 0% finished 0 bytes/1.66602 KB at 0 Bit/s |
| 06.05.20 16:12 | INFO | Waiting for file transfers… |
| 06.05.20 16:12 | DEBUG | Loading file “s_dreryk_7.20.1.0_20200506T003305.7z” |
| 06.05.20 16:13 | DEBUG | Loading “DRERYK/s_dreryk_7.20.1.0_20200506T003305.7z”. 33% finished 288.97 MB/872.213 MB at 40.4002 MBit/s |
| 06.05.20 16:14 | DEBUG | Loading “DRERYK/s_dreryk_7.20.1.0_20200506T003305.7z”. 70% finished 615.299 MB/872.213 MB at 45.6234 MBit/s |
| 06.05.20 16:15 | DEBUG | GT: Loaded file “s_dreryk_7.20.1.0_20200506T003305.7z” |
| 06.05.20 16:15 | DEBUG | Loading file “s_rawdata_7.20.1.0_20200506T003857.7z” |
| 06.05.20 16:15 | DEBUG | PT: Hashing file “s_dreryk_7.20.1.0_20200506T003305.7z” |
| 06.05.20 16:15 | DEBUG | HT: Copying file: “/BACKUP/pdcsrv/200506-1535/DRERYK/s_dreryk_7.20.1.0_20200506T003305.7z” (id=5) |
| 06.05.20 16:15 | DEBUG | HT: Renaming file to “/BACKUP/pdcsrv/200506-1535/DRERYK/s_dreryk_7.20.1.0_20200506T003305.7z” |
| 06.05.20 16:16 | DEBUG | Loading “DRERYK/s_rawdata_7.20.1.0_20200506T003857.7z”. 6% finished 350.211 MB/5.21799 GB at 48.9619 MBit/s |
| 06.05.20 16:17 | DEBUG | Loading “DRERYK/s_rawdata_7.20.1.0_20200506T003857.7z”. 12% finished 693.665 MB/5.21799 GB at 48.0128 MBit/s |
| 06.05.20 16:18 | DEBUG | Loading “DRERYK/s_rawdata_7.20.1.0_20200506T003857.7z”. 19% finished 1.03315 GB/5.21799 GB at 50.9289 MBit/s |
| 06.05.20 16:19 | DEBUG | Loading “DRERYK/s_rawdata_7.20.1.0_20200506T003857.7z”. 26% finished 1.38597 GB/5.21799 GB at 50.5084 MBit/s |
| 06.05.20 16:20 | DEBUG | Loading “DRERYK/s_rawdata_7.20.1.0_20200506T003857.7z”. 33% finished 1.72473 GB/5.21799 GB at 48.497 MBit/s |
| 06.05.20 16:21 | DEBUG | Loading “DRERYK/s_rawdata_7.20.1.0_20200506T003857.7z”. 39% finished 2.06305 GB/5.21799 GB at 48.4303 MBit/s |
| 06.05.20 16:22 | DEBUG | Loading “DRERYK/s_rawdata_7.20.1.0_20200506T003857.7z”. 45% finished 2.39811 GB/5.21799 GB at 47.9679 MBit/s |
| 06.05.20 16:23 | DEBUG | Loading “DRERYK/s_rawdata_7.20.1.0_20200506T003857.7z”. 52% finished 2.75456 GB/5.21799 GB at 51.0282 MBit/s |
| 06.05.20 16:24 | DEBUG | Loading “DRERYK/s_rawdata_7.20.1.0_20200506T003857.7z”. 59% finished 3.09876 GB/5.21799 GB at 49.2759 MBit/s |
| 06.05.20 16:25 | DEBUG | Loading “DRERYK/s_rawdata_7.20.1.0_20200506T003857.7z”. 66% finished 3.46736 GB/5.21799 GB at 52.7698 MBit/s |
| 06.05.20 16:26 | DEBUG | Loading “DRERYK/s_rawdata_7.20.1.0_20200506T003857.7z”. 73% finished 3.83607 GB/5.21799 GB at 52.7846 MBit/s |
| 06.05.20 16:27 | DEBUG | Loading “DRERYK/s_rawdata_7.20.1.0_20200506T003857.7z”. 80% finished 4.20511 GB/5.21799 GB at 52.8332 MBit/s |
| 06.05.20 16:28 | DEBUG | Loading “DRERYK/s_rawdata_7.20.1.0_20200506T003857.7z”. 87% finished 4.57583 GB/5.21799 GB at 53.0732 MBit/s |
| 06.05.20 16:29 | DEBUG | Loading “DRERYK/s_rawdata_7.20.1.0_20200506T003857.7z”. 94% finished 4.94619 GB/5.21799 GB at 53.0214 MBit/s |
| 06.05.20 16:29 | DEBUG | GT: Loaded file “s_rawdata_7.20.1.0_20200506T003857.7z” |
| 06.05.20 16:29 | DEBUG | Loading file “DRERYK” (metadata only) |
| 06.05.20 16:29 | DEBUG | PT: Hashing file “s_rawdata_7.20.1.0_20200506T003857.7z” |
| 06.05.20 16:29 | INFO | Waiting for file hashing and copying threads… |
| 06.05.20 16:30 | DEBUG | HT: Copying file: “/BACKUP/pdcsrv/200506-1535/DRERYK/s_rawdata_7.20.1.0_20200506T003857.7z” (id=9) |
| 06.05.20 16:30 | DEBUG | HT: Renaming file to “/BACKUP/pdcsrv/200506-1535/DRERYK/s_rawdata_7.20.1.0_20200506T003857.7z” |
| 06.05.20 16:30 | INFO | Waiting for metadata download stream to finish |
| 06.05.20 16:30 | DEBUG | Waiting for metadata download stream to finish (attempt 0, pdcsrv). 10s since last meta-data transfer. Forcefully shutting down after 2m 20s without transfer. |
| 06.05.20 16:30 | DEBUG | Waiting for metadata download stream to finish (attempt 1, pdcsrv). 20s since last meta-data transfer. Forcefully shutting down after 2m 20s without transfer. |
| 06.05.20 16:30 | DEBUG | Waiting for metadata download stream to finish (attempt 2, pdcsrv). 30s since last meta-data transfer. Forcefully shutting down after 2m 20s without transfer. |
| 06.05.20 16:30 | DEBUG | Waiting for metadata download stream to finish (attempt 3, pdcsrv). 40s since last meta-data transfer. Forcefully shutting down after 2m 20s without transfer. |
| 06.05.20 16:30 | DEBUG | Waiting for metadata download stream to finish (attempt 4, pdcsrv). 50s since last meta-data transfer. Forcefully shutting down after 2m 20s without transfer. |
| 06.05.20 16:31 | DEBUG | Waiting for metadata download stream to finish (attempt 5, pdcsrv). 1m since last meta-data transfer. Forcefully shutting down after 2m 20s without transfer. |
| 06.05.20 16:31 | DEBUG | Waiting for metadata download stream to finish (attempt 6, pdcsrv). 1m 10s since last meta-data transfer. Forcefully shutting down after 2m 20s without transfer. |
| 06.05.20 16:31 | DEBUG | Waiting for metadata download stream to finish (attempt 7, pdcsrv). 1m 20s since last meta-data transfer. Forcefully shutting down after 2m 20s without transfer. |
| 06.05.20 16:31 | DEBUG | Waiting for metadata download stream to finish (attempt 8, pdcsrv). 1m 30s since last meta-data transfer. Forcefully shutting down after 2m 20s without transfer. |
| 06.05.20 16:31 | DEBUG | Waiting for metadata download stream to finish (attempt 9, pdcsrv). 1m 40s since last meta-data transfer. Forcefully shutting down after 2m 20s without transfer. |
| 06.05.20 16:31 | DEBUG | Loading "urbackup/FILE_METADATA |
| 06.05.20 16:31 | INFO | Writing new file list… |
| 06.05.20 16:31 | INFO | All metadata was present |
| 06.05.20 16:31 | INFO | Backup verification is enabled. Verifying file backup… |
| 06.05.20 16:35 | DEBUG | Verified 11 files |
| 06.05.20 16:35 | INFO | Backup verification ok |
| 06.05.20 16:35 | DEBUG | Syncing file system… |
| 06.05.20 16:35 | DEBUG | Creating symbolic links. -1 |
| 06.05.20 16:35 | DEBUG | Creating symbolic links. -2 |
| 06.05.20 16:35 | DEBUG | Symbolic links created. |
| 06.05.20 16:35 | INFO | Transferred 6.06977 GB - Average speed: 16.8492 MBit/s |
| 06.05.20 16:35 | DEBUG | Script does not exist urbackup/post_incr_filebackup |
| 06.05.20 16:35 | INFO | Time taken for backing up client pdcsrv: 59m 26s |
| 06.05.20 16:35 | INFO | Backup succeeded |