Race with ip=dhcp bootparameter in ip_rcv_finish on am335x

Hi,

I am using am335x (beaglebone white) with "ip=dhcp" inside my
bootparameters. It seems there exists some race, rarely it boots fine
and often it crashed with following messages:

First (Without successful dhcp ip assign and is very rarely):

[    6.249083] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[    6.398943] .
[    7.400822] Unable to handle kernel paging request at virtual address 7402a8c8
[    7.408419] pgd = c0004000
[    7.411351] [7402a8c8] *pgd=00000000
[    7.415121] Internal error: Oops: 5 [#1] SMP ARM
[    7.419968] Modules linked in:
[    7.423197] CPU: 0 PID: 0 Comm: swapper/0 Tainted: G        W       4.2.0-11195-ge81be90 #124
[    7.432118] Hardware name: Generic AM33XX (Flattened Device Tree)
[    7.438509] task: c0a996c8 ti: c0a92000 task.ti: c0a92000
[    7.444189] PC is at ip_route_input_noref+0x620/0xeb4
[    7.449491] LR is at trace_hardirqs_on_caller+0xb0/0x1e8
[    7.455055] pc : [<c054b49c>]    lr : [<c008e198>]    psr: 20000113
[    7.455055] sp : c0a93c70  ip : 0000000f  fp : ffffff8f
[    7.467072] r10: c0b35c80  r9 : 00000000  r8 : ce5f9400
[    7.472543] r7 : ce5ef000  r6 : 00000000  r5 : ce615640  r4 : ce5ffd40
[    7.479378] r3 : 7402a8c0  r2 : 00000001  r1 : c0549f74  r0 : ce5ffd40
[    7.486216] Flags: nzCv  IRQs on  FIQs on  Mode SVC_32  ISA ARM  Segment none
[    7.493686] Control: 10c5387d  Table: 80004019  DAC: 00000051
[    7.499699] Process swapper/0 (pid: 0, stack limit = 0xc0a92218)
[    7.505989] Stack: (0xc0a93c70 to 0xc0a94000)
[    7.510561] 3c60:                                     00000000 00000000 c054afa4 00000000
[    7.519131] 3c80: 00000000 c0b56080 00000000 00000000 00000000 00070044 00000004 00000000
[    7.527705] 3ca0: 7402a8c0 0000012d 00000000 00000004 00000000 00000000 c0586298 00000000
[    7.536278] 3cc0: 00000000 00000000 0102a8c0 7402a8c0 cfba6c34 00000000 c0a996c8 ce615640
[    7.544852] 3ce0: c0551310 ce61b850 c07c6b10 c0b560b8 c0a95744 00000000 00000000 c0550668
[    7.553422] 3d00: ce5ef000 c0a5ed00 60000113 c0090d44 00000001 ce615640 c04f85d0 00000050
[    7.561996] 3d20: ce61b800 ce5ef000 c0a95744 00000000 00000000 c0551310 00000001 00000000
[    7.570563] 3d40: c04f85d0 ce000140 ce638100 00000050 ce61b800 cfba6b10 ce61b99a ce61b99a
[    7.579135] 3d60: c0a82730 c0a92000 ce61b850 c0a5ed94 00000100 0102a8c0 c0a996c8 c0a9791c
[    7.587709] 3d80: ce5ef000 ce5ef048 00000008 ce615640 ce5ef05c ce6156ec ce615640 c04f85d0
[    7.596289] 3da0: c0ad3f0c 00000000 c0a92000 ce5ef054 00000000 c04fb4e8 60000113 ce615640

153 more lines

On 09/23/2015 12:29 PM, Alexander Aring wrote:

Hi,

I am using am335x (beaglebone white) with "ip=dhcp" inside my
bootparameters. It seems there exists some race, rarely it boots fine
and often it crashed with following messages:

First (Without successful dhcp ip assign and is very rarely):

[    6.249083] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[    6.398943] .
[    7.400822] Unable to handle kernel paging request at virtual address 7402a8c8
[    7.408419] pgd = c0004000
[    7.411351] [7402a8c8] *pgd=00000000
[    7.415121] Internal error: Oops: 5 [#1] SMP ARM
[    7.419968] Modules linked in:
[    7.423197] CPU: 0 PID: 0 Comm: swapper/0 Tainted: G        W       4.2.0-11195-ge81be90 #124
[    7.432118] Hardware name: Generic AM33XX (Flattened Device Tree)
[    7.438509] task: c0a996c8 ti: c0a92000 task.ti: c0a92000
[    7.444189] PC is at ip_route_input_noref+0x620/0xeb4
[    7.449491] LR is at trace_hardirqs_on_caller+0xb0/0x1e8

<<<snip>>>

[    7.759169] [<c054b49c>] (ip_route_input_noref) from [<c0550668>] (ip_rcv_finish+0xd4/0x67c)

<<<snip>>>

--------

I tried to bisect this issue without success, sometimes it's booting fine
and sometimes I got the above messages. Could anybody help me here to
fixing this issue?

- Alex

Hi Alex,
This should be fixed by commit bde6f9ded1bd 
("net: Initialize table in fib result") in net-next.

Cheers,
 Nik

Hi,

On Wed, Sep 23, 2015 at 12:36:13PM +0200, Nikolay Aleksandrov wrote:

On 09/23/2015 12:29 PM, Alexander Aring wrote:

quoted

Hi,

I am using am335x (beaglebone white) with "ip=dhcp" inside my
bootparameters. It seems there exists some race, rarely it boots fine
and often it crashed with following messages:

First (Without successful dhcp ip assign and is very rarely):

[    6.249083] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[    6.398943] .
[    7.400822] Unable to handle kernel paging request at virtual address 7402a8c8
[    7.408419] pgd = c0004000
[    7.411351] [7402a8c8] *pgd=00000000
[    7.415121] Internal error: Oops: 5 [#1] SMP ARM
[    7.419968] Modules linked in:
[    7.423197] CPU: 0 PID: 0 Comm: swapper/0 Tainted: G        W       4.2.0-11195-ge81be90 #124
[    7.432118] Hardware name: Generic AM33XX (Flattened Device Tree)
[    7.438509] task: c0a996c8 ti: c0a92000 task.ti: c0a92000
[    7.444189] PC is at ip_route_input_noref+0x620/0xeb4
[    7.449491] LR is at trace_hardirqs_on_caller+0xb0/0x1e8

<<<snip>>>

quoted

[    7.759169] [<c054b49c>] (ip_route_input_noref) from [<c0550668>] (ip_rcv_finish+0xd4/0x67c)

<<<snip>>>

quoted

--------

I tried to bisect this issue without success, sometimes it's booting fine
and sometimes I got the above messages. Could anybody help me here to
fixing this issue?

- Alex

Hi Alex,
This should be fixed by commit bde6f9ded1bd 
("net: Initialize table in fib result") in net-next.

I tried to cherry-picked this commit and saw this is already in net-next.
I also tried to boot current net, the race is still there.

- Alex

On Wed, Sep 23, 2015 at 12:36:13PM +0200, Nikolay Aleksandrov wrote:

On 09/23/2015 12:29 PM, Alexander Aring wrote:

quoted

Hi,

I am using am335x (beaglebone white) with "ip=dhcp" inside my
bootparameters. It seems there exists some race, rarely it boots fine
and often it crashed with following messages:

First (Without successful dhcp ip assign and is very rarely):

[    6.249083] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[    6.398943] .
[    7.400822] Unable to handle kernel paging request at virtual address 7402a8c8
[    7.408419] pgd = c0004000
[    7.411351] [7402a8c8] *pgd=00000000
[    7.415121] Internal error: Oops: 5 [#1] SMP ARM
[    7.419968] Modules linked in:
[    7.423197] CPU: 0 PID: 0 Comm: swapper/0 Tainted: G        W       4.2.0-11195-ge81be90 #124
[    7.432118] Hardware name: Generic AM33XX (Flattened Device Tree)
[    7.438509] task: c0a996c8 ti: c0a92000 task.ti: c0a92000
[    7.444189] PC is at ip_route_input_noref+0x620/0xeb4
[    7.449491] LR is at trace_hardirqs_on_caller+0xb0/0x1e8

<<<snip>>>

quoted

[    7.759169] [<c054b49c>] (ip_route_input_noref) from [<c0550668>] (ip_rcv_finish+0xd4/0x67c)

<<<snip>>>

quoted

--------

I tried to bisect this issue without success, sometimes it's booting fine
and sometimes I got the above messages. Could anybody help me here to
fixing this issue?

- Alex

Hi Alex,
This should be fixed by commit bde6f9ded1bd 
("net: Initialize table in fib result") in net-next.

Ok, I think I have two issues with two different races the first one was
fixed by bde6f9ded1bd ("net: Initialize table in fib result"), but the
second one is still there:

[    8.615806] ------------[ cut here ]------------
[    8.620678] Kernel BUG at c016c3d0 [verbose debug info unavailable]
[    8.627229] Internal error: Oops - BUG: 0 [#1] SMP ARM
[    8.632611] Modules linked in:
[    8.635836] CPU: 0 PID: 766 Comm: kworker/0:1H Tainted: G        W       4.2.0-11248-gfbd0351 #140
[    8.645208] Hardware name: Generic AM33XX (Flattened Device Tree)
[    8.651616] Workqueue: rpciod xprt_autoclose
[    8.656091] task: ce3c52c0 ti: ce642000 task.ti: ce642000
[    8.661744] PC is at iput+0x1a8/0x1f0
[    8.665579] LR is at xprt_autoclose+0x2c/0x54
[    8.670136] pc : [<c016c3d0>]    lr : [<c066c884>]    psr: 20000113
[    8.670136] sp : ce643e80  ip : 00000000  fp : c0b56688
[    8.682133] r10: 00000001  r9 : ce643ec8  r8 : 00000000
[    8.687599] r7 : feff3000  r6 : ce615800  r5 : ce615bc0  r4 : ce615b54
[    8.694421] r3 : 00000060  r2 : 0000000f  r1 : 0f10e000  r0 : cdbed720
[    8.701254] Flags: nzCv  IRQs on  FIQs on  Mode SVC_32  ISA ARM  Segment none
[    8.708718] Control: 10c5387d  Table: 80004019  DAC: 00000051
[    8.714732] Process kworker/0:1H (pid: 766, stack limit = 0xce642218)
[    8.721464] Stack: (0xce643e80 to 0xce644000)
[    8.726033] 3e80: c066f828 ce615b54 ce615bc0 ce615800 feff3000 00000000 ce643ec8 c066c884
[    8.734596] 3ea0: ce615b54 ce5ff440 cfb9e340 c0057928 00000001 00000000 c00578b4 cfb9e340
[    8.743152] 3ec0: c0057cc8 00000000 c137972c c0cc1960 00000000 c09979f4 cfb9e340 cfb9e340
[    8.751714] 3ee0: ce5ff458 cfb9e370 ce642000 00000008 c0b55ba0 ce5ff440 cfb9e340 c0057c54
[    8.760274] 3f00: ce659940 ce5ff440 c0057c18 00000000 ce659940 ce5ff440 c0057c18 00000000
[    8.768834] 3f20: 00000000 00000000 00000000 c005d918 c0b5697c 00000000 00000000 ce5ff440
[    8.777390] 3f40: 00000000 00000000 dead4ead ffffffff ffffffff c0b65d60 00000000 00000000
[    8.785951] 3f60: c0922088 ce643f64 ce643f64 00000000 00000000 dead4ead ffffffff ffffffff
[    8.794513] 3f80: c0b65d60 00000000 00000000 c0922088 ce643f90 ce643f90 ce643fac ce659940
[    8.803069] 3fa0: c005d844 00000000 00000000 c000f770 00000000 00000000 00000000 00000000
[    8.811628] 3fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
[    8.820185] 3fe0: 00000000 00000000 00000000 00000000 00000013 00000000 8fdf6861 8fdf6c61
[    8.828741] [<c016c3d0>] (iput) from [<c066c884>] (xprt_autoclose+0x2c/0x54)
[    8.836133] [<c066c884>] (xprt_autoclose) from [<c0057928>] (process_one_work+0x19c/0x48c)
[    8.844784] [<c0057928>] (process_one_work) from [<c0057c54>] (worker_thread+0x3c/0x4a0)
[    8.853256] [<c0057c54>] (worker_thread) from [<c005d918>] (kthread+0xd4/0xf0)

76 more lines

Hi,

On Wed, Sep 23, 2015 at 01:57:57PM +0200, Alexander Aring wrote:
...

quoted

Ok, I think I have two issues with two different races the first one was
fixed by bde6f9ded1bd ("net: Initialize table in fib result"), but the
second one is still there:

[    8.615806] ------------[ cut here ]------------
[    8.620678] Kernel BUG at c016c3d0 [verbose debug info unavailable]
[    8.627229] Internal error: Oops - BUG: 0 [#1] SMP ARM
[    8.632611] Modules linked in:
[    8.635836] CPU: 0 PID: 766 Comm: kworker/0:1H Tainted: G        W       4.2.0-11248-gfbd0351 #140
[    8.645208] Hardware name: Generic AM33XX (Flattened Device Tree)
[    8.651616] Workqueue: rpciod xprt_autoclose
[    8.656091] task: ce3c52c0 ti: ce642000 task.ti: ce642000
[    8.661744] PC is at iput+0x1a8/0x1f0
[    8.665579] LR is at xprt_autoclose+0x2c/0x54
[    8.670136] pc : [<c016c3d0>]    lr : [<c066c884>]    psr: 20000113
[    8.670136] sp : ce643e80  ip : 00000000  fp : c0b56688
[    8.682133] r10: 00000001  r9 : ce643ec8  r8 : 00000000
[    8.687599] r7 : feff3000  r6 : ce615800  r5 : ce615bc0  r4 : ce615b54
[    8.694421] r3 : 00000060  r2 : 0000000f  r1 : 0f10e000  r0 : cdbed720
[    8.701254] Flags: nzCv  IRQs on  FIQs on  Mode SVC_32  ISA ARM  Segment none
[    8.708718] Control: 10c5387d  Table: 80004019  DAC: 00000051
[    8.714732] Process kworker/0:1H (pid: 766, stack limit = 0xce642218)
[    8.721464] Stack: (0xce643e80 to 0xce644000)
[    8.726033] 3e80: c066f828 ce615b54 ce615bc0 ce615800 feff3000 00000000 ce643ec8 c066c884
[    8.734596] 3ea0: ce615b54 ce5ff440 cfb9e340 c0057928 00000001 00000000 c00578b4 cfb9e340
[    8.743152] 3ec0: c0057cc8 00000000 c137972c c0cc1960 00000000 c09979f4 cfb9e340 cfb9e340
[    8.751714] 3ee0: ce5ff458 cfb9e370 ce642000 00000008 c0b55ba0 ce5ff440 cfb9e340 c0057c54
[    8.760274] 3f00: ce659940 ce5ff440 c0057c18 00000000 ce659940 ce5ff440 c0057c18 00000000
[    8.768834] 3f20: 00000000 00000000 00000000 c005d918 c0b5697c 00000000 00000000 ce5ff440
[    8.777390] 3f40: 00000000 00000000 dead4ead ffffffff ffffffff c0b65d60 00000000 00000000
[    8.785951] 3f60: c0922088 ce643f64 ce643f64 00000000 00000000 dead4ead ffffffff ffffffff
[    8.794513] 3f80: c0b65d60 00000000 00000000 c0922088 ce643f90 ce643f90 ce643fac ce659940
[    8.803069] 3fa0: c005d844 00000000 00000000 c000f770 00000000 00000000 00000000 00000000
[    8.811628] 3fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
[    8.820185] 3fe0: 00000000 00000000 00000000 00000000 00000013 00000000 8fdf6861 8fdf6c61
[    8.828741] [<c016c3d0>] (iput) from [<c066c884>] (xprt_autoclose+0x2c/0x54)
[    8.836133] [<c066c884>] (xprt_autoclose) from [<c0057928>] (process_one_work+0x19c/0x48c)
[    8.844784] [<c0057928>] (process_one_work) from [<c0057c54>] (worker_thread+0x3c/0x4a0)

3 more quoted lines

Additional missing information is that I am booting via nfsroot and
xprt_autoclose is something from sunrpc.

Finally I figured out that commit
4876cc779ff525b9c2376d8076edf47815e71f2c ("SUNRPC: Ensure we release the
TCP socket once it has been closed") occur this races. After reverting
this commit everything works fine.

I added now:

Steven Rostedt [off-list ref]
Trond Myklebust [off-list ref]

to cc to report about this issue.

- Alex

On Wed, 23 Sep 2015 14:27:15 +0200
Alexander Aring [off-list ref] wrote:

\

Finally I figured out that commit
4876cc779ff525b9c2376d8076edf47815e71f2c ("SUNRPC: Ensure we release the
TCP socket once it has been closed") occur this races. After reverting
this commit everything works fine.

Yay! Everybody sing! "Fix one bug and replace it by another..."

-- Steve

+linux-nfs mailing list

On Wed, Sep 23, 2015 at 8:27 AM, Alexander Aring [off-list ref] wrote:

Hi,

On Wed, Sep 23, 2015 at 01:57:57PM +0200, Alexander Aring wrote:
...

quoted

quoted

Ok, I think I have two issues with two different races the first one was
fixed by bde6f9ded1bd ("net: Initialize table in fib result"), but the
second one is still there:

[    8.615806] ------------[ cut here ]------------
[    8.620678] Kernel BUG at c016c3d0 [verbose debug info unavailable]
[    8.627229] Internal error: Oops - BUG: 0 [#1] SMP ARM
[    8.632611] Modules linked in:
[    8.635836] CPU: 0 PID: 766 Comm: kworker/0:1H Tainted: G        W       4.2.0-11248-gfbd0351 #140
[    8.645208] Hardware name: Generic AM33XX (Flattened Device Tree)
[    8.651616] Workqueue: rpciod xprt_autoclose
[    8.656091] task: ce3c52c0 ti: ce642000 task.ti: ce642000
[    8.661744] PC is at iput+0x1a8/0x1f0
[    8.665579] LR is at xprt_autoclose+0x2c/0x54
[    8.670136] pc : [<c016c3d0>]    lr : [<c066c884>]    psr: 20000113
[    8.670136] sp : ce643e80  ip : 00000000  fp : c0b56688
[    8.682133] r10: 00000001  r9 : ce643ec8  r8 : 00000000
[    8.687599] r7 : feff3000  r6 : ce615800  r5 : ce615bc0  r4 : ce615b54
[    8.694421] r3 : 00000060  r2 : 0000000f  r1 : 0f10e000  r0 : cdbed720
[    8.701254] Flags: nzCv  IRQs on  FIQs on  Mode SVC_32  ISA ARM  Segment none
[    8.708718] Control: 10c5387d  Table: 80004019  DAC: 00000051
[    8.714732] Process kworker/0:1H (pid: 766, stack limit = 0xce642218)
[    8.721464] Stack: (0xce643e80 to 0xce644000)
[    8.726033] 3e80: c066f828 ce615b54 ce615bc0 ce615800 feff3000 00000000 ce643ec8 c066c884
[    8.734596] 3ea0: ce615b54 ce5ff440 cfb9e340 c0057928 00000001 00000000 c00578b4 cfb9e340
[    8.743152] 3ec0: c0057cc8 00000000 c137972c c0cc1960 00000000 c09979f4 cfb9e340 cfb9e340
[    8.751714] 3ee0: ce5ff458 cfb9e370 ce642000 00000008 c0b55ba0 ce5ff440 cfb9e340 c0057c54
[    8.760274] 3f00: ce659940 ce5ff440 c0057c18 00000000 ce659940 ce5ff440 c0057c18 00000000
[    8.768834] 3f20: 00000000 00000000 00000000 c005d918 c0b5697c 00000000 00000000 ce5ff440
[    8.777390] 3f40: 00000000 00000000 dead4ead ffffffff ffffffff c0b65d60 00000000 00000000
[    8.785951] 3f60: c0922088 ce643f64 ce643f64 00000000 00000000 dead4ead ffffffff ffffffff
[    8.794513] 3f80: c0b65d60 00000000 00000000 c0922088 ce643f90 ce643f90 ce643fac ce659940
[    8.803069] 3fa0: c005d844 00000000 00000000 c000f770 00000000 00000000 00000000 00000000
[    8.811628] 3fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000

23 more quoted lines

Is that happening when the transport is being torn down? If so, is it
fixed by http://git.linux-nfs.org/?p=trondmy/linux-nfs.git;a=commitdiff;h=79234c3db6842a3de03817211d891e0c2878f756
?

Hi,

On Wed, Sep 23, 2015 at 09:16:00AM -0400, Trond Myklebust wrote:
...

Is that happening when the transport is being torn down? If so, is it
fixed by http://git.linux-nfs.org/?p=trondmy/linux-nfs.git;a=commitdiff;h=79234c3db6842a3de03817211d891e0c2878f756
?

thanks. This patch fixed my issue.

- Alex