You are not logged in.

#1 2019-11-26 01:17:06

fryfrog
Member
Registered: 2019-11-13
Posts: 7

NFS Server Issues on Odroid H2

Getting NFS working should be easy, a few lines in `/etc/exports`, install `nfs-utils` and `systemctl start nfs-server`. I've done this on a Pi 4 and on my real server, it works great and is easy. But I'm having a heck of a time getting it working on an Odroid H2.


The kernel is custom compiled w/ a patch to re-enable some features used by ZFS, but I started w/ an unpatched kernel w/ the same behavior. Dropping to an unpatched *or* patched LTS kernel changes things a little. It still doesn't work, but I don't get the "blocked for more than X seconds". And oddly, nfsv3 works.

0 _ fryfrog@acai ~ $ uname -a
Linux acai 5.3.13-arch1-1 #2 SMP PREEMPT Mon, 25 Nov 2019 04:05:31 +0000 x86_64 GNU/Linux

There are 3 more of these, but it didn't seem worth wasting space showing them.

0 _ fryfrog@acai ~ $ cat /proc/cpuinfo | head -30
processor       : 0
vendor_id       : GenuineIntel
cpu family      : 6
model           : 122
model name      : Intel(R) Celeron(R) J4105 CPU @ 1.50GHz
stepping        : 1
microcode       : 0x32
cpu MHz         : 680.843
cache size      : 4096 KB
physical id     : 0
siblings        : 4
core id         : 0
cpu cores       : 4
apicid          : 0
initial apicid  : 0
fpu             : yes
fpu_exception   : yes
cpuid level     : 24
wp              : yes
flags           : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtscp lm constant_tsc art arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc cpuid aperfmperf tsc_known_freq pni pclmulqdq dtes64 monitor ds_cpl vmx est tm2 ssse3 sdbg cx16 xtpr pdcm sse4_1 sse4_2 x2apic movbe popcnt tsc_deadline_timer aes xsave rdrand lahf_lm 3dnowprefetch cpuid_fault cat_l2 cdp_l2 ssbd ibrs ibpb stibp ibrs_enhanced tpr_shadow vnmi flexpriority ept vpid ept_ad fsgsbase tsc_adjust smep erms mpx rdt_a rdseed smap clflushopt intel_pt sha_ni xsaveopt xsavec xgetbv1 xsaves dtherm ida arat pln pts umip rdpid md_clear arch_capabilities
bugs            : cpu_meltdown spectre_v1 spectre_v2 spec_store_bypass
bogomips        : 2996.00
clflush size    : 64
cache_alignment : 64
address sizes   : 39 bits physical, 48 bits virtual
power management:

This is what happens when I `sudo systemctl start nfs-server`, which incidentally *hangs* and just stays there. The `nfsdcld` segfaults, but a restart brings it back online "just fine".

[Nov25 17:06] kauditd_printk_skb: 1 callbacks suppressed
[  +0.000002] audit: type=1101 audit(1574730414.656:147): pid=7649 uid=1002 auid=1002 ses=1 msg='op=PAM:accounting grantors=pam_unix,pam_permit,pam_time acct="fryfrog" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/1 res=success'
[  +0.000334] audit: type=1110 audit(1574730414.656:148): pid=7649 uid=0 auid=1002 ses=1 msg='op=PAM:setcred grantors=pam_unix,pam_permit,pam_env acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/1 res=success'
[  +0.000302] audit: type=1105 audit(1574730414.656:149): pid=7649 uid=0 auid=1002 ses=1 msg='op=PAM:session_open grantors=pam_limits,pam_unix,pam_permit acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/1 res=success'
[  +0.064197] audit: type=1130 audit(1574730414.719:150): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=rpc-statd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[  +0.039344] RPC: Registered named UNIX socket transport module.
[  +0.000003] RPC: Registered udp transport module.
[  +0.000001] RPC: Registered tcp transport module.
[  +0.000000] RPC: Registered tcp NFSv4.1 backchannel transport module.
[  +0.005892] audit: type=1130 audit(1574730414.766:151): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=nfs-idmapd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[  +0.014631] audit: type=1130 audit(1574730414.779:152): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=rpcbind comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[  +0.037210] Installing knfsd (copyright (C) 1996 okir@monad.swb.de).
[  +0.005714] audit: type=1130 audit(1574730414.823:153): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=nfs-mountd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[  +0.002197] audit: type=1130 audit(1574730414.826:154): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=nfsdcld comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[  +0.130504] nfsdcld[7673]: segfault at 0 ip 000055c6b78ac7c7 sp 00007ffeb57c9950 error 4 in nfsdcld[55c6b78a9000+9000]
[  +0.000026] Code: 48 29 f9 81 c1 23 04 00 00 c1 e9 03 f3 48 ab 48 8b 3c 24 ff 15 9a a7 00 00 48 8d bb 9a 00 00 00 48 8d 8b 92 00 00 00 48 89 c6 <48> 8b 00 48 83 e7 f8 48 29 f9 48 89 83 92 00 00 00 48 8b 86 f8 03
[  +0.000110] audit: type=1701 audit(1574730414.959:155): auid=4294967295 uid=0 gid=0 ses=4294967295 pid=7673 comm="nfsdcld" exe="/usr/bin/nfsdcld" sig=11 res=1
[Nov25 17:07] kauditd_printk_skb: 3 callbacks suppressed
[  +0.000002] audit: type=1100 audit(1574730426.007:159): pid=7825 uid=1002 auid=1002 ses=1 msg='op=PAM:authentication grantors=pam_unix,pam_permit acct="fryfrog" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/2 res=success'

