kern.log spammed by NFS messages

[LeifSec]

When doing backups since today the `kern.log` is spammed with huge amount several GB - ~ as large as the backup file) of messages

```
2023-08-04T09:59:19.278111+02:00 hv1 kernel: [793097.803800] NFS: write_begin(dump/vzdump-qemu-109-2023_08_04-09_51_32.vma.dat(136249364), 4096@46983004160)
2023-08-04T09:59:19.278113+02:00 hv1 kernel: [793097.803811] NFS: write_end(dump/vzdump-qemu-109-2023_08_04-09_51_32.vma.dat(136249364), 4096@46983004160)
2023-08-04T09:59:19.278115+02:00 hv1 kernel: [793097.803817] NFS: nfs_updatepage(dump/vzdump-qemu-109-2023_08_04-09_51_32.vma.dat 4096@46983004160)
2023-08-04T09:59:19.278117+02:00 hv1 kernel: [793097.803824] NFS: nfs_updatepage returns 0 (isize 46983008256)
2023-08-04T09:59:19.278119+02:00 hv1 kernel: [793097.803829] NFS: write_begin(dump/vzdump-qemu-109-2023_08_04-09_51_32.vma.dat(136249364), 4096@46983008256)
2023-08-04T09:59:19.278121+02:00 hv1 kernel: [793097.803839] NFS: write_end(dump/vzdump-qemu-109-2023_08_04-09_51_32.vma.dat(136249364), 4096@46983008256)
2023-08-04T09:59:19.278123+02:00 hv1 kernel: [793097.803845] NFS: nfs_updatepage(dump/vzdump-qemu-109-2023_08_04-09_51_32.vma.dat 4096@46983008256)
2023-08-04T09:59:19.278161+02:00 hv1 kernel: [793097.803854] NFS: nfs_updatepage returns 0 (isize 46983012352)
2023-08-04T09:59:19.278164+02:00 hv1 kernel: [793097.804166] decode_attr_type: type=00
2023-08-04T09:59:19.278166+02:00 hv1 kernel: [793097.804171] decode_attr_change: change attribute=7263373637269464507
2023-08-04T09:59:19.278168+02:00 hv1 kernel: [793097.804175] decode_attr_size: file size=36468424704
2023-08-04T09:59:19.278170+02:00 hv1 kernel: [793097.804177] decode_attr_fsid: fsid=(0x0/0x0)
2023-08-04T09:59:19.278172+02:00 hv1 kernel: [793097.804180] decode_attr_fileid: fileid=0
2023-08-04T09:59:19.278174+02:00 hv1 kernel: [793097.804182] decode_attr_fs_locations: fs_locations done, error = 0
2023-08-04T09:59:19.278176+02:00 hv1 kernel: [793097.804185] decode_attr_mode: file mode=00
2023-08-04T09:59:19.278179+02:00 hv1 kernel: [793097.804187] decode_attr_nlink: nlink=1
2023-08-04T09:59:19.278181+02:00 hv1 kernel: [793097.804190] decode_attr_rdev: rdev=(0x0:0x0)
2023-08-04T09:59:19.278182+02:00 hv1 kernel: [793097.804193] decode_attr_space_used: space used=36336340992
2023-08-04T09:59:19.278184+02:00 hv1 kernel: [793097.804195] decode_attr_time_access: atime=0
2023-08-04T09:59:19.278186+02:00 hv1 kernel: [793097.804198] decode_attr_time_metadata: ctime=1691135959
2023-08-04T09:59:19.278187+02:00 hv1 kernel: [793097.804200] decode_attr_time_modify: mtime=1691135959
2023-08-04T09:59:19.278189+02:00 hv1 kernel: [793097.804203] decode_attr_mounted_on_fileid: fileid=0
2023-08-04T09:59:19.278191+02:00 hv1 kernel: [793097.804205] decode_getfattr_attrs: xdr returned 0
2023-08-04T09:59:19.278193+02:00 hv1 kernel: [793097.804207] decode_getfattr_generic: xdr returned 0
2023-08-04T09:59:19.278195+02:00 hv1 kernel: [793097.804211] --> nfs4_alloc_slot used_slots=3fffffff highest_used=29 max_slots=30
2023-08-04T09:59:19.278197+02:00 hv1 kernel: [793097.804216] <-- nfs4_alloc_slot used_slots=3fffffff highest_used=29 slotid=4294967295
2023-08-04T09:59:19.278199+02:00 hv1 kernel: [793097.804220] nfs41_sequence_process: Error 0 free the slot
2023-08-04T09:59:19.278201+02:00 hv1 kernel: [793097.804227] NFS: nfs_update_inode(0:73/136249364 fh_crc=0xef461341 ct=2 info=0x7e200)
2023-08-04T09:59:19.278203+02:00 hv1 kernel: [793097.804243] encode_sequence: sessionid=1690873330:3427275370:5:0 seqid=74518 slotid=9 max_slotid=29 cache_this=0
2023-08-04T09:59:19.278254+02:00 hv1 kernel: [793097.804329] NFS: write(dump/vzdump-qemu-109-2023_08_04-09_51_32.vma.dat, 8192@46983012352)
2023-08-04T09:59:19.278257+02:00 hv1 kernel: [793097.804337] NFS: write_begin(dump/vzdump-qemu-109-2023_08_04-09_51_32.vma.dat(136249364), 4096@46983012352)
2023-08-04T09:59:19.278259+02:00 hv1 kernel: [793097.804351] NFS: write_end(dump/vzdump-qemu-109-2023_08_04-09_51_32.vma.dat(136249364), 4096@46983012352)
2023-08-04T09:59:19.278261+02:00 hv1 kernel: [793097.804357] NFS: nfs_updatepage(dump/vzdump-qemu-109-2023_08_04-09_51_32.vma.dat 4096@46983012352)
2023-08-04T09:59:19.278263+02:00 hv1 kernel: [793097.804365] NFS: nfs_updatepage returns 0 (isize 46983016448)
```

