[Linux-cachefs] [PATCH 0/1] Debug oops in cachefiles_prepare_write with NFS netfs conversion on reexport server
David Wysochanski
dwysocha at redhat.com
Mon Oct 31 20:20:53 UTC 2022
On Fri, Sep 23, 2022 at 4:14 PM Dave Wysochanski <dwysocha at redhat.com>
wrote:
>
> Daire this debug patch is for your setup when you have time to test it.
> Also I am not sure if David Howells has a theory as to what is happening
> just from the oops and description below. I will also keep looking a
> bit more at what might be happening.
>
> This patch should help debug the oops seen by Daire's re-export
> server while running tests on some of my NFS fscache netfs conversion
> patches. This is only the first patch but should give at least
> the next clues as to what is happening.
>
> Add this patch on top of my v8 series just posted on Sep 22:
> https://marc.info/?l=linux-nfs&m=166385481714542&w=4
>
> Once built and booted, you should enable ftrace events for netfs,
> cachefiles, and fscache. To start with, use the following comprehensive
> trace events. Note I'm not using trace-cmd because I think you
> mentioned this may not work due to the older userspace on your
> machine. If you use the /proc files you can also control the events:
> echo 1 > /sys/kernel/debug/tracing/events/cachefiles/enable
> echo 1 > /sys/kernel/debug/tracing/events/fscache/enable
> echo 1 > /sys/kernel/debug/tracing/events/netfs/enable
> echo 1 > /sys/kernel/debug/tracing/tracing_on
>
> The above should be the equivalent of:
> trace-cmd start -e netfs:* -e fscache:* -e cachefiles:*
>
> You may need to increase buffer_size_kb:
> cat /sys/kernel/debug/tracing/buffer_size_kb
> 1024
> echo 16384 > /sys/kernel/debug/tracing/buffer_size_kb
> cat /sys/kernel/debug/tracing/buffer_size_kb
> 16384
>
> Then make sure the following is set:
> sysctl kernel.ftrace_dump_on_oops=1
> sysctl kernel.panic_on_oops=1
>
> Then reproduce the problem. My current theory is detailed below, and if
> it's on the mark, I'd expect to see the ftrace event buffer contain a
> line like this:
>
> [ 99.078288] kworker/-140 5..... 27889469us :
cachefiles_prepare_write: object == NULL: c=00000004
>
> Then we can take the cookie value and hopefully discern the history of
> the crash. From the oops, below is my current theory of what is
> happening.
>
Daire has reproduced the problem with this debug patch and is hitting
the above BUG which matches the previous theory of what is happening and
gets us a bit further along.
Per his ftrace we see the suspected BUG:
[29720.158119] kworker/-23613 3..... 9424722090us :
cachefiles_prepare_write: object == NULL: c=00000b95
Back up from there to see if we can determine what happened:
$ grep -B 4000 "object == NULL:" loncloudnfscache5-serial.log | egrep
'(c=00000b95|R=00278174)'
[29690.046137] kworker/-19194 1..... 9424710955us : fscache_cookie:
c=00000b95 - lrudo r=3
[29690.082232] kworker/-19194 1..... 9424710955us : fscache_access:
c=00000b95 UNPIN cache r=3 a=0
[29690.091621] kworker/-19194 1..... 9424710955us : fscache_cookie:
c=00000b95 GQ endac r=4
[29690.261035] kworker/-19194 1..... 9424710957us : fscache_cookie:
c=00000b95 PUT lru r=3
[29690.607434] nfsd-2004 5...1. 9424710960us : fscache_active:
c=00000b95 USE r=3 a=0 c=1
[29692.215455] nfsd-2004 5..... 9424710975us : fscache_access:
c=00000b95 BEGIN io_read r=3 a=1
[29692.405546] kworker/-25371 0..... 9424710975us : fscache_cookie:
c=00000b95 - work r=3
[29692.421426] nfsd-2004 5..... 9424710976us : netfs_read:
R=00278174 READAHEAD c=00000b95 ni=8bb0005 s=0 10000
[29692.488038] kworker/-25371 0..... 9424710976us : cachefiles_ref:
c=00000b95 o=0009b320 u=1 SEE withdraw_cookie
[29692.520323] kworker/-25371 0...1. 9424710976us : cachefiles_ref:
c=00000b95 o=0009b320 u=1 SEE withdrawal
[29692.656826] kworker/-25371 0..... 9424710977us : cachefiles_ref:
c=00000b95 o=0009b320 u=1 SEE clean_commit
[29692.683613] nfsd-2004 5..... 9424710977us : netfs_rreq_ref:
R=00278174 GET SUBREQ r=2
[29692.750300] nfsd-2004 5..... 9424710977us :
cachefiles_prep_read: R=00278174[0] DOWN no-data f=01 s=0 10000
ni=8bb0005 B=5a601b9
[29692.837249] nfsd-2004 5..... 9424710977us : netfs_sreq:
R=00278174[0] DOWN PREP f=01 s=0 0/10000 e=0
[29692.916087] nfsd-2004 5..... 9424710978us : netfs_sreq:
R=00278174[0] DOWN SUBMT f=01 s=0 0/10000 e=0
[29693.315546] kworker/-25371 0..... 9424710983us : cachefiles_ref:
c=00000b95 o=0009b320 u=1 PUT detach
[29693.381768] kworker/-25371 0..... 9424710983us : fscache_cookie:
c=00000b95 PUT obj r=2
[29693.427768] kworker/-25371 0...1. 9424710983us : fscache_cookie:
c=00000b95 - x-lru r=2
[29693.446174] kworker/-25371 0..... 9424710984us : fscache_cookie:
c=00000b95 PQ work r=1
[29720.026557] kworker/-23613 3..... 9424722078us : netfs_sreq:
R=00278174[0] DOWN TERM f=01 s=0 10000/10000 e=0
[29720.037562] kworker/-23613 3..... 9424722078us : netfs_rreq:
R=00278174 RA ASSESS f=22
[29720.061359] kworker/-23613 3..... 9424722079us : netfs_rreq:
R=00278174 RA UNLOCK f=22
[29720.132747] kworker/-23613 3..... 9424722087us : netfs_sreq_ref:
R=00278174[0] PUT TERM r=1
[29720.145155] kworker/-23613 3..... 9424722088us : netfs_rreq:
R=00278174 RA COPY f=02
[29720.158119] kworker/-23613 3..... 9424722090us :
cachefiles_prepare_write: object == NULL: c=00000b95
So nfsd-2004 initiated a read and data was not in the cache, so we had
to get it from NFS:
[29692.683613] nfsd-2004 5..... 9424710977us : netfs_rreq_ref:
R=00278174 GET SUBREQ r=2
[29692.750300] nfsd-2004 5..... 9424710977us :
cachefiles_prep_read: R=00278174[0] DOWN no-data f=01 s=0 10000
ni=8bb0005 B=5a601b9
[29692.837249] nfsd-2004 5..... 9424710977us : netfs_sreq:
R=00278174[0] DOWN PREP f=01 s=0 0/10000 e=0
[29692.916087] nfsd-2004 5..... 9424710978us : netfs_sreq:
R=00278174[0] DOWN SUBMT f=01 s=0 0/10000 e=0
....
When the read completes successfully, we see the UNLOCK and attempt to
copy to the cache but we get the "object == NULL"
[29720.026557] kworker/-23613 3..... 9424722078us : netfs_sreq:
R=00278174[0] DOWN TERM f=01 s=0 10000/10000 e=0
[29720.037562] kworker/-23613 3..... 9424722078us : netfs_rreq:
R=00278174 RA ASSESS f=22
[29720.061359] kworker/-23613 3..... 9424722079us : netfs_rreq:
R=00278174 RA UNLOCK f=22
[29720.132747] kworker/-23613 3..... 9424722087us : netfs_sreq_ref:
R=00278174[0] PUT TERM r=1
[29720.145155] kworker/-23613 3..... 9424722088us : netfs_rreq:
R=00278174 RA COPY f=02
[29720.158119] kworker/-23613 3..... 9424722090us :
cachefiles_prepare_write: object == NULL: c=00000b95
But how did we get the "object == NULL"?
The previous oops analysis indicated that likely the only way this
would happen is if cachefiles_withdraw_cookie()
were called. Sure enough, we do see this in the trace prior to
nfsd-2004 initiating the read:
[29690.607434] nfsd-2004 5...1. 9424710960us : fscache_active:
c=00000b95 USE r=3 a=0 c=1
[29692.215455] nfsd-2004 5..... 9424710975us : fscache_access:
c=00000b95 BEGIN io_read r=3 a=1
[29692.405546] kworker/-25371 0..... 9424710975us : fscache_cookie:
c=00000b95 - work r=3
[29692.421426] nfsd-2004 5..... 9424710976us : netfs_read:
R=00278174 READAHEAD c=00000b95 ni=8bb0005 s=0 10000
[29692.488038] kworker/-25371 0..... 9424710976us : cachefiles_ref:
c=00000b95 o=0009b320 u=1 SEE withdraw_cookie
[29692.520323] kworker/-25371 0...1. 9424710976us : cachefiles_ref:
c=00000b95 o=0009b320 u=1 SEE withdrawal
[29692.656826] kworker/-25371 0..... 9424710977us : cachefiles_ref:
c=00000b95 o=0009b320 u=1 SEE clean_commit
[29692.750300] nfsd-2004 5..... 9424710977us :
cachefiles_prep_read: R=00278174[0] DOWN no-data f=01 s=0 10000
ni=8bb0005 B=5a601b9
[29692.837249] nfsd-2004 5..... 9424710977us : netfs_sreq:
R=00278174[0] DOWN PREP f=01 s=0 0/10000 e=0
[29692.916087] nfsd-2004 5..... 9424710978us : netfs_sreq:
R=00278174[0] DOWN SUBMT f=01 s=0 0/10000 e=0
This looks like a race between kworker/-25371 and nfsd-2004.
NOTE: cachefiles_withdraw_cookie ==
cookie->volume->cache->ops->withdraw_cookie
below.
The cookie had to have gone through the following part of the state machine:
fs/fscache/cookie.c
686 /*
687 * Perform work upon the cookie, such as committing its cache state,
688 * relinquishing it or withdrawing the backing cache. We're protected
from the
689 * cache going away under us as object withdrawal must come through
this
690 * non-reentrant work item.
691 */
692 static void fscache_cookie_state_machine(struct fscache_cookie *cookie)
693 {
694 enum fscache_cookie_state state;
695 bool wake = false;
696
697 _enter("c=%x", cookie->debug_id);
698
699 again:
700 spin_lock(&cookie->lock);
701 again_locked:
702 state = cookie->state;
703 switch (state) {
...
763 case FSCACHE_COOKIE_STATE_LRU_DISCARDING:
764 case FSCACHE_COOKIE_STATE_RELINQUISHING:
765 case FSCACHE_COOKIE_STATE_WITHDRAWING:
766 if (cookie->cache_priv) {
767 spin_unlock(&cookie->lock);
768
cookie->volume->cache->ops->withdraw_cookie(cookie);
769 spin_lock(&cookie->lock);
770 }
771
772 if (test_and_clear_bit(FSCACHE_COOKIE_DO_INVALIDATE,
&cookie->flags))
773 fscache_end_cookie_access(cookie,
fscache_access_invalidate_cookie_end);
774
775 switch (state) {
776 case FSCACHE_COOKIE_STATE_RELINQUISHING:
777 fscache_see_cookie(cookie,
fscache_cookie_see_relinquish);
778 fscache_unhash_cookie(cookie);
779 __fscache_set_cookie_state(cookie,
780
FSCACHE_COOKIE_STATE_DROPPED);
781 wake = true;
782 goto out;
783 case FSCACHE_COOKIE_STATE_LRU_DISCARDING:
784 fscache_see_cookie(cookie,
fscache_cookie_see_lru_discard);
785 break;
786 case FSCACHE_COOKIE_STATE_WITHDRAWING:
787 fscache_see_cookie(cookie,
fscache_cookie_see_withdraw);
788 break;
789 default:
790 BUG();
791 }
792
793 clear_bit(FSCACHE_COOKIE_NEEDS_UPDATE, &cookie->flags);
794 clear_bit(FSCACHE_COOKIE_DO_WITHDRAW, &cookie->flags);
795 clear_bit(FSCACHE_COOKIE_DO_LRU_DISCARD,
&cookie->flags);
796 clear_bit(FSCACHE_COOKIE_DO_PREP_TO_WRITE,
&cookie->flags);
797 set_bit(FSCACHE_COOKIE_NO_DATA_TO_READ,
&cookie->flags);
798 __fscache_set_cookie_state(cookie,
FSCACHE_COOKIE_STATE_QUIESCENT);
799 wake = true;
800 goto again_locked;
801
802 case FSCACHE_COOKIE_STATE_DROPPED:
803 break;
804
805 default:
806 WARN_ONCE(1, "Cookie %x in unexpected state %u\n",
807 cookie->debug_id, state);
808 break;
809 }
There's only 3 possibilities for the cache->state if we've called
withdraw_cookie, but we see this in the ftrace log,
which tells us which one it is:
[29693.315546] kworker/-25371 0..... 9424710983us : cachefiles_ref:
c=00000b95 o=0009b320 u=1 PUT detach
[29693.381768] kworker/-25371 0..... 9424710983us : fscache_cookie:
c=00000b95 PUT obj r=2
[29693.427768] kworker/-25371 0...1. 9424710983us : fscache_cookie:
c=00000b95 - x-lru r=2
[29693.446174] kworker/-25371 0..... 9424710984us : fscache_cookie:
c=00000b95 PQ work r=1
The "x-lru" only happens if state == FSCACHE_COOKIE_STATE_LRU_DISCARDING.
>From the state machine, the only place that happens is if the cookie
is active and someone sets the bit:
729 case FSCACHE_COOKIE_STATE_ACTIVE:
730 if
(test_and_clear_bit(FSCACHE_COOKIE_DO_PREP_TO_WRITE, &cookie->flags)) {
731 spin_unlock(&cookie->lock);
732 fscache_prepare_to_write(cookie);
733 spin_lock(&cookie->lock);
734 }
735 if (test_bit(FSCACHE_COOKIE_DO_LRU_DISCARD,
&cookie->flags)) {
736 __fscache_set_cookie_state(cookie,
737
FSCACHE_COOKIE_STATE_LRU_DISCARDING);
738 wake = true;
739 goto again_locked;
740 }
741 fallthrough;
The only place that happens is here:
848 static void fscache_cookie_lru_do_one(struct fscache_cookie *cookie)
849 {
850 fscache_see_cookie(cookie, fscache_cookie_see_lru_do_one);
851
852 spin_lock(&cookie->lock);
853 if (cookie->state != FSCACHE_COOKIE_STATE_ACTIVE ||
854 time_before(jiffies, cookie->unused_at +
fscache_lru_cookie_timeout) ||
855 atomic_read(&cookie->n_active) > 0) {
856 spin_unlock(&cookie->lock);
857 fscache_stat(&fscache_n_cookies_lru_removed);
858 } else {
859 set_bit(FSCACHE_COOKIE_DO_LRU_DISCARD, &cookie->flags);
860 spin_unlock(&cookie->lock);
861 fscache_stat(&fscache_n_cookies_lru_expired);
862 _debug("lru c=%x", cookie->debug_id);
863 __fscache_withdraw_cookie(cookie);
864 }
865
866 fscache_put_cookie(cookie, fscache_cookie_put_lru);
867 }
The above gets called from:
869 static void fscache_cookie_lru_worker(struct work_struct *work)
870 {
871 struct fscache_cookie *cookie;
872 unsigned long unused_at;
873
874 spin_lock(&fscache_cookie_lru_lock);
875
876 while (!list_empty(&fscache_cookie_lru)) {
877 cookie = list_first_entry(&fscache_cookie_lru,
878 struct fscache_cookie,
commit_link);
879 unused_at = cookie->unused_at +
fscache_lru_cookie_timeout;
880 if (time_before(jiffies, unused_at)) {
881 timer_reduce(&fscache_cookie_lru_timer,
unused_at);
882 break;
883 }
884
885 list_del_init(&cookie->commit_link);
886 fscache_stat_d(&fscache_n_cookies_lru);
887 spin_unlock(&fscache_cookie_lru_lock);
888 fscache_cookie_lru_do_one(cookie);
889 spin_lock(&fscache_cookie_lru_lock);
890 }
891
892 spin_unlock(&fscache_cookie_lru_lock);
893 }
894
895 static void fscache_cookie_lru_timed_out(struct timer_list *timer)
896 {
897 queue_work(fscache_wq, &fscache_cookie_lru_work);
898 }
Somehow it looks like the cookie gets freed via the LRU while another
process
is in the process of using it. Is there some race between use and unuse of
cookies that NFS exposes? Need to take a close look at the
fscache_use_cookie()
and fscache_unuse_cookie() as there seems to be some race possible.
565 /*
566 * Start using the cookie for I/O. This prevents the backing object
from being
567 * reaped by VM pressure.
568 */
569 void __fscache_use_cookie(struct fscache_cookie *cookie, bool
will_modify)
570 {
571 enum fscache_cookie_state state;
572 bool queue = false;
573 int n_active;
574
575 _enter("c=%08x", cookie->debug_id);
576
577 if (WARN(test_bit(FSCACHE_COOKIE_RELINQUISHED, &cookie->flags),
578 "Trying to use relinquished cookie\n"))
579 return;
580
581 spin_lock(&cookie->lock);
582
583 n_active = atomic_inc_return(&cookie->n_active);
584 trace_fscache_active(cookie->debug_id,
refcount_read(&cookie->ref),
585 n_active,
atomic_read(&cookie->n_accesses),
586 will_modify ?
587 fscache_active_use_modify :
fscache_active_use);
588
589 again:
590 state = fscache_cookie_state(cookie);
591 switch (state) {
592 case FSCACHE_COOKIE_STATE_QUIESCENT:
593 queue = fscache_begin_lookup(cookie, will_modify);
594 break;
595
596 case FSCACHE_COOKIE_STATE_LOOKING_UP:
597 case FSCACHE_COOKIE_STATE_CREATING:
598 if (will_modify)
599 set_bit(FSCACHE_COOKIE_LOCAL_WRITE,
&cookie->flags);
600 break;
601 case FSCACHE_COOKIE_STATE_ACTIVE:
602 case FSCACHE_COOKIE_STATE_INVALIDATING:
603 if (will_modify &&
604 !test_and_set_bit(FSCACHE_COOKIE_LOCAL_WRITE,
&cookie->flags)) {
605 set_bit(FSCACHE_COOKIE_DO_PREP_TO_WRITE,
&cookie->flags);
606 queue = true;
607 }
608 break;
609
610 case FSCACHE_COOKIE_STATE_FAILED:
611 case FSCACHE_COOKIE_STATE_WITHDRAWING:
612 break;
613
614 case FSCACHE_COOKIE_STATE_LRU_DISCARDING:
615 spin_unlock(&cookie->lock);
616 wait_var_event(&cookie->state,
617 fscache_cookie_state(cookie) !=
618 FSCACHE_COOKIE_STATE_LRU_DISCARDING);
619 spin_lock(&cookie->lock);
620 goto again;
621
622 case FSCACHE_COOKIE_STATE_DROPPED:
623 case FSCACHE_COOKIE_STATE_RELINQUISHING:
624 WARN(1, "Can't use cookie in state %u\n", state);
625 break;
626 }
627
628 spin_unlock(&cookie->lock);
629 if (queue)
630 fscache_queue_cookie(cookie,
fscache_cookie_get_use_work);
631 _leave("");
632 }
633 EXPORT_SYMBOL(__fscache_use_cookie);
634
635 static void fscache_unuse_cookie_locked(struct fscache_cookie *cookie)
636 {
637 clear_bit(FSCACHE_COOKIE_DISABLED, &cookie->flags);
638 if (!test_bit(FSCACHE_COOKIE_IS_CACHING, &cookie->flags))
639 return;
640
641 cookie->unused_at = jiffies;
642 spin_lock(&fscache_cookie_lru_lock);
643 if (list_empty(&cookie->commit_link)) {
644 fscache_get_cookie(cookie, fscache_cookie_get_lru);
645 fscache_stat(&fscache_n_cookies_lru);
646 }
647 list_move_tail(&cookie->commit_link, &fscache_cookie_lru);
648
649 spin_unlock(&fscache_cookie_lru_lock);
650 timer_reduce(&fscache_cookie_lru_timer,
651 jiffies + fscache_lru_cookie_timeout);
652 }
653
654 /*
655 * Stop using the cookie for I/O.
656 */
657 void __fscache_unuse_cookie(struct fscache_cookie *cookie,
658 const void *aux_data, const loff_t
*object_size)
659 {
660 unsigned int debug_id = cookie->debug_id;
661 unsigned int r = refcount_read(&cookie->ref);
662 unsigned int a = atomic_read(&cookie->n_accesses);
663 unsigned int c;
664
665 if (aux_data || object_size)
666 __fscache_update_cookie(cookie, aux_data, object_size);
667
668 /* Subtract 1 from counter unless that drops it to 0 (ie. it
was 1) */
669 c = atomic_fetch_add_unless(&cookie->n_active, -1, 1);
670 if (c != 1) {
671 trace_fscache_active(debug_id, r, c - 1, a,
fscache_active_unuse);
672 return;
673 }
674
675 spin_lock(&cookie->lock);
676 r = refcount_read(&cookie->ref);
677 a = atomic_read(&cookie->n_accesses);
678 c = atomic_dec_return(&cookie->n_active);
679 trace_fscache_active(debug_id, r, c, a, fscache_active_unuse);
680 if (c == 0)
681 fscache_unuse_cookie_locked(cookie);
682 spin_unlock(&cookie->lock);
683 }
684 EXPORT_SYMBOL(__fscache_unuse_cookie);
On Fri, Sep 23, 2022 at 4:14 PM Dave Wysochanski <dwysocha at redhat.com>
wrote:
> Daire this debug patch is for your setup when you have time to test it.
> Also I am not sure if David Howells has a theory as to what is happening
> just from the oops and description below. I will also keep looking a
> bit more at what might be happening.
>
> This patch should help debug the oops seen by Daire's re-export
> server while running tests on some of my NFS fscache netfs conversion
> patches. This is only the first patch but should give at least
> the next clues as to what is happening.
>
> Add this patch on top of my v8 series just posted on Sep 22:
> https://marc.info/?l=linux-nfs&m=166385481714542&w=4
>
> Once built and booted, you should enable ftrace events for netfs,
> cachefiles, and fscache. To start with, use the following comprehensive
> trace events. Note I'm not using trace-cmd because I think you
> mentioned this may not work due to the older userspace on your
> machine. If you use the /proc files you can also control the events:
> echo 1 > /sys/kernel/debug/tracing/events/cachefiles/enable
> echo 1 > /sys/kernel/debug/tracing/events/fscache/enable
> echo 1 > /sys/kernel/debug/tracing/events/netfs/enable
> echo 1 > /sys/kernel/debug/tracing/tracing_on
>
> The above should be the equivalent of:
> trace-cmd start -e netfs:* -e fscache:* -e cachefiles:*
>
> You may need to increase buffer_size_kb:
> cat /sys/kernel/debug/tracing/buffer_size_kb
> 1024
> echo 16384 > /sys/kernel/debug/tracing/buffer_size_kb
> cat /sys/kernel/debug/tracing/buffer_size_kb
> 16384
>
> Then make sure the following is set:
> sysctl kernel.ftrace_dump_on_oops=1
> sysctl kernel.panic_on_oops=1
>
> Then reproduce the problem. My current theory is detailed below, and if
> it's on the mark, I'd expect to see the ftrace event buffer contain a
> line like this:
>
> [ 99.078288] kworker/-140 5..... 27889469us :
> cachefiles_prepare_write: object == NULL: c=00000004
>
> Then we can take the cookie value and hopefully discern the history of
> the crash. From the oops, below is my current theory of what is
> happening.
>
>
> Summary of oops
> ===============
> Theory from oops decode and struct offsets (crash-utility) is that somehow
> the cachefiles_object * is going to NULL while a write is going in
> progress.
>
> If that is true, then look at how a cachefiles_object * value stored inside
> fscache_cookie.cache_priv could be NULL. There appears to be only one
> possibility, and that is cachefiles_withdraw_cookie() was called despite
> the fact that we are trying to write to the object.
>
>
>
> Details on how cachefiles_object * could be NULL
> ================================================
> [dwysocha at dwysocha kernel]$ grep -n "cache_priv =" fs/cachefiles/*.[ch]
> fs/cachefiles/interface.c:188: cookie->cache_priv = object;
> fs/cachefiles/interface.c:373: cookie->cache_priv = NULL;
> fs/cachefiles/volume.c:80: vcookie->cache_priv = volume;
> fs/cachefiles/volume.c:114: volume->vcookie->cache_priv = NULL;
> [dwysocha at dwysocha kernel]$
>
>
> 346 /*
> 347 * Withdraw caching for a cookie.
> 348 */
> 349 static void cachefiles_withdraw_cookie(struct fscache_cookie *cookie)
> 350 {
> 351 struct cachefiles_object *object = cookie->cache_priv;
> 352 struct cachefiles_cache *cache = object->volume->cache;
> 353 const struct cred *saved_cred;
> 354
> 355 _enter("o=%x", object->debug_id);
> 356 cachefiles_see_object(object,
> cachefiles_obj_see_withdraw_cookie);
> 357
> 358 if (!list_empty(&object->cache_link)) {
> 359 spin_lock(&cache->object_list_lock);
> 360 cachefiles_see_object(object,
> cachefiles_obj_see_withdrawal);
> 361 list_del_init(&object->cache_link);
> 362 spin_unlock(&cache->object_list_lock);
> 363 }
> 364
> 365 cachefiles_ondemand_clean_object(object);
> 366
> 367 if (object->file) {
> 368 cachefiles_begin_secure(cache, &saved_cred);
> 369 cachefiles_clean_up_object(object, cache);
> 370 cachefiles_end_secure(cache, saved_cred);
> 371 }
> 372
> 373 cookie->cache_priv = NULL;
> 374 cachefiles_put_object(object, cachefiles_obj_put_detach);
> 375 }
>
> Since this is not a volume, the above is the only possibility for how
> cookie->cache_prive == NULL, aside from memory corruption, which
> seems unlikely given the predictable nature of the crashes.
>
>
>
> Details on how we conclude cachefiles_object * == NULL
> ======================================================
>
> First, netfs_cache_resources * cannot be null because the caller
> netfs_rreq_do_write_to_cache() does the below to set 'cres' before
> passing 'cres' to cachefiles_prepare_write:
> struct netfs_cache_resources *cres = &rreq->cache_resources;
>
> crash> struct -o netfs_cache_resources.cache_priv
> struct netfs_cache_resources {
> [8] void *cache_priv;
> }
>
> It's possible that 'netfs_cache_resources.cache_priv' value is NULL.
> But that would not explain the offset of 32 into the structure
> for the next dereference - this is not where we panic (we panic
> on a address of 0000000000000008, not 0000000000000032)
>
> crash> struct -o fscache_cookie.cache_priv
> struct fscache_cookie {
> [32] void *cache_priv;
> }
>
> So clearly the above is not NULL. However, the value of
> fscache_cookie.cache_priv
> is possible to be NULL since the offset of 'volume' member is 8. So if the
> cachefiles_object * which is stored inside fscache_cookie.cache_priv ==
> NULL,
> this would explain the crash.
>
> crash> struct -o cachefiles_object.volume
> struct cachefiles_object {
> [8] struct cachefiles_volume *volume;
> }
> crash>
>
>
>
>
> From Daire
>
> 58710.346376] BUG: kernel NULL pointer dereference, address:
> 0000000000000008
> [58710.353508] #PF: supervisor read access in kernel mode
> [58710.358775] #PF: error_code(0x0000) - not-present page
> [58710.364041] PGD 0 P4D 0
> [58710.366721] Oops: 0000 [#1] PREEMPT SMP NOPTI
> [58710.371212] CPU: 12 PID: 9134 Comm: kworker/u129:0 Tainted: G E
> 6.0.0-2.dneg.x86_64 #1
> [58710.380647] Hardware name: Google Google Compute Engine/Google
> Compute Engine, BIOS Google 07/22/2022
> [58710.389995] Workqueue: events_unbound netfs_rreq_write_to_cache_work
> [netfs]
> [58710.397188] RIP: 0010:cachefiles_prepare_write+0x28/0x90 [cachefiles]
>
>
>
> #./scripts/faddr2line --list fs/cachefiles/cachefiles.ko
> cachefiles_prepare_write+0x2
> cachefiles_prepare_write+0x28/0x90:
>
> cachefiles_prepare_write at
>
> /user_data/rpmbuild/BUILD/kernel-ml-6.0.0/linux-6.0.0-2.dneg.x86_64/fs/cachefiles/io.c:587
> 582 static int cachefiles_prepare_write(struct netfs_cache_resources
> *cres,
> 583 loff_t *_start, size_t *_len, loff_t i_size,
> 584 bool no_space_allocated_yet)
> 585 {
> 586 struct cachefiles_object *object = cachefiles_cres_object(cres);
> >587< struct cachefiles_cache *cache = object->volume->cache;
> 588 const struct cred *saved_cred;
> 589 int ret;
> 590
> 591 if (!cachefiles_cres_file(cres)) {
> 592 if (!fscache_wait_for_operation(cres, FSCACHE_WANT_WRITE))
>
> #./scripts/faddr2line --list fs/netfs/netfs.ko
> netfs_rreq_write_to_cache_work+0x11c
> netfs_rreq_write_to_cache_work+0x11c/0x320:
>
> netfs_rreq_do_write_to_cache at
>
> /user_data/rpmbuild/BUILD/kernel-ml-6.0.0/linux-6.0.0-2.dneg.x86_64/fs/netfs/io.c:200
> 195 list_del_init(&next->rreq_link);
> 196 netfs_put_subrequest(next, false,
> 197 netfs_sreq_trace_put_merged);
> 198 }
> 199
> >200< ret = cres->ops->prepare_write(cres, &subreq->start, &subreq->len,
> 201 rreq->i_size, true);
> 202 if (ret < 0) {
> 203 trace_netfs_failure(rreq, subreq, ret, netfs_fail_prepare_write);
> 204 trace_netfs_sreq(subreq, netfs_sreq_trace_write_skip);
> 205 continue;
>
> (inlined by) netfs_rreq_write_to_cache_work at
>
> /user_data/rpmbuild/BUILD/kernel-ml-6.0.0/linux-6.0.0-2.dneg.x86_64/fs/netfs/io.c:229
> 224 static void netfs_rreq_write_to_cache_work(struct work_struct *work)
> 225 {
> 226 struct netfs_io_request *rreq =
> 227 container_of(work, struct netfs_io_request, work);
> 228
> >229< netfs_rreq_do_write_to_cache(rreq);
> 230 }
> 231
> 232 static void netfs_rreq_write_to_cache(struct netfs_io_request *rreq)
> 233 {
> 234 rreq->work.func = netfs_rreq_write_to_cache_work;
>
>
>
>
> 162 /*
> 163 * Perform any outstanding writes to the cache. We inherit a ref from
> the
> 164 * caller.
> 165 */
> 166 static void netfs_rreq_do_write_to_cache(struct netfs_io_request *rreq)
> 167 {
> 168 struct netfs_cache_resources *cres = &rreq->cache_resources;
> <--- THIS CANNOT BE NULL ????
> 169 struct netfs_io_subrequest *subreq, *next, *p;
> 170 struct iov_iter iter;
> 171 int ret;
> 172
> 173 trace_netfs_rreq(rreq, netfs_rreq_trace_copy);
> 174
> 175 /* We don't want terminating writes trying to wake us up
> whilst we're
> 176 * still going through the list.
> 177 */
> 178 atomic_inc(&rreq->nr_copy_ops);
> 179
> 180 list_for_each_entry_safe(subreq, p, &rreq->subrequests,
> rreq_link) {
> 181 if (!test_bit(NETFS_SREQ_COPY_TO_CACHE,
> &subreq->flags)) {
> 182 list_del_init(&subreq->rreq_link);
> 183 netfs_put_subrequest(subreq, false,
> 184
> netfs_sreq_trace_put_no_copy);
> 185 }
> 186 }
> 187
> 188 list_for_each_entry(subreq, &rreq->subrequests, rreq_link) {
> 189 /* Amalgamate adjacent writes */
> 190 while (!list_is_last(&subreq->rreq_link,
> &rreq->subrequests)) {
> 191 next = list_next_entry(subreq, rreq_link);
> 192 if (next->start != subreq->start + subreq->len)
> 193 break;
> 194 subreq->len += next->len;
> 195 list_del_init(&next->rreq_link);
> 196 netfs_put_subrequest(next, false,
> 197
> netfs_sreq_trace_put_merged);
> 198 }
> 199
> 200 ret = cres->ops->prepare_write(cres, &subreq->start,
> &subreq->len, <--- PRESUMABLY WE ARE HERE ???
> 201 rreq->i_size, true);
>
>
>
>
>
>
>
> [58710.346376] BUG: kernel NULL pointer dereference, address:
> 0000000000000008
> [58710.353508] #PF: supervisor read access in kernel mode
> [58710.358775] #PF: error_code(0x0000) - not-present page
> [58710.364041] PGD 0 P4D 0
> [58710.366721] Oops: 0000 [#1] PREEMPT SMP NOPTI
> [58710.371212] CPU: 12 PID: 9134 Comm: kworker/u129:0 Tainted: G
> E 6.0.0-2.dneg.x86_64 #1
> [58710.380647] Hardware name: Google Google Compute Engine/Google
> Compute Engine, BIOS Google 07/22/2022
> [58710.389995] Workqueue: events_unbound netfs_rreq_write_to_cache_work
> [netfs]
> [58710.397188] RIP: 0010:cachefiles_prepare_write+0x28/0x90 [cachefiles]
> [58710.403767] Code: 00 00 0f 1f 44 00 00 41 57 49 89 d7 41 56 41 55
> 41 54 49 89 f4 55 44 89 c5 53 48 8b 47 08 48 89 fb 48 83 7f 10 00 4c
> 8b 70 20 <49> 8b 46 08 4c 8b 28 74 3f 49 8b 7d 50 e8 66 c6 0b cd 48 8b
> 73 10
> [58710.422676] RSP: 0018:ffffb6e12728bde8 EFLAGS: 00010286
> [58710.428031] RAX: ffff93649754b970 RBX: ffff9335925e38f0 RCX:
> 00000000030cb5e8
> [58710.435303] RDX: ffff9335123653e0 RSI: ffff9335123653d8 RDI:
> ffff9335925e38f0
> [58710.442567] RBP: 0000000000000001 R08: 0000000000000001 R09:
> 8080808080808080
> [58710.449833] R10: ffff9335900444f4 R11: 000000000000000f R12:
> ffff9335123653d8
> [58710.457109] R13: ffff9335925e38f0 R14: 0000000000000000 R15:
> ffff9335123653e0
> [58710.464374] FS: 0000000000000000(0000) GS:ffff93733f900000(0000)
> knlGS:0000000000000000
> [58710.472593] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [58710.478480] CR2: 0000000000000008 CR3: 0000004055e56003 CR4:
> 00000000003706e0
> [58710.485767] DR0: 0000000000000000 DR1: 0000000000000000 DR2:
> 0000000000000000
> [58710.493037] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7:
> 0000000000000400
> [58710.500316] Call Trace:
> [58710.502894] <TASK>
> [58710.505126] netfs_rreq_write_to_cache_work+0x11c/0x320 [netfs]
> [58710.511201] process_one_work+0x217/0x3e0
> [58710.515358] worker_thread+0x4a/0x3b0
> [58710.519152] ? process_one_work+0x3e0/0x3e0
> [58710.523467] kthread+0xd6/0x100
> [58710.526740] ? kthread_complete_and_exit+0x20/0x20
> [58710.531659] ret_from_fork+0x1f/0x30
> [58710.535370] </TASK>
> [58710.537702] Modules linked in: rpcsec_gss_krb5(E) tcp_diag(E)
> inet_diag(E) nfsv3(E) nfs(E) cachefiles(E) fscache(E) netfs(E) ext4(E)
> mbcache(E) jbd2(E) intel_rapl_msr(E) intel_rapl_common(E) sg(E)
> nfit(E) libnvdimm(E) i2c_piix4(E) rapl(E) nfsd(E) auth_rpcgss(E)
> sch_fq(E) nfs_acl(E) lockd(E) tcp_bbr(E) grace(E) binfmt_misc(E)
> ip_tables(E) xfs(E) libcrc32c(E) sd_mod(E) t10_pi(E)
> crc64_rocksoft_generic(E) crc64_rocksoft(E) crc64(E) 8021q(E) garp(E)
> mrp(E) stp(E) crct10dif_pclmul(E) llc(E) crc32_pclmul(E)
> crc32c_intel(E) scsi_transport_iscsi(E) ghash_clmulni_intel(E)
> serio_raw(E) virtio_scsi(E) gve(E) sunrpc(E) dm_mirror(E)
> dm_region_hash(E) dm_log(E) dm_mod(E) fuse(E)
> [58710.596756] CR2: 0000000000000008
> [58710.600204] ---[ end trace 0000000000000000 ]---
> [58710.604952] RIP: 0010:cachefiles_prepare_write+0x28/0x90 [cachefiles]
> [58710.611534] Code: 00 00 0f 1f 44 00 00 41 57 49 89 d7 41 56 41 55
> 41 54 49 89 f4 55 44 89 c5 53 48 8b 47 08 48 89 fb 48 83 7f 10 00 4c
> 8b 70 20 <49> 8b 46 08 4c 8b 28 74 3f 49 8b 7d 50 e8 66 c6 0b cd 48 8b
> 73 10
> [58710.630429] RSP: 0018:ffffb6e12728bde8 EFLAGS: 00010286
> [58710.635799] RAX: ffff93649754b970 RBX: ffff9335925e38f0 RCX:
> 00000000030cb5e8
> [58710.643077] RDX: ffff9335123653e0 RSI: ffff9335123653d8 RDI:
> ffff9335925e38f0
> [58710.650342] RBP: 0000000000000001 R08: 0000000000000001 R09:
> 8080808080808080
> [58710.657607] R10: ffff9335900444f4 R11: 000000000000000f R12:
> ffff9335123653d8
> [58710.664872] R13: ffff9335925e38f0 R14: 0000000000000000 R15:
> ffff9335123653e0
> [58710.672142] FS: 0000000000000000(0000) GS:ffff93733f900000(0000)
> knlGS:0000000000000000
> [58710.680362] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [58710.686238] CR2: 0000000000000008 CR3: 0000004055e56003 CR4:
> 00000000003706e0
> [58710.693503] DR0: 0000000000000000 DR1: 0000000000000000 DR2:
> 0000000000000000
> [58710.700767] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7:
> 0000000000000400
> [58710.708031] Kernel panic - not syncing: Fatal exception
> [58710.714064] Kernel Offset: 0xc600000 from 0xffffffff81000000
> (relocation range: 0xffffffff80000000-0xffffffffbfffffff)
> [58710.724898] ---[ end Kernel panic - not syncing: Fatal exception ]---
>
> I think I reported this one (or similar before) but to be honest, I
> have lost track of whether I have only seen it in your branches or I
> have seen it in the vanilla kernel too?
>
> Certainly I have seen it many times over the last few months testing
> various branches.
>
> Daire
>
>
>
>
>
>
> Dave Wysochanski (1):
> Debug1 Daire crash in cachefiles_prepare_write
>
> fs/cachefiles/io.c | 32 +++++++++++++++++++++++++++++---
> 1 file changed, 29 insertions(+), 3 deletions(-)
>
> --
> 2.31.1
>
> --
> Linux-cachefs mailing list
> Linux-cachefs at redhat.com
> https://listman.redhat.com/mailman/listinfo/linux-cachefs
>
>
More information about the Linux-cachefs
mailing list