Backup completes with errors


#1

Using latest Linux client and latest freeNas server.

Seeing this in the server log,

Error getting file metadata. Errorcode: CANNOT_OPEN_FILE (3)

Seeing this in the client logs,
2018-07-07 13:49:18: SQLite: recovered 2387 frames from WAL file /usr/local/var/urbackup/backup_client.db-wal code: 283
2018-07-07 13:49:18: urbackupserver: Server started up successfully!
2018-07-07 13:49:18: FileSrv: Binding UDP socket at port 35622…
2018-07-07 13:49:18: FileSrv: done.
2018-07-07 13:49:18: FileSrv: Servername: -server-
2018-07-07 13:49:18: FileSrv: Server started up successfully
2018-07-07 13:49:18: FileSrv: UDP Thread startet
2018-07-07 13:49:18: Started UrBackupClient Backend…
2018-07-07 13:49:19: Looking for old Sessions… 0 sessions
2018-07-07 13:49:19: Internet only mode not enabled. Waiting for local server for 3:00…
2018-07-07 13:49:19: Final path: /home/jproko/zap2xml-HD
2018-07-07 13:49:19: Final path: /home/jproko/.mythtv
2018-07-07 13:49:19: Final path: /mythtv/db_backups
2018-07-07 13:49:19: Final path: /mnt/pictures
2018-07-07 13:49:19: Final path: /var/mythtv/channels
2018-07-07 13:49:25: urbackupserver: No available slots… starting new Worker
2018-07-07 13:49:25: ClientService cmd: #IWjPmy39YqaRH1eIWTjjA#STOP SC “.symlink_channels”#token=c6qDWIhuOfgkpTYnHRPo
2018-07-07 13:49:25: rc=0 hasError=true state=0
2018-07-07 13:49:25: FileSrv: Received data…
2018-07-07 13:49:25: FileSrv: Received a Packet.
2018-07-07 13:49:25: ClientService cmd: #IWjPmy39YqaRH1eIWTjjA#2DID BACKUP status_id=13&server_token=c6qDWIhuOfgkpTYnHRPo&group=0
2018-07-07 13:49:25: rc=0 hasError=true state=0
2018-07-07 13:49:25: FileSrv: Received data…
2018-07-07 13:49:25: FileSrv: Received a Packet.
2018-07-07 13:49:25: FileSrv: Sending script output (normal) urbackup/FILE_METADATA|c6qDWIhuOfgkpTYnHRPo|1039 metadata_id=0
2018-07-07 13:49:25: FileSrv: Mapped name: /usr/local/var/urbackup/data/FILE_METADATA|c6qDWIhuOfgkpTYnHRPo|1039
2018-07-07 13:49:25: FileSrv: Info: Couldn’t open script
2018-07-07 13:49:25: FileSrv: Received data…
2018-07-07 13:49:25: FileSrv: Received a Packet.
2018-07-07 13:49:25: Received flush.
2018-07-07 13:49:26: ClientService cmd: #IWjPmy39YqaRH1eIWTjjA#WRITE TOKENS
2018-07-07 13:49:26: rc=0 hasError=true state=0
2018-07-07 13:49:26: FileSrv: Received data…
2018-07-07 13:49:26: FileSrv: Received a Packet.
2018-07-07 13:49:26: FileSrv: Sending file (normal) urbackup/tokens_c6qDWIhuOfgkpTYnHRPo.properties metadata_id=0
2018-07-07 13:49:26: FileSrv: Mapped name: /usr/local/var/urbackup/data/tokens_c6qDWIhuOfgkpTYnHRPo.properties
2018-07-07 13:49:26: FileSrv: Received data…
2018-07-07 13:49:26: FileSrv: Received a Packet.
2018-07-07 13:49:26: Received flush.
2018-07-07 13:49:26: FileSrv: Recv Error in RecvMessage
2018-07-07 13:49:30: ClientService cmd: #IWjPmy39YqaRH1eIWTjjA#1CHANNEL capa=4096&token=c6qDWIhuOfgkpTYnHRPo&restore_version=1&virtual_client=
2018-07-07 13:49:30: New channel: Number of Channels: 1
2018-07-07 13:49:30: FileSrv: Recv Error in RecvMessage
2018-07-07 13:49:30: ClientService cmd: #IWjPmy39YqaRH1eIWTjjA#2LOGDATA 1530989369 0-1530987577-Starting unscheduled incremental file backup…
0-1530987578-Backing up “zap2xml-HD” without snapshot.
0-1530987578-Following symbolic link at “/home/jproko/zap2xml-HD/icons” to “/var/mythtv/channels” confirms symlink backup target “.symlink_channels” to “/var/mythtv/channels”
0-1530987578-Indexing of “zap2xml-HD” done. 7 filesystem lookups 0 db lookups and 0 db updates
0-1530987578-Backing up “.mythtv” without snapshot.
0-1530987578-Indexing of “.mythtv” done. 50 filesystem lookups 0 db lookups and 0 db updates
0-1530987578-Backing up “db_backups” without snapshot.
0-1530987578-Indexing of “db_backups” done. 1 filesystem lookups 0 db lookups and 0 db updates
0-1530987578-Backing up “pictures” without snapshot.
0-1530987578-Indexing of “pictures” done. 590 filesystem lookups 0 db lookups and 0 db updates
0-1530987578-Backing up “.symlink_channels” without snapshot.
0-1530987578-server: Loading file list…
0-1530987578-server: Calculating file tree differences…
0-1530987578-server: Calculating tree difference size…
0-1530987578-server: Linking unchanged and loading new files…
0-1530987578-Referencing snapshot on “server” for path “zap2xml-HD” failed: FAILED
0-1530987579-Referencing snapshot on “server” for path “.mythtv” failed: FAILED
0-1530987579-Referencing snapshot on “server” for path “db_backups” failed: FAILED
0-1530987579-Referencing snapshot on “server” for path “pictures” failed: FAILED
0-1530989016-Waiting for file transfers…
0-1530989235-Removing snapshot on “server” for path “pictures” failed: TIMEOUT
0-1530989345-Referencing snapshot on “server” for path “.symlink_channels” failed: TIMEOUT
0-1530989365-Waiting for file hashing and copying threads…
2-1530989365-Error getting file metadata. Errorcode: CANNOT_OPEN_FILE (3)
0-1530989366-Writing new file list…
0-1530989366-Transferred 34.1268 GB - Average speed: 164.093 MBit/s
0-1530989369-Time taken for backing up client server: 29m 51s
0-1530989369-Backup completed with issues

