Backup completes with errors

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…

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

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]

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

Here is the output from the client,

client_tr.txt (3.7 MB)

So I tried a few things ,

I added each directory under /mythtv/photos/

tree -L 1 /mythtv/photos

/mythtv/photos
├── 2012
├── 2013
├── 2014
├── 2015
├── 2016
├── 2017
├── 2018
├── temp
└── to_be_printed
And it worked. Backup successful.

But if I remove all and add only /mythtv/photos it doesn’t … and I get these again,
2018-07-21 22:17:03: Extended attribute list size increased. Retrying…
2018-07-21 22:17:03: Extended attribute list size increased. Retrying…
2018-07-21 22:17:03: Extended attribute list size increased. Retrying…
2018-07-21 22:17:03: Extended attribute list size increased. Retrying…
2018-07-21 22:17:03: Extended attribute list size increased. Retrying…
2018-07-21 22:17:03: Extended attribute list size increased. Retrying…
2018-07-21 22:17:03: Extended attribute list size increased. Retrying…
2018-07-21 22:17:03: Extended attribute list size increased. Retrying…
2018-07-21 22:17:03: Extended attribute list size increased. Retrying…
2018-07-21 22:17:03: Extended attribute list size increased. Retrying…
2018-07-21 22:17:03: Extended attribute list size increased. Retrying…
2018-07-21 22:17:03: Extended attribute list size increased. Retrying…

Changed the mount point to this /mnt/pictures and still the same result.

seeing this the server log,

07/21/18 22:56 DEBUG Loading file “IMG_6414.JPG”
07/21/18 22:56 DEBUG PT: Hashing file “IMG_6413.JPG”
07/21/18 22:56 DEBUG HT: Linked file: “/mnt/backups/server/180721-2232/pictures/2018/06/09/IMG_6413.JPG”
07/21/18 22:56 DEBUG GT: Loaded file “IMG_6414.JPG”
07/21/18 22:56 DEBUG Loading file “IMG_6415.JPG”
07/21/18 22:56 DEBUG PT: Hashing file “IMG_6414.JPG”
07/21/18 22:56 DEBUG HT: Linked file: “/mnt/backups/server/180721-2232/pictures/2018/06/09/IMG_6414.JPG”
07/21/18 22:56 DEBUG GT: Loaded file “IMG_6415.JPG”
07/21/18 22:56 DEBUG Loading file “09” (metadata only)
07/21/18 22:56 DEBUG Loading file “06” (metadata only)
07/21/18 22:56 DEBUG Loading file “2018” (metadata only)
07/21/18 22:56 DEBUG Loading file “temp” (metadata only)
07/21/18 22:56 DEBUG Loading file “to_be_printed” (metadata only)
07/21/18 22:56 DEBUG Loading file “pictures” (metadata only)
07/21/18 22:56 DEBUG PT: Hashing file “IMG_6415.JPG”
07/21/18 22:56 DEBUG HT: Linked file: “/mnt/backups/server/180721-2232/pictures/2018/06/09/IMG_6415.JPG”
07/21/18 22:56 DEBUG Share “pictures” on “server” is still in use (meta-data transfer). Waiting before removing snapshot…
07/21/18 22:56 DEBUG Loading "urbackup/FILE_METADATA
07/21/18 22:58 DEBUG Loading "urbackup/FILE_METADATA
07/21/18 22:59 DEBUG Loading "urbackup/FILE_METADATA

Yeah, the file system/kernel seems to return something unexpected. It probably works with this patch: https://github.com/uroni/urbackup_backend/commit/56b888ae4232d9dbd71ed764f87f58165d235056 Thanks for posting the strace output!

I copied the update in and recompiled on the backend … same issue.

Could you post what the debug log and strace output shows again? Thanks!

This is the last few entries from the client log,
2018-07-23 14:13:56: FileSrv: Mapped name: /mythtv/photos
2018-07-23 14:13:56: FileSrv: Received a Packet.
2018-07-23 14:13:56: Received flush.
2018-07-23 14:13:56: Extended attribute list size increased. Retrying…
2018-07-23 14:13:56: Extended attribute list size increased. Retrying…
2018-07-23 14:13:56: Extended attribute list size increased. Retrying…
2018-07-23 14:13:56: Extended attribute list size increased. Retrying…
2018-07-23 14:13:56: Extended attribute list size increased. Retrying…
2018-07-23 14:13:56: Extended attribute list size increased. Retrying…

2018-07-23 14:13:56: Extended attribute list size increased. Retrying…
2018-07-23 14:13:56: Extended attribute list size increased. Retrying…
2018-07-23 14:13:56: Extended attribute list size increased. Retrying…
2018-07-23 14:13:56: ClientService cmd: #IhvX182WyIyLFIU5MqPVP#STOP SC “photos”#token=c6qDWIhuOfgkpTYnHRPo
2018-07-23 14:13:56: Extended attribute list size increased. Retrying…
2018-07-23 14:13:56: Extended attribute list size increased. Retrying…
2018-07-23 14:13:56: Extended attribute list size increased. Retrying…
2018-07-23 14:13:56: Extended attribute list size increased. Retrying…

client_tr-2.txt.gz (68.3 KB)

It looks the same… Are you sure you applied the patch?

So I copied in this file (attached),

ls -la /urbackup-server-2.2.11-a/fileservplugin/FileMetadataPipe.cpp

-rw-r–r-- 1 root wheel 33485 Jul 22 19:28 /urbackup-server-2.2.11-a/fileservplugin/FileMetadataPipe.cpp

And recompiled and installed. Was there anything else I am missing?

FileMetadataPipe.cpp.gz (204 Bytes)
and installed. Was there anything else I am missing?

Yeah, you need to do this for the client…

I am using the Linux binary,

Any idea when it will be updated with your fix?