[More details for a sshd failure. The other examples are omitted. The sshd failure also shows a all-zeros-up-to-a-page-boundary issue, just for a different address range.] On 2020-May-7, at 12:06, Mark Millard <marklmi_at_yahoo.com> wrote: > > [mountd failure example: also at sz_size2index_lookup assert > for the same zero'd memory problem.] > >> On 2020-May-7, at 00:46, Mark Millard <marklmi_at_yahoo.com> wrote: >> >> [__je_sz_size2index_tab seems messed up in 2 of the >> asserting contexts: first 384 are zero in both. More >> before that is also messed up (all zero). I show the >> details later below.] >> >> On 2020-May-6, at 16:57, Mark Millard <marklmi at yahoo.com> wrote: >> >>> [This explores process crashes that happen during system >>> shutdown, in a context not having MALLOC_PRODUCTION= . >>> So assert failures are reported as the stopping points.] >>> >>> It looks like shutdown -p now, shutdown -r now, and the >>> like can lead some processes to assert during their exit >>> attempt, including a sshd failure (that I've not seen >>> before), rpcbind, and nfsd. I show information about the >>> observed asserts for those below. >>> >>> >>> sshd hit an assert, failing slab == extent_slab_get(extent) : >>> >>> (gdb) bt >>> #0 thr_kill () at thr_kill.S:4 >>> #1 0x50927170 in __raise (s=6) at /usr/src/lib/libc/gen/raise.c:52 >>> #2 0x50886cc0 in abort () at /usr/src/lib/libc/stdlib/abort.c:67 >>> #3 0x508834b0 in arena_dalloc (tsdn=<optimized out>, ptr=<optimized out>, tcache=<optimized out>, alloc_ctx=<optimized out>, slow_path=<optimized out>) >>> at /usr/src/contrib/jemalloc/include/jemalloc/internal/arena_inlines_b.h:315 >>> #4 idalloctm (tsdn=0x500dd040, ptr=0x5008a180, tcache=0x500dd160, alloc_ctx=<optimized out>, is_internal=<optimized out>, slow_path=<optimized out>) >>> at /usr/src/contrib/jemalloc/include/jemalloc/internal/jemalloc_internal_inlines_c.h:118 >>> #5 0x5087b0a4 in ifree (tsd=0x500dd040, ptr=0x5008a180, tcache=0x500dd160, slow_path=<optimized out>) at jemalloc_jemalloc.c:2590 >>> #6 0x5087acac in __je_free_default (ptr=0x5008a180) at jemalloc_jemalloc.c:2784 >>> #7 0x5087b294 in __free (ptr=0x5008a180) at jemalloc_jemalloc.c:2852 >>> #8 0x10029464 in server_accept_loop (config_s=<optimized out>, sock_in=<optimized out>, sock_out=<optimized out>, newsock=<optimized out>) at /usr/src/crypto/openssh/sshd.c:1185 >>> #9 main (ac=<optimized out>, av=0xffffde3c) at /usr/src/crypto/openssh/sshd.c:2009 >>> >>> . . . >>> (gdb) up >>> #2 0x50886cc0 in abort () at /usr/src/lib/libc/stdlib/abort.c:67 >>> 67 (void)raise(SIGABRT); >>> (gdb) up >>> #3 0x508834b0 in arena_dalloc (tsdn=<optimized out>, ptr=<optimized out>, tcache=<optimized out>, alloc_ctx=<optimized out>, slow_path=<optimized out>) >>> at /usr/src/contrib/jemalloc/include/jemalloc/internal/arena_inlines_b.h:315 >>> 315 assert(slab == extent_slab_get(extent)); >>> >>> (gdb) list >>> 310 rtree_ctx = tsd_rtree_ctx(tsdn_tsd(tsdn)); >>> 311 extent_t *extent = rtree_extent_read(tsdn, &extents_rtree, >>> 312 rtree_ctx, (uintptr_t)ptr, true); >>> 313 assert(szind == extent_szind_get(extent)); >>> 314 assert(szind < SC_NSIZES); >>> 315 assert(slab == extent_slab_get(extent)); >>> 316 } >>> 317 >>> 318 if (likely(slab)) { >>> 319 /* Small allocation. */ >>> >>> More fully: >>> >>> 285 JEMALLOC_ALWAYS_INLINE void >>> 286 arena_dalloc(tsdn_t *tsdn, void *ptr, tcache_t *tcache, >>> 287 alloc_ctx_t *alloc_ctx, bool slow_path) { >>> 288 assert(!tsdn_null(tsdn) || tcache == NULL); >>> 289 assert(ptr != NULL); >>> 290 >>> 291 if (unlikely(tcache == NULL)) { >>> 292 arena_dalloc_no_tcache(tsdn, ptr); >>> 293 return; >>> 294 } >>> 295 >>> 296 szind_t szind; >>> 297 bool slab; >>> 298 rtree_ctx_t *rtree_ctx; >>> 299 if (alloc_ctx != NULL) { >>> 300 szind = alloc_ctx->szind; >>> 301 slab = alloc_ctx->slab; >>> 302 assert(szind != SC_NSIZES); >>> 303 } else { >>> 304 rtree_ctx = tsd_rtree_ctx(tsdn_tsd(tsdn)); >>> 305 rtree_szind_slab_read(tsdn, &extents_rtree, rtree_ctx, >>> 306 (uintptr_t)ptr, true, &szind, &slab); >>> 307 } >>> 308 >>> 309 if (config_debug) { >>> 310 rtree_ctx = tsd_rtree_ctx(tsdn_tsd(tsdn)); >>> 311 extent_t *extent = rtree_extent_read(tsdn, &extents_rtree, >>> 312 rtree_ctx, (uintptr_t)ptr, true); >>> 313 assert(szind == extent_szind_get(extent)); >>> 314 assert(szind < SC_NSIZES); >>> 315 assert(slab == extent_slab_get(extent)); >>> 316 } >>> 317 >>> 318 if (likely(slab)) { >>> 319 /* Small allocation. */ >>> 320 tcache_dalloc_small(tsdn_tsd(tsdn), tcache, ptr, szind, >>> 321 slow_path); >>> 322 } else { >>> 323 arena_dalloc_large(tsdn, ptr, tcache, szind, slow_path); >>> 324 } >>> 325 } >> >> . . . The machine code for: 309 if (config_debug) { 310 rtree_ctx = tsd_rtree_ctx(tsdn_tsd(tsdn)); 311 extent_t *extent = rtree_extent_read(tsdn, &extents_rtree, 312 rtree_ctx, (uintptr_t)ptr, true); 313 assert(szind == extent_szind_get(extent)); 314 assert(szind < SC_NSIZES); 315 assert(slab == extent_slab_get(extent)); 316 } was dropping the address in "extent" the next instruction after finding it: replacing with with a field's value. So by the time the status of the assert could be known, examining extent was a difficulty. So I touched the source code to force the address to be kept and to give a place to breakpoint on failure before calling another routine: # svnlite diff /usr/src/contrib/jemalloc/include/jemalloc/internal/arena_inlines_b.h Index: /usr/src/contrib/jemalloc/include/jemalloc/internal/arena_inlines_b.h =================================================================== --- /usr/src/contrib/jemalloc/include/jemalloc/internal/arena_inlines_b.h (revision 360322) +++ /usr/src/contrib/jemalloc/include/jemalloc/internal/arena_inlines_b.h (working copy) _at__at_ -308,11 +308,11 _at__at_ if (config_debug) { rtree_ctx = tsd_rtree_ctx(tsdn_tsd(tsdn)); - extent_t *extent = rtree_extent_read(tsdn, &extents_rtree, + extent_t * volatile extent = rtree_extent_read(tsdn, &extents_rtree, rtree_ctx, (uintptr_t)ptr, true); assert(szind == extent_szind_get(extent)); assert(szind < SC_NSIZES); - assert(slab == extent_slab_get(extent)); + assert((slab == extent_slab_get(extent)) ?true :extent==NULL); } if (likely(slab)) { The ":extent==NULL" should be guaranteed to produce :false as a result but with more code involved to get there. It gave me a place to breakpoint on failure. (gdb) bt -full #0 0x50883258 in arena_dalloc (tsdn=<optimized out>, ptr=<optimized out>, tcache=<optimized out>, alloc_ctx=<optimized out>, slow_path=<optimized out>) at /usr/src/contrib/jemalloc/include/jemalloc/internal/arena_inlines_b.h:315 extent = 0x51007fc0 slab = <optimized out> szind = <optimized out> rtree_ctx = 0x500dd06c extent = <optimized out> #1 idalloctm (tsdn=0x500dd040, ptr=0x5008a180, tcache=0x500dd160, alloc_ctx=<optimized out>, is_internal=<optimized out>, slow_path=<optimized out>) at /usr/src/contrib/jemalloc/include/jemalloc/internal/jemalloc_internal_inlines_c.h:118 No locals. #2 0x5087b0e4 in ifree (tsd=0x500dd040, ptr=0x5008a180, tcache=0x500dd160, slow_path=<optimized out>) at jemalloc_jemalloc.c:2590 alloc_ctx = {szind = 0, slab = true} rtree_ctx = <optimized out> usize = <optimized out> #3 0x5087acec in __je_free_default (ptr=0x5008a180) at jemalloc_jemalloc.c:2784 tcache = 0x500dd160 tsd = <optimized out> #4 0x5087b2d4 in __free (ptr=0x5008a180) at jemalloc_jemalloc.c:2852 log_var = <optimized out> log_var = <optimized out> #5 0x10029464 in server_accept_loop (config_s=<optimized out>, sock_in=<optimized out>, sock_out=<optimized out>, newsock=<optimized out>) at /usr/src/crypto/openssh/sshd.c:1185 from = {ss_len = 16 '\020', ss_family = 2 '\002', __ss_pad1 = "\317\200\300\250\001\031", __ss_align = 0, __ss_pad2 = "\000\000\000\000\000\000\000\002Am", '\000' <repeats 19 times>, "\065\341I\000\000\000\000^\264\234\331", '\000' <repeats 12 times>, "^\262\027\034-a\241H\000\000\000\000\000\000\000\000^\264\235Y,\024\247\030\000\000\000\000\000\000\000\000V\312\331f6-N\370\000\000\000\000\000\000\000\000\000\000\002\000\000\000\000\000\000\000\000\b"} rnd = '\000' <repeats 255 times> startup_p = {6, 7} startups = 1 i = <optimized out> maxfd = 6 fdset = <optimized out> fromlen = <optimized out> ret = <optimized out> j = <optimized out> pid = <optimized out> laddr = <optimized out> raddr = <optimized out> #6 main (ac=<optimized out>, av=0xffffde3c) at /usr/src/crypto/openssh/sshd.c:2009 config_s = {8, 9} on = 1 ssh = 0x0 logfile = <optimized out> newsock = -1 sock_out = -1 sock_in = -1 connection_info = <optimized out> i = <optimized out> opt = <optimized out> line = <optimized out> r = <optimized out> key = <optimized out> pubkey = <optimized out> keytype = <optimized out> fp = <optimized out> j = <optimized out> new_umask = <optimized out> already_daemon = <optimized out> remote_port = <optimized out> remote_ip = <optimized out> rdomain = <optimized out> --Type <RET> for more, q to quit, c to continue without paging-- laddr = <optimized out> authctxt = <optimized out> obytes = <optimized out> ibytes = <optimized out> (gdb) list 310 rtree_ctx = tsd_rtree_ctx(tsdn_tsd(tsdn)); 311 extent_t * volatile extent = rtree_extent_read(tsdn, &extents_rtree, 312 rtree_ctx, (uintptr_t)ptr, true); 313 assert(szind == extent_szind_get(extent)); 314 assert(szind < SC_NSIZES); 315 assert((slab == extent_slab_get(extent)) ?true :extent==NULL); 316 } 317 318 if (likely(slab)) { 319 /* Small allocation. */ (gdb) print/x extent $6 = 0x51007fc0 (gdb) print/x *extent $2 = {e_bits = 0x0, e_addr = 0x0, {e_size_esn = 0x0, e_bsize = 0x0}, ql_link = {qre_next = 0x0, qre_prev = 0x0}, ph_link = {phn_prev = 0x0, phn_next = 0x0, phn_lchild = 0x0}, {e_slab_data = { bitmap = {0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0xffffffff, 0xffffffff, 0xffffffff, 0xffffffff, 0xffffffff, 0xffffffff, 0xffffffff, 0xffffffff, 0xffffffff, 0xffffffff, 0xfff8}}, {e_alloc_time = { ns = 0x0}, e_prof_tctx = {repr = 0x0}}}} It looks like the prefix of the above has been stomped on to be zeros. Checking addresses as well: (gdb) x/64x extent 0x51007fc0: 0x00000000 0x00000000 0x00000000 0x00000000 0x51007fd0: 0x00000000 0x00000000 0x00000000 0x00000000 0x51007fe0: 0x00000000 0x00000000 0x00000000 0x00000000 0x51007ff0: 0x00000000 0x00000000 0x00000000 0x00000000 0x51008000: 0xffffffff 0xffffffff 0xffffffff 0xffffffff 0x51008010: 0xffffffff 0xffffffff 0xffffffff 0xffffffff 0x51008020: 0xffffffff 0xffffffff 0x0000fff8 0x00000000 0x51008030: 0x00000000 0x00000000 0x00000000 0x00000000 0x51008040: 0x00000800 0x0014f000 0x5008b000 0x00005000 0x51008050: 0x51008040 0x51008040 0x00000000 0x00000000 0x51008060: 0x00000000 0x00000000 0x00000000 0x00000000 0x51008070: 0x00000000 0x00000000 0x00000000 0x00000000 0x51008080: 0x00000000 0x00000000 0x00000000 0x00000000 0x51008090: 0x00000000 0x00000000 0x00000000 0x00000000 0x510080a0: 0x00000000 0x00000000 0x00000000 0x00000000 0x510080b0: 0x00000000 0x00000000 0x00000000 0x00000000 Note that the non-zero values start at: 0x51008000, again a page boundary, like the other examples in prior notes for other cases. This appears to be another example of memory having been stomped on/replaced that likely previously had the intended values. The first prior non-zero values are at: 0x51005a30: 0x00000000 0x51008740 0x0000000f 0x01000000 0x51005a40: 0x51008740 0x0000000f 0x01000000 0x51008740 0x51005a50: 0x0000000f 0x01000000 0x51008740 0x0000000f 0x51005a60: 0x01000000 0x51008740 0x0000000f 0x01000000 0x51005a70: 0x51008740 0x0000000f 0x01000000 0x51008740 0x51005a80: 0x0000000f 0x01000000 0x51008940 0x00000014 0x51005a90: 0x01000000 0x510089c0 0x00000014 0x01000000 0x51005aa0: 0x51008a40 0x00000018 0x01000000 0x51008ac0 0x51005ab0: 0x00000018 0x01000000 0x51008b40 0x00000018 0x51005ac0: 0x01000000 0x51008bc0 0x00000018 0x01000000 0x51005ad0: 0x51008c40 0x00000018 0x01000000 0x51008cc0 0x51005ae0: 0x00000001 0x01000000 0x00000000 0x00000000 So the pages for address ranges 0x51006yyy and 0x51007yyy seem to be all-zero, along with the tail of the page for the range 0x51005yyy. #2 (ifree) in the backtrace shows the alloc_ctx content: alloc_ctx = {szind = 0, slab = true} So slab==true but the bit in extent->e_bits==false, leading to the failed assert. Before going to sleep for the night, I could ssh into the old PowerMac without this detection. After getting up, trying the same got the failure detection. I did not have the machine doing anything else special between. The other examples in the other programs are similar: just waiting long enough with normal background processing going on eventually leads to the context for the next explicit use (or exit) to detect the problem. I'm still no where near identifying when the stomped-on memory range is trashed with zeros in code terms in any example program. But sshd, dhclient, rpcbind, nfsd, and sendmail all seem to have some common subject area(s) involved in their implementation. So I suspect something common across those is essentially involved. For reference: In #0: (gdb) print/x rtree_ctx $5 = 0x500dd06c (gdb) print/x *rtree_ctx $4 = {cache = {{leafkey = 0x50000000, leaf = 0x51004fc0}, {leafkey = 0x1, leaf = 0x0}, {leafkey = 0x1, leaf = 0x0}, {leafkey = 0x50c00000, leaf = 0x51008dc0}, {leafkey = 0x1, leaf = 0x0} <repeats 12 times>}, l2_cache = {{leafkey = 0x1, leaf = 0x0}, {leafkey = 0x1, leaf = 0x0}, {leafkey = 0x1, leaf = 0x0}, {leafkey = 0x1, leaf = 0x0}, {leafkey = 0x1, leaf = 0x0}, { leafkey = 0x1, leaf = 0x0}, {leafkey = 0x1, leaf = 0x0}, {leafkey = 0x1, leaf = 0x0}}} === Mark Millard marklmi at yahoo.com ( dsl-only.net went away in early 2018-Mar)Received on Fri May 08 2020 - 14:14:34 UTC
This archive was generated by hypermail 2.4.0 : Wed May 19 2021 - 11:41:23 UTC