Re: Kernel NFS boot failure
From: Grygorii Strashko
Date: Fri Aug 19 2016 - 07:20:35 EST
Hi All,
On 08/11/2016 07:25 PM, Grygorii Strashko wrote:
> On 08/03/2016 06:04 PM, Grygorii Strashko wrote:
>> Hi Vladimir,
>>
>> On 08/03/2016 03:06 PM, Vladimir Murzin wrote:
>>> On 03/08/16 12:41, Grygorii Strashko wrote:
>>>> We observe Kernel boot failure while running NFS boot stress test (1000 iterations):
>>>> - Linux version 4.7.0
>>
>> I'd like to pay your attention that this issue also reproducible with
>> Kernel 4.7.0!
>> The same can be seen from the log I've provided in first e-mail:
>> [ 0.000000] Linux version 4.7.0 (lcpdbld@xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx) (gcc version 4.9.3 20150413 (prerelease) (Linaro GCC 4.9-2015.05) ) #1 SMP Fri Jul 29 17:41:27 CDT 2016
>>
>>
>> I've not run the test with current master at it's not been tagged yet.
>
> Still in progress. rc1 unstable on my platforms due to other issues :(
>
>>
>>>> - am335x-evm (TI AM335x EVM)
>>>> - failure rate 10-20 times per test.
>>>> Originally this issue was reproduced using TI Kernel 4.4
>>>> ( git://git.ti.com/ti-linux-kernel/ti-linux-kernel.git, branch: ti-linux-4.4.y)
>>>> on both am335x-evm and am57xx-beagle-x15(am57xx-evm) platforms.
>>>> This issues has not been reproduced with TI Kernel 4.1 before.
>>>>
>>>> The SysRq shows that system stuck in nfs_fs_mount()
>>>>
>>>> [ 207.904632] [<c07ab34c>] (schedule) from [<c0783554>] (rpc_wait_bit_killable+0x2c/0xd8)
>>>> [ 207.912996] [<c0783554>] (rpc_wait_bit_killable) from [<c07ab7f0>] (__wait_on_bit+0x84/0xc0)
>>>> [ 207.921812] [<c07ab7f0>] (__wait_on_bit) from [<c07ab890>] (out_of_line_wait_on_bit+0x64/0x70)
>>>> [ 207.930810] [<c07ab890>] (out_of_line_wait_on_bit) from [<c07843f4>] (__rpc_execute+0x18c/0x544)
>>>> [ 207.939988] [<c07843f4>] (__rpc_execute) from [<c0779f24>] (rpc_run_task+0x13c/0x158)
>>>> [ 207.948166] [<c0779f24>] (rpc_run_task) from [<c0779f84>] (rpc_call_sync+0x44/0xc4)
>>>> [ 207.956163] [<c0779f84>] (rpc_call_sync) from [<c077a04c>] (rpc_ping+0x48/0x68)
>>>> [ 207.963796] [<c077a04c>] (rpc_ping) from [<c077a158>] (rpc_create_xprt+0xec/0x164)
>>>> [ 207.971702] [<c077a158>] (rpc_create_xprt) from [<c077a2c0>] (rpc_create+0xf0/0x1a0)
>>>> [ 207.979794] [<c077a2c0>] (rpc_create) from [<c0393088>] (nfs_create_rpc_client+0xd4/0xec)
>>>> [ 207.988338] [<c0393088>] (nfs_create_rpc_client) from [<c0394d10>] (nfs_init_client+0x20/0x78)
>>>> [ 207.997332] [<c0394d10>] (nfs_init_client) from [<c03949d4>] (nfs_create_server+0xa0/0x3bc)
>>>> [ 208.006057] [<c03949d4>] (nfs_create_server) from [<c03b197c>] (nfs3_create_server+0x8/0x20)
>>>> [ 208.014879] [<c03b197c>] (nfs3_create_server) from [<c03a34c4>] (nfs_try_mount+0xc4/0x1f0)
>>>> [ 208.023513] [<c03a34c4>] (nfs_try_mount) from [<c03a2c48>] (nfs_fs_mount+0x290/0x910)
>>>> [ 208.031702] [<c03a2c48>] (nfs_fs_mount) from [<c0294d24>] (mount_fs+0x44/0x168)
>>>>
I was able to reproduce this issue with NFS/SUNRPC debug logs enabled using TI kernel 4.4.
I'd be appreciated for any help :( and be happy to run any kind of tests or check debug patches if needed.
>From the logs I found that problem happens when rpc_task 2 is freeing too late as in the below log.
(marked as [GS])
Starting kernel ...
[ 0.000000] Booting Linux on physical CPU 0x0
[ 0.000000] Initializing cgroup subsys cpuset
[ 0.000000] Initializing cgroup subsys cpu
[ 0.000000] Initializing cgroup subsys cpuacct
[ 0.000000] Linux version 4.4.18-32575-g5db1dce (lcpdbld@xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx) (gcc version 4.9.3 20150413 (prerelease) (Linaro GCC 4.9-2015.05) ) #2 SMP PREEMPT Wed Aug 17 10:49:14 CDT 2016
[ 0.000000] CPU: ARMv7 Processor [412fc0f2] revision 2 (ARMv7), cr=30c5387d
[ 0.000000] CPU: PIPT / VIPT nonaliasing data cache, PIPT instruction cache
[ 0.000000] Machine model: TI AM5728 EVM
[ 0.000000] Reserved memory: created CMA memory pool at 0x0000000095800000, size 56 MiB
[ 0.000000] Reserved memory: initialized node ipu2_cma@95800000, compatible id shared-dma-pool
[ 0.000000] Reserved memory: created CMA memory pool at 0x0000000099000000, size 64 MiB
[ 0.000000] Reserved memory: initialized node dsp1_cma@99000000, compatible id shared-dma-pool
[ 0.000000] Reserved memory: created CMA memory pool at 0x000000009d000000, size 32 MiB
[ 0.000000] Reserved memory: initialized node ipu1_cma@9d000000, compatible id shared-dma-pool
[ 0.000000] Reserved memory: created CMA memory pool at 0x000000009f000000, size 8 MiB
[ 0.000000] Reserved memory: initialized node dsp2_cma@9f000000, compatible id shared-dma-pool
[ 0.000000] cma: Reserved 24 MiB at 0x00000000fe400000
[ 0.000000] Forcing write-allocate cache policy for SMP
[ 0.000000] Memory policy: Data cache writealloc
[ 0.000000] OMAP4: Map 0x00000000ffd00000 to fe600000 for dram barrier
[ 0.000000] DRA752 ES1.1
[ 0.000000] PERCPU: Embedded 11 pages/cpu @eed31000 s14848 r8192 d22016 u45056
[ 0.000000] Built 1 zonelists in Zone order, mobility grouping on. Total pages: 521792
[ 0.000000] Kernel command line: console=ttyO2,115200n8 earlyprintk=serial,ttyO2,115200n8 rootwait ip=:::::eth0:dhcp root=/dev/nfs rw nfsroot=192.168.0.1:/home/tigtfarm10/NFS_exports/linux/am57xx-evm/autofs/f1a395609921e4cdad1b0bb2ec56f877,nolock,v3,tcp,rsize=4096,wsize=4096
[ 0.000000] PID hash table entries: 4096 (order: 2, 16384 bytes)
[ 0.000000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
[ 0.000000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
[ 0.000000] Memory: 1875576K/2094080K available (6523K kernel code, 358K rwdata, 2408K rodata, 336K init, 289K bss, 30088K reserved, 188416K cma-reserved, 1283072K highmem)
[ 0.000000] Virtual kernel memory layout:
[ 0.000000] vector : 0xffff0000 - 0xffff1000 ( 4 kB)
[ 0.000000] fixmap : 0xffc00000 - 0xfff00000 (3072 kB)
[ 0.000000] vmalloc : 0xf0800000 - 0xff800000 ( 240 MB)
[ 0.000000] lowmem : 0xc0000000 - 0xf0000000 ( 768 MB)
[ 0.000000] pkmap : 0xbfe00000 - 0xc0000000 ( 2 MB)
[ 0.000000] modules : 0xbf000000 - 0xbfe00000 ( 14 MB)
[ 0.000000] .text : 0xc0008000 - 0xc08c106c (8933 kB)
[ 0.000000] .init : 0xc08c2000 - 0xc0916000 ( 336 kB)
[ 0.000000] .data : 0xc0916000 - 0xc096f9a0 ( 359 kB)
[ 0.000000] .bss : 0xc0972000 - 0xc09ba6b0 ( 290 kB)
[ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=2, Nodes=1
[ 0.000000] Preemptible hierarchical RCU implementation.
[ 0.000000] Build-time adjustment of leaf fanout to 32.
[ 0.000000] NR_IRQS:16 nr_irqs:16 16
[ 0.000000] OMAP clockevent source: timer1 at 32786 Hz
[ 0.000000] Architected cp15 timer(s) running at 6.14MHz (virt).
[ 0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x16af5adb9, max_idle_ns: 440795202250 ns
[ 0.000004] sched_clock: 56 bits at 6MHz, resolution 162ns, wraps every 4398046511023ns
[ 0.000015] Switching to timer-based delay loop, resolution 162ns
[ 0.000328] clocksource: 32k_counter: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 58327039986419 ns
[ 0.000337] OMAP clocksource: 32k_counter at 32768 Hz
[ 0.000760] Console: colour dummy device 80x30
[ 0.000776] WARNING: Your 'console=ttyO2' has been replaced by 'ttyS2'
[ 0.000782] This ensures that you still see kernel messages. Please
[ 0.000788] update your kernel commandline.
[ 0.000801] Calibrating delay loop (skipped), value calculated using timer frequency.. 12.29 BogoMIPS (lpj=61475)
[ 0.000814] pid_max: default: 32768 minimum: 301
[ 0.000906] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes)
[ 0.000916] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes)
[ 0.001461] Initializing cgroup subsys io
[ 0.001478] Initializing cgroup subsys memory
[ 0.001502] Initializing cgroup subsys devices
[ 0.001514] Initializing cgroup subsys freezer
[ 0.001525] Initializing cgroup subsys perf_event
[ 0.001536] Initializing cgroup subsys pids
[ 0.001562] CPU: Testing write buffer coherency: ok
[ 0.001764] /cpus/cpu@0 missing clock-frequency property
[ 0.001781] /cpus/cpu@1 missing clock-frequency property
[ 0.001791] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
[ 0.001827] Setting up static identity map for 0x800082c0 - 0x80008318
[ 0.080183] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
[ 0.080250] Brought up 2 CPUs
[ 0.080262] SMP: Total of 2 processors activated (24.59 BogoMIPS).
[ 0.080269] CPU: All CPU(s) started in SVC mode.
[ 0.080643] devtmpfs: initialized
[ 0.106472] VFP support v0.3: implementor 41 architecture 4 part 30 variant f rev 0
[ 0.107342] omap_hwmod: l3_main_2 using broken dt data from ocp
[ 0.304568] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[ 0.308002] pinctrl core: initialized pinctrl subsystem
[ 0.308848] NET: Registered protocol family 16
[ 0.309801] DMA: preallocated 256 KiB pool for atomic coherent allocations
[ 0.340242] cpuidle: using governor ladder
[ 0.370275] cpuidle: using governor menu
[ 0.378776] OMAP GPIO hardware version 0.1
[ 0.385225] irq: no irq domain found for /ocp/l4@4a000000/scm@2000/pinmux@1400 !
[ 0.409647] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
[ 0.409657] hw-breakpoint: maximum watchpoint size is 8 bytes.
[ 0.410122] omap4_sram_init:Unable to allocate sram needed to handle errata I688
[ 0.410131] omap4_sram_init:Unable to get sram pool needed to handle errata I688
[ 0.410723] OMAP DMA hardware revision 0.0
[ 0.444520] omap-dma-engine 4a056000.dma-controller: OMAP DMA engine driver
[ 0.445630] edma 43300000.edma: memcpy is disabled
[ 0.450477] edma 43300000.edma: TI EDMA DMA engine driver
[ 0.454327] omap-iommu 40d01000.mmu: 40d01000.mmu registered
[ 0.454507] omap-iommu 40d02000.mmu: 40d02000.mmu registered
[ 0.454658] omap-iommu 58882000.mmu: 58882000.mmu registered
[ 0.454806] omap-iommu 55082000.mmu: 55082000.mmu registered
[ 0.455061] omap-iommu 41501000.mmu: 41501000.mmu registered
[ 0.455249] omap-iommu 41502000.mmu: 41502000.mmu registered
[ 0.458152] palmas 0-0058: Irq flag is 0x00000008
[ 0.472649] palmas 0-0058: Muxing GPIO 2f, PWM 0, LED 0
[ 0.554028] omap_i2c 48070000.i2c: bus 0 rev0.12 at 400 kHz
[ 0.554526] omap_i2c 48060000.i2c: bus 2 rev0.12 at 400 kHz
[ 0.555103] omap_i2c 4807c000.i2c: bus 4 rev0.12 at 400 kHz
[ 0.555313] media: Linux media interface: v0.10
[ 0.555368] Linux video capture interface: v2.00
[ 0.555410] pps_core: LinuxPPS API ver. 1 registered
[ 0.555417] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@xxxxxxxx>
[ 0.555443] PTP clock support registered
[ 0.555490] EDAC MC: Ver: 3.0.0
[ 0.556248] omap-mailbox 4883c000.mailbox: omap mailbox rev 0x400
[ 0.556543] omap-mailbox 4883e000.mailbox: omap mailbox rev 0x400
[ 0.556831] omap-mailbox 48840000.mailbox: omap mailbox rev 0x400
[ 0.557123] omap-mailbox 48842000.mailbox: omap mailbox rev 0x400
[ 0.557444] Advanced Linux Sound Architecture Driver Initialized.
[ 0.558290] clocksource: Switched to clocksource arch_sys_counter
[ 0.569416] NET: Registered protocol family 2
[ 0.569913] TCP established hash table entries: 8192 (order: 3, 32768 bytes)
[ 0.569977] TCP bind hash table entries: 8192 (order: 4, 65536 bytes)
[ 0.570101] TCP: Hash tables configured (established 8192 bind 8192)
[ 0.570149] UDP hash table entries: 512 (order: 2, 16384 bytes)
[ 0.570180] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
[ 0.570325] NET: Registered protocol family 1
[ 0.570361] RPC: creating workqueue rpciod
[ 0.570524] RPC: registering /proc/net/rpc
[ 0.570662] svc: Adding svc transport class 'tcp'
[ 0.570670] svc: Adding svc transport class 'udp'
[ 0.570687] RPC: Registered named UNIX socket transport module.
[ 0.570694] RPC: Registered udp transport module.
[ 0.570699] RPC: Registered tcp transport module.
[ 0.570705] RPC: Registered tcp NFSv4.1 backchannel transport module.
[ 0.571727] hw perfevents: enabled with armv7_cortex_a15 PMU driver, 7 counters available
[ 0.574145] futex hash table entries: 512 (order: 3, 32768 bytes)
[ 0.582005] squashfs: version 4.0 (2009/01/31) Phillip Lougher
[ 0.582247] RPC: creating workqueue nfsiod
[ 0.582620] RPC: registering /proc/net/rpc/nfs
[ 0.582669] NFS: Registering the id_resolver key type
[ 0.582700] Key type id_resolver registered
[ 0.582707] Key type id_legacy registered
[ 0.582770] ntfs: driver 2.1.32 [Flags: R/O].
[ 0.584763] bounce: pool size: 64 pages
[ 0.584920] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 248)
[ 0.584936] io scheduler noop registered
[ 0.584949] io scheduler deadline registered
[ 0.584984] io scheduler cfq registered (default)
[ 0.589950] pinctrl-single 4a003400.pinmux: 282 pins at pa fc003400 size 1128
[ 0.593494] PCI host bridge /ocp/axi@0/pcie@51000000 ranges:
[ 0.593505] No bus range found for /ocp/axi@0/pcie@51000000, using [bus 00-ff]
[ 0.593536] IO 0x20003000..0x20012fff -> 0x00000000
[ 0.593556] MEM 0x20013000..0x2fffffff -> 0x20013000
[ 0.623979] dra7-pcie 51000000.pcie: link is not up
[ 0.624163] dra7-pcie 51000000.pcie: PCI host bridge to bus 0000:00
[ 0.624175] pci_bus 0000:00: root bus resource [bus 00-ff]
[ 0.624185] pci_bus 0000:00: root bus resource [io 0x0000-0xffff]
[ 0.624195] pci_bus 0000:00: root bus resource [mem 0x20013000-0x2fffffff]
[ 0.624598] PCI: bus0: Fast back to back transfers disabled
[ 0.638362] PCI: bus1: Fast back to back transfers disabled
[ 0.638409] irq: no irq domain found for /ocp/axi@0/pcie@51000000/interrupt-controller !
[ 0.638449] irq: no irq domain found for /ocp/axi@0/pcie@51000000/interrupt-controller !
[ 0.638487] pci 0000:00:00.0: BAR 0: assigned [mem 0x20100000-0x201fffff]
[ 0.638502] pci 0000:00:00.0: BAR 8: assigned [mem 0x20200000-0x202fffff]
[ 0.638514] pci 0000:00:00.0: BAR 9: assigned [mem 0x20300000-0x203fffff pref]
[ 0.638525] pci 0000:00:00.0: BAR 1: assigned [mem 0x20020000-0x2002ffff]
[ 0.638538] pci 0000:00:00.0: BAR 7: assigned [io 0x1000-0x1fff]
[ 0.638553] pci 0000:01:00.0: BAR 6: assigned [mem 0x20300000-0x2030ffff pref]
[ 0.638564] pci 0000:01:00.0: BAR 5: assigned [mem 0x20200000-0x202001ff]
[ 0.638584] pci 0000:01:00.0: BAR 4: assigned [io 0x1000-0x101f]
[ 0.638603] pci 0000:01:00.0: BAR 0: assigned [io 0x1020-0x1027]
[ 0.638621] pci 0000:01:00.0: BAR 2: assigned [io 0x1028-0x102f]
[ 0.638639] pci 0000:01:00.0: BAR 1: assigned [io 0x1030-0x1033]
[ 0.638658] pci 0000:01:00.0: BAR 3: assigned [io 0x1034-0x1037]
[ 0.638676] pci 0000:00:00.0: PCI bridge to [bus 01]
[ 0.638686] pci 0000:00:00.0: bridge window [io 0x1000-0x1fff]
[ 0.638698] pci 0000:00:00.0: bridge window [mem 0x20200000-0x202fffff]
[ 0.638708] pci 0000:00:00.0: bridge window [mem 0x20300000-0x203fffff pref]
[ 0.638936] pcieport 0000:00:00.0: Signaling PME through PCIe PME interrupt
[ 0.638947] pci 0000:01:00.0: Signaling PME through PCIe PME interrupt
[ 0.640117] backlight supply power not found, using dummy regulator
[ 0.701389] Serial: 8250/16550 driver, 10 ports, IRQ sharing disabled
[ 0.704755] 48020000.serial: ttyS2 at MMIO 0x48020000 (irq = 301, base_baud = 3000000) is a 8250
[ 1.803275] console [ttyS2] enabled
[ 1.807606] 48422000.serial: ttyS7 at MMIO 0x48422000 (irq = 302, base_baud = 3000000) is a 8250
[ 1.817676] [drm] Initialized drm 1.1.0 20060810
[ 1.824304] OMAP DSS rev 6.1
[ 1.828074] omapdss_dss 58000000.dss: bound 58001000.dispc (ops dispc_component_ops)
[ 1.836561] omapdss_dss 58000000.dss: bound 58040000.encoder (ops hdmi5_component_ops)
[ 1.852730] loop: module loaded
[ 1.858711] libphy: Fixed MDIO Bus: probed
[ 1.908322] davinci_mdio 48485000.mdio: davinci mdio revision 1.6
[ 1.914447] davinci_mdio 48485000.mdio: detected phy mask fffffff9
[ 1.924982] libphy: 48485000.mdio: probed
[ 1.929054] davinci_mdio 48485000.mdio: phy[1]: device 48485000.mdio:01, driver Micrel KSZ9031 Gigabit PHY
[ 1.938788] davinci_mdio 48485000.mdio: phy[2]: device 48485000.mdio:02, driver Micrel KSZ9031 Gigabit PHY
[ 1.949155] cpsw 48484000.ethernet: Detected MACID = 74:da:ea:47:8b:26
[ 1.956425] cpsw 48484000.ethernet: cpsw: Detected MACID = 74:da:ea:47:8b:27
[ 1.964968] mousedev: PS/2 mouse device common for all mice
[ 1.971072] i2c /dev entries driver
[ 1.977349] gpio-fan gpio_fan: GPIO fan initialized
[ 1.983301] tmp102 0-0048: initialized
[ 1.989999] omap_hsmmc 4809c000.mmc: Got CD GPIO
[ 2.038843] omap_hsmmc 480b4000.mmc: no pinctrl state for sdr25 mode
[ 2.045225] omap_hsmmc 480b4000.mmc: no pinctrl state for sdr12 mode
[ 2.068430] vdd_3v3: supplied by regen1
[ 2.149616] ledtrig-cpu: registered to indicate activity on CPUs
[ 2.159632] davinci-mcasp 48468000.mcasp: ERRATA i868 workaround is enabled
[ 2.167775] NET: Registered protocol family 10
[ 2.183098] sit: IPv6 over IPv4 tunneling driver
[ 2.188303] NET: Registered protocol family 17
[ 2.192973] Key type dns_resolver registered
[ 2.197370] omap_voltage_late_init: Voltage driver support not added
[ 2.204273] Adding alias for supply vdd,cpu0 -> vdd,4a003b20.oppdm
[ 2.210499] Adding alias for supply vbb,cpu0 -> vbb,4a003b20.oppdm
[ 2.217194] Adding alias for supply vdd,cpu0 -> vdd,4a003b20.oppdm
[ 2.223424] Adding alias for supply vbb,cpu0 -> vbb,4a003b20.oppdm
[ 2.231589] Power Management for TI OMAP4+ devices.
[ 2.236687] Registering SWP/SWPB emulation handler
[ 2.243623] dmm 4e000000.dmm: initialized all PAT entries
[ 2.271099] [drm] Supports vblank timestamp caching Rev 2 (21.10.2013).
[ 2.277741] [drm] No driver support for vblank timestamp query.
[ 2.337700] mmc0: host does not support reading read-only switch, assuming write-enable
[ 2.349180] mmc0: new high speed SDHC card at address aaaa
[ 2.355029] mmcblk0: mmc0:aaaa SL08G 7.40 GiB
[ 2.360674] mmcblk0: p1 p2 p3
[ 2.422915] mmc1: MAN_BKOPS_EN bit is not set
[ 2.435914] mmc1: new DDR MMC card at address 0001
[ 2.451053] mmcblk1: mmc1:0001 S10004 3.56 GiB
[ 2.465778] mmcblk1boot0: mmc1:0001 S10004 partition 1 4.00 MiB
[ 2.471891] mmcblk1boot1: mmc1:0001 S10004 partition 2 4.00 MiB
[ 2.478728] mmcblk1: p1 p2 p3
[ 2.562262] [drm] Enabling DMM ywrap scrolling
[ 2.600301] Console: switching to colour frame buffer device 100x30
[ 2.608627] omapdrm omapdrm.0: fb0: omapdrm frame buffer device
[ 2.638571] [drm] Initialized omapdrm 1.0.0 20110917 on minor 0
[ 2.645862] input: gpio_keys as /devices/platform/gpio_keys/input/input0
[ 2.652827] hctosys: unable to open rtc device (rtc0)
[ 2.668349] net eth0: initializing cpsw version 1.15 (0)
[ 2.673702] net eth0: initialized cpsw ale version 1.4
[ 2.678878] net eth0: ALE Table size 1024
[ 2.770336] net eth0: phy found : id is : 0x221622
[ 2.781714] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[ 6.776920] cpsw 48484000.ethernet eth0: Link is Up - 1Gbps/Full - flow control rx/tx
[ 6.784829] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[ 6.798309] Sending DHCP requests ., OK
[ 6.848304] IP-Config: Got DHCP answer from 192.168.0.1, my address is 192.168.0.97
[ 6.856129] IP-Config: Complete:
[ 6.859400] device=eth0, hwaddr=74:da:ea:47:8b:26, ipaddr=192.168.0.97, mask=255.255.255.0, gw=192.168.0.1
[ 6.870013] host=192.168.0.97, domain=ti.com, nis-domain=(none)
[ 6.876395] bootserver=0.0.0.0, rootserver=192.168.0.1, rootpath=
[ 6.882795] nameserver0=192.0.2.2, nameserver1=192.0.2.3
[ 6.888933] aic_dvdd_fixed: disabling
[ 6.892611] vmmcwl_fixed: disabling
[ 6.896293] ldousb: disabling
[ 6.899787] ALSA device list:
[ 6.902765] No soundcards found.
[ 6.907052] Root-NFS: nfsroot=/home/tigtfarm10/NFS_exports/linux/am57xx-evm/autofs/f1a395609921e4cdad1b0bb2ec56f877,nolock,v3,tcp,rsize=4096,wsize=4096
[ 6.920854] NFS: nfs mount opts='vers=2,udp,rsize=4096,wsize=4096,nolock,v3,tcp,rsize=4096,wsize=4096,nolock,addr=192.168.0.1'
[ 6.932330] NFS: parsing nfs mount option 'vers=2'
[ 6.937399] NFS: parsing nfs mount option 'udp'
[ 6.942194] NFS: parsing nfs mount option 'rsize=4096'
[ 6.947561] NFS: parsing nfs mount option 'wsize=4096'
[ 6.952967] NFS: parsing nfs mount option 'nolock'
[ 6.957980] NFS: parsing nfs mount option 'v3'
[ 6.962725] NFS: parsing nfs mount option 'tcp'
[ 6.967607] NFS: parsing nfs mount option 'rsize=4096'
[ 6.972959] NFS: parsing nfs mount option 'wsize=4096'
[ 6.978359] NFS: parsing nfs mount option 'nolock'
[ 6.983345] NFS: parsing nfs mount option 'addr=192.168.0.1'
[ 6.989222] NFS: MNTPATH: '/home/tigtfarm10/NFS_exports/linux/am57xx-evm/autofs/f1a395609921e4cdad1b0bb2ec56f877'
[ 6.999540] NFS: sending MNT request for 192.168.0.1:/home/tigtfarm10/NFS_exports/linux/am57xx-evm/autofs/f1a395609921e4cdad1b0bb2ec56f877
[ 7.012046] RPC: set up xprt to 192.168.0.1 (autobind) via tcp
[ 7.018454] RPC: created transport eddc9000 with 65536 slots
[ 7.024659] RPC: creating mount client for 192.168.0.1 (xprt eddc9000)
[ 7.031785] RPC: creating UNIX authenticator for client ee8ead00
[ 7.038376] RPC: new task initialized, procpid 1
[ 7.043532] RPC: allocated task edd8cc00
[ 7.047993] RPC: 1 __rpc_execute flags=0x680
[ 7.052636] RPC: 1 call_start mount3 proc NULL (sync)
[ 7.058055] RPC: 1 call_reserve (status 0)
[ 7.062524] RPC: 1 reserved req ee8eac00 xid 57c6e885
[ 7.067944] RPC: wake_up_first(eddc9100 "xprt_sending")
[ 7.073725] RPC: 1 call_reserveresult (status 0)
[ 7.078720] RPC: 1 call_refresh (status 0)
[ 7.083180] RPC: 1 holding NULL cred c096c2f0
[ 7.087901] RPC: 1 refreshing NULL cred c096c2f0
[ 7.092894] RPC: 1 call_refreshresult (status 0)
[ 7.097877] RPC: 1 call_allocate (status 0)
[ 7.102432] RPC: 1 allocated buffer of size 92 at eddc9800
[ 7.108302] RPC: 1 call_bind (status 0)
[ 7.112502] RPC: 1 rpcb_getport_async(192.168.0.1, 100005, 3, 6)
[ 7.118913] RPC: 1 sleep_on(queue "xprt_binding" time 4294938008)
[ 7.125380] RPC: 1 added to queue eddc90a4 "xprt_binding"
[ 7.131159] RPC: 1 setting alarm for 60000 ms
[ 7.135884] RPC: 1 rpcb_getport_async: trying rpcbind version 2
[ 7.142197] RPC: set up xprt to 192.168.0.1 (port 111) via tcp
[ 7.148601] RPC: created transport eddca800 with 65536 slots
[ 7.154805] RPC: creating rpcbind client for 192.168.0.1 (xprt eddca800)
[ 7.162115] RPC: creating UNIX authenticator for client edd8f200
[ 7.168679] RPC: new task initialized, procpid 1
[ 7.173835] RPC: allocated task edd8cd00
[ 7.178367] RPC: rpc_release_client(edd8f200)
[ 7.183285] RPC: 2 __rpc_execute flags=0x681
[ 7.187919] RPC: 2 call_start rpcbind2 proc GETPORT (async)
[ 7.193875] RPC: 2 call_reserve (status 0)
[ 7.193893] RPC: 1 sync task going to sleep
[ 7.202894] RPC: 2 reserved req edd8f100 xid 926299b2
[ 7.208328] RPC: wake_up_first(eddca900 "xprt_sending")
[ 7.214096] RPC: 2 call_reserveresult (status 0)
[ 7.219089] RPC: 2 call_refresh (status 0)
[ 7.223549] RPC: 2 looking up UNIX cred
[ 7.227745] RPC: looking up UNIX cred
[ 7.231958] RPC: allocating UNIX cred for uid 0 gid 0
[ 7.237553] RPC: 2 refreshing UNIX cred edd8cf00
[ 7.242799] RPC: 2 call_refreshresult (status 0)
[ 7.247782] RPC: 2 call_allocate (status 0)
[ 7.252340] RPC: 2 allocated buffer of size 508 at eddcb000
[ 7.258296] RPC: 2 call_bind (status 0)
[ 7.262494] RPC: 2 call_connect xprt eddca800 is not connected
[ 7.268713] RPC: 2 xprt_connect xprt eddca800 is not connected
[ 7.274917] RPC: 2 sleep_on(queue "xprt_pending" time 4294938023)
[ 7.281392] RPC: 2 added to queue eddca95c "xprt_pending"
[ 7.287159] RPC: 2 setting alarm for 60000 ms
[ 7.291939] RPC: xs_connect scheduled xprt eddca800
[ 7.297405] RPC: worker connecting xprt eddca800 via tcp to 192.168.0.1 (port 111)
[ 7.305897] RPC: eddca800 connect status 115 connected 0 sock state 2
[ 7.306109] RPC: xs_tcp_state_change client eddca800...
[ 7.306114] RPC: state 1 conn 0 dead 0 zapped 1 sk_shutdown 0
[ 7.306118] RPC: 2 __rpc_wake_up_task (now 4294938026)
[ 7.306120] RPC: 2 disabling timer
[ 7.306124] RPC: 2 removed from queue eddca95c "xprt_pending"
[ 7.306134] RPC: __rpc_wake_up_task done
[ 7.316303] RPC: 2 __rpc_execute flags=0x681
[ 7.316306] RPC: 2 xprt_connect_status: retrying
[ 7.316310] RPC: 2 call_connect_status (status -11)
[ 7.316313] RPC: 2 call_timeout (minor)
[ 7.316315] RPC: 2 call_bind (status 0)
[ 7.316319] RPC: 2 call_connect xprt eddca800 is connected
[ 7.316322] RPC: 2 call_transmit (status 0)
[ 7.316324] RPC: 2 xprt_prepare_transmit
[ 7.316328] RPC: 2 failed to lock transport eddca800
[ 7.316331] RPC: 2 sleep_on(queue "xprt_sending" time 4294938027)
[ 7.316334] RPC: 2 added to queue eddca900 "xprt_sending"
[ 7.400396] RPC: wake_up_first(eddca900 "xprt_sending")
[ 7.406168] RPC: 2 __rpc_wake_up_task (now 4294938036)
[ 7.411684] RPC: 2 removed from queue eddca900 "xprt_sending"
[ 7.417800] RPC: __rpc_wake_up_task done
[ 7.422290] RPC: 2 __rpc_execute flags=0x681
[ 7.426965] RPC: 2 call_status (status -11)
[ 7.431657] RPC: 2 call_transmit (status 0)
[ 7.436202] RPC: 2 xprt_prepare_transmit
[ 7.440498] RPC: 2 rpc_xdr_encode (status 0)
[ 7.445129] RPC: 2 marshaling UNIX cred edd8cf00
[ 7.450122] RPC: 2 using AUTH_UNIX cred edd8cf00 to wrap rpc data
[ 7.456587] RPC: 2 encoding PMAP_GETPORT call (100005, 3, 6, 0)
[ 7.462885] RPC: 2 xprt_transmit(92)
[ 7.466841] RPC: xs_tcp_send_request(92) = 0
[ 7.467095] RPC: xs_tcp_data_ready...
[ 7.467130] RPC: xs_tcp_data_recv started
[ 7.467134] RPC: reading TCP record fragment of length 28
[ 7.467136] RPC: reading XID (4 bytes)
[ 7.467138] RPC: reading request with XID 926299b2
[ 7.467140] RPC: reading CALL/REPLY flag (4 bytes)
[ 7.467142] RPC: read reply XID 926299b2
[ 7.467145] RPC: XID 926299b2 read 20 bytes
[ 7.467148] RPC: xprt = eddca800, tcp_copied = 28, tcp_offset = 28, tcp_reclen = 28
[ 7.467151] RPC: 2 xid 926299b2 complete (28 bytes received)
[ 7.467154] RPC: xs_tcp_data_recv done
[ 7.528985] RPC: 2 xmit complete
[ 7.532571] RPC: wake_up_first(eddca900 "xprt_sending")
[ 7.538348] RPC: 2 call_status (status 28)
[ 7.542806] RPC: 2 call_decode (status 28)
[ 7.547263] RPC: 2 validating UNIX cred edd8cf00
[ 7.552255] RPC: 2 using AUTH_UNIX cred edd8cf00 to unwrap rpc data
[ 7.558920] RPC: 2 PMAP_GETPORT result: 41203
[ 7.563638] RPC: 2 call_decode result 0
[ 7.567834] RPC: setting port for xprt eddc9000 to 41203
[ 7.573698] RPC: 2 rpcb_getport_done(status 0, port 41203)
[ 7.579561] RPC: 2 return 0, status 0
[ 7.583582] RPC: 2 release task
[ 7.587081] RPC: freeing buffer of size 508 at eddcb000
[ 7.592856] RPC: 2 release request edd8f100
[ 7.597401] RPC: wake_up_first(eddca9b8 "xprt_backlog")
[ 7.603177] RPC: rpc_release_client(edd8f200)
[ 7.608072] RPC: destroying rpcbind client for 192.168.0.1
[ 7.614135] RPC: destroying transport eddca800
[ 7.619150] RPC: xs_destroy xprt eddca800
[ 7.623695] RPC: xs_close xprt eddca800
[ 7.628078] RPC: xs_tcp_state_change client eddca800...
[ 7.633856] RPC: state 4 conn 1 dead 0 zapped 1 sk_shutdown 3
[ 7.640180] RPC: xs_tcp_state_change client eddca800...
[ 7.645947] RPC: state 5 conn 0 dead 0 zapped 1 sk_shutdown 3
[ 7.652265] RPC: xs_tcp_state_change client eddca800...
[ 7.658031] RPC: state 7 conn 0 dead 0 zapped 1 sk_shutdown 3
[ 7.664329] RPC: disconnected transport eddca800
[ 7.669493] RPC: xs_tcp_state_change client eddca800...
[ 7.675259] RPC: state 7 conn 0 dead 0 zapped 1 sk_shutdown 3
[ 7.681556] RPC: disconnected transport eddca800
[ 7.686711] RPC: xs_tcp_data_ready...
[ 7.690938] RPC: disconnected transport eddca800
[ 7.696099] RPC: 1 __rpc_wake_up_task (now 4294938065)
[ 7.701613] RPC: 1 disabling timer
[ 7.705374] RPC: 1 removed from queue eddc90a4 "xprt_binding"
[ 7.711499] RPC: __rpc_wake_up_task done
[GS] In good case "RPC: 2 freeing task" can be seen here
[ 7.711506] RPC: 1 sync task resuming
[ 7.711510] RPC: 1 call_bind_status (status 0)
[ 7.711512] RPC: 1 call_connect xprt eddc9000 is not connected
[ 7.711515] RPC: 1 xprt_connect xprt eddc9000 is not connected
[ 7.711519] RPC: 1 sleep_on(queue "xprt_pending" time 4294938067)
[ 7.711521] RPC: 1 added to queue eddc915c "xprt_pending"
[ 7.711523] RPC: 1 setting alarm for 60000 ms
[ 7.711527] RPC: xs_connect scheduled xprt eddc9000
[ 7.711534] RPC: 1 sync task going to sleep
[ 7.711557] RPC: xs_bind 0.0.0.0:872: ok (0)
[ 7.711560] RPC: worker connecting xprt eddc9000 via tcp to 192.168.0.1 (port 41203)
[ 7.711604] RPC: eddc9000 connect status 115 connected 0 sock state 2
[ 7.711607] RPC: wake_up_first(eddc9100 "xprt_sending")
[ 7.711733] RPC: xs_tcp_state_change client eddc9000...
[ 7.711737] RPC: state 1 conn 0 dead 0 zapped 1 sk_shutdown 0
[ 7.711740] RPC: 1 __rpc_wake_up_task (now 4294938067)
[ 7.711741] RPC: 1 disabling timer
[ 7.711744] RPC: 1 removed from queue eddc915c "xprt_pending"
[ 7.711750] RPC: __rpc_wake_up_task done
[ 7.711790] RPC: 1 sync task resuming
[ 7.711793] RPC: 1 xprt_connect_status: retrying
[ 7.711796] RPC: 1 call_connect_status (status -11)
[ 7.711797] RPC: 1 call_timeout (minor)
[ 7.711799] RPC: 1 call_bind (status 0)
[ 7.711802] RPC: 1 call_connect xprt eddc9000 is connected
[ 7.711803] RPC: 1 call_transmit (status 0)
[ 7.711805] RPC: 1 xprt_prepare_transmit
[ 7.711808] RPC: 1 rpc_xdr_encode (status 0)
[GS] =OR= In good case "RPC: 2 freeing task" can be seen here
[ 7.711809] RPC: 1 marshaling NULL cred c096c2f0
[ 7.711812] RPC: 1 using AUTH_NULL cred c096c2f0 to wrap rpc data
[ 7.711814] RPC: 1 xprt_transmit(44)
[ 7.711839] RPC: xs_tcp_send_request(44) = 0
[ 7.711841] RPC: 1 xmit complete
[ 7.711844] RPC: 1 sleep_on(queue "xprt_pending" time 4294938067)
[ 7.711846] RPC: 1 added to queue eddc915c "xprt_pending"
[ 7.711848] RPC: 1 setting alarm for 60000 ms
[ 7.711852] RPC: wake_up_first(eddc9100 "xprt_sending")
[ 7.711855] RPC: 1 sync task going to sleep
[ 7.712063] RPC: xs_tcp_data_ready...
[ 7.712091] RPC: xs_tcp_data_recv started
[ 7.712094] RPC: reading TCP record fragment of length 24
[ 7.712096] RPC: reading XID (4 bytes)
[ 7.712098] RPC: reading request with XID 57c6e885
[ 7.712101] RPC: reading CALL/REPLY flag (4 bytes)
[ 7.712102] RPC: read reply XID 57c6e885
[ 7.712105] RPC: XID 57c6e885 read 16 bytes
[ 7.712107] RPC: xprt = eddc9000, tcp_copied = 24, tcp_offset = 24, tcp_reclen = 24
[ 7.712110] RPC: 1 xid 57c6e885 complete (24 bytes received)
[ 7.712113] RPC: 1 __rpc_wake_up_task (now 4294938067)
[ 7.712114] RPC: 1 disabling timer
[ 7.712117] RPC: 1 removed from queue eddc915c "xprt_pending"
[ 7.712123] RPC: __rpc_wake_up_task done
[ 7.712129] RPC: 1 sync task resuming
[ 7.712131] RPC: 1 call_status (status 24)
[ 7.712134] RPC: 1 call_decode (status 24)
[ 7.712136] RPC: 1 validating NULL cred c096c2f0
[ 7.712140] RPC: 1 using AUTH_NULL cred c096c2f0 to unwrap rpc data
[ 7.712141] RPC: 1 call_decode result 0
[ 7.712144] RPC: 1 return 0, status 0
[ 7.712145] RPC: 1 release task
[ 7.712150] RPC: freeing buffer of size 92 at eddc9800
[ 7.712153] RPC: 1 release request ee8eac00
[ 7.712154] RPC: wake_up_first(eddc91b8 "xprt_backlog")
[ 7.712157] RPC: rpc_release_client(ee8ead00)
[ 7.712160] RPC: 1 freeing task
[ 7.712164] RPC: new task initialized, procpid 1
[ 7.712166] RPC: allocated task ee257300
[ 7.712169] RPC: 3 __rpc_execute flags=0x1280
[ 7.712171] RPC: 3 call_start mount3 proc MOUNT (sync)
[ 7.712173] RPC: 3 call_reserve (status 0)
[ 7.712176] RPC: 3 reserved req ee8eac00 xid 58c6e885
[ 7.712179] RPC: wake_up_first(eddc9100 "xprt_sending")
[ 7.712182] RPC: 3 call_reserveresult (status 0)
[ 7.712184] RPC: 3 call_refresh (status 0)
[ 7.712186] RPC: 3 looking up UNIX cred
[ 7.712188] RPC: looking up UNIX cred
[ 7.712191] RPC: 3 refreshing UNIX cred edd8cf00
[ 7.712193] RPC: 3 call_refreshresult (status 0)
[ 7.712195] RPC: 3 call_allocate (status 0)
[ 7.712198] RPC: 3 allocated buffer of size 1604 at eeb5f000
[ 7.712200] RPC: 3 call_bind (status 0)
[ 7.712202] RPC: 3 call_connect xprt eddc9000 is connected
[ 7.712204] RPC: 3 call_transmit (status 0)
[ 7.712205] RPC: 3 xprt_prepare_transmit
[ 7.712208] RPC: 3 rpc_xdr_encode (status 0)
[ 7.712209] RPC: 3 marshaling UNIX cred edd8cf00
[ 7.712212] RPC: 3 using AUTH_UNIX cred edd8cf00 to wrap rpc data
[ 7.712215] RPC: 3 xprt_transmit(168)
[ 7.712222] RPC: xs_tcp_data_recv done
[ 7.712257] RPC: xs_tcp_send_request(168) = 0
[ 7.712259] RPC: 3 xmit complete
[ 7.712262] RPC: 3 sleep_on(queue "xprt_pending" time 4294938067)
[ 7.712264] RPC: 3 added to queue eddc915c "xprt_pending"
[ 7.712266] RPC: 3 setting alarm for 60000 ms
[ 7.712269] RPC: wake_up_first(eddc9100 "xprt_sending")
[ 7.712273] RPC: 3 sync task going to sleep
[ 7.721103] RPC: xs_tcp_data_ready...
[ 7.721123] RPC: xs_tcp_data_recv started
[ 7.721126] RPC: reading TCP record fragment of length 76
[ 7.721127] RPC: reading XID (4 bytes)
[ 7.721129] RPC: reading reply for XID 58c6e885
[ 7.721131] RPC: reading CALL/REPLY flag (4 bytes)
[ 7.721133] RPC: read reply XID 58c6e885
[ 7.721136] RPC: XID 58c6e885 read 68 bytes
[ 7.721139] RPC: xprt = eddc9000, tcp_copied = 76, tcp_offset = 76, tcp_reclen = 76
[ 7.721141] RPC: 3 xid 58c6e885 complete (76 bytes received)
[ 7.721144] RPC: 3 __rpc_wake_up_task (now 4294938068)
[ 7.721145] RPC: 3 disabling timer
[ 7.721147] RPC: 3 removed from queue eddc915c "xprt_pending"
[ 7.721154] RPC: __rpc_wake_up_task done
[ 7.721159] RPC: 3 sync task resuming
[ 7.721162] RPC: 3 call_status (status 76)
[ 7.721164] RPC: 3 call_decode (status 76)
[ 7.721166] RPC: 3 validating UNIX cred edd8cf00
[ 7.721169] RPC: 3 using AUTH_UNIX cred edd8cf00 to unwrap rpc data
[ 7.721171] NFS: received 1 auth flavors
[ 7.721173] NFS: auth flavor[0]: 1
[ 7.721175] RPC: 3 call_decode result 0
[ 7.721177] RPC: 3 return 0, status 0
[ 7.721178] RPC: 3 release task
[ 7.721182] RPC: freeing buffer of size 1604 at eeb5f000
[ 7.721186] RPC: 3 release request ee8eac00
[ 7.721188] RPC: wake_up_first(eddc91b8 "xprt_backlog")
[ 7.721191] RPC: rpc_release_client(ee8ead00)
[ 7.721194] RPC: 3 freeing task
[ 7.721197] RPC: shutting down mount client for 192.168.0.1
[ 7.721198] RPC: rpc_release_client(ee8ead00)
[ 7.721200] RPC: destroying UNIX authenticator c096c324
[ 7.721205] RPC: destroying mount client for 192.168.0.1
[ 7.721238] NFS: MNT request succeeded
[ 7.721241] NFS: attempting to use auth flavor 1
[ 7.721257] --> nfs_init_server()
[ 7.721260] --> nfs_get_client(192.168.0.1,v3)
[ 7.721264] RPC: looking up machine cred for service *
[ 7.721269] RPC: allocated machine cred ee257300 for uid 0 gid 0
[ 7.721279] RPC: set up xprt to 192.168.0.1 (autobind) via tcp
[ 7.721296] RPC: created transport eeb5f800 with 65536 slots
[ 7.721299] RPC: creating nfs client for 192.168.0.1 (xprt eeb5f800)
[ 7.721333] RPC: creating UNIX authenticator for client ee24f600
[ 7.721336] RPC: new task initialized, procpid 1
[ 7.721338] RPC: allocated task ee257380
[ 7.721341] RPC: 4 __rpc_execute flags=0x680
[ 7.721344] RPC: 4 call_start nfs3 proc NULL (sync)
[ 7.721347] RPC: 4 call_reserve (status 0)
[ 7.721350] RPC: 4 reserved req ee24f500 xid 799833c3
[ 7.721353] RPC: wake_up_first(eeb5f900 "xprt_sending")
[ 7.721356] RPC: 4 call_reserveresult (status 0)
[ 7.721357] RPC: 4 call_refresh (status 0)
[ 7.721360] RPC: 4 holding NULL cred c096c2f0
[ 7.721362] RPC: 4 refreshing NULL cred c096c2f0
[ 7.721364] RPC: 4 call_refreshresult (status 0)
[ 7.721367] RPC: 4 call_allocate (status 0)
[ 7.721369] RPC: 4 allocated buffer of size 92 at ee2ac800
[ 7.721371] RPC: 4 call_bind (status 0)
[ 7.721374] RPC: 4 rpcb_getport_async(192.168.0.1, 100003, 3, 6)
[ 7.721376] RPC: 4 sleep_on(queue "xprt_binding" time 4294938068)
[ 7.721378] RPC: 4 added to queue eeb5f8a4 "xprt_binding"
[ 7.721380] RPC: 4 setting alarm for 60000 ms
[ 7.721385] RPC: 4 rpcb_getport_async: trying rpcbind version 2
[ 7.721393] RPC: set up xprt to 192.168.0.1 (port 111) via tcp
[ 7.721407] RPC: created transport ee2ac000 with 65536 slots
[ 7.721409] RPC: creating rpcbind client for 192.168.0.1 (xprt ee2ac000)
[ 7.721432] RPC: creating UNIX authenticator for client ee24f900
[ 7.721435] RPC: new task initialized, procpid 1
[ 7.721437] RPC: allocated task ee257480
[ 7.721440] RPC: rpc_release_client(ee24f900)
[ 7.721442] RPC: 4 sync task going to sleep
[ 7.721450] RPC: xs_tcp_data_recv done
[ 7.721458] RPC: 5 __rpc_execute flags=0x681
[ 7.721460] RPC: 5 call_start rpcbind2 proc GETPORT (async)
[ 7.721462] RPC: 5 call_reserve (status 0)
[ 7.721465] RPC: 5 reserved req ee24f800 xid 9916d160
[ 7.721468] RPC: wake_up_first(ee2ac100 "xprt_sending")
[ 7.721471] RPC: 5 call_reserveresult (status 0)
[ 7.721473] RPC: 5 call_refresh (status 0)
[ 7.721474] RPC: 5 looking up UNIX cred
[ 7.721476] RPC: looking up UNIX cred
[ 7.721478] RPC: allocating UNIX cred for uid 0 gid 0
[ 7.721480] RPC: 5 refreshing UNIX cred ee257500
[ 7.721482] RPC: 5 call_refreshresult (status 0)
[ 7.721485] RPC: 5 call_allocate (status 0)
[ 7.721487] RPC: 5 allocated buffer of size 508 at ee2ad800
[ 7.721489] RPC: 5 call_bind (status 0)
[ 7.721491] RPC: 5 call_connect xprt ee2ac000 is not connected
[ 7.721493] RPC: 5 xprt_connect xprt ee2ac000 is not connected
[ 7.721497] RPC: 5 sleep_on(queue "xprt_pending" time 4294938068)
[ 7.721498] RPC: 5 added to queue ee2ac15c "xprt_pending"
[ 7.721500] RPC: 5 setting alarm for 60000 ms
[ 7.721504] RPC: xs_connect scheduled xprt ee2ac000
[ 7.721514] RPC: worker connecting xprt ee2ac000 via tcp to 192.168.0.1 (port 111)
[ 7.721555] RPC: ee2ac000 connect status 115 connected 0 sock state 2
[ 7.721558] RPC: wake_up_first(ee2ac100 "xprt_sending")
[ 7.721687] RPC: xs_tcp_state_change client ee2ac000...
[ 7.721690] RPC: state 1 conn 0 dead 0 zapped 1 sk_shutdown 0
[ 7.721693] RPC: 5 __rpc_wake_up_task (now 4294938068)
[ 7.721695] RPC: 5 disabling timer
[ 7.721697] RPC: 5 removed from queue ee2ac15c "xprt_pending"
[ 7.721703] RPC: __rpc_wake_up_task done
[ 7.721744] RPC: 5 __rpc_execute flags=0x681
[ 7.721746] RPC: 5 xprt_connect_status: retrying
[ 7.721748] RPC: 5 call_connect_status (status -11)
[ 7.721750] RPC: 5 call_timeout (minor)
[ 7.721752] RPC: 5 call_bind (status 0)
[ 7.721755] RPC: 5 call_connect xprt ee2ac000 is connected
[ 7.721756] RPC: 5 call_transmit (status 0)
[ 7.721758] RPC: 5 xprt_prepare_transmit
[ 7.721760] RPC: 5 rpc_xdr_encode (status 0)
[ 7.721762] RPC: 5 marshaling UNIX cred ee257500
[ 7.721765] RPC: 5 using AUTH_UNIX cred ee257500 to wrap rpc data
[ 7.721768] RPC: 5 encoding PMAP_GETPORT call (100003, 3, 6, 0)
[ 7.721769] RPC: 5 xprt_transmit(92)
[ 7.721796] RPC: xs_tcp_send_request(92) = 0
[ 7.721798] RPC: 5 xmit complete
[ 7.721800] RPC: 5 sleep_on(queue "xprt_pending" time 4294938068)
[ 7.721803] RPC: 5 added to queue ee2ac15c "xprt_pending"
[ 7.721805] RPC: 5 setting alarm for 60000 ms
[ 7.721808] RPC: wake_up_first(ee2ac100 "xprt_sending")
[ 7.722037] RPC: xs_tcp_data_ready...
[ 7.722066] RPC: xs_tcp_data_recv started
[ 7.722069] RPC: reading TCP record fragment of length 28
[ 7.722071] RPC: reading XID (4 bytes)
[ 7.722073] RPC: reading request with XID 9916d160
[ 7.722075] RPC: reading CALL/REPLY flag (4 bytes)
[ 7.722076] RPC: read reply XID 9916d160
[ 7.722079] RPC: XID 9916d160 read 20 bytes
[ 7.722082] RPC: xprt = ee2ac000, tcp_copied = 28, tcp_offset = 28, tcp_reclen = 28
[ 7.722084] RPC: 5 xid 9916d160 complete (28 bytes received)
[ 7.722087] RPC: 5 __rpc_wake_up_task (now 4294938068)
[ 7.722088] RPC: 5 disabling timer
[ 7.722091] RPC: 5 removed from queue ee2ac15c "xprt_pending"
[ 7.722093] RPC: __rpc_wake_up_task done
[ 7.722095] RPC: xs_tcp_data_recv done
[ 7.722101] RPC: 5 __rpc_execute flags=0xe81
[ 7.722103] RPC: 5 call_status (status 28)
[ 7.722105] RPC: 5 call_decode (status 28)
[ 7.722108] RPC: 5 validating UNIX cred ee257500
[ 7.722110] RPC: 5 using AUTH_UNIX cred ee257500 to unwrap rpc data
[ 7.722112] RPC: 5 PMAP_GETPORT result: 2049
[ 7.722114] RPC: 5 call_decode result 0
[ 7.722116] RPC: setting port for xprt eeb5f800 to 2049
[ 7.722120] RPC: 5 rpcb_getport_done(status 0, port 2049)
[ 7.722122] RPC: 5 return 0, status 0
[ 7.722123] RPC: 5 release task
[ 7.722128] RPC: freeing buffer of size 508 at ee2ad800
[ 7.722131] RPC: 5 release request ee24f800
[ 7.722132] RPC: wake_up_first(ee2ac1b8 "xprt_backlog")
[ 7.722135] RPC: rpc_release_client(ee24f900)
[ 7.722138] RPC: destroying rpcbind client for 192.168.0.1
[ 7.722165] RPC: destroying transport ee2ac000
[ 7.722185] RPC: xs_destroy xprt ee2ac000
[ 7.722188] RPC: xs_close xprt ee2ac000
[ 7.722212] RPC: xs_tcp_state_change client ee2ac000...
[ 7.722215] RPC: state 4 conn 1 dead 0 zapped 1 sk_shutdown 3
[ 7.722225] RPC: disconnected transport ee2ac000
[ 7.722232] RPC: 4 __rpc_wake_up_task (now 4294938068)
[ 7.722234] RPC: 4 disabling timer
[ 7.722236] RPC: 4 removed from queue eeb5f8a4 "xprt_binding"
[ 7.722243] RPC: __rpc_wake_up_task done
[ 7.722249] RPC: 4 sync task resuming
[ 7.722251] RPC: 4 call_bind_status (status 0)
[ 7.722253] RPC: 4 call_connect xprt eeb5f800 is not connected
[ 7.722255] RPC: 4 xprt_connect xprt eeb5f800 is not connected
[ 7.722258] RPC: 4 sleep_on(queue "xprt_pending" time 4294938068)
[ 7.722261] RPC: 4 added to queue eeb5f95c "xprt_pending"
[ 7.722263] RPC: 4 setting alarm for 60000 ms
[ 7.722266] RPC: xs_connect scheduled xprt eeb5f800
[ 7.722270] RPC: 4 sync task going to sleep
[ 7.722276] RPC: 5 freeing task
[ 7.722289] RPC: xs_bind 0.0.0.0:936: ok (0)
[ 7.722292] RPC: worker connecting xprt eeb5f800 via tcp to 192.168.0.1 (port 2049)
[ 7.722371] RPC: eeb5f800 connect status 115 connected 0 sock state 2
[ 7.722379] RPC: wake_up_first(eeb5f900 "xprt_sending")
[ 8.988298] omap_i2c 48070000.i2c: controller timed out
[ 9.128222] RPC: destroying transport eddc9000
[ 9.133237] RPC: xs_destroy xprt eddc9000
[ 9.137782] RPC: xs_close xprt eddc9000
[ 9.142179] RPC: xs_tcp_state_change client eddc9000...
[ 9.147945] RPC: state 4 conn 1 dead 0 zapped 1 sk_shutdown 3
[ 9.148286] RPC: unx_free_cred edd8cf00
[ 9.158642] RPC: xs_tcp_state_change client eddc9000...
[ 9.164411] RPC: state 5 conn 0 dead 0 zapped 1 sk_shutdown 3
[ 9.170724] RPC: xs_tcp_state_change client eddc9000...
[ 9.176489] RPC: state 7 conn 0 dead 0 zapped 1 sk_shutdown 3
[ 9.182789] RPC: disconnected transport eddc9000
[ 9.187944] RPC: xs_tcp_state_change client eddc9000...
[ 9.193719] RPC: state 7 conn 0 dead 0 zapped 1 sk_shutdown 3
[ 9.200016] RPC: disconnected transport eddc9000
[ 9.205170] RPC: xs_tcp_data_ready...
[ 9.209402] RPC: disconnected transport eddc9000
[ 9.214586] RPC: 2 freeing task
[GS] This is failed sequence ^^^^^
[ 62.749957] random: nonblocking pool is initialized
[ 67.838287] RPC: 4 timeout
[ 67.841361] RPC: 4 __rpc_wake_up_task (now 4294944080)
[ 67.846868] RPC: 4 disabling timer
[ 67.850647] RPC: 4 removed from queue eeb5f95c "xprt_pending"
[ 67.856775] RPC: __rpc_wake_up_task done
[ 67.861262] RPC: 4 sync task resuming
[ 67.865286] RPC: 4 xprt_connect_status: connect attempt timed out
[ 67.871787] RPC: 4 call_connect_status (status -110)
[ 67.877124] RPC: 4 call_timeout (minor)
[ 67.881339] RPC: 4 call_bind (status 0)
[ 67.885543] RPC: 4 call_connect xprt eeb5f800 is not connected
[ 67.891766] RPC: 4 xprt_connect xprt eeb5f800 is not connected
[ 67.897973] RPC: 4 sleep_on(queue "xprt_pending" time 4294944085)
[ 67.904456] RPC: 4 added to queue eeb5f95c "xprt_pending"
[ 67.910241] RPC: 4 setting alarm for 120000 ms
[ 67.915055] RPC: 4 sync task going to sleep
[ 135.038293] RPC: xs_error_report client eeb5f800, error=110...
[ 135.044676] RPC: 4 __rpc_wake_up_task (now 4294950800)
[ 135.050188] RPC: 4 disabling timer
[ 135.053957] RPC: 4 removed from queue eeb5f95c "xprt_pending"
[ 135.060079] RPC: __rpc_wake_up_task done
[ 135.064542] RPC: xs_tcp_state_change client eeb5f800...
[ 135.070317] RPC: state 7 conn 0 dead 0 zapped 1 sk_shutdown 3
[ 135.076609] RPC: disconnected transport eeb5f800
[ 135.081790] RPC: 4 sync task resuming
[ 135.085819] RPC: 4 xprt_connect_status: connect attempt timed out
[ 135.092334] RPC: 4 call_connect_status (status -110)
[ 135.097667] RPC: 4 call_timeout (minor)
[ 135.101888] RPC: 4 call_bind (status 0)
[ 135.106087] RPC: 4 call_connect xprt eeb5f800 is not connected
[ 135.112305] RPC: 4 xprt_connect xprt eeb5f800 is not connected
[ 135.118531] RPC: 4 sleep_on(queue "xprt_pending" time 4294950808)
[ 135.125002] RPC: 4 added to queue eeb5f95c "xprt_pending"
[ 135.130786] RPC: 4 setting alarm for 180000 ms
[ 135.135604] RPC: xs_connect delayed xprt eeb5f800 for 3 seconds
[ 135.142083] RPC: xs_tcp_state_change client eeb5f800...
[ 135.147852] RPC: state 7 conn 0 dead 0 zapped 1 sk_shutdown 3
[ 135.154159] RPC: disconnected transport eeb5f800
[ 135.159328] RPC: 4 __rpc_wake_up_task (now 4294950812)
[ 135.164833] RPC: 4 disabling timer
[ 135.168614] RPC: 4 removed from queue eeb5f95c "xprt_pending"
[ 135.174730] RPC: __rpc_wake_up_task done
[ 135.179231] RPC: 4 xprt_connect_status: retrying
[ 135.184221] RPC: 4 call_connect_status (status -11)
[ 135.189510] RPC: 4 call_timeout (minor)
[ 135.193709] RPC: 4 call_bind (status 0)
[ 135.197908] RPC: 4 call_connect xprt eeb5f800 is not connected
[ 135.204158] RPC: 4 xprt_connect xprt eeb5f800 is not connected
[ 135.210443] RPC: 4 failed to lock transport eeb5f800
[ 135.215785] RPC: 4 sleep_on(queue "xprt_sending" time 4294950817)
[ 135.222280] RPC: 4 added to queue eeb5f900 "xprt_sending"
[ 135.228065] RPC: 4 sync task going to sleep
[ 138.188320] RPC: xs_bind 0.0.0.0:936: ok (0)
[ 138.193139] RPC: worker connecting xprt eeb5f800 via tcp to 192.168.0.1 (port 2049)
[ 138.201418] RPC: eeb5f800 connect status 115 connected 0 sock state 2
[ 138.208433] RPC: wake_up_first(eeb5f900 "xprt_sending")
[ 138.214202] RPC: 4 __rpc_wake_up_task (now 4294951117)
[ 138.219723] RPC: 4 removed from queue eeb5f900 "xprt_sending"
[ 138.225851] RPC: __rpc_wake_up_task done
[ 138.230344] RPC: 4 sync task resuming
[ 138.234369] RPC: 4 call_connect_status (status -11)
[ 138.239664] RPC: 4 call_timeout (minor)
[ 138.243870] RPC: 4 call_bind (status 0)
[ 138.248070] RPC: 4 call_connect xprt eeb5f800 is not connected
[ 138.254295] RPC: 4 xprt_connect xprt eeb5f800 is not connected
[ 138.260520] RPC: 4 sleep_on(queue "xprt_pending" time 4294951122)
[ 138.266987] RPC: 4 added to queue eeb5f95c "xprt_pending"
[ 138.272772] RPC: 4 setting alarm for 180000 ms
[ 138.277588] RPC: 4 sync task going to sleep
- 12:26:16 [INFO] Boot attempt 1/1 failed
- 12:26:16 [INFO] Collecting kernel traces via sysrq...
- 12:26:27 [INFO] [ 208.203437] sysrq: SysRq : Show State
[ 208.207123] task PC stack pid father
[ 208.212370] swapper/0 D c0660fe0 0 1 0 0x00000000
[ 208.218765] Backtrace:
[ 208.221239] [<c0660cfc>] (__schedule) from [<c06613c0>] (schedule+0x54/0xc4)
[ 208.228316] r10:ee318e00 r9:fffffe00 r8:c063b54c r7:eeda1db4 r6:ee88da34 r5:00000082
[ 208.236216] r4:ee88c000
[ 208.238772] [<c066136c>] (schedule) from [<c063b57c>] (rpc_wait_bit_killable+0x30/0xe4)
[ 208.246808] r5:00000082 r4:00000082
[ 208.250416] [<c063b54c>] (rpc_wait_bit_killable) from [<c066195c>] (__wait_on_bit+0x8c/0xcc)
[ 208.258886] r5:00000082 r4:ee88da28
[ 208.262492] [<c06618d0>] (__wait_on_bit) from [<c0661a10>] (out_of_line_wait_on_bit+0x74/0x7c)
[ 208.271137] r9:fffffe00 r8:00000000 r7:ee2573b8 r6:00000001 r5:ee890000 r4:00000000
[ 208.278952] [<c066199c>] (out_of_line_wait_on_bit) from [<c063c4a0>] (__rpc_execute+0x20c/0x394)
[ 208.287772] r7:ee2573b8 r6:c096c8f4 r5:eeb5f95c r4:ee257380
[ 208.293487] [<c063c294>] (__rpc_execute) from [<c063c950>] (rpc_execute+0x6c/0x70)
[ 208.301085] r9:c067b694 r8:ee2a0910 r7:c0965a40 r6:c0965a40 r5:00000000 r4:ee257380
[ 208.308902] [<c063c8e4>] (rpc_execute) from [<c0634bb0>] (rpc_run_task+0xac/0xb4)
[ 208.316413] r5:ee88dad4 r4:ee257380
[ 208.320017] [<c0634b04>] (rpc_run_task) from [<c0634c00>] (rpc_call_sync+0x48/0xc4)
[ 208.327702] r5:ee88dbc4 r4:ee24f600
[ 208.331307] [<c0634bb8>] (rpc_call_sync) from [<c0634cd8>] (rpc_ping+0x5c/0x78)
[ 208.338644] r4:ee24f600
[ 208.341194] [<c0634c7c>] (rpc_ping) from [<c0634dac>] (rpc_create_xprt+0xb8/0xd0)
[ 208.348705] r4:ee24f600
[ 208.351254] [<c0634cf4>] (rpc_create_xprt) from [<c0634e78>] (rpc_create+0xb4/0x1c4)
[ 208.359028] r7:c0965a40 r6:c0965a40 r5:00000000 r4:ee88dbc4
[ 208.364743] [<c0634dc4>] (rpc_create) from [<c01e1abc>] (nfs_create_rpc_client+0xdc/0x12c)
[ 208.373039] r6:ee88dc94 r5:00000001 r4:ee318e00
[ 208.377698] [<c01e19e0>] (nfs_create_rpc_client) from [<c01e2778>] (nfs_init_client+0x3c/0xd8)
[ 208.386343] r6:eeafefec r5:ee88dca8 r4:ee318e00
[ 208.391002] [<c01e273c>] (nfs_init_client) from [<c01e1840>] (nfs_get_client+0x254/0x3c4)
[ 208.399209] r5:ee88dca8 r4:eeafef18
[ 208.402813] [<c01e15ec>] (nfs_get_client) from [<c01e2994>] (nfs_create_server+0xbc/0x4cc)
[ 208.411109] r10:c09313d4 r9:ee88ddc4 r8:ee24dcc0 r7:ee88dca8 r6:c096c8f0 r5:eeb5f000
[ 208.419006] r4:ee2a0800
[ 208.421559] [<c01e28d8>] (nfs_create_server) from [<c01fa574>] (nfs3_create_server+0x10/0x28)
[ 208.430117] r10:00000001 r9:edd8ca80 r8:c09313d4 r7:c096c8f0 r6:ee88ddc4 r5:00000000
[ 208.438016] r4:ee2a0800
[ 208.440568] [<c01fa564>] (nfs3_create_server) from [<c01ee8a8>] (nfs_try_mount+0xe4/0x340)
[ 208.448865] r5:00000000 r4:ee2a0800
[ 208.452474] [<c01ee7c4>] (nfs_try_mount) from [<c01ee14c>] (nfs_fs_mount+0x624/0xb78)
[ 208.460333] r10:00000400 r9:00008000 r8:edd8ca8c r7:edd8ca80 r6:c096c8f0 r5:c01ee7c4
[ 208.468232] r4:c09313d4
[ 208.470787] [<c01edb28>] (nfs_fs_mount) from [<c0120a90>] (mount_fs+0x1c/0xac)
[ 208.478037] r10:c0930e40 r9:c0928c94 r8:c0930e40 r7:c0930e40 r6:00008000 r5:edd8ca80
[ 208.485936] r4:c01edb28
[ 208.488490] [<c0120a74>] (mount_fs) from [<c0139acc>] (vfs_kern_mount+0x50/0xf8)
[ 208.495914] r8:edd8e000 r7:c0930e40 r6:00008000 r5:edd8ca80 r4:edd71900
[ 208.502681] [<c0139a7c>] (vfs_kern_mount) from [<c013cbb4>] (do_mount+0x1a8/0xc20)
[ 208.510278] r9:c0928c94 r8:edd68c40 r7:edd8ca80 r6:00008000 r5:00000020 r4:edd8e000
[ 208.518094] [<c013ca0c>] (do_mount) from [<c013d9a0>] (SyS_mount+0x7c/0xa8)
[ 208.525081] r10:c090283c r9:c08c25ec r8:00008000 r7:c07eff78 r6:00000000 r5:edd8ca80
[ 208.532979] r4:edd68c40
[ 208.535532] [<c013d924>] (SyS_mount) from [<c08c3494>] (mount_root+0x70/0x12c)
[ 208.542781] r8:c091071c r7:00000006 r6:00000005 r5:c091b888 r4:c0972024
[ 208.549549] [<c08c3424>] (mount_root) from [<c08c36b0>] (prepare_namespace+0x160/0x1a4)
[ 208.557584] r7:c0972000 r6:c0972000 r5:c0902871 r4:c0972024
[ 208.563297] [<c08c3550>] (prepare_namespace) from [<c08c2fdc>] (kernel_init_freeable+0x274/0x284)
[ 208.572203] r5:c0902838 r4:00000008
[ 208.575811] [<c08c2d68>] (kernel_init_freeable) from [<c0660444>] (kernel_init+0x18/0xf0)
[ 208.584019] r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:c066042c
[ 208.591918] r4:c0972000
[ 208.594472] [<c066042c>] (kernel_init) from [<c000fa88>] (ret_from_fork+0x14/0x2c)
[ 208.602070] r5:c066042c r4:00000000
--
regards,
-grygorii