Re: [syzbot] WARNING: bad unlock balance in rxrpc_do_sendmsg

[syzbot <syzbot+7f0483225d0c94cb3441@syzkaller.appspotmail.com>]

Hello,

syzbot tried to test the proposed patch but the build/boot failed:

: BNEP filters: protocol multicast
[   11.858163][    T1] Bluetooth: BNEP socket layer initialized
[   11.864007][    T1] Bluetooth: CMTP (CAPI Emulation) ver 1.0
[   11.870006][    T1] Bluetooth: CMTP socket layer initialized
[   11.876108][    T1] Bluetooth: HIDP (Human Interface Emulation) ver 1.2
[   11.883027][    T1] Bluetooth: HIDP socket layer initialized
[   11.892802][    T1] NET: Registered PF_RXRPC protocol family
[   11.898816][    T1] Key type rxrpc registered
[   11.903368][    T1] Key type rxrpc_s registered
[   11.909035][    T1] NET: Registered PF_KCM protocol family
[   11.915665][    T1] lec:lane_module_init: lec.c: initialized
[   11.921574][    T1] mpoa:atm_mpoa_init: mpc.c: initialized
[   11.928018][    T1] l2tp_core: L2TP core driver, V2.0
[   11.933453][    T1] l2tp_ppp: PPPoL2TP kernel driver, V2.0
[   11.939099][    T1] l2tp_ip: L2TP IP encapsulation support (L2TPv3)
[   11.945982][    T1] l2tp_netlink: L2TP netlink interface
[   11.951559][    T1] l2tp_eth: L2TP ethernet pseudowire support (L2TPv3)
[   11.958477][    T1] l2tp_ip6: L2TP IP encapsulation support for IPv6 (L2TPv3)
[   11.966178][    T1] NET: Registered PF_PHONET protocol family
[   11.972631][    T1] 8021q: 802.1Q VLAN Support v1.8
[   11.987664][    T1] DCCP: Activated CCID 2 (TCP-like)
[   11.993261][    T1] DCCP: Activated CCID 3 (TCP-Friendly Rate Control)
[   12.000884][    T1] sctp: Hash tables configured (bind 32/56)
[   12.009112][    T1] NET: Registered PF_RDS protocol family
[   12.015798][    T1] Registered RDS/infiniband transport
[   12.022034][    T1] Registered RDS/tcp transport
[   12.027101][    T1] tipc: Activated (version 2.0.0)
[   12.032836][    T1] NET: Registered PF_TIPC protocol family
[   12.039346][    T1] tipc: Started in single node mode
[   12.045614][    T1] NET: Registered PF_SMC protocol family
[   12.052053][    T1] 9pnet: Installing 9P2000 support
[   12.058118][    T1] NET: Registered PF_CAIF protocol family
[   12.069167][    T1] NET: Registered PF_IEEE802154 protocol family
[   12.075802][    T1] Key type dns_resolver registered
[   12.080965][    T1] Key type ceph registered
[   12.085898][    T1] libceph: loaded (mon/osd proto 15/24)
[   12.092926][    T1] batman_adv: B.A.T.M.A.N. advanced 2022.2 (compatibility version 15) loaded
[   12.101941][    T1] openvswitch: Open vSwitch switching datapath
[   12.111525][    T1] NET: Registered PF_VSOCK protocol family
[   12.117955][    T1] mpls_gso: MPLS GSO support
[   12.134629][    T1] IPI shorthand broadcast: enabled
[   12.139859][    T1] AVX2 version of gcm_enc/dec engaged.
[   12.145876][    T1] AES CTR mode by8 optimization enabled
[   12.155779][    T1] sched_clock: Marking stable (12138076585, 17368961)->(12161137287, -5691741)
[   12.167112][    T1] registered taskstats version 1
[   12.234177][    T1] Loading compiled-in X.509 certificates
[   12.245779][    T1] Loaded X.509 cert 'Build time autogenerated kernel key: 16fa2afaa7210bc2438dbf8447100de29a0bc70d'
[   12.259289][    T1] zswap: loaded using pool lzo/zbud
[   12.266413][    T1] debug_vm_pgtable: [debug_vm_pgtable         ]: Validating architecture page table helpers
[   13.815072][    T1] Key type ._fscrypt registered
[   13.820356][    T1] Key type .fscrypt registered
[   13.825167][    T1] Key type fscrypt-provisioning registered
[   13.837059][    T1] kAFS: Red Hat AFS client v0.1 registering.
[   13.852391][    T1] Btrfs loaded, crc32c=crc32c-intel, assert=on, zoned=yes, fsverity=yes
[   13.861737][    T1] Key type big_key registered
[   13.870272][    T1] Key type encrypted registered
[   13.875671][    T1] ima: No TPM chip found, activating TPM-bypass!
[   13.882332][    T1] Loading compiled-in module X.509 certificates
[   13.891979][    T1] Loaded X.509 cert 'Build time autogenerated kernel key: 16fa2afaa7210bc2438dbf8447100de29a0bc70d'
[   13.904089][    T1] ima: Allocated hash algorithm: sha256
[   13.909975][    T1] ima: No architecture policies found
[   13.916111][    T1] evm: Initialising EVM extended attributes:
[   13.922235][    T1] evm: security.selinux
[   13.926735][    T1] evm: security.SMACK64 (disabled)
[   13.931859][    T1] evm: security.SMACK64EXEC (disabled)
[   13.937528][    T1] evm: security.SMACK64TRANSMUTE (disabled)
[   13.943548][    T1] evm: security.SMACK64MMAP (disabled)
[   13.949022][    T1] evm: security.apparmor (disabled)
[   13.954231][    T1] evm: security.ima
[   13.958042][    T1] evm: security.capability
[   13.962504][    T1] evm: HMAC attrs: 0x1
[   14.046064][    T1] PM:   Magic number: 2:748:401
[   14.051323][    T1] usb usb38-port7: hash matches
[   14.058853][    T1] printk: console [netcon0] enabled
[   14.064737][    T1] netconsole: network logging started
[   14.070553][    T1] gtp: GTP module loaded (pdp ctx size 104 bytes)
[   14.080150][    T1] rdma_rxe: loaded
[   14.084458][    T1] cfg80211: Loading compiled-in X.509 certificates for regulatory database
[   14.096699][    T1] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
[   14.105001][    T1] ALSA device list:
[   14.106011][   T14] platform regulatory.0: Direct firmware load for regulatory.db failed with error -2
[   14.108906][    T1]   #0: Dummy 1
[   14.108920][    T1]   #1: Loopback 1
[   14.118716][   T14] platform regulatory.0: Falling back to sysfs fallback for: regulatory.db
[   14.124736][    T1]   #2: Virtual MIDI Card 1
[   14.142829][    T1] md: Waiting for all devices to be available before autodetect
[   14.150560][    T1] md: If you don't use raid, use raid=noautodetect
[   14.157094][    T1] md: Autodetecting RAID arrays.
[   14.162108][    T1] md: autorun ...
[   14.165854][    T1] md: ... autorun DONE.
[   14.276553][    T1] EXT4-fs (sda1): mounted filesystem with ordered data mode. Quota mode: none.
[   14.285966][    T1] VFS: Mounted root (ext4 filesystem) readonly on device 8:1.
[   14.323634][    T1] devtmpfs: mounted
[   14.339508][    T1] Freeing unused kernel image (initmem) memory: 2744K
[   14.352992][    T1] Write protecting the kernel read-only data: 176128k
[   14.364738][    T1] Freeing unused kernel image (text/rodata gap) memory: 2016K
[   14.372956][    T1] Freeing unused kernel image (rodata/data gap) memory: 392K
[   14.386193][    T1] Failed to set sysctl parameter 'max_rcu_stall_to_panic=1': parameter not found
[   14.396254][    T1] Run /sbin/init as init process
[   14.748233][    T1] SELinux:  Class mctp_socket not defined in policy.
[   14.755142][    T1] SELinux:  Class anon_inode not defined in policy.
[   14.761846][    T1] SELinux:  Class io_uring not defined in policy.
[   14.768317][    T1] SELinux: the above unknown classes and permissions will be denied
[   14.827412][    T1] SELinux:  policy capability network_peer_controls=1
[   14.834281][    T1] SELinux:  policy capability open_perms=1
[   14.840096][    T1] SELinux:  policy capability extended_socket_class=1
[   14.847142][    T1] SELinux:  policy capability always_check_network=0
[   14.853909][    T1] SELinux:  policy capability cgroup_seclabel=1
[   14.860245][    T1] SELinux:  policy capability nnp_nosuid_transition=1
[   14.867038][    T1] SELinux:  policy capability genfs_seclabel_symlinks=0
[   14.874017][    T1] SELinux:  policy capability ioctl_skip_cloexec=0
[   15.372859][   T27] audit: type=1403 audit(1661120546.300:2): auid=4294967295 ses=4294967295 lsm=selinux res=1
[   15.419548][ T2939] mount (2939) used greatest stack depth: 25104 bytes left
[   15.445064][ T2940] EXT4-fs (sda1): re-mounted. Quota mode: none.
mount: mounting smackfs on /sys/fs/smackfs failed: No such file or directory
mount: mounting mqueue on /dev/mqueue failed: No such file or directory
mount: mounting hugetlbfs on /dev/hugepages failed: No such file or directory
mount: mounting fuse.lxcfs on /var/lib/lxcfs fai[   15.591258][ T2942] mount (2942) used greatest stack depth: 24232 bytes left
led: No such file or directory
Starting syslogd: [   15.765727][   T27] audit: type=1400 audit(1661120546.690:3): avc:  denied  { read write } for  pid=2954 comm="syslogd" path="/dev/null" dev="devtmpfs" ino=5 scontext=system_u:system_r:syslogd_t tcontext=system_u:object_r:device_t tclass=chr_file permissive=1
OK
[   15.814376][   T27] audit: type=1400 audit(1661120546.740:4): avc:  denied  { read } for  pid=2954 comm="syslogd" name="log" dev="sda1" ino=1125 scontext=system_u:system_r:syslogd_t tcontext=system_u:object_r:var_t tclass=lnk_file permissive=1
Starting acpid: [   15.839700][   T27] audit: type=1400 audit(1661120546.760:5): avc:  denied  { search } for  pid=2954 comm="syslogd" name="/" dev="tmpfs" ino=1 scontext=system_u:system_r:syslogd_t tcontext=system_u:object_r:tmpfs_t tclass=dir permissive=1
[   15.861223][   T27] audit: type=1400 audit(1661120546.760:6): avc:  denied  { write } for  pid=2954 comm="syslogd" name="/" dev="tmpfs" ino=1 scontext=system_u:system_r:syslogd_t tcontext=system_u:object_r:tmpfs_t tclass=dir permissive=1
[   15.882689][   T27] audit: type=1400 audit(1661120546.760:7): avc:  denied  { add_name } for  pid=2954 comm="syslogd" name="messages" scontext=system_u:system_r:syslogd_t tcontext=system_u:object_r:tmpfs_t tclass=dir permissive=1
OK
[   15.923298][   T27] audit: type=1400 audit(1661120546.760:8): avc:  denied  { create } for  pid=2954 comm="syslogd" name="messages" scontext=system_u:system_r:syslogd_t tcontext=system_u:object_r:tmpfs_t tclass=file permissive=1
[   15.944279][   T27] audit: type=1400 audit(1661120546.760:9): avc:  denied  { append open } for  pid=2954 comm="syslogd" path="/tmp/messages" dev="tmpfs" ino=2 scontext=system_u:system_r:syslogd_t tcontext=system_u:object_r:tmpfs_t tclass=file permissive=1
Starting klogd: [   15.967402][   T27] audit: type=1400 audit(1661120546.760:10): avc:  denied  { getattr } for  pid=2954 comm="syslogd" path="/tmp/messages" dev="tmpfs" ino=2 scontext=system_u:system_r:syslogd_t tcontext=system_u:object_r:tmpfs_t tclass=file permissive=1
[   15.992369][   T27] audit: type=1400 audit(1661120546.800:11): avc:  denied  { use } for  pid=2956 comm="acpid" path="/dev/console" dev="rootfs" ino=1076 scontext=system_u:system_r:acpid_t tcontext=system_u:system_r:kernel_t tclass=fd permissive=1
OK
Running sysctl: OK
[   16.225258][ T2967] logger (2967) used greatest stack depth: 22976 bytes left
Populating /dev using udev: [   16.435978][ T2971] udevd[2971]: starting version 3.2.10
[   16.686715][ T2972] udevd[2972]: starting eudev-3.2.10
done
Starting system message bus: [   28.569901][   T27] kauditd_printk_skb: 14 callbacks suppressed
[   28.569911][   T27] audit: type=1400 audit(1661120559.490:26): avc:  denied  { use } for  pid=3171 comm="dbus-daemon" path="/dev/console" dev="rootfs" ino=1076 scontext=system_u:system_r:system_dbusd_t tcontext=system_u:system_r:kernel_t tclass=fd permissive=1
[   28.599571][   T27] audit: type=1400 audit(1661120559.490:27): avc:  denied  { read write } for  pid=3171 comm="dbus-daemon" path="/dev/console" dev="rootfs" ino=1076 scontext=system_u:system_r:system_dbusd_t tcontext=system_u:object_r:root_t tclass=chr_file permissive=1
[   28.642390][   T27] audit: type=1400 audit(1661120559.560:28): avc:  denied  { search } for  pid=3171 comm="dbus-daemon" name="/" dev="tmpfs" ino=1 scontext=system_u:system_r:system_dbusd_t tcontext=system_u:object_r:tmpfs_t tclass=dir permissive=1
[   28.665649][   T27] audit: type=1400 audit(1661120559.580:29): avc:  denied  { write } for  pid=3171 comm="dbus-daemon" name="dbus" dev="tmpfs" ino=1393 scontext=system_u:system_r:system_dbusd_t tcontext=system_u:object_r:tmpfs_t tclass=dir permissive=1
done
[   28.689039][   T27] audit: type=1400 audit(1661120559.580:30): avc:  denied  { add_name } for  pid=3171 comm="dbus-daemon" name="system_bus_socket" scontext=system_u:system_r:system_dbusd_t tcontext=system_u:object_r:tmpfs_t tclass=dir permissive=1
[   28.711654][   T27] audit: type=1400 audit(1661120559.580:31): avc:  denied  { create } for  pid=3171 comm="dbus-daemon" name="system_bus_socket" scontext=system_u:system_r:system_dbusd_t tcontext=system_u:object_r:tmpfs_t tclass=sock_file permissive=1
[   28.734633][   T27] audit: type=1400 audit(1661120559.580:32): avc:  denied  { setattr } for  pid=3171 comm="dbus-daemon" name="system_bus_socket" dev="tmpfs" ino=1394 scontext=system_u:system_r:system_dbusd_t tcontext=system_u:object_r:tmpfs_t tclass=sock_file permissive=1
[   28.759424][   T27] audit: type=1400 audit(1661120559.590:33): avc:  denied  { create } for  pid=3171 comm="dbus-daemon" name="messagebus.pid" scontext=system_u:system_r:system_dbusd_t tcontext=system_u:object_r:tmpfs_t tclass=file permissive=1
[   28.782144][   T27] audit: type=1400 audit(1661120559.590:34): avc:  denied  { write open } for  pid=3171 comm="dbus-daemon" path="/run/messagebus.pid" dev="tmpfs" ino=1395 scontext=system_u:system_r:system_dbusd_t tcontext=system_u:object_r:tmpfs_t tclass=file permissive=1
[   28.807197][   T27] audit: type=1400 audit(1661120559.590:35): avc:  denied  { getattr } for  pid=3171 comm="dbus-daemon" path="/run/messagebus.pid" dev="tmpfs" ino=1395 scontext=system_u:system_r:system_dbusd_t tcontext=system_u:object_r:tmpfs_t tclass=file permissive=1
Starting network: OK
Starting dhcpcd...
dhcpcd-9.4.0 starting
dev: loaded udev
DUID 00:04:18:1b:51:b6:f4:39:97:fb:3c:5d:6f:3f:70:18:1a:62
forked to background, child pid 3185
[   30.625552][ T3186] 8021q: adding VLAN 0 to HW filter on device bond0
[   30.638978][ T3186] eql: remember to turn off Van-Jacobson compression on your slave devices
Starting sshd: OK