And I am seeing a lot of these,
2018-07-07 13:12:15: Extended attribute list size increased. Retrying…


#2

Yeah, the client restartet. That causes the file backup to fail.


#3

okay … ignore the fact that the client restarted. What about the these,

2018-07-08 05:53:11: Extended attribute list size increased. Retrying…
2018-07-08 05:53:11: Extended attribute list size increased. Retrying…
2018-07-08 05:53:11: Extended attribute list size increased. Retrying…
2018-07-08 05:53:11: Extended attribute list size increased. Retrying…
2018-07-08 05:53:11: Extended attribute list size increased. Retrying…
2018-07-08 05:53:11: Extended attribute list size increased. Retrying…
2018-07-08 05:53:11: Extended attribute list size increased. Retrying…
2018-07-08 05:53:11: Extended attribute list size increased. Retrying…
2018-07-08 05:53:11: Extended attribute list size increased. Retrying…
2018-07-08 05:53:11: Extended attribute list size increased. Retrying…
2018-07-08 05:53:11: Extended attribute list size increased. Retrying…
2018-07-08 05:53:11: Extended attribute list size increased. Retrying…
2018-07-08 05:53:11: Extended attribute list size increased. Retrying…
2018-07-08 05:53:11: Extended attribute list size increased. Retrying…
2018-07-08 05:53:11: Extended attribute list size increased. Retrying…
2018-07-08 05:53:11: Extended attribute list size increased. Retrying…
2018-07-08 05:53:11: Extended attribute list size increased. Retrying…
2018-07-08 05:53:11: Extended attribute list size increased. Retrying…
2018-07-08 05:53:11: Extended attribute list size increased. Retrying…
2018-07-08 05:53:11: Extended attribute list size increased. Retrying…
2018-07-08 05:53:11: Extended attribute list size increased. Retrying…
2018-07-08 05:53:11: Extended attribute list size increased. Retrying…
2018-07-08 05:53:11: Extended attribute list size increased. Retrying…
2018-07-08 05:53:11: Extended attribute list size increased. Retrying…
2018-07-08 05:53:11: Extended attribute list size increased. Retrying…
2018-07-08 05:53:11: Extended attribute list size increased. Retrying…
2018-07-08 05:53:11: Extended attribute list size increased. Retrying…
2018-07-08 05:53:11: Extended attribute list size increased. Retrying…
2018-07-08 05:53:11: Extended attribute list size increased. Retrying…
2018-07-08 05:53:11: Extended attribute list size increased. Retrying…
2018-07-08 05:53:11: Extended attribute list size increased. Retrying…
2018-07-08 05:53:11: Extended attribute list size increased. Retrying…
2018-07-08 05:53:11: Extended attribute list size increased. Retrying…
2018-07-08 05:53:11: Extended attribute list size increased. Retrying…
2018-07-08 05:53:11: Extended attribute list size increased. Retrying…
2018-07-08 05:53:11: Extended attribute list size increased. Retrying…

