Kernel oops with ecryptfs_verbosity=1

[Daniel DeFreez]

When the ecryptfs_verbosity module parameter is enabled (handy), I have experienced frequent kernel null pointer dereferences. See example trace below.

This looks like it is the result of ecryptfs_encrypt_extent and ecryptfs_decrypt_extent using page_address(page) on pages that are not necessarily mapped. These address lookups are only performed when verbose mode is enabled.

I have attached a patch that kmaps the unencrypted page prior to printing debug information. The extra kmap shouldn't be an issue, as it is only performed in a debugging scenario.

Typical trace:

Jan 8 22:13:05 e4 sudo: daniel : TTY=pts/0 ; PWD=/home/daniel ; USER=root ; COMMAND=/sbin/modprobe ecryptfs ecryptfs_verbosity=1
Jan 8 22:13:05 e4 sudo: pam_unix(sudo:session): session opened for user root by daniel(uid=1000)
Jan 8 22:13:05 e4 kernel: [ 166.173901] eCryptfs verbosity set to 1. Secret values will be written to the syslog!
Jan 8 22:13:16 e4 sudo: daniel : TTY=pts/0 ; PWD=/home/daniel ; USER=root ; COMMAND=/bin/mount -t ecryptfs bottom top
Jan 8 22:13:16 e4 sudo: pam_unix(sudo:session): session opened for user root by daniel(uid=1000)
Jan 8 22:13:39 e4 kernel: [ 200.305189] ecryptfs_open: Setting flags for stat...
Jan 8 22:13:39 e4 kernel: [ 200.305193] ecryptfs_open: This is a directory
Jan 8 22:13:49 e4 kernel: [ 210.519997] ecryptfs_initialize_file: Initializing crypto context
Jan 8 22:13:49 e4 kernel: [ 210.520254] ecryptfs_generate_new_key: Generated new session key:
Jan 8 22:13:49 e4 kernel: [ 210.520260] 0x38.0x89.0xc3.0x76.0x03.0x87.0x1e.0xe5.0xd0.0x20.0xc7.0x15.0xfa.0xc7.0xeb.0x63.
Jan 8 22:13:49 e4 kernel: [ 210.520270] ecryptfs_init_crypt_ctx: Initializing cipher [aes]; strlen = [3]; key_size_bits = [128]
Jan 8 22:13:49 e4 kernel: [ 210.522945] write_tag_3_packet: Using previously generated session key encryption key of size [64]
Jan 8 22:13:49 e4 kernel: [ 210.522948] write_tag_3_packet: Cached session key encryption key:
Jan 8 22:13:49 e4 kernel: [ 210.522950] 0x9a.0xc7.0x2c.0xbe.0xb5.0xb4.0x15.0x3d.0x87.0x86.0x63.0x88.0xbc.0xfe.0x50.0x2e.
Jan 8 22:13:49 e4 kernel: [ 210.522959] write_tag_3_packet: Session key encryption key:
Jan 8 22:13:49 e4 kernel: [ 210.522961] 0x9a.0xc7.0x2c.0xbe.0xb5.0xb4.0x15.0x3d.0x87.0x86.0x63.0x88.0xbc.0xfe.0x50.0x2e.
Jan 8 22:13:49 e4 kernel: [ 210.522972] write_tag_3_packet: Encrypting [16] bytes of the key
Jan 8 22:13:49 e4 kernel: [ 210.522989] write_tag_3_packet: This should be the encrypted key:
Jan 8 22:13:49 e4 kernel: [ 210.522992] write_tag_3_packet: EFEK of size [16]:
Jan 8 22:13:49 e4 kernel: [ 210.522993] 0x10.0x93.0x8c.0x2d.0x28.0xd0.0x05.0x48.0x55.0xfe.0xef.0xe7.0x5f.0x15.0x36.0x05.
Jan 8 22:13:49 e4 kernel: [ 210.523085] ecryptfs_open: Setting flags for stat...
Jan 8 22:13:49 e4 kernel: [ 210.523090] ecryptfs_open: inode w/ addr = [0xf4c6c000], i_ino = [0x00000000000e5b42] size: [0x0000000000000000]
Jan 8 22:13:49 e4 kernel: [ 210.523118] ecryptfs_write_end: Calling fill_zeros_to_end_of_page(page w/ index = [0x0000000000000000], to = [15])
Jan 8 22:13:49 e4 kernel: [ 210.523123] ecryptfs_write_end: Expanded file size to [0x000000000000000f]
Jan 8 22:13:49 e4 kernel: [ 210.523134] ecryptfs_derive_iv: root iv:
Jan 8 22:13:49 e4 kernel: [ 210.523136] 0x3b.0xa0.0x98.0x71.0x04.0x60.0x0a.0x57.0x2b.0x4a.0x34.0x60.0x04.0x1e.0xfb.0xb3.
Jan 8 22:13:49 e4 kernel: [ 210.523145] ecryptfs_derive_iv: source:
Jan 8 22:13:49 e4 kernel: [ 210.523146] 0x3b.0xa0.0x98.0x71.0x04.0x60.0x0a.0x57.0x2b.0x4a.0x34.0x60.0x04.0x1e.0xfb.0xb3.
Jan 8 22:13:49 e4 kernel: [ 210.523155] 0x30.0x00.0x00.0x00.0x00.0x00.0x00.0x00.0x00.0x00.0x00.0x00.0x00.0x00.0x00.0x00.
Jan 8 22:13:49 e4 kernel: [ 210.523166] ecryptfs_derive_iv: derived iv:
Jan 8 22:13:49 e4 kernel: [ 210.523167] 0xbc.0xdd.0xb6.0xf0.0xf4.0x95.0x8a.0x94.0xa0.0xde.0xbd.0x1b.0x71.0xe3.0xd5.0x9a.
Jan 8 22:13:49 e4 kernel: [ 210.523176] ecryptfs_encrypt_extent: Encrypting extent with iv:
Jan 8 22:13:49 e4 kernel: [ 210.523178] 0xbc.0xdd.0xb6.0xf0.0xf4.0x95.0x8a.0x94.0xa0.0xde.0xbd.0x1b.0x71.0xe3.0xd5.0x9a.
Jan 8 22:13:49 e4 kernel: [ 210.523187] ecryptfs_encrypt_extent: First 8 bytes before encryption:
Jan 8 22:13:49 e4 kernel: [ 210.523200] BUG: unable to handle kernel NULL pointer dereference at (null)
Jan 8 22:13:49 e4 kernel: [ 210.524015] IP: [<f8075e12>] ecryptfs_dump_hex+0x32/0xa0 [ecryptfs]
Jan 8 22:13:49 e4 kernel: [ 210.525058] *pde = 00000000
Jan 8 22:13:49 e4 kernel: [ 210.525292] Oops: 0000 [#1] SMP
Jan 8 22:13:49 e4 kernel: [ 210.525292] Modules linked in: ecb ecryptfs [last unloaded: ecryptfs]
Jan 8 22:13:49 e4 kernel: [ 210.525292]
Jan 8 22:13:49 e4 kernel: [ 210.525292] Pid: 1773, comm: bash Not tainted 3.2.0+ #1 Bochs Bochs
Jan 8 22:13:49 e4 kernel: [ 210.525292] EIP: 0060:[<f8075e12>] EFLAGS: 00010202 CPU: 3
Jan 8 22:13:49 e4 kernel: [ 210.525292] EIP is at ecryptfs_dump_hex+0x32/0xa0 [ecryptfs]
Jan 8 22:13:49 e4 kernel: [ 210.525292] EAX: 00000001 EBX: 00000000 ECX: c187da80 EDX: 00000008
Jan 8 22:13:49 e4 kernel: [ 210.525292] ESI: f4c6c16c EDI: f4c6c000 EBP: f4c4dd58 ESP: f4c4dd44
Jan 8 22:13:49 e4 kernel: [ 210.525292] DS: 007b ES: 007b FS: 00d8 GS: 0033 SS: 0068
Jan 8 22:13:49 e4 kernel: [ 210.525292] Process bash (pid: 1773, ti=f4c4c000 task=f5170000 task.ti=f4c4c000)
Jan 8 22:13:49 e4 kernel: [ 210.525292] Stack:
Jan 8 22:13:49 e4 kernel: [ 210.525292] c10ce688 c187da80 00000001 00000001 f4c6c16c f4c4de00 f806fac5 f8078478
Jan 8 22:13:49 e4 kernel: [ 210.525292] f8076bf7 f80780d4 f80767c4 0000000f f4c6c000 00000000 f4c6c1b8 00000000
Jan 8 22:13:49 e4 kernel: [ 210.525292] 00000000 f4c5b000 f6e95b60 00000000 00000000 f77dc100 00000000 00000000
Jan 8 22:13:49 e4 kernel: [ 210.525292] Call Trace:
Jan 8 22:13:49 e4 kernel: [ 210.525292] [<c10ce688>] ? page_address+0xa8/0xd0
Jan 8 22:13:49 e4 kernel: [ 210.525292] [<f806fac5>] ecryptfs_encrypt_page+0x425/0x4b0 [ecryptfs]
Jan 8 22:13:49 e4 kernel: [ 210.525292] [<c10b34b0>] ? generic_file_buffered_write+0x170/0x210
Jan 8 22:13:49 e4 kernel: [ 210.525292] [<f806e054>] ecryptfs_writepage+0x24/0x80 [ecryptfs]
Jan 8 22:13:49 e4 kernel: [ 210.525292] [<c10ba8fb>] __writepage+0xb/0x30
Jan 8 22:13:49 e4 kernel: [ 210.525292] [<c10baee0>] write_cache_pages+0x190/0x360
Jan 8 22:13:49 e4 kernel: [ 210.525292] [<c10ba8f0>] ? set_page_dirty+0x60/0x60
Jan 8 22:13:49 e4 kernel: [ 210.525292] [<c1243d1d>] ? blk_finish_plug+0xd/0x30
Jan 8 22:13:49 e4 kernel: [ 210.525292] [<c10b4f3a>] ? generic_file_aio_write+0x8a/0xd0
Jan 8 22:13:49 e4 kernel: [ 210.525292] [<c10bb0e9>] generic_writepages+0x39/0x60
Jan 8 22:13:49 e4 kernel: [ 210.525292] [<c10bc555>] do_writepages+0x25/0x30
Jan 8 22:13:49 e4 kernel: [ 210.525292] [<c10b4728>] __filemap_fdatawrite_range+0x58/0x70
Jan 8 22:13:49 e4 kernel: [ 210.525292] [<c10b5736>] filemap_fdatawrite+0x26/0x30
Jan 8 22:13:49 e4 kernel: [ 210.525292] [<c10b576f>] filemap_write_and_wait+0x2f/0x50
Jan 8 22:13:49 e4 kernel: [ 210.525292] [<f806b1cb>] ecryptfs_flush+0x1b/0x20 [ecryptfs]
Jan 8 22:13:49 e4 kernel: [ 210.525292] [<c10e8c8e>] filp_close+0x2e/0x70
Jan 8 22:13:49 e4 kernel: [ 210.525292] [<c10f8ea4>] sys_dup3+0xf4/0x140
Jan 8 22:13:49 e4 kernel: [ 210.525292] [<c10f8f15>] sys_dup2+0x25/0x60
Jan 8 22:13:49 e4 kernel: [ 210.525292] [<c157b30c>] sysenter_do_call+0x12/0x22
Jan 8 22:13:49 e4 kernel: [ 210.525292] Code: 5d f8 89 c3 a1 08 ca 07 f8 89 75 fc 85 c0 7e 11 85 d2 75 17 c7 04 24 e1 c4 07 f8 e8 5f ca 4f c9 90 8b 5d f8 8b 75 fc 89 ec 5d c3 <0f> b6 03 89 55 f4 c7 04 24 ce c4 07 f8 89 44 24 04 e8 3e ca 4f
Jan 8 22:13:49 e4 kernel: [ 210.525292] EIP: [<f8075e12>] ecryptfs_dump_hex+0x32/0xa0 [ecryptfs] SS:ESP 0068:f4c4dd44
Jan 8 22:13:49 e4 kernel: [ 210.525292] CR2: 0000000000000000
Jan 8 22:13:49 e4 kernel: [ 210.525845] ---[ end trace 9522d500eba5932b ]---

[Dustin Kirkland  (kirkland)]

Thanks for the report and patch, which looks good to me, +1.

I've triaged the bug and assigned to Tyler, who will get it
tested/applied/uploaded to his kernel tree. Thanks!

[Tyler Hicks (tyhicks)]

Rather than adding the kmap call, I'm inclined to remove these debug statements from the code entirely. These debug messages have not been useful to me in a long time. Do you find these specific debug statements handy, Daniel?

On a side note, I couldn't apply the patch upstream, anyways, because the commit message is not in the proper format. There must be a subject, a body, and a signed-of-by line. Documentation/SubmittingPatches has more details.

[Tyler Hicks (tyhicks)]

Knocking this down to medium since it requires an admin to load the module with a specific parameter. You'd never run this in a production environment because key material is dumped to the syslog in this mode.

[Daniel DeFreez (w1yo262-daniel-lo8mzs0)]

I do not use these specific debug statements much, no. I was going to simply cut them out, but instead looked for a fix because I assumed somebody wanted them there (and out of curiosity).

I apologize for the malformed patch. I wasn't thinking about upstream. I'll use the documented format in the future.

Thanks,

Daniel

[Tyler Hicks (tyhicks)]

On 2012-01-10 02:56:38, Daniel DeFreez wrote:
> I do not use these specific debug statements much, no. I was going to
> simply cut them out, but instead looked for a fix because I assumed
> somebody wanted them there (and out of curiosity).

Ok, good.

> I apologize for the malformed patch. I wasn't thinking about upstream.
> I'll use the documented format in the future.

No problem! I appreciate the report and the patch.

If I just end up ripping out those messages, I'll mention you in the
Reported-by: commit message tag.

[Tyler Hicks (tyhicks)]

This has landed in Linus' tree:

http://git.kernel.org/linus/58ded24f0fcb85bddb665baba75892f6ad0f4b8a

[Tyler Hicks (tyhicks)]

This fix was released in 3.3-rc2:

58ded24f0fcb85bddb665baba75892f6ad0f4b8a