From owner-freebsd-fs@FreeBSD.ORG Sat Jul 19 10:01:03 2014 Return-Path: Delivered-To: freebsd-fs@freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [8.8.178.115]) (using TLSv1 with cipher ADH-AES256-SHA (256/256 bits)) (No client certificate requested) by hub.freebsd.org (Postfix) with ESMTPS id A05E57DE for ; Sat, 19 Jul 2014 10:01:03 +0000 (UTC) Received: from smtprelay06.ispgateway.de (smtprelay06.ispgateway.de [80.67.31.102]) (using TLSv1 with cipher DHE-RSA-AES256-SHA (256/256 bits)) (Client did not present a certificate) by mx1.freebsd.org (Postfix) with ESMTPS id 0DE7D2C10 for ; Sat, 19 Jul 2014 10:01:02 +0000 (UTC) Received: from [78.35.154.137] (helo=fabiankeil.de) by smtprelay06.ispgateway.de with esmtpsa (SSLv3:AES128-SHA:128) (Exim 4.68) (envelope-from ) id 1X8RRl-00028t-Bg for freebsd-fs@freebsd.org; Sat, 19 Jul 2014 12:00:53 +0200 Date: Sat, 19 Jul 2014 12:00:55 +0200 From: Fabian Keil To: FreeBSD-fs Subject: zfs receive abort(): internal error: File too large Message-ID: <132a24ce.33d69bdc@fabiankeil.de> MIME-Version: 1.0 Content-Type: multipart/signed; micalg=pgp-sha1; boundary="Sig_/O9WPSDW0WHp2oOZEwz6yLQd"; protocol="application/pgp-signature" X-Df-Sender: Nzc1MDY3 X-BeenThere: freebsd-fs@freebsd.org X-Mailman-Version: 2.1.18 Precedence: list List-Id: Filesystems List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Sat, 19 Jul 2014 10:01:03 -0000 --Sig_/O9WPSDW0WHp2oOZEwz6yLQd Content-Type: text/plain; charset=US-ASCII Content-Transfer-Encoding: quoted-printable 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@r500 ~ $zogftw sync | [...] | receiving incremental stream of tank/usr/local@2014-06-23_22:33 into inte= nso1/backup/r500/tank/usr/local@2014-06-23_22:33 | in @ 29.4 MiB/s, out @ 0.0 KiB/s, 4674 MiB total, buffer 100% fullintern= al error: File too large | mbuffer: error: outputThread: error writing to at offset 0x1241c= 0000: Broken pipe | summary: 4674 MiByte in 3 min 45.9 sec - average of 20.7 MiB/s | mbuffer: warning: error during output to : Broken pipe | fk@r500 ~ $gdb-core zfs.core=20 | [...] | 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=3D6) 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=3D, error=3D, fmt=3D, ap=3D, hdl=3D,=20 | error=3D, fmt=3D, ap=3D) | at /usr/src/cddl/lib/libzfs/../../../cddl/contrib/opensolaris/lib/lib= zfs/common/libzfs_util.c:277 | #4 zfs_standard_error_fmt (hdl=3D, error=3D, fmt=3D) | at /usr/src/cddl/lib/libzfs/../../../cddl/contrib/opensolaris/lib/lib= zfs/common/libzfs_util.c:403 | #5 0x000000080168b485 in zfs_standard_error (hdl=3D0x3022, warning: Unma= pped DWARF Register #-2 encountered. | error=3D,=20 | msg=3D0x8019fa10a "\017\202\214\031") at /usr/src/cddl/li= b/libzfs/../../../cddl/contrib/opensolaris/lib/libzfs/common/libzfs_util.c:= 341 | #6 0x0000000801681b9a in zfs_receive_one (hdl=3D, infd=3D= , tosnap=3D, flags=3D, drr=3D0= x0,=20 | drr_noswap=3D0x0, sendfs=3D, stream_nv=3D, stream_avl=3D, cleanup_fd=3D,=20 | action_handlep=3D, top_zfs=3D) | at /usr/src/cddl/lib/libzfs/../../../cddl/contrib/opensolaris/lib/lib= zfs/common/libzfs_sendrecv.c:3109 | #7 zfs_receive_impl (hdl=3D0x80301a200, tosnap=3D, flags= =3D0x7fffffffde90, infd=3D, sendfs=3D,=20 | stream_nv=3D, stream_avl=3D, top_zfs=3D= , cleanup_fd=3D, action_handlep=3D) | at /usr/src/cddl/lib/libzfs/../../../cddl/contrib/opensolaris/lib/lib= zfs/common/libzfs_sendrecv.c:3275 | #8 0x0000000801681395 in zfs_receive_package (destname=3D= , flags=3D, drr=3D0x0, zc=3D0x3001777c1, top_zfs=3D,=20 | cleanup_fd=3D, action_handlep=3D, hdl= =3D, fd=3D) | at /usr/src/cddl/lib/libzfs/../../../cddl/contrib/opensolaris/lib/lib= zfs/common/libzfs_sendrecv.c:2501 | #9 zfs_receive_impl (hdl=3D0x80301a200, tosnap=3D0x7fffffffeae5 "intenso= 1/backup/r500/tank/usr/local", flags=3D0x7fffffffde90, infd=3D0,=20 | sendfs=3D, stream_nv=3D, stream_avl=3D<= optimized out>, top_zfs=3D, cleanup_fd=3D,=20 | action_handlep=3D) at /usr/src/cddl/lib/libzfs/../../.= ./cddl/contrib/opensolaris/lib/libzfs/common/libzfs_sendrecv.c:3281 | #10 0x000000080167fe71 in zfs_receive (hdl=3D0x80301a200, tosnap=3D0x7fff= ffffeae5 "intenso1/backup/r500/tank/usr/local", flags=3D0x7fffffffde90, inf= d=3D0,=20 | stream_avl=3D0x0) at /usr/src/cddl/lib/libzfs/../../../cddl/contrib/o= pensolaris/lib/libzfs/common/libzfs_sendrecv.c:3304 | #11 0x00000000004099a1 in zfs_do_receive (argc=3D, argv=3D= 0x7fffffffe7a0) | at /usr/src/cddl/sbin/zfs/../../../cddl/contrib/opensolaris/cmd/zfs/z= fs_main.c:3950 | #12 0x000000000040572f in main (argc=3D, argv=3D) | at /usr/src/cddl/sbin/zfs/../../../cddl/contrib/opensolaris/cmd/zfs/z= fs_main.c:6953 | (gdb) f 3 | #3 0x000000080168ba92 in zfs_verror (hdl=3D, error=3D, fmt=3D, ap=3D, hdl=3D,=20 | error=3D, fmt=3D, ap=3D) | at /usr/src/cddl/lib/libzfs/../../../cddl/contrib/opensolaris/lib/lib= zfs/common/libzfs_util.c:277 | 277 abort(); | (gdb) l | 272=09 | 273 if (hdl->libzfs_printerr) { | 274 if (error =3D=3D EZFS_UNKNOWN) { | 275 (void) fprintf(stderr, dgettext(TEXT_DOMAIN, "internal " | 276 "error: %s\n"), libzfs_error_description(hdl)); | 277 abort(); | 278 } | 279=09 | 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= @2014-06-23_22:33 | 1001 4641 3703 mbuffer -m 100M | 0 4642 3703 sudo -c - zfs receive -v -u -F intenso1/backup/r500/ta= nk/usr/local | 0 4643 4640 zfs send -I @2013-12-22_11:27 tank/usr/local@2014-06-2= 3_22:33 | 0 4644 4642 zfs receive -v -u -F intenso1/backup/r500/tank/usr/loc= al 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@r500 ~ $sudo zfs send -I @2013-12-22_11:27 tank/usr/local@2014-06-23_2= 2:33 | zstreamdump | BEGIN record | hdrtype =3D 2 | features =3D 4 | magic =3D 2f5bacbac | creation_time =3D 0 | type =3D 0 | flags =3D 0x0 | toguid =3D 0 | fromguid =3D 0 | toname =3D tank/usr/local@2014-06-23_22:33 | END checksum =3D 2fb1374c0/c59b43b4b2/1a3f6af4955b/262293c445759 | BEGIN record | hdrtype =3D 1 | features =3D 4 | magic =3D 2f5bacbac | creation_time =3D 53a88f1e | type =3D 2 | flags =3D 0x0 | toguid =3D f2e0cfa41ab80745 | fromguid =3D f1f10991be60bd7d | toname =3D tank/usr/local@2014-06-23_22:33 | END checksum =3D 1bdac72d140ea8d1/9e56d965e806168a/ed215fadf1a47e7f/a99aa= 9cca7be2746 | END checksum =3D 0/0/0/0 | SUMMARY: | Total DRR_BEGIN records =3D 2 | Total DRR_END records =3D 3 | Total DRR_OBJECT records =3D 98837 | Total DRR_FREEOBJECTS records =3D 796 | Total DRR_WRITE records =3D 140583 | Total DRR_WRITE_BYREF records =3D 0 | Total DRR_WRITE_EMBEDDED records =3D 0 | Total DRR_FREE records =3D 103847 | Total DRR_SPILL records =3D 0 | Total records =3D 344068 | Total write size =3D 7722947584 (0x1cc52d400) Receiving tank/usr/local@2014-06-23_22:33 non-incrementally works as expected, receiving additional incremental snapshots works too. The zpools: | fk@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: |=20 | NAME STATE READ WRITE CKSUM | intenso1 ONLINE 0 0 0 | label/intenso1.eli ONLINE 0 0 0 |=20 | errors: No known data errors |=20 | 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 20= 14 | config: |=20 | NAME STATE READ WRITE CKSUM | tank ONLINE 0 0 0 | ada0s1d.eli ONLINE 0 0 0 |=20 | errors: No known data errors | fk@r500 ~ $zpool upgrade | This system supports ZFS pool feature flags. |=20 | All pools are formatted using feature flags. |=20 |=20 | 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. |=20 | POOL FEATURE | --------------- | tank | embedded_data =20 | fk@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 --Sig_/O9WPSDW0WHp2oOZEwz6yLQd Content-Type: application/pgp-signature; name=signature.asc Content-Disposition: attachment; filename=signature.asc -----BEGIN PGP SIGNATURE----- Version: GnuPG v2 iEYEARECAAYFAlPKQdYACgkQBYqIVf93VJ1LxACgmtDdAjJ4jw6G0ISUeyD5Xadx rl0AnRn3lE+r0h2K+8HF6uQlnb995fLM =Uie7 -----END PGP SIGNATURE----- --Sig_/O9WPSDW0WHp2oOZEwz6yLQd--