See? Of note here is that blueberry, apple and raspberry are Pi 4s that are *off*, but did try to nfs mount in the past. Long memory?

3 _ fryfrog@acai ~ $ sudo systemctl status nfsdcld
* nfsdcld.service - NFSv4 Client Tracking Daemon
   Loaded: loaded (/usr/lib/systemd/system/nfsdcld.service; static; vendor preset: disabled)
  Drop-In: /etc/systemd/system/nfsdcld.service.d
           `-override.conf
   Active: failed (Result: core-dump) since Mon 2019-11-25 17:14:32 PST; 41s ago
  Process: 2042 ExecStart=/usr/sbin/nfsdcld --debug --foreground (code=dumped, signal=SEGV)
 Main PID: 2042 (code=dumped, signal=SEGV)

Nov 25 17:14:31 acai nfsdcld[2042]: nfsdcld: cld_pipe_open: opening upcall pipe /var/lib/nfs/rpc_pipefs/nfsd/cld
Nov 25 17:14:31 acai nfsdcld[2042]: nfsdcld: main: Starting event dispatch handler.
Nov 25 17:14:31 acai nfsdcld[2042]: nfsdcld: cld_gracestart: updating grace epochs
Nov 25 17:14:31 acai nfsdcld[2042]: nfsdcld: sqlite_grace_start: current_epoch=3 recovery_epoch=2
Nov 25 17:14:31 acai nfsdcld[2042]: nfsdcld: cld_gracestart: sending client records to the kernel
Nov 25 17:14:31 acai nfsdcld[2042]: nfsdcld: Sending client Linux NFSv4.2 blueberry
Nov 25 17:14:31 acai nfsdcld[2042]: nfsdcld: Sending client Linux NFSv4.2 apple
Nov 25 17:14:31 acai nfsdcld[2042]: nfsdcld: Sending client Linux NFSv4.2 raspberry
Nov 25 17:14:32 acai systemd[1]: nfsdcld.service: Main process exited, code=dumped, status=11/SEGV
Nov 25 17:14:32 acai systemd[1]: nfsdcld.service: Failed with result 'core-dump'.

And running after restart...

0 _ fryfrog@acai ~ $ sudo systemctl status nfsdcld.service
* nfsdcld.service - NFSv4 Client Tracking Daemon
   Loaded: loaded (/usr/lib/systemd/system/nfsdcld.service; static; vendor preset: disabled)
  Drop-In: /etc/systemd/system/nfsdcld.service.d
           `-override.conf
   Active: active (running) since Mon 2019-11-25 17:09:10 PST; 6s ago
 Main PID: 7993 (nfsdcld)
    Tasks: 1 (limit: 9317)
   Memory: 564.0K
   CGroup: /system.slice/nfsdcld.service
           `-7993 /usr/sbin/nfsdcld --debug --foreground

Nov 25 17:09:10 acai systemd[1]: Started NFSv4 Client Tracking Daemon.
Nov 25 17:09:10 acai nfsdcld[7993]: nfsdcld: sqlite_startup_query_grace: current_epoch=3 recovery_epoch=2
Nov 25 17:09:10 acai nfsdcld[7993]: nfsdcld: sqlite_check_db_health: returning 0
Nov 25 17:09:10 acai nfsdcld[7993]: nfsdcld: cld_pipe_init: init pipe handlers
Nov 25 17:09:10 acai nfsdcld[7993]: nfsdcld: cld_pipe_open: opening upcall pipe /var/lib/nfs/rpc_pipefs/nfsd/cld
Nov 25 17:09:10 acai nfsdcld[7993]: nfsdcld: main: Starting event dispatch handler.

A status of *all* the nfs service mentioned in `nfs-server`.

* nfs-server.service - NFS server and services
   Loaded: loaded (/usr/lib/systemd/system/nfs-server.service; disabled; vendor preset: disabled)
  Drop-In: /etc/systemd/system/nfs-server.service.d
           `-override.conf
   Active: activating (start) since Mon 2019-11-25 17:14:31 PST; 1min 45s ago
  Process: 2043 ExecStartPre=/usr/sbin/exportfs -rv (code=exited, status=0/SUCCESS)
 Main PID: 2044 (rpc.nfsd)
    Tasks: 1 (limit: 4915)
   Memory: 672.0K
   CGroup: /system.slice/nfs-server.service
           `-2044 /usr/sbin/rpc.nfsd --debug

Nov 25 17:14:31 acai systemd[1]: Starting NFS server and services...
Nov 25 17:14:31 acai exportfs[2043]: exporting *:/hot
Nov 25 17:14:31 acai exportfs[2043]: exporting *:/cold
Nov 25 17:14:31 acai rpc.nfsd[2044]: rpc.nfsd: knfsd is currently down
Nov 25 17:14:31 acai rpc.nfsd[2044]: rpc.nfsd: Writing version string to kernel: -2 +3 +4 +4.1 +4.2
Nov 25 17:14:31 acai rpc.nfsd[2044]: rpc.nfsd: Created AF_INET TCP socket.
Nov 25 17:14:31 acai rpc.nfsd[2044]: rpc.nfsd: Created AF_INET6 TCP socket.

* proc-fs-nfsd.mount - NFSD configuration filesystem
   Loaded: loaded (/usr/lib/systemd/system/proc-fs-nfsd.mount; static; vendor preset: disabled)
   Active: active (mounted) since Mon 2019-11-25 17:14:31 PST; 1min 45s ago
    Where: /proc/fs/nfsd
     What: nfsd
    Tasks: 0 (limit: 4915)
   Memory: 76.0K
   CGroup: /system.slice/proc-fs-nfsd.mount

Nov 25 17:14:31 acai systemd[1]: Mounting NFSD configuration filesystem...
Nov 25 17:14:31 acai systemd[1]: Mounted NFSD configuration filesystem.

* nfs-mountd.service - NFS Mount Daemon
   Loaded: loaded (/usr/lib/systemd/system/nfs-mountd.service; static; vendor preset: disabled)
  Drop-In: /etc/systemd/system/nfs-mountd.service.d
           `-override.conf
   Active: active (running) since Mon 2019-11-25 17:14:31 PST; 1min 45s ago
 Main PID: 2041 (rpc.mountd)
    Tasks: 1 (limit: 4915)
   Memory: 24.7M
   CGroup: /system.slice/nfs-mountd.service
           `-2041 /usr/sbin/rpc.mountd --debug all --foreground

Nov 25 17:14:31 acai systemd[1]: Started NFS Mount Daemon.
Nov 25 17:14:31 acai rpc.mountd[2041]: Version 2.4.2 starting
Nov 25 17:14:31 acai rpc.mountd[2041]: rpc.mountd: Version 2.4.2 starting

* rpcbind.socket - RPCbind Server Activation Socket
   Loaded: loaded (/usr/lib/systemd/system/rpcbind.socket; disabled; vendor preset: disabled)
   Active: active (running) since Mon 2019-11-25 17:14:31 PST; 1min 45s ago
   Listen: /run/rpcbind.sock (Stream)
           0.0.0.0:111 (Stream)
           0.0.0.0:111 (Datagram)
           [::]:111 (Stream)
           [::]:111 (Datagram)
    Tasks: 0 (limit: 4915)
   Memory: 60.0K
   CGroup: /system.slice/rpcbind.socket

Nov 25 17:14:31 acai systemd[1]: Listening on RPCbind Server Activation Socket.

* rpc-statd.service - NFS status monitor for NFSv2/3 locking.
   Loaded: loaded (/usr/lib/systemd/system/rpc-statd.service; static; vendor preset: disabled)
  Drop-In: /etc/systemd/system/rpc-statd.service.d
           `-override.conf
   Active: active (running) since Mon 2019-11-25 17:14:31 PST; 1min 45s ago
 Main PID: 2028 (rpc.statd)
    Tasks: 1 (limit: 4915)
   Memory: 48.8M
   CGroup: /system.slice/rpc-statd.service
           `-2028 /usr/sbin/rpc.statd --foreground

Nov 25 17:14:31 acai systemd[1]: Started NFS status monitor for NFSv2/3 locking..
Nov 25 17:14:31 acai rpc.statd[2028]: Version 2.4.2 starting
Nov 25 17:14:31 acai rpc.statd[2028]: Flags: No-Daemon TI-RPC
Nov 25 17:14:31 acai rpc.statd[2028]: Local NSM state number: 3
Nov 25 17:14:31 acai rpc.statd[2028]: Effective UID, GID: 65534, 0
Nov 25 17:14:31 acai rpc.statd[2028]: Waiting for client connections

* nfs-idmapd.service - NFSv4 ID-name mapping service
   Loaded: loaded (/usr/lib/systemd/system/nfs-idmapd.service; static; vendor preset: disabled)
  Drop-In: /etc/systemd/system/nfs-idmapd.service.d
           `-override.conf
   Active: active (running) since Mon 2019-11-25 17:14:31 PST; 1min 45s ago
 Main PID: 2038 (rpc.idmapd)
    Tasks: 1 (limit: 4915)
   Memory: 572.0K
   CGroup: /system.slice/nfs-idmapd.service
           `-2038 /usr/sbin/rpc.idmapd -f -v

Nov 25 17:14:31 acai rpc.idmapd[2038]: rpc.idmapd: libnfsidmap: using domain: lan
Nov 25 17:14:31 acai rpc.idmapd[2038]: rpc.idmapd: libnfsidmap: Realms list: 'LAN'
Nov 25 17:14:31 acai rpc.idmapd[2038]: libnfsidmap: using domain: lan
Nov 25 17:14:31 acai rpc.idmapd[2038]: libnfsidmap: Realms list: 'LAN'
Nov 25 17:14:31 acai rpc.idmapd[2038]: libnfsidmap: loaded plugin /usr/lib/libnfsidmap/nsswitch.so for method nsswitch
Nov 25 17:14:31 acai rpc.idmapd[2038]: rpc.idmapd: libnfsidmap: loaded plugin /usr/lib/libnfsidmap/nsswitch.so for method nsswitch
Nov 25 17:14:31 acai rpc.idmapd[2038]: rpc.idmapd: Expiration time is 600 seconds.
Nov 25 17:14:31 acai rpc.idmapd[2038]: Expiration time is 600 seconds.
Nov 25 17:14:31 acai rpc.idmapd[2038]: rpc.idmapd: nfsdopenone: Opening /proc/net/rpc/nfs4.nametoid/channel failed: errno 2 (No such file or directory)
Nov 25 17:14:31 acai rpc.idmapd[2038]: nfsdopenone: Opening /proc/net/rpc/nfs4.nametoid/channel failed: errno 2 (No such file or directory)

* rpc-statd-notify.service - Notify NFS peers of a restart
   Loaded: loaded (/usr/lib/systemd/system/rpc-statd-notify.service; static; vendor preset: disabled)
  Drop-In: /etc/systemd/system/rpc-statd-notify.service.d
           `-override.conf
   Active: inactive (dead)

