FS_ENET ERROR(s) 0x12 at second NFS RPC port lookup (100005/1)
Remi Lefevre
rlefevre at gmail.com
Wed Oct 1 02:44:37 EST 2008
Hi,
I use static IP config to boot Linux-2.6.27-rc7 denx from NFS on a MPC8270
custom board. The first NFS RPC port lookup completes successfully:
[ 2.892607] Looking up port of RPC 100003/2 on 192.168.0.1
...
[ 5.308767] Root-NFS: Portmapper on server returned 2049 as nfsd port
No fs_enet error is reported.
But the second RPC port lookup fails with a fs_net error:
[ 5.315243] Looking up port of RPC 100005/1 on 192.168.0.1
...
[ 5.528022] RPC: 2 call_bind (status 0)
[ 5.532280] RPC: 2 call_connect xprt c7853400 is connected
[ 5.538185] RPC: 2 call_transmit (status 0)
[ 5.542767] RPC: 2 xprt_prepare_transmit
[ 5.547091] RPC: 2 rpc_xdr_encode (status 0)
[ 5.551757] RPC: 2 marshaling UNIX cred c78ed800
[ 5.556776] RPC: 2 using AUTH_UNIX cred c78ed800 to wrap rpc data
[ 5.563292] RPC: rpcb_encode_mapping(100005, 1, 17, 0)
[ 5.569024] RPC: 2 xprt_transmit(80)
[ 5.573391] fs_enet: eth0 FS_ENET ERROR(s) 0x12
[ 5.577958] RPC: xs_udp_send_request(80) = 80
[ 5.582809] RPC: 2 xmit complete
On a side note, the upper layer does not seem to notice the error as it
returns a "rpcbind: server not responding, timed out" error after a while,
but the port lookup is never received by the server.
At this moment (before the reboot after 180 seconds), ping requests also lead
to "FS_ENET ERROR(s) 0x12" but ARP requests are still answered correctly.
I get the same behavior if I use FCC2 instead of FCC1.
Any idea would be greatly appreciated.
Best regards,
Rémi
Tcpdump:
1 0.000000 da:b0:4e:0f:0a:26 Broadcast ARP Who
has 192.168.0.1? Tell 192.168.0.42
2 0.000032 Giga-Byt_72:7c:b6 da:b0:4e:0f:0a:26 ARP
192.168.0.1 is at 00:20:ed:72:7c:b6
3 0.000209 192.168.0.42 192.168.0.1 Portmap V2
GETPORT Call (Reply In 4) NFS(100003) V:2 UDP
4 0.000467 192.168.0.1 192.168.0.42 Portmap V2
GETPORT Reply (Call In 3) Port:2049
5 4.996926 Giga-Byt_72:7c:b6 da:b0:4e:0f:0a:26 ARP Who
has 192.168.0.42? Tell 192.168.0.1
6 4.997151 da:b0:4e:0f:0a:26 Giga-Byt_72:7c:b6 ARP
192.168.0.42 is at da:b0:4e:0f:0a:26
7 9.293063 192.168.0.1 192.168.0.42 ICMP
Echo (ping) request
8 10.292965 192.168.0.1 192.168.0.42 ICMP
Echo (ping) request
9 11.292976 192.168.0.1 192.168.0.42 ICMP
Echo (ping) request
[...other ping...]
12 20.394112 Giga-Byt_72:7c:b6 Broadcast ARP
Who has 192.168.0.42? Tell 192.168.0.1
13 20.394337 da:b0:4e:0f:0a:26 Giga-Byt_72:7c:b6 ARP
192.168.0.42 is at da:b0:4e:0f:0a:26
Boot:
[ 0.000000] Linux version 2.6.27-rc7 (gcc version 4.2.2) #3 Tue Sep
30 17:30:39 CEST 2008
...
[ 0.000000] Zone PFN ranges:
[ 0.000000] DMA 0x00000000 -> 0x00008000
[ 0.000000] Normal 0x00008000 -> 0x00008000
[ 0.000000] Movable zone start PFN for each node
[ 0.000000] early_node_map[1] active PFN ranges
[ 0.000000] 0: 0x00000000 -> 0x00008000
[ 0.000000] paging_init done
[ 0.000000] Built 1 zonelists in Zone order, mobility grouping on.
Total pages: 32512
[ 0.000000] Kernel command line: root=/dev/nfs rw
nfsroot=192.168.0.1:/opt/eldk-4.2/ppc_6xx
ip=192.168.0.42:192.168.0.1:192.168.0.1:255.255.255.0:dmyx:eth0:off
console=ttyCPM0,115200n8
[ 0.000000] IP-Config: Parameter #0: `192.168.0.42'
[ 0.000000] IP-Config: Parameter #1: `192.168.0.1'
[ 0.000000] IP-Config: Parameter #2: `192.168.0.1'
[ 0.000000] IP-Config: Parameter #3: `255.255.255.0'
[ 0.000000] IP-Config: Parameter #4: `dmyx'
[ 0.000000] IP-Config: Parameter #5: `eth0'
[ 0.000000] IP-Config: Parameter #6: `off'
[ 0.000000] PID hash table entries: 512 (order: 9, 2048 bytes)
[ 0.000000] clocksource: timebase mult[c0e6b75] shift[22] registered
[ 0.000392] console [ttyCPM0] enabled
[ 0.189357] Dentry cache hash table entries: 16384 (order: 4, 65536 bytes)
[ 0.197491] Inode-cache hash table entries: 8192 (order: 3, 32768 bytes)
[ 0.232601] Memory: 127044k/131072k available (2508k kernel code,
3884k reserved, 92k data, 119k bss, 144k init)
[ 0.243001] SLUB: Genslabs=12, HWalign=32, Order=0-3, MinObjects=0,
CPUs=1, Nodes=1
[ 0.250648] Calibrating delay loop... 41.34 BogoMIPS (lpj=82688)
[ 0.333226] Mount-cache hash table entries: 512
[ 0.342369] net_namespace: 288 bytes
[ 0.346805] NET: Registered protocol family 16
[ 0.382394] NET: Registered protocol family 2
[ 0.419811] IP route cache hash table entries: 1024 (order: 0, 4096 bytes)
[ 0.428192] TCP established hash table entries: 4096 (order: 3, 32768 bytes)
[ 0.435713] TCP bind hash table entries: 4096 (order: 2, 16384 bytes)
[ 0.442368] TCP: Hash tables configured (established 4096 bind 4096)
[ 0.448703] TCP reno registered
[ 0.463908] NET: Registered protocol family 1
[ 0.522188] RPC: creating workqueue nfsiod
[ 0.530731] RPC: registering /proc/net/rpc
[ 0.535382] RPC: registering /proc/net/rpc/nfs
[ 0.540622] JFFS2 version 2.2. (NAND) (c) 2001-2006 Red Hat, Inc.
[ 0.550555] msgmni has been set to 248
[ 0.554665] io scheduler noop registered
[ 0.558480] io scheduler anticipatory registered (default)
[ 0.564036] io scheduler deadline registered
[ 0.568701] io scheduler cfq registered
[ 1.199635] ttyCPM0 at MMIO 0xc905ca90 (irq = 16) is a CPM UART
[ 1.231991] brd: module loaded
[ 1.247199] loop: module loaded
[ 1.254228] eth0: fs_enet: da:b0:4e:0f:0a:26
[ 1.261053] eth1: fs_enet: b6:e1:11:b2:0b:22
[ 1.269971] CPM2 Bitbanged MII: probed
[ 1.276396] i2c /dev entries driver
[ 1.285576] TCP cubic registered
[ 1.288787] NET: Registered protocol family 17
[ 1.294319] RPC: creating workqueue rpciod
[ 1.299932] RPC: registering /proc/net/rpc
[ 1.304679] svc: Adding svc transport class 'tcp'
[ 1.309280] svc: Adding svc transport class 'udp'
[ 1.314193] RPC: Registered udp transport module.
[ 1.318798] RPC: Registered tcp transport module.
[ 1.327533] IP-Config: Entered.
[ 1.832825] IP-Config: eth0 UP (able=1, xid=de9a95b6)
[ 2.839908] IP-Config: Complete:
[ 2.842777] device=eth0, addr=192.168.0.42,
mask=255.255.255.0, gw=192.168.0.1,
[ 2.850513] host=dmyx, domain=, nis-domain=(none),
[ 2.855885] bootserver=192.168.0.1, rootserver=192.168.0.1, rootpath=
[ 2.863596] Root-NFS: Mounting /opt/eldk-4.2/ppc_6xx on server
192.168.0.1 as root
[ 2.871169] Root-NFS: rsize = 4096, wsize = 4096, timeo = 0, retrans = 0
[ 2.878320] Root-NFS: acreg (min,max) = (3,60), acdir (min,max) = (30,60)
[ 2.885552] Root-NFS: nfsd port = -1, mountd port = 0, flags = 00000200
[ 2.892607] Looking up port of RPC 100003/2 on 192.168.0.1
[ 2.898164] RPC: rpcb_getport_sync(192.168.0.1, 100003, 2, 17)
[ 2.904746] RPC: set up transport to address addr=192.168.0.1
port=111 proto=udp
[ 2.912641] RPC: created transport c7853400 with 16 slots
[ 2.918616] RPC: creating rpcbind client for 192.168.0.1
(xprt c7853400)
...
[ 2.892607] Looking up port of RPC 100003/2 on 192.168.0.1
...
(exactly identical to next request except the port number and no fs_enet error)
...
[ 5.308767] Root-NFS: Portmapper on server returned 2049 as nfsd port
[ 5.315243] Looking up port of RPC 100005/1 on 192.168.0.1
[ 5.320808] RPC: rpcb_getport_sync(192.168.0.1, 100005, 1, 17)
[ 5.327404] RPC: set up transport to address addr=192.168.0.1
port=111 proto=udp
[ 5.335305] RPC: created transport c7853400 with 16 slots
[ 5.341283] RPC: creating rpcbind client for 192.168.0.1
(xprt c7853400)
[ 5.348608] RPC: creating UNIX authenticator for client c7895200
[ 5.355213] RPC: 0 looking up UNIX cred
[ 5.359459] RPC: looking up UNIX cred
[ 5.363677] RPC: allocating UNIX cred for uid 0 gid 0
[ 5.369325] RPC: new task initialized, procpid 1
[ 5.374494] RPC: allocated task c783c500
[ 5.379020] RPC: 2 __rpc_execute flags=0x280
[ 5.383684] RPC: 2 call_start rpcbind2 proc GETPORT (sync)
[ 5.389608] RPC: 2 call_reserve (status 0)
[ 5.394078] RPC: 2 reserved req c780b000 xid cc0a6feb
[ 5.399573] RPC: 2 call_reserveresult (status 0)
[ 5.404599] RPC: 2 call_allocate (status 0)
[ 5.409186] RPC: 2 allocated buffer of size 412 at c7983000
[ 5.415178] RPC: 2 call_bind (status 0)
[ 5.419388] RPC: 2 call_connect xprt c7853400 is not connected
[ 5.425679] RPC: 2 xprt_connect xprt c7853400 is not connected
[ 5.431937] RPC: 2 xprt_cwnd_limited cong = 0 cwnd = 256
[ 5.437670] RPC: 2 sleep_on(queue "xprt_pending" time 4294893603)
[ 5.444190] RPC: 2 added to queue c7853588 "xprt_pending"
[ 5.449939] RPC: 2 setting alarm for 5000 ms
[ 5.454675] RPC: xs_connect scheduled xprt c7853400
[ 5.460155] RPC: 2 sync task going to sleep
[ 5.464810] RPC: disconnected transport c7853400
[ 5.469949] RPC: 2 __rpc_wake_up_task (now 4294893611)
[ 5.475485] RPC: 2 disabling timer
[ 5.479202] RPC: 2 removed from queue c7853588 "xprt_pending"
[ 5.485458] RPC: __rpc_wake_up_task done
[ 5.489926] RPC: unx_free_cred c78edd00
[ 5.494450] RPC: xs_bind4 0.0.0.0:0: ok (0)
[ 5.499138] RPC: worker connecting xprt c7853400 to address:
addr=192.168.0.1 port=111 proto=udp
[ 5.508664] RPC: 2 sync task resuming
[ 5.512595] RPC: 2 xprt_connect_status: connection broken
[ 5.518409] RPC: 2 call_connect_status (status -107)
[ 5.523794] RPC: 2 call_timeout (minor)
[ 5.528022] RPC: 2 call_bind (status 0)
[ 5.532280] RPC: 2 call_connect xprt c7853400 is connected
[ 5.538185] RPC: 2 call_transmit (status 0)
[ 5.542767] RPC: 2 xprt_prepare_transmit
[ 5.547091] RPC: 2 rpc_xdr_encode (status 0)
[ 5.551757] RPC: 2 marshaling UNIX cred c78ed800
[ 5.556776] RPC: 2 using AUTH_UNIX cred c78ed800 to wrap rpc data
[ 5.563292] RPC: rpcb_encode_mapping(100005, 1, 17, 0)
[ 5.569024] RPC: 2 xprt_transmit(80)
[ 5.573391] fs_enet: eth0 FS_ENET ERROR(s) 0x12
[ 5.577958] RPC: xs_udp_send_request(80) = 80
[ 5.582809] RPC: 2 xmit complete
[ 5.586425] RPC: 2 sleep_on(queue "xprt_pending" time 4294893640)
[ 5.592951] RPC: 2 added to queue c7853588 "xprt_pending"
[ 5.598754] RPC: 2 setting alarm for 10000 ms
[ 5.603537] RPC: 2 sync task going to sleep
... (other retries)
[ 35.795325] rpcbind: server 192.168.0.1 not responding, timed out
[ 35.881159] Root-NFS: Unable to get mountd port number from server,
using default
[ 35.888727] Root-NFS: mountd port is 627
[ 35.892664] NFS: sending MNT request for server:/opt/eldk-4.2/ppc_6xx
[ 66.422513] NFS: failed to create RPC client, status=-5
[ 66.427765] Root-NFS: Server returned error -5 while mounting
/opt/eldk-4.2/ppc_6xx
[ 66.435693] VFS: Unable to mount root fs via NFS, trying floppy.
[ 66.442262] VFS: Cannot open root device "nfs" or unknown-block(2,0)
[ 66.448655] Please append a correct "root=" boot option; here are
the available partitions:
[ 66.457179] Kernel panic - not syncing: VFS: Unable to mount root
fs on unknown-block(2,0)
[ 66.465454] Rebooting in 180 seconds..
DTS soc parts:
soc at f0000000 {
#address-cells = <1>;
#size-cells = <1>;
device_type = "soc";
compatible = "fsl,mpc8280", "fsl,pq2-soc", "simple-bus";
ranges = <0x00000000 0xf0000000 0x00053000>;
// Temporary -- will go away once kernel uses ranges for get_immrbase().
reg = <0xf0000000 0x00053000>;
cpm at 119c0 {
#address-cells = <1>;
#size-cells = <1>;
#interrupt-cells = <2>;
compatible = "fsl,mpc8280-cpm", "fsl,cpm2", "simple-bus";
reg = <0x119c0 0x30>;
ranges;
clock-frequency = <290304000>;
muram at 0 {
#address-cells = <1>;
#size-cells = <1>;
ranges = <0 0 0x10000>;
data at 0 {
compatible = "fsl,cpm-muram-data";
reg = <0x0 0x2000 0x9800 0x800>;
};
};
brg at 119f0 {
compatible = "fsl,mpc8280-brg", "fsl,cpm2-brg";
reg = <0x119f0 0x10 0x115f0 0x10>;
/*clock-frequency = <36288000>; Do I need this ? */
};
...
fcc1: ethernet at 11300 {
device_type = "network";
compatible = "fsl,mpc8280-fcc-enet",
"fsl,cpm2-fcc-enet";
reg = <0x11300 0x20 0x8400 0x100 0x11390 0x1>;
interrupts = <32 8>;
interrupt-parent = <&PIC>;
phy-handle = <&PHY1>;
linux,network-index = <0>;
fsl,cpm-command = <0x12000300>;
};
...
More information about the Linuxppc-embedded
mailing list