where the ` NFS` part is dominant. With cleaning the `kern.log `and `syslog` (`truncate --size 0`) before disk space on `local (hv1)` is running out the backups finally succeeded.


`pveversion -v`
```
proxmox-ve: 8.0.2 (running kernel: 6.2.16-4-pve)
pve-manager: 8.0.4 (running version: 8.0.4/d258a813cfa6b390)
pve-kernel-6.2: 8.0.5
proxmox-kernel-helper: 8.0.3
pve-kernel-5.15: 7.4-4
proxmox-kernel-6.2.16-6-pve: 6.2.16-7
proxmox-kernel-6.2: 6.2.16-7
pve-kernel-6.2.16-5-pve: 6.2.16-6
pve-kernel-6.2.16-4-pve: 6.2.16-5
pve-kernel-5.3: 6.1-6
pve-kernel-5.15.108-1-pve: 5.15.108-1
pve-kernel-5.13.19-2-pve: 5.13.19-4
pve-kernel-5.3.18-3-pve: 5.3.18-3
pve-kernel-5.3.18-2-pve: 5.3.18-2
ceph-fuse: 16.2.11+ds-2
corosync: 3.1.7-pve3
criu: 3.17.1-2
glusterfs-client: 10.3-5
ifupdown: residual config
ifupdown2: 3.2.0-1+pmx3
ksm-control-daemon: 1.4-1
libjs-extjs: 7.0.0-3
libknet1: 1.25-pve1
libproxmox-acme-perl: 1.4.6
libproxmox-backup-qemu0: 1.4.0
libproxmox-rs-perl: 0.3.1
libpve-access-control: 8.0.4
libpve-apiclient-perl: 3.3.1
libpve-common-perl: 8.0.7
libpve-guest-common-perl: 5.0.4
libpve-http-server-perl: 5.0.4
libpve-rs-perl: 0.8.5
libpve-storage-perl: 8.0.2
libqb0: 1.0.5-1
libspice-server1: 0.15.1-1
lvm2: 2.03.16-2
lxc-pve: 5.0.2-4
lxcfs: 5.0.3-pve3
novnc-pve: 1.4.0-2
proxmox-backup-client: 3.0.2-1
proxmox-backup-file-restore: 3.0.2-1
proxmox-kernel-helper: 8.0.3
proxmox-mail-forward: 0.2.0
proxmox-mini-journalreader: 1.4.0
proxmox-offline-mirror-helper: 0.6.2
proxmox-widget-toolkit: 4.0.6
pve-cluster: 8.0.3
pve-container: 5.0.4
pve-docs: 8.0.4
pve-edk2-firmware: 3.20230228-4
pve-firewall: 5.0.3
pve-firmware: 3.7-1
pve-ha-manager: 4.0.2
pve-i18n: 3.0.5
pve-qemu-kvm: 8.0.2-4
pve-xtermjs: 4.16.0-3
qemu-server: 8.0.6
smartmontools: 7.3-pve1
spiceterm: 3.3.0
swtpm: 0.8.0+pve1
vncterm: 1.8.0
zfsutils-linux: 2.1.12-pve1
```
Actually I cannot find real error messages. Also the write speed is OK. In `/etc/vzdump.conf` there is also now `tmpdir: /tmp`.

 