* nfsdcld.service - NFSv4 Client Tracking Daemon
   Loaded: loaded (/usr/lib/systemd/system/nfsdcld.service; static; vendor preset: disabled)
  Drop-In: /etc/systemd/system/nfsdcld.service.d
           `-override.conf
   Active: active (running) since Mon 2019-11-25 17:15:58 PST; 18s ago
 Main PID: 2302 (nfsdcld)
    Tasks: 1 (limit: 4915)
   Memory: 580.0K
   CGroup: /system.slice/nfsdcld.service
           `-2302 /usr/sbin/nfsdcld --debug --foreground

Nov 25 17:15:58 acai systemd[1]: Started NFSv4 Client Tracking Daemon.
Nov 25 17:15:58 acai nfsdcld[2302]: nfsdcld: sqlite_startup_query_grace: current_epoch=3 recovery_epoch=2
Nov 25 17:15:58 acai nfsdcld[2302]: nfsdcld: sqlite_check_db_health: returning 0
Nov 25 17:15:58 acai nfsdcld[2302]: nfsdcld: cld_pipe_init: init pipe handlers
Nov 25 17:15:58 acai nfsdcld[2302]: nfsdcld: cld_pipe_open: opening upcall pipe /var/lib/nfs/rpc_pipefs/nfsd/cld
Nov 25 17:15:58 acai nfsdcld[2302]: nfsdcld: main: Starting event dispatch handler.

