Friday, December 29, 2017

Steps to debug a Linux Kernel Crash

This article gives a glimpse of standard steps to be followed for debugging a crash without getting into actual fix needed for the discussed actual crash scenario.

Note :- I have included the steps that I personally aware of , hence Reader is requested to give inputs to enhance the analysis if he/she feels like that.

Lets discuss the below Android/Linux Kernel Crash here :-

BUG: Bad page state in process Binder_1  pfn:808ff
page:c06edfe0 count:0 mapcount:0 mapping:  (null) index:0x0
page flags: 0x400(reserved)
Unable to handle kernel NULL pointer dereference at virtual address 00000ff0
pgd = e8b34000
[00000ff0] *pgd=00000000
Internal error: Oops: 5 [#1] PREEMPT SMP ARM
Modules linked in: snd_soc_dra7_atl net1080 cdc_subset cdc_ncm cdc_ether usbnet                                                                                         lzo arc4 8021q crc7 crc_ccitt garp dns_resolver xfrm6_mode_tunnel xfrm6_mode_tra                                                                                        nsport stp sit llc input_polldev sdio_uart ntfs hfsplus hfs nls_utf8 cmemk usb_s                                                                                        torage bcmdhd g_ffs_adb snd_usb_audio snd_usbmidi_lib snd_rawmidi snd_hwdep dwc3                                                                                         xhci_hcd libcomposite udc_core dwc3_omap omap_usb3 snd_harman omap_usb2 snd_pcm                                                                                         snd_timer omap_control_usb snd_page_alloc traceBuf snd soundcore lvsd tun mac80                                                                                        211 omaplfb(O) pvrsrvkm(O) [last unloaded: g_ffs]
CPU: 0    Tainted: G    B   W  O  (3.8.13-00562-g606a54b-dirty #1)
pc : []    lr : []    psr: 80000013
sp : e7a4fe08  ip : 00000000  fp : 00000101
r10: e7a4fe60  r9 : e58e9bc0  r8 : ffffff01
r7 : 00000ff0  r6 : c020b7a8  r5 : 00000100  r4 : 00000000
r3 : 00000000  r2 : 00001220  r1 : 00100001  r0 : 00000000
Flags: Nzcv  IRQs on  FIQs on  Mode SVC_32  ISA ARM  Segment user
Control: 10c5387d  Table: a8b3406a  DAC: 00000015

PC: 0xc020b6b4:
b6b4  e2503000 0a00000b e3a00000 e5932000 e2800001 e3120002 112fff1e e5931010
b6d4  e2832010 e3110001 13c12003 e2523000 1afffff5 e12fff1e e1a00003 e12fff1e
b6f4  e92d43f8 e1a09000 e5900000 e1a05001 e3500000 e1a06002 08bd83f8 e5991008
b714  e3510000 1245721f 12658001 11a07207 0a00000c e1550001 e3a03000 e1a04003
b734  37904007 30883001 e5893008 31a01005 33c44003 e12fff36 e5991008 e1a00004
b754  e3510000 1afffff2 e3a03000 e5893000 e8bd83f8 e3a01c01 e59f2000 eaffffdf
b774  c020b7a8 e92d4038 e1b05201 e1a04000 0a000001 e1a01005 ebffc713 e2451010
b794  e7943001 e3c33001 e3833002 e7843001 e8bd8038 e3510c01 0a000000 eafb1d2c

LR: 0xc00ac63c:
c63c  e1a01b01 e3c224ff 1a00001a e3d22503 01a03002 15841000 e2855001 e1550009
c65c  e0866003 e2844020 1affffe6 e3560000 1a00000e e5982000 e59f104c e1a02f22
c67c  e0622202 e0813302 e593238c e0623003 e3530d0f 0a000003 e1a00008 eb005011
c69c  e1a00008 eb00500f e3a00001 e8bd83f8 e3a00000 e8bd83f8 e1a00004 ebffff85
c6bc  e3a03001 eaffffe3 00313ce1 c069b7c0 e92d4ff0 e24dd064 e59dc090 e58d104c
c6dc  e58d201c e59c138c e58d0024 e061100c e2830004 e1a01341 e59da094 e0812201
c6fc  e59d1088 e0823402 e59d204c e083c803 e26cc000 e28d305c e58dc050 eb0035d5
c71c  e59d805c e3580000 e58d0040 0a0000c0 e59dc01c e3a03001 e1a09008 e1a0bc13

SP: 0xe7a4fd88:
fd88  00000001 e7a4fe60 00000101 c04b187c c0518fb0 e7a4fdb4 c0013a40 e7a4fdb4
fda8  c020b734 80000013 ffffffff e7a4fdf4 ffffff01 c00135a0 00000000 00100001
fdc8  00001220 00000000 00000000 00000100 c020b7a8 00000ff0 ffffff01 e58e9bc0
fde8  e7a4fe60 00000101 00000000 e7a4fe08 c00ac6bc c020b734 80000013 ffffffff
fe08  00000001 ffffffea e58e9bc0 00004000 00000000 00001000 00000002 c020bad0
fe28  c020b934 00000002 c067da88 00000002 c067da88 c02f0fe8 e7a4e030 c04f2d64
fe48  e8a66500 e647a2c0 00000000 00ffc00f c0d19d00 e58e9bc0 e270ed08 e58e9648
fe68  b410d4a0 e8a66500 e8c4658c 00000001 c06b8180 e8c46540 00000000 e647a2c0

R6: 0xc020b728:
b728  e1550001 e3a03000 e1a04003 3790.4007 30883001 e5893008 31a01005 33c44003
b748  e12fff36 e5991008 e1a00004 e3510000 1afffff2 e3a03000 e5893000 e8bd83f8
b768  e3a01c01 e59f2000 eaffffdf c020b7a8 e92d4038 e1b05201 e1a04000 0a000001
b788  e1a01005 ebffc713 e2451010 e7943001 e3c33001 e3833002 e7843001 e8bd8038
b7a8  e3510c01 0a000000 eafb1d2c e3a01000 eafa8a45 e1510002 e92d4ff0 e1a06001
b7c8  e24dd00c e1a08002 e1a0a003 e1a05000 8a000033 e3a07000 e3a0100c e1a04007
b7e8  e1a0b006 ebffc6fb e2483001 e58d3004 e1a0000b e1a0100a e59d3030 e12fff33
b808  e2509000 0a00001c e1a0100b ebffffd7 e5952008 e3570000 e0862002 e5852008

R8: 0xfffffe81:
fe80  ******** ******** ******** ******** ******** ******** ******** ********
fea0  ******** ******** ******** ******** ******** ******** ******** ********
fec0  ******** ******** ******** ******** ******** ******** ******** ********
fee0  ******** ******** ******** ******** ******** ******** ******** ********
ff00  ******** ******** ******** ******** ******** ******** ******** ********
ff20  ******** ******** ******** ******** ******** ******** ******** ********
ff40  ******** ******** ******** ******** ******** ******** ******** ********
ff60  ******** ******** ******** ******** ******** ******** ******** ********
ff80  ******** ******** ******** ******** ******** ******** ******** ********

R9: 0xe58e9b40:
9b40  00000000 e8f543c0 f9001b40 00000000 00000000 00000000 00000000 00000000
9b60  00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
9b80  00000001 f9028000 04fd7000 00000000 e79012c0 00000000 00000000 00000000
9ba0  00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
9bc0  c08ff200 00000004 00100001 00200200 cefdb440 00000000 00000000 00000000
9be0  00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
9c00  00000000 e58945c0 ef0040f0 00000000 00000000 00000000 00000000 00000000
9c20  00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000

R10: 0xe7a4fde0:
fde0  ffffff01 e58e9bc0 e7a4fe60 00000101 00000000 e7a4fe08 c00ac6bc c020b734
fe00  80000013 ffffffff 00000001 ffffffea e58e9bc0 00004000 00000000 00001000
fe20  00000002 c020bad0 c020b934 00000002 c067da88 00000002 c067da88 c02f0fe8
fe40  e7a4e030 c04f2d64 e8a66500 e647a2c0 00000000 00ffc00f c0d19d00 e58e9bc0
fe60  e270ed08 e58e9648 b410d4a0 e8a66500 e8c4658c 00000001 c06b8180 e8c46540
fe80  00000000 e647a2c0 c02f0dc0 c02ef574 00000000 e7a4fed0 e793c000 e7a4e038
fea0  00ffc000 00001000 e7974280 e8c4657c e8814e00 b6301a44 e7974280 e7a4e000
fec0  00000001 e8a376c0 0000000d e8f477e0 b6301a44 c02efdd0 00000000 00000000
Process Binder_1 (pid: 1464, stack limit = 0xe7a4e240)
Stack: (0xe7a4fe08 to 0xe7a50000)
fe00:                   00000001 ffffffea e58e9bc0 00004000 00000000 00001000
fe20: 00000002 c020bad0 c020b934 00000002 c067da88 00000002 c067da88 c02f0fe8
fe40: e7a4e030 c04f2d64 e8a66500 e647a2c0 00000000 00ffc00f c0d19d00 e58e9bc0
fe60: e270ed08 e58e9648 b410d4a0 e8a66500 e8c4658c 00000001 c06b8180 e8c46540
fe80: 00000000 e647a2c0 c02f0dc0 c02ef574 00000000 e7a4fed0 e793c000 e7a4e038
fea0: 00ffc000 00001000 e7974280 e8c4657c e8814e00 b6301a44 e7974280 e7a4e000
fec0: 00000001 e8a376c0 0000000d e8f477e0 b6301a44 c02efdd0 00000000 00000000
fee0: 00000001 00ffc000 00001000 00000001 00000000 00000000 00000002 b6301a44
ff00: e8a376c0 0000000d 00000001 c00e68c8 00000000 ffffffff 00000001 00000000
ff20: 00000000 00000060 e8b59240 e8f477e0 e8a376c0 c01c1718 e7a4ff50 00000000
ff40: 00000001 c01c1d70 e7a4ff50 c01b9164 e7a4e001 e88275d0 e8186f70 b6301a44
ff60: c0144900 00000000 00000001 e8a376c0 0000000d 00000000 b5581420 c00e6b18
ff80: 00000000 00000001 00000000 00000000 00001000 0000000d 00000036 c0013be8
ffa0: e7a4e000 c0013a40 00000000 00001000 0000000d c0144900 b6301a44 b6301a20
ffc0: 00000000 00001000 0000000d 00000036 10000003 b6301acc 00000003 b5581420
ffe0: 00ffc000 b6301a10 b6f006f1 b6ee98d4 400f0010 0000000d 00000000 00000000
Function entered at [] from []
Function entered at [] from []
Function entered at [] from []
Function entered at [] from []
Function entered at [] from []
Function entered at [] from []
Function entered at [] from []
Code: 0a00000c e1550001 e3a03000 e1a04003 (37904007)
---[ end trace 0f267459ee8159f7 ]---
type=1400 audit(1468584593.158:35913): avc: denied { connectto } for pid=3480 co                                                                                        mm="JDWP" path=006A6477702D636F6E74726F6C scontext=u:r:gmTbt:s0 tcontext=u:r:su:                                                                                        s0 tclass=unix_stream_socket permissive=0
snd_harman_pcm_trigger 183 cmd 0 Dir 1 buff 0x80000, period 0x8000
snd_harman_pcm_trigger 183 cmd 1 Dir 1 buff 0x80000, period 0x8000
type=1400 audit(1468584593.878:35914): avc: denied { connectto } for pid=3713 co                                                                                        mm="JDWP" path=006A6477702D636F6E74726F6C scontext=u:r:gmOnstarVttproxyserver:s0                                                                                         tcontext=u:r:su:s0 tclass=unix_stream_socket permissive=0
type=1400 audit(1468584593.958:35915): avc: denied { connectto } for pid=2992 co                                                                                        mm="JDWP" path=006A6477702D636F6E74726F6C scontext=u:r:gmNavmgr:s0 tcontext=u:r:                                                                                        su:s0 tclass=unix_stream_socket permissive=0
type=1400 audit(1468584593.988:35916): avc: denied { connectto } for pid=3797 co                                                                                        mm="JDWP" path=006A6477702D636F6E74726F6C scontext=u:r:gmOnstarVttproxyserver:s0                                                                                         tcontext=u:r:su:s0 tclass=unix_stream_socket permissive=0
type=1400 audit(1468584595.158:35917): avc: denied { connectto } for pid=3480 co                                                                                        mm="JDWP" path=006A6477702D636F6E74726F6C scontext=u:r:gmTbt:s0 tcontext=u:r:su:                                                                                        s0 tclass=unix_stream_socket permissive=0
type=1400 audit(1468584595.878:35918): avc: denied { connectto } for pid=3713 co                                                                                        mm="JDWP" path=006A6477702D636F6E74726F6C scontext=u:r:gmOnstarVttproxyserver:s0                                                                                         tcontext=u:r:su:s0 tclass=unix_stream_socket permissive=0
type=1400 audit(1468584595.958:35919): avc: denied { connectto } for pid=2992 co                                                                                        mm="JDWP" path=006A6477702D636F6E74726F6C scontext=u:r:gmNavmgr:s0 tcontext=u:r:                                                                                        su:s0 tclass=unix_stream_socket permissive=0
type=1400 audit(1468584595.988:35920): avc: denied { connectto } for pid=3797 co                                                                                        mm="JDWP" path=006A6477702D636F6E74726F6C scontext=u:r:gmOnstarVttproxyserver:s0                                                                                         tcontext=u:r:su:s0 tclass=unix_stream_socket permissive=0
type=1400 audit(1468584597.158:35921): avc: denied { connectto } for pid=3480 co                                                                                        mm="JDWP" path=006A6477702D636F6E74726F6C scontext=u:r:gmTbt:s0 tcontext=u:r:su:                                                                                        s0 tclass=unix_stream_socket permissive=0
type=1400 audit(1468584597.878:35922): avc: denied { connectto } for pid=3713 co                                                                                        mm="JDWP" path=006A6477702D636F6E74726F6C scontext=u:r:gmOnstarVttproxyserver:s0                                                                                         tcontext=u:r:su:s0 tclass=unix_stream_socket permissive=0
type=1400 audit(1468584597.958:35923): avc: denied { connectto } for pid=2992 co                                                                                        mm="JDWP" path=006A6477702D636F6E74726F6C scontext=u:r:gmNavmgr:s0 tcontext=u:r:                                                                                        su:s0 tclass=unix_stream_socket permissive=0
type=1400 audit(1468584597.988:35924): avc: denied { connectto } for pid=3797 co                                                                                        mm="JDWP" path=006A6477702D636F6E74726F6C scontext=u:r:gmOnstarVttproxyserver:s0                                                                                         tcontext=u:r:su:s0 tclass=unix_stream_socket permissive=0
type=1400 audit(1468584599.158:35925): avc: denied { connectto } for pid=3480 co                                                                                        mm="JDWP" path=006A6477702D636F6E74726F6C scontext=u:r:gmTbt:s0 tcontext=u:r:su:                                                                                        s0 tclass=unix_stream_socket permissive=0
type=1400 audit(1468584599.878:35926): avc: denied { connectto } for pid=3713 co                                                                                        mm="JDWP" path=006A6477702D636F6E74726F6C scontext=u:r:gmOnstarVttproxyserver:s0                                                                                         tcontext=u:r:su:s0 tclass=unix_stream_socket permissive=0
type=1400 audit(1468584599.958:35927): avc: denied { connectto } for pid=2992 co                                                                                        mm="JDWP" path=006A6477702D636F6E74726F6C scontext=u:r:gmNavmgr:s0 tcontext=u:r:                                                                                        su:s0 tclass=unix_stream_socket permissive=0
type=1400 audit(1468584599.998:35928): avc: denied { connectto } for pid=3797 co                                                                                        mm="JDWP" path=006A6477702D636F6E74726F6C scontext=u:r:gmOnstarVttproxyserver:s0                                                                                         tcontext=u:r:su:s0 tclass=unix_stream_socket permissive=0
type=1400 audit(1468584601.158:35929): avc: denied { connectto } for pid=3480 co                                                                                        mm="JDWP" path=006A6477702D636F6E74726F6C scontext=u:r:gmTbt:s0 tcontext=u:r:su:                                                                                        s0 tclass=unix_stream_socket permissive=0
type=1400 audit(1468584601.878:35930): avc: denied { connectto } for pid=3713 co                                                                                        mm="JDWP" path=006A6477702D636F6E74726F6C scontext=u:r:gmOnstarVttproxyserver:s0                                                                                         tcontext=u:r:su:s0 tclass=unix_stream_socket permissive=0
type=1400 audit(1468584601.958:35931): avc: denied { connectto } for pid=2992 co                                                                                        mm="JDWP" path=006A6477702D636F6E74726F6C scontext=u:r:gmNavmgr:s0 tcontext=u:r:                                                                                        su:s0 tclass=unix_stream_socket permissive=0
type=1400 audit(1468584601.998:35932): avc: denied { connectto } for pid=3797 co                                                                                        mm="JDWP" path=006A6477702D636F6E74726F6C scontext=u:r:gmOnstarVttproxyserver:s0                                                                                         tcontext=u:r:su:s0 tclass=unix_stream_socket permissive=0
type=1400 audit(1468584603.158:35933): avc: denied { connectto } for pid=3480 co                                                                                        mm="JDWP" path=006A6477702D636F6E74726F6C scontext=u:r:gmTbt:s0 tcontext=u:r:su:                                                                                        s0 tclass=unix_stream_socket permissive=0
### [oops_do_dump:65] should be done
Kernel panic - not syncing: Fatal exception
CPU1: stopping
Function entered at [] from []
Function entered at [] from []
Function entered at [] from []
Exception stack(0xe8891f88 to 0xe8891fd0)
1f80:                   c16dbb08 00000000 00000003 c0031d84 e8890000 e8890000
1fa0: c069c708 00000000 c0630690 e8890000 c04c0124 00000000 c06290d0 e8891fd0
1fc0: c003033c c0014bb4 a0000013 ffffffff
Function entered at [] from []
Function entered at [] from []
Function entered at [] from [<804ad288>]
type=1400 audit(1468584603.248:35934): avc: denied { connectto } for pid=3713 co                                                                                        mm="JDWP" path=006A6477702D636F6E74726F6C scontext=u:r:gmOnstarVttproxyserver:s0                                                                                         tcontext=u:r:su:s0 tclass=unix_stream_socket permissive=0

Interesting Points to Note :-

  1. It is important to get the VMLINUX image so that an Objdump can be generated using the ARM compiler. This can be generated using  "arm-linux-androideabi-objdump -Sd vmlinux > output.txt". The Output.txt gives you an objdump with or without symbols as may be the build.
  2. CPU0 triggered the Crash here because that is the first CPU that crashed in this multi-core system and CPU1 is crashed due to the CPU0, hence we will be more interested in CPU0 here.
  3. BUG: Bad page state in process Binder_1 (Self-Explanatory)
  4. Unable to handle kernel NULL pointer dereference  (Self-Explanatory)
  5. Internal error: Oops: 5 [#1] PREEMPT SMP ARM.
  6. CPU: 0    Tainted: G    B   W  O  (3.8.13-00562-g606a54b-dirty #1)
The Oops Number mentioned in (4)  here is 5, This is the error code value in hex. Each bit has a significance of its own:

  • bit 0 == 0 means no page found, 1 means a protection fault
  • bit 1 == 0 means read, 1 means write
  • bit 2 == 0 means kernel, 1 means user-mode
  • [#1] — this value is the number of times the Oops occurred. Multiple Oops can be triggered as a cascading effect of the first one.
Other important point is in the point (5), Have a look it "Tainted kernels" section in https://www.kernel.org/doc/Documentation/oops-tracing.txt

ARM registers like lr and psr.

pc : []    lr : []    psr: 80000013

sp : e7a4fe08  ip : 00000000  fp : 00000101
r10: e7a4fe60  r9 : e58e9bc0  r8 : ffffff01
r7 : 00000ff0  r6 : c020b7a8  r5 : 00000100  r4 : 00000000
r3 : 00000000  r2 : 00001220  r1 : 00100001  r0 : 00000000
Flags: Nzcv  IRQs on  FIQs on  Mode SVC_32  ISA ARM  Segment user






No comments:

Post a Comment