And this from the server,
|07/07/18 21:49 |DEBUG |Loading “urbackup/FILE_METADATA|c6qDWIhuOfgkpTYnHRPo|1040”. Loaded 6.04199 KB at 824 Bit/s|
|—|---|—|
|07/07/18 21:51 |DEBUG |Loading “urbackup/FILE_METADATA|c6qDWIhuOfgkpTYnHRPo|1040”. Loaded 0 bytes at 0 Bit/s|
|07/07/18 21:52 |DEBUG |Loading “urbackup/FILE_METADATA|c6qDWIhuOfgkpTYnHRPo|1040”. Loaded 5.65625 KB at 768 Bit/s|
|07/07/18 21:54 |DEBUG |Loading “urbackup/FILE_METADATA|c6qDWIhuOfgkpTYnHRPo|1040”. Loaded 0 bytes at 32 Bit/s|
|07/07/18 21:55 |DEBUG |Loading “urbackup/FILE_METADATA|c6qDWIhuOfgkpTYnHRPo|1040”. Loaded 2.82812 KB at 384 Bit/s|
|07/07/18 21:57 |DEBUG |Loading “urbackup/FILE_METADATA|c6qDWIhuOfgkpTYnHRPo|1040”. Loaded 0 bytes at 224 Bit/s|
|07/07/18 21:58 |DEBUG |Loading “urbackup/FILE_METADATA|c6qDWIhuOfgkpTYnHRPo|1040”. Loaded 2.82812 KB at 384 Bit/s|
|07/07/18 22:00 |DEBUG |Loading “urbackup/FILE_METADATA|c6qDWIhuOfgkpTYnHRPo|1040”. Loaded 0 bytes at 224 Bit/s|
|07/07/18 22:01 |DEBUG |Loading “urbackup/FILE_METADATA|c6qDWIhuOfgkpTYnHRPo|1040”. Loaded 6.04199 KB at 824 Bit/s|
|07/07/18 22:03 |DEBUG |Loading “urbackup/FILE_METADATA|c6qDWIhuOfgkpTYnHRPo|1040”. Loaded 0 bytes at 0 Bit/s|
|07/07/18 22:04 |DEBUG |Loading “urbackup/FILE_METADATA|c6qDWIhuOfgkpTYnHRPo|1040”. Loaded 2.82812 KB at 384 Bit/s|
|07/07/18 22:06 |ERROR |Error getting file metadata. Errorcode: TIMEOUT (2)|

Showing an ETA to finish in 292487235 years 4 months 2 weeks 1 day 8 hours 9 minutes.

The full back takes no longer than 30 minutes typically.

Also found this in dmesg,
[59001.694628] PipeFile: stdou[16606]: segfault at 0 ip (null) sp 00007f2e3cbd3928 error 14 in urbackupclientbackend[55e9b3a21000+2de000]


#4

Could you attach strace to such a process (With strace -f -p PID) and post a section including llistxattr here?


#5

Here is the output from the client,

client_tr.txt (3.7 MB)