syzkaller

syzkaller login: [   76.294776][   T14] cfg80211: failed to load regulatory.db


syzkaller build log:
go env (err=<nil>)
GO111MODULE="auto"
GOARCH="amd64"
GOBIN=""
GOCACHE="/syzkaller/.cache/go-build"
GOENV="/syzkaller/.config/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GOINSECURE=""
GOMODCACHE="/syzkaller/jobs/linux/gopath/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/syzkaller/jobs/linux/gopath"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64"
GOVCS=""
GOVERSION="go1.17"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
CGO_ENABLED="1"
GOMOD="/syzkaller/jobs/linux/gopath/src/github.com/google/syzkaller/go.mod"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build994994397=/tmp/go-build -gno-record-gcc-switches"

git status (err=<nil>)
HEAD detached at 1434eec0b
nothing to commit, working tree clean


go list -f '{{.Stale}}' ./sys/syz-sysgen | grep -q false || go install ./sys/syz-sysgen
make .descriptions
bin/syz-sysgen
touch .descriptions
GOOS=linux GOARCH=amd64 go build "-ldflags=-s -w -X github.com/google/syzkaller/prog.GitRevision=1434eec0b84075b7246560cfa89f20cdb3d8077f -X 'github.com/google/syzkaller/prog.gitRevisionDate=20220629-111539'" "-tags=syz_target syz_os_linux syz_arch_amd64 " -o ./bin/linux_amd64/syz-fuzzer github.com/google/syzkaller/syz-fuzzer
GOOS=linux GOARCH=amd64 go build "-ldflags=-s -w -X github.com/google/syzkaller/prog.GitRevision=1434eec0b84075b7246560cfa89f20cdb3d8077f -X 'github.com/google/syzkaller/prog.gitRevisionDate=20220629-111539'" "-tags=syz_target syz_os_linux syz_arch_amd64 " -o ./bin/linux_amd64/syz-execprog github.com/google/syzkaller/tools/syz-execprog
GOOS=linux GOARCH=amd64 go build "-ldflags=-s -w -X github.com/google/syzkaller/prog.GitRevision=1434eec0b84075b7246560cfa89f20cdb3d8077f -X 'github.com/google/syzkaller/prog.gitRevisionDate=20220629-111539'" "-tags=syz_target syz_os_linux syz_arch_amd64 " -o ./bin/linux_amd64/syz-stress github.com/google/syzkaller/tools/syz-stress
mkdir -p ./bin/linux_amd64
gcc -o ./bin/linux_amd64/syz-executor executor/executor.cc \
	-m64 -O2 -pthread -Wall -Werror -Wparentheses -Wunused-const-variable -Wframe-larger-than=16384 -Wno-stringop-overflow -Wno-array-bounds -Wno-format-overflow -static-pie -fpermissive -w -DGOOS_linux=1 -DGOARCH_amd64=1 \
	-DHOSTGOOS_linux=1 -DGIT_REVISION=\"1434eec0b84075b7246560cfa89f20cdb3d8077f\"


Error text is too large and was truncated, full error text is at:
https://syzkaller.appspot.com/x/error.txt?x=14b8bffd080000


Tested on:

commit:         568035b0 Linux 6.0-rc1
git tree:       https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git
kernel config:  https://syzkaller.appspot.com/x/.config?x=930fc801ca92783a
dashboard link: https://syzkaller.appspot.com/bug?extid=7f0483225d0c94cb3441
compiler:       gcc (Debian 10.2.1-6) 10.2.1 20210110, GNU ld (GNU Binutils for Debian) 2.35.2
patch:          https://syzkaller.appspot.com/x/patch.diff?x=17e2730d080000