[Hannes Laimer]

Hey,

it looks like your kernel is just a little verbose. You can check this using cat /proc/sys/kernel/printk, it'll look something like this: 7 4 6 7. The third number is the minimum log level, which means only messages with that level or more severe will be logged. You can change it temporarily with echo "7 4 1 7" > /proc/sys/kernel/printk, for making the change persistent use echo "kernel.printk = 7 4 1 7" >> /etc/sysctl.conf and sysctl -p afterwards.

Log Level	Description
0 (KERN_EMERG)	system is unusable
1 (KERN_ALERT)	action must be taken immediately
2 (KERN_CRIT)	critical conditions
3 (KERN_ERR)	error conditions
4 (KERN_WARNING)	warning conditions
5 (KERN_NOTICE)	normal but significant condition
6 (KERN_INFO)	informational
7 (KERN_DEBUG)	debug-level messages

https://www.kernel.org/doc/html/next/core-api/printk-basics.html

 

[LeifSec]

Hey,

it looks like your kernel is just a little verbose. You can check this using cat /proc/sys/kernel/printk, it'll look something like this: 7 4 6 7. The third number is the minimum log level, which means only messages with that level or more severe will be logged. You can change it temporarily with echo "7 4 1 7" > /proc/sys/kernel/printk, for making the change persistent use echo "kernel.printk = 7 4 1 7" >> /etc/sysctl.conf and sysctl -p afterwards.

Log Level	Description
0 (KERN_EMERG)	system is unusable
1 (KERN_ALERT)	action must be taken immediately
2 (KERN_CRIT)	critical conditions
3 (KERN_ERR)	error conditions
4 (KERN_WARNING)	warning conditions
5 (KERN_NOTICE)	normal but significant condition
6 (KERN_INFO)	informational
7 (KERN_DEBUG)	debug-level messages

https://www.kernel.org/doc/html/next/core-api/printk-basics.html

It had already been `4 4 1 7` and even setting it to `3 3 1 3` does not stop it.
Maybe it is similar to https://forum.proxmox.com/threads/log-files-full-of-nfs-messages.82777 - but not related to a certain node.
Also disabling nfs logs does not help: `rpcdebug -m nfsd -c all`+ restart service.

The problem might have appeared after:
- Connection to nfs was temporary broken (because of firewall settings) - but did not appear directly beyond this.
- Updated on the NFS-Server.

I have seen that there have been updates to Proxmox and the Linux kernel - maybe I reboot the machine / restart services on Monday morning and maybe the problem disappears then.

 

[LeifSec]

Reboot after the Proxmox + kernel (-> 6.2.16-6-pve) update solved the problem - no NFS messages in logs anymore (during backup).