zfs receive abort(): internal error: File too large

Fabian Keil freebsd-listen at fabiankeil.de
Sat Jul 19 10:01:03 UTC 2014 

Receiving a certain differential snapshot reproducible triggers
an assertion in zfs(8) on my system (currently 11-CURRENT r268660,
but I'll rebuild with HEAD over the weekend):

| fk at r500 ~ $zogftw sync
| [...]
| receiving incremental stream of tank/usr/local at 2014-06-23_22:33 into intenso1/backup/r500/tank/usr/local at 2014-06-23_22:33
| in @ 29.4 MiB/s, out @  0.0 KiB/s, 4674 MiB total, buffer 100% fullinternal error: File too large
| mbuffer: error: outputThread: error writing to <stdout> at offset 0x1241c0000: Broken pipe
| summary: 4674 MiByte in  3 min 45.9 sec - average of 20.7 MiB/s
| mbuffer: warning: error during output to <stdout>: Broken pipe

| fk at r500 ~ $gdb-core zfs.core 
| [...]
| Reading symbols from /sbin/zfs...done.
| [New process 101713]
| [New Thread 803006400 (LWP 101713)]
| Core was generated by `zfs'.
| Program terminated with signal 6, Aborted.
| #0  kill () at kill.S:3
| 3	RSYSCALL(kill)
| (gdb) where
| #0  kill () at kill.S:3
| #1  0x00000008019fa016 in __raise (s=6) at /usr/src/lib/libc/gen/raise.c:45
| #2  0x00000008019f8849 in abort () at /usr/src/lib/libc/stdlib/abort.c:65
| #3  0x000000080168ba92 in zfs_verror (hdl=<optimized out>, error=<optimized out>, fmt=<optimized out>, ap=<optimized out>, hdl=<optimized out>, 
|     error=<optimized out>, fmt=<optimized out>, ap=<optimized out>)
|     at /usr/src/cddl/lib/libzfs/../../../cddl/contrib/opensolaris/lib/libzfs/common/libzfs_util.c:277
| #4  zfs_standard_error_fmt (hdl=<optimized out>, error=<optimized out>, fmt=<optimized out>)
|     at /usr/src/cddl/lib/libzfs/../../../cddl/contrib/opensolaris/lib/libzfs/common/libzfs_util.c:403
| #5  0x000000080168b485 in zfs_standard_error (hdl=0x3022, warning: Unmapped DWARF Register #-2 encountered.
| error=<error reading variable: Unable to access DWARF register number 0xfffffffe>, 
|     msg=0x8019fa10a <getpid+10> "\017\202\214\031") at /usr/src/cddl/lib/libzfs/../../../cddl/contrib/opensolaris/lib/libzfs/common/libzfs_util.c:341
| #6  0x0000000801681b9a in zfs_receive_one (hdl=<optimized out>, infd=<optimized out>, tosnap=<optimized out>, flags=<optimized out>, drr=0x0, 
|     drr_noswap=0x0, sendfs=<optimized out>, stream_nv=<optimized out>, stream_avl=<optimized out>, cleanup_fd=<optimized out>, 
|     action_handlep=<optimized out>, top_zfs=<optimized out>)
|     at /usr/src/cddl/lib/libzfs/../../../cddl/contrib/opensolaris/lib/libzfs/common/libzfs_sendrecv.c:3109
| #7  zfs_receive_impl (hdl=0x80301a200, tosnap=<optimized out>, flags=0x7fffffffde90, infd=<optimized out>, sendfs=<optimized out>, 
|     stream_nv=<optimized out>, stream_avl=<optimized out>, top_zfs=<optimized out>, cleanup_fd=<optimized out>, action_handlep=<optimized out>)
|     at /usr/src/cddl/lib/libzfs/../../../cddl/contrib/opensolaris/lib/libzfs/common/libzfs_sendrecv.c:3275
| #8  0x0000000801681395 in zfs_receive_package (destname=<optimized out>, flags=<optimized out>, drr=0x0, zc=0x3001777c1, top_zfs=<optimized out>, 
|     cleanup_fd=<optimized out>, action_handlep=<optimized out>, hdl=<optimized out>, fd=<optimized out>)
|     at /usr/src/cddl/lib/libzfs/../../../cddl/contrib/opensolaris/lib/libzfs/common/libzfs_sendrecv.c:2501
| #9  zfs_receive_impl (hdl=0x80301a200, tosnap=0x7fffffffeae5 "intenso1/backup/r500/tank/usr/local", flags=0x7fffffffde90, infd=0, 
|     sendfs=<optimized out>, stream_nv=<optimized out>, stream_avl=<optimized out>, top_zfs=<optimized out>, cleanup_fd=<optimized out>, 
|     action_handlep=<optimized out>) at /usr/src/cddl/lib/libzfs/../../../cddl/contrib/opensolaris/lib/libzfs/common/libzfs_sendrecv.c:3281
| #10 0x000000080167fe71 in zfs_receive (hdl=0x80301a200, tosnap=0x7fffffffeae5 "intenso1/backup/r500/tank/usr/local", flags=0x7fffffffde90, infd=0, 
|     stream_avl=0x0) at /usr/src/cddl/lib/libzfs/../../../cddl/contrib/opensolaris/lib/libzfs/common/libzfs_sendrecv.c:3304
| #11 0x00000000004099a1 in zfs_do_receive (argc=<optimized out>, argv=0x7fffffffe7a0)
|     at /usr/src/cddl/sbin/zfs/../../../cddl/contrib/opensolaris/cmd/zfs/zfs_main.c:3950
| #12 0x000000000040572f in main (argc=<optimized out>, argv=<optimized out>)
|     at /usr/src/cddl/sbin/zfs/../../../cddl/contrib/opensolaris/cmd/zfs/zfs_main.c:6953
| (gdb) f 3
| #3  0x000000080168ba92 in zfs_verror (hdl=<optimized out>, error=<optimized out>, fmt=<optimized out>, ap=<optimized out>, hdl=<optimized out>, 
|     error=<optimized out>, fmt=<optimized out>, ap=<optimized out>)
|     at /usr/src/cddl/lib/libzfs/../../../cddl/contrib/opensolaris/lib/libzfs/common/libzfs_util.c:277
| 277				abort();
| (gdb) l
| 272	
| 273		if (hdl->libzfs_printerr) {
| 274			if (error == EZFS_UNKNOWN) {
| 275				(void) fprintf(stderr, dgettext(TEXT_DOMAIN, "internal "
| 276				    "error: %s\n"), libzfs_error_description(hdl));
| 277				abort();
| 278			}
| 279	
| 280			(void) fprintf(stderr, "%s: %s\n", hdl->libzfs_action,
| 281			    libzfs_error_description(hdl));

What zogftw does is:

|    0   4640   3703 sudo -c - zfs send -I @2013-12-22_11:27 tank/usr/local at 2014-06-23_22:33
| 1001   4641   3703 mbuffer -m 100M
|    0   4642   3703 sudo -c - zfs receive -v -u -F intenso1/backup/r500/tank/usr/local
|    0   4643   4640 zfs send -I @2013-12-22_11:27 tank/usr/local at 2014-06-23_22:33
|    0   4644   4642 zfs receive -v -u -F intenso1/backup/r500/tank/usr/local

It happens when receiving to other pools as well,
mbuffer always gets to 67.1 MiB.

zstreamdump doesn't seem to consider the stream objectionable:

| fk at r500 ~ $sudo zfs send -I @2013-12-22_11:27 tank/usr/local at 2014-06-23_22:33 | zstreamdump
| BEGIN record
| 	hdrtype = 2
| 	features = 4
| 	magic = 2f5bacbac
| 	creation_time = 0
| 	type = 0
| 	flags = 0x0
| 	toguid = 0
| 	fromguid = 0
| 	toname = tank/usr/local at 2014-06-23_22:33
| END checksum = 2fb1374c0/c59b43b4b2/1a3f6af4955b/262293c445759
| BEGIN record
| 	hdrtype = 1
| 	features = 4
| 	magic = 2f5bacbac
| 	creation_time = 53a88f1e
| 	type = 2
| 	flags = 0x0
| 	toguid = f2e0cfa41ab80745
| 	fromguid = f1f10991be60bd7d
| 	toname = tank/usr/local at 2014-06-23_22:33
| END checksum = 1bdac72d140ea8d1/9e56d965e806168a/ed215fadf1a47e7f/a99aa9cca7be2746
| END checksum = 0/0/0/0
| SUMMARY:
| 	Total DRR_BEGIN records = 2
| 	Total DRR_END records = 3
| 	Total DRR_OBJECT records = 98837
| 	Total DRR_FREEOBJECTS records = 796
| 	Total DRR_WRITE records = 140583
| 	Total DRR_WRITE_BYREF records = 0
| 	Total DRR_WRITE_EMBEDDED records = 0
| 	Total DRR_FREE records = 103847
| 	Total DRR_SPILL records = 0
| 	Total records = 344068
| 	Total write size = 7722947584 (0x1cc52d400)

Receiving tank/usr/local at 2014-06-23_22:33 non-incrementally works
as expected, receiving additional incremental snapshots works too.

The zpools:

| fk at r500 ~ $zpool status
|   pool: intenso1
|  state: ONLINE
|   scan: scrub repaired 0 in 0h8m with 0 errors on Fri Jul 18 17:42:59 2014
| config:
| 
| 	NAME                  STATE     READ WRITE CKSUM
| 	intenso1              ONLINE       0     0     0
| 	  label/intenso1.eli  ONLINE       0     0     0
| 
| errors: No known data errors
| 
|   pool: tank
|  state: ONLINE
| status: Some supported features are not enabled on the pool. The pool can
| 	still be used, but some features are unavailable.
| action: Enable all features using 'zpool upgrade'. Once this is done,
| 	the pool may no longer be accessible by software that does not support
| 	the features. See zpool-features(7) for details.
|   scan: scrub repaired 0 in 4h11m with 0 errors on Sat Mar 22 18:25:01 2014
| config:
| 
| 	NAME           STATE     READ WRITE CKSUM
| 	tank           ONLINE       0     0     0
| 	  ada0s1d.eli  ONLINE       0     0     0
| 
| errors: No known data errors

| fk at r500 ~ $zpool upgrade
| This system supports ZFS pool feature flags.
| 
| All pools are formatted using feature flags.
| 
| 
| Some supported features are not enabled on the following pools. Once a
| feature is enabled the pool may become incompatible with software
| that does not support the feature. See zpool-features(7) for details.
| 
| POOL  FEATURE
| ---------------
| tank
|       embedded_data
 
| fk at r500 ~ $zpool list
| NAME       SIZE  ALLOC   FREE    CAP  DEDUP  HEALTH  ALTROOT
| intenso1  2.72T  13.3G  2.71T     0%  1.00x  ONLINE  -
| tank       228G   193G  35.2G    84%  1.00x  ONLINE  -

According to my logs, I first saw the problem with r267067
(using a different receiving pool), but as the dataset hasn't
been zfs-sent for about 6 months, the problem could be quite
a bit older.

Fabian
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 181 bytes
Desc: not available
URL: <http://lists.freebsd.org/pipermail/freebsd-fs/attachments/20140719/354e947c/attachment.sig>

More information about the freebsd-fs mailing list