* auth-rpcgss-module.service - Kernel Module supporting RPCSEC_GSS
   Loaded: loaded (/usr/lib/systemd/system/auth-rpcgss-module.service; static; vendor preset: disabled)
  Drop-In: /etc/systemd/system/auth-rpcgss-module.service.d
           `-override.conf
   Active: inactive (dead)
Condition: start condition failed at Mon 2019-11-25 17:14:31 PST; 1min 45s ago
           `- ConditionPathExists=/etc/krb5.keytab was not met

Nov 25 17:14:31 acai systemd[1]: Condition check resulted in Kernel Module supporting RPCSEC_GSS being skipped.

* rpc-gssd.service - RPC security service for NFS client and server
   Loaded: loaded (/usr/lib/systemd/system/rpc-gssd.service; static; vendor preset: disabled)
  Drop-In: /etc/systemd/system/rpc-gssd.service.d
           `-override.conf
   Active: inactive (dead)
Condition: start condition failed at Mon 2019-11-25 17:14:31 PST; 1min 45s ago
           `- ConditionPathExists=/etc/krb5.keytab was not met

Nov 25 17:14:31 acai systemd[1]: Condition check resulted in RPC security service for NFS client and server being skipped.

* gssproxy.service - GSSAPI Proxy Daemon
   Loaded: loaded (/usr/lib/systemd/system/gssproxy.service; disabled; vendor preset: disabled)
  Drop-In: /etc/systemd/system/gssproxy.service.d
           `-override.conf
   Active: active (running) since Mon 2019-11-25 17:14:31 PST; 1min 45s ago
 Main PID: 2026 (gssproxy)
    Tasks: 6 (limit: 4915)
   Memory: 1.4M
   CGroup: /system.slice/gssproxy.service
           `-2026 /usr/bin/gssproxy --debug --debug-level 3 --interactive

Nov 25 17:14:31 acai gssproxy[2026]: [2019/11/26 01:14:31]: Debug Enabled (level: 3)
Nov 25 17:14:31 acai gssproxy[2026]: Error when reading config directory: File /etc/gssproxy/gssproxy.conf did not match provided patterns. Skipping.
Nov 25 17:14:31 acai gssproxy[2026]: [2019/11/26 01:14:31]: Keytab /etc/krb5.keytab has no content (-1765328203)
Nov 25 17:14:31 acai gssproxy[2026]: [2019/11/26 01:14:31]: Service: nfs-server, Enckey: [ephemeral], Enctype: 18
Nov 25 17:14:31 acai gssproxy[2026]: [2019/11/26 01:14:31]: Keytab /etc/gssproxy/http.keytab has no content (-1765328203)
Nov 25 17:14:31 acai gssproxy[2026]: [2019/11/26 01:14:31]: Service: HTTP, Enckey: [ephemeral], Enctype: 18
Nov 25 17:14:31 acai gssproxy[2026]: [2019/11/26 01:14:31]: Keytab /etc/krb5.keytab has no content (-1765328203)
Nov 25 17:14:31 acai gssproxy[2026]: [2019/11/26 01:14:31]: Service: nfs-client, Enckey: [ephemeral], Enctype: 18
Nov 25 17:14:31 acai gssproxy[2026]: [2019/11/26 01:14:31]: Kernel doesn't support GSS-Proxy (can't open /proc/net/rpc/use-gss-proxy: 2 (No such file or directory))
Nov 25 17:14:31 acai gssproxy[2026]: [2019/11/26 01:14:31]: Problem with kernel communication!  NFS server will not work

* rpc-svcgssd.service - RPC security service for NFS server
   Loaded: loaded (/usr/lib/systemd/system/rpc-svcgssd.service; static; vendor preset: disabled)
   Active: inactive (dead)
Condition: start condition failed at Mon 2019-11-25 17:14:31 PST; 1min 45s ago
           `- ConditionPathExists=/etc/krb5.keytab was not met

Nov 25 17:14:31 acai systemd[1]: Condition check resulted in RPC security service for NFS server being skipped.

This is what it does...

[Nov25 17:16] kauditd_printk_skb: 1 callbacks suppressed
[  +0.000003] audit: type=1101 audit(1574730976.758:128): pid=2377 uid=1002 auid=1002 ses=1 msg='op=PAM:accounting grantors=pam_unix,pam_permit,pam_time acct="fryfrog" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/2 res=success'
[  +0.000266] audit: type=1110 audit(1574730976.758:129): pid=2377 uid=0 auid=1002 ses=1 msg='op=PAM:setcred grantors=pam_unix,pam_permit,pam_env acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/2 res=success'
[  +0.000173] audit: type=1105 audit(1574730976.758:130): pid=2377 uid=0 auid=1002 ses=1 msg='op=PAM:session_open grantors=pam_limits,pam_unix,pam_permit acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/2 res=success'
[  +0.146341] audit: type=1106 audit(1574730976.904:131): pid=2377 uid=0 auid=1002 ses=1 msg='op=PAM:session_close grantors=pam_limits,pam_unix,pam_permit acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/2 res=success'
[  +0.000185] audit: type=1104 audit(1574730976.904:132): pid=2377 uid=0 auid=1002 ses=1 msg='op=PAM:setcred grantors=pam_unix,pam_permit,pam_env acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/2 res=success'
[  +5.521133] audit: type=1101 audit(1574730982.425:133): pid=2411 uid=1002 auid=1002 ses=1 msg='op=PAM:accounting grantors=pam_unix,pam_permit,pam_time acct="fryfrog" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/2 res=success'
[  +0.000255] audit: type=1110 audit(1574730982.425:134): pid=2411 uid=0 auid=1002 ses=1 msg='op=PAM:setcred grantors=pam_unix,pam_permit,pam_env acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/2 res=success'
[  +0.000179] audit: type=1105 audit(1574730982.425:135): pid=2411 uid=0 auid=1002 ses=1 msg='op=PAM:session_open grantors=pam_limits,pam_unix,pam_permit acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/2 res=success'
[  +8.990070] audit: type=1106 audit(1574730991.419:136): pid=2411 uid=0 auid=1002 ses=1 msg='op=PAM:session_close grantors=pam_limits,pam_unix,pam_permit acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/2 res=success'
[  +0.000396] audit: type=1104 audit(1574730991.419:137): pid=2411 uid=0 auid=1002 ses=1 msg='op=PAM:setcred grantors=pam_unix,pam_permit,pam_env acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/2 res=success'
[ +20.597602] INFO: task rpc.nfsd:2044 blocked for more than 122 seconds.
[  +0.000019]       Tainted: P           OE     5.3.13-arch1-1 #2
[  +0.000009] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  +0.000012] rpc.nfsd        D    0  2044      1 0x80004080
[  +0.000008] Call Trace:
[  +0.000022]  ? __schedule+0x27f/0x6d0
[  +0.000008]  schedule+0x43/0xd0
[  +0.000007]  schedule_timeout+0x299/0x3d0
[  +0.000009]  wait_for_common+0xeb/0x190
[  +0.000008]  ? wake_up_q+0x60/0x60
[  +0.000055]  __cld_pipe_upcall+0x5e/0x90 [nfsd]
[  +0.000043]  ? alloc_cld_upcall+0xc2/0xe0 [nfsd]
[  +0.000039]  nfsd4_cld_tracking_init+0xfc/0x1d0 [nfsd]
[  +0.000039]  nfsd4_client_tracking_init+0xa5/0x160 [nfsd]
[  +0.000041]  nfs4_state_start_net+0x237/0x280 [nfsd]
[  +0.000040]  nfsd_svc+0x1c6/0x2e0 [nfsd]
[  +0.000040]  write_threads+0xb5/0x120 [nfsd]
[  +0.000042]  ? write_pool_threads+0x2c0/0x2c0 [nfsd]
[  +0.000037]  nfsctl_transaction_write+0x45/0x70 [nfsd]
[  +0.000010]  vfs_write+0xac/0x1b0
[  +0.000008]  ksys_write+0x67/0xe0
[  +0.000009]  do_syscall_64+0x4e/0x110
[  +0.000009]  entry_SYSCALL_64_after_hwframe+0x44/0xa9
[  +0.000007] RIP: 0033:0x7ffa4895d497
[  +0.000015] Code: Bad RIP value.
[  +0.000004] RSP: 002b:00007ffd9806e158 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
[  +0.000006] RAX: ffffffffffffffda RBX: 000055bf57d70440 RCX: 00007ffa4895d497
[  +0.000002] RDX: 0000000000000002 RSI: 000055bf57d70440 RDI: 0000000000000003
[  +0.000003] RBP: 0000000000000003 R08: 0000000000000002 R09: 00007ffd9806dff0
[  +0.000003] R10: 00007ffd9806dea7 R11: 0000000000000246 R12: 0000000000000000
[  +0.000003] R13: 0000000000000001 R14: 0000000000000001 R15: 000055bf5870c2a0

`sudo mount -v -t nfs acai.lan:/hot /mnt/nfs`

[Nov25 17:19] audit: type=1106 audit(1574731140.512:141): pid=2719 uid=0 auid=1002 ses=1 msg='op=PAM:session_close grantors=pam_limits,pam_unix,pam_permit acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/2 res=success'
[  +0.000168] audit: type=1104 audit(1574731140.512:142): pid=2719 uid=0 auid=1002 ses=1 msg='op=PAM:setcred grantors=pam_unix,pam_permit,pam_env acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/2 res=success'
[  +0.009848] audit: type=1101 audit(1574731140.522:143): pid=2721 uid=1002 auid=1002 ses=1 msg='op=PAM:accounting grantors=pam_unix,pam_permit,pam_time acct="fryfrog" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/2 res=success'
[  +0.000263] audit: type=1110 audit(1574731140.522:144): pid=2721 uid=0 auid=1002 ses=1 msg='op=PAM:setcred grantors=pam_unix,pam_permit,pam_env acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/2 res=success'
[  +0.000160] audit: type=1105 audit(1574731140.522:145): pid=2721 uid=0 auid=1002 ses=1 msg='op=PAM:session_open grantors=pam_limits,pam_unix,pam_permit acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/2 res=success'
[  +0.026617] FS-Cache: Loaded
[  +0.045195] FS-Cache: Netfs 'nfs' registered for caching
[  +0.006934] Key type dns_resolver registered
[  +0.222071] NFS: Registering the id_resolver key type
[  +0.000017] Key type id_resolver registered
[  +0.000002] Key type id_legacy registered

sudo mount -v -t nfs acai.lan:/hot /mnt/nfs w/ rpcdebug -m rpc -s all

[Nov25 17:20] audit: type=1106 audit(1574731249.055:181): pid=3267 uid=0 auid=1002 ses=1 msg='op=PAM:session_close grantors=pam_limits,pam_unix,pam_permit acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/2 res=success'
[  +0.000164] audit: type=1104 audit(1574731249.055:182): pid=3267 uid=0 auid=1002 ses=1 msg='op=PAM:setcred grantors=pam_unix,pam_permit,pam_env acct="root" exe="/usr/bin/sudo" hostname=? addr=? terminal=/dev/pts/2 res=success'
[  +0.018327] RPC:       set up xprt to 10.0.1.9 (port 2049) via tcp
[  +0.000015] RPC:       created transport 0000000076206fc4 with 65536 slots
[  +0.000003] RPC:       creating nfs client for acai.lan (xprt 0000000076206fc4)
[  +0.000034] RPC:       Couldn't create auth handle (flavor 390004)
[  +0.000014] RPC:       destroying transport 0000000076206fc4
[  +0.000013] RPC:        destroy backchannel transport
[  +0.000001] RPC:        backchannel list empty= true
[  +0.000002] RPC:       xs_destroy xprt 0000000076206fc4
[  +0.000001] RPC:       xs_close xprt 0000000076206fc4
[  +0.000007] RPC:       set up xprt to 10.0.1.9 (port 2049) via tcp
[  +0.000004] RPC:       created transport 0000000052b792c8 with 65536 slots
[  +0.000002] RPC:       creating nfs client for acai.lan (xprt 0000000052b792c8)
[  +0.000014] RPC:       new task initialized, procpid 3271
[  +0.000002] RPC:       allocated task 00000000523d3b23
[  +0.000002] RPC:    27 __rpc_execute flags=0x690
[  +0.000002] RPC:    27 call_start nfs4 proc NULL (sync)
[  +0.000001] RPC:    27 call_reserve (status 0)
[  +0.000002] RPC:    27 reserved req 000000007f5d5f8d xid d991f247
[  +0.000001] RPC:    27 call_reserveresult (status 0)
[  +0.000001] RPC:    27 call_refresh (status 0)
[  +0.000002] RPC:    27 call_refreshresult (status 0)
[  +0.000001] RPC:    27 call_allocate (status 0)
[  +0.000002] RPC:    27 allocated buffer of size 96 at 000000000a02cdf0
[  +0.000001] RPC:    27 call_encode (status 0)
[  +0.000004] RPC:    27 call_connect xprt 0000000052b792c8 is not connected
[  +0.000001] RPC:    27 xprt_prepare_transmit
[  +0.000002] RPC:    27 xprt_connect xprt 0000000052b792c8 is not connected
[  +0.000002] RPC:    27 sleep_on(queue "xprt_pending" time 4295022028)
[  +0.000001] RPC:    27 added to queue 0000000084156fa1 "xprt_pending"
[  +0.000001] RPC:    27 setting alarm for 60000 ms
[  +0.000002] RPC:       xs_connect scheduled xprt 0000000052b792c8
[  +0.000011] RPC:    27 sync task going to sleep
[  +0.000028] RPC:       xs_bind 0.0.0.0:991: ok (0)
[  +0.000004] RPC:       worker connecting xprt 0000000052b792c8 via tcp to 10.0.1.9 (port 2049)
[  +0.000068] RPC:       xs_tcp_state_change client 0000000052b792c8...
[  +0.000002] RPC:       state 1 conn 0 dead 0 zapped 1 sk_shutdown 0
[  +0.000022] svc: socket 00000000b6359869 TCP (listen) state change 10
[  +0.000004] RPC:       0000000052b792c8 connect status 115 connected 1 sock state 1
[  +0.000002] RPC:       wake_up_first(000000007922883a "xprt_sending")
[  +0.000003] RPC:    27 __rpc_wake_up_task (now 4295022028)
[  +0.000001] RPC:    27 disabling timer
[  +0.000002] RPC:    27 removed from queue 0000000084156fa1 "xprt_pending"
[  +0.000007] RPC:       __rpc_wake_up_task done
[  +0.000005] RPC:    27 sync task resuming
[  +0.000001] RPC:    27 call_connect_status (status -11)
[  +0.000002] RPC:    27 call_transmit (status 0)
[  +0.000000] RPC:    27 xprt_prepare_transmit
[  +0.000024] svc: socket 00000000a7e8bc96 TCP (listen) state change 1
[  +0.000012] RPC:       xs_tcp_send_request(40) = 0
[  +0.000002] RPC:       wake_up_first(000000007922883a "xprt_sending")
[  +0.000002] RPC:    27 sleep_on(queue "xprt_pending" time 4295022028)
[  +0.000001] RPC:    27 added to queue 0000000084156fa1 "xprt_pending"
[  +0.000000] RPC:    27 setting alarm for 60000 ms
[  +0.000002] RPC:    27 sync task going to sleep

Last edited by fryfrog (2019-11-26 01:27:55)

Offline

#2 2019-11-26 04:31:53

fryfrog
Member
Registered: 2019-11-13
Posts: 7

Re: NFS Server Issues on Odroid H2

And it *works* on 4.19.86, but *only* if I don't use CIDR notation like `10.0.1.0/24`, so I've just defined all the individual hosts.

Linux acai 4.19.86-1-lts #1 SMP Mon, 25 Nov 2019 06:42:03 +0000 x86_64 GNU/Linux

So weird. hmm

Offline

#3 2019-12-17 22:35:27

vianney
Member
Registered: 2019-12-17
Posts: 2

Re: NFS Server Issues on Odroid H2

Hi fryfrog,

I upgraded today from 5.3.x to 5.4.3 (on an intel NUC) and noticed nfs service was not working anymore, hanging when I was starting it, until timeout and having the same behavior when I tried to stop it.
Unfortunately, I did not have time to look much at logs but I could see that nfsdcld was also stopping with segfault. rpc.nfsd then hung.

I will try to take some time to investigate in the coming days. I would like to prevent downgrading software/kernel version on my box. Did you find anything beside what you posted here since you encountered this issue ?

Offline

#4 2019-12-17 23:01:12

fryfrog
Member
Registered: 2019-11-13
Posts: 7

Re: NFS Server Issues on Odroid H2

Nothing since getting it working on the LTS kernel. I've *got* the normal kernel on it, so I could boot it for more troubleshooting. hmm

Offline

#5 2020-01-03 13:38:38

vianney
Member
Registered: 2019-12-17
Posts: 2

Re: NFS Server Issues on Odroid H2

For future readers:

I stopped investigating a few days after my message and removed nfs-utils. I now use glusterfs with nfs support for shares where I couldn't do otherwise.

Offline

#6 2020-06-26 18:58:07

fryfrog
Member
Registered: 2019-11-13
Posts: 7

Re: NFS Server Issues on Odroid H2

I just want to follow up and say that I went with @vianney's solution too, I setup glusterfs on the "server" and just use it on the clients as well (not nfs). Its working fine at least.

Offline

Board footer

Powered by FluxBB