[BUG] ext4/block null pointer crashes in linux-next

[BUG] ext4/block null pointer crashes in linux-next

[valdis.kletnieks]

So I finally had a chance to find a replicator and finish bisecting this and:

[/usr/src/linux-next] git bisect good
e2b0989954ae7c80609f77e7ce203bea6d2c54e1 is the first bad commit
commit e2b0989954ae7c80609f77e7ce203bea6d2c54e1
Author: Dennis Zhou (Facebook) <dennisszhou@gmail.com>
Date:   Tue Sep 11 14:41:35 2018 -0400

    blkcg: cleanup and make blk_get_rl use blkg_lookup_create

I was able to do a bit of sleuthing with strace, and I tracked it down to one of
several execve() calls that 'rpm' makes with my replicating test case.

 grep execve /root/rpm-exec-strace 
execve("/usr/bin/rpm", ["rpm", "-Uvh", "--force", "dracut-049-4.git20181010.fc30.x8"...], 0x7ffc9d967d80 /* 33 vars */) = 0
[pid 119212] execve("/bin/sh", ["/bin/sh", "/usr/src/redhat/tmp/rpm-tmp.w7fu"..., "0", "0"], 0x7ffdfe17d480 /* 33 vars */) = 0
[pid 119213] execve("/sbin/ldconfig", ["/sbin/ldconfig"], 0x558ccf928ac0 /* 33 vars */) = 0
[pid 119216] execve("/bin/sh", ["/bin/sh", "/usr/src/redhat/tmp/rpm-tmp.bIKt"..., "0", "0"], 0x7ffdfe17d480 /* 33 vars */) = 0
[pid 119217] execve("/usr/bin/systemd-run", ["/usr/bin/systemd-run", "/usr/bin/systemctl", "start", "man-db-cache-update"], 0x56360645d290 /* 33 vars */) = 0
[pid 119221] execve("/bin/sh", ["/bin/sh", "/usr/src/redhat/tmp/rpm-tmp.OGWg"..., "0", "0"], 0x7ffdfe17d480 /* 33 vars */) = 0
[pid 119920] execve("/usr/bin/systemctl", ["/usr/bin/systemctl", "daemon-reload"], 0x55c0f5d43c30 /* 33 vars */) = 0

The ldconfig and systemctl commands run just fine stand-alone, so I'm suspecting the
calls to run the temp files - it's quite possible that execve() gets invoked on them before
writeback has actually gotten the data to the disk - though that shouldn't matter.

But I managed to trigger a different traceback. I cd /usr/src/redhat/tmp, and I
did an 'rm *' - and never got a prompt back. Traceback out of pstore below.

Now here's the weird part - I'd already unmounted, fsck'ed, and remounted the
file system before the 'rm *'.  And thinking that there was one file with a
busted inode that passed fsck.ext4's sniff test, I did:

cd /usr/src/redhat/tmp
for i in `find . -type f`; do sleep 5; echo $i; rm $i; done

and that worked just fine. Nothing left in that directory but . and ..  
I then re-ran my rpm-based replicator and it blew up again.

Traceback of the rm crash (I have *no* idea why it has systemd-tmpfile as Comm:
as none of the tmpfile config reference /usr/src at all, and the config says it
shouldn't have been running at the time of the crash, and I can't replicate as
the directory is now empty...)

[  919.756309] BUG: unable to handle kernel NULL pointer dereference at 0000000000000000
[  919.756317] PGD 0 P4D 0
[  919.756327] Oops: 0000 [#1] PREEMPT SMP PTI
[  919.756333] CPU: 0 PID: 3659 Comm: systemd-tmpfile Tainted: G           O    T 4.19.0-rc6-next-20181005-dirty #621
[  919.756337] Hardware name: Dell Inc. Latitude E6530/07Y85M, BIOS A21 02/21/2018
[  919.756346] RIP: 0010:__get_request+0x31/0x7e0
[  919.756351] Code: 89 e5 41 57 41 56 41 55 49 89 fd 41 54 41 89 f4 53 48 83 ec 50 48 8b 1f 48 85 d2 48 89 55 b8 89 4d c0 44 89 45 c4 48 8b 43 18 <48> 8b 00
48 89 45 b0 0f 84 ba 03 00 00 48 8b 42 58 48 85 c0 48 89
[  919.756355] RSP: 0018:ffffad75883ef858 EFLAGS: 00010086
[  919.756361] RAX: 0000000000000000 RBX: ffffa27a9892b000 RCX: 0000000000000000
[  919.756366] RDX: ffffa27a8a81cf00 RSI: 0000000000003000 RDI: ffffa27993c25840
[  919.756370] RBP: ffffad75883ef8d0 R08: 0000000000600000 R09: 0000000000000001
[  919.756374] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000003000
[  919.756378] R13: ffffa27993c25840 R14: ffffa27a8a81cf00 R15: ffffa27993c258c0
[  919.756383] FS:  00007f15be4f7940(0000) GS:ffffa27a9d400000(0000) knlGS:0000000000000000
[  919.756387] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  919.756391] CR2: 0000000000000000 CR3: 00000004058ee006 CR4: 00000000001606f0
[  919.756395] Call Trace:
[  919.756410]  get_request+0x214/0x8b0
[  919.756420]  ? remove_wait_queue+0x70/0x70
[  919.756429]  blk_queue_bio+0x23b/0x760
[  919.756439]  generic_make_request+0x2fe/0x570
[  919.756446]  ? guard_bio_eod+0x40/0x320
[  919.756455]  submit_bio+0x4d/0x190
[  919.756460]  ? submit_bio+0x4d/0x190
[  919.756465]  ? guard_bio_eod+0x172/0x320
[  919.756473]  submit_bh_wbc+0x236/0x2b0
[  919.756481]  ll_rw_block+0xdf/0xf0
[  919.756490]  ext4_bread+0x96/0xe0
[  919.756498]  __ext4_read_dirblock+0x44/0x3c0
[  919.756508]  htree_dirblock_to_tree+0x6f/0x2c0
[  919.756522]  ext4_htree_fill_tree+0xc6/0x3c0
[  919.756529]  ? ext4_readdir+0x9e8/0xc30
[  919.756536]  ? ext4_readdir+0x9e8/0xc30
[  919.756542]  ? kmem_cache_alloc_trace+0x382/0x4a0
[  919.756551]  ext4_readdir+0x893/0xc30
[  919.756568]  iterate_dir+0xa6/0x1c0
[  919.756575]  ksys_getdents64+0x13d/0x1f0
[  919.756580]  ? iterate_dir+0x1c0/0x1c0
[  919.756590]  __x64_sys_getdents64+0x1b/0x20
[  919.756596]  do_syscall_64+0x8f/0xa52
[  919.756602]  ? trace_hardirqs_off_caller+0x22/0x150
[  919.756609]  ? trace_hardirqs_off_thunk+0x1a/0x1c
[  919.756619]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
[  919.756624] RIP: 0033:0x7f15bf1ace7b

The original RPM replicable traceback:
[  680.692888] BUG: unable to handle kernel NULL pointer dereference at 0000000000000000
[  680.692895] PGD 0 P4D 0
[  680.692901] Oops: 0000 [#1] PREEMPT SMP PTI
[  680.692905] CPU: 3 PID: 15464 Comm: sh Tainted: G           O    T 4.19.0-rc6-next-20181005-dirty #621
[  680.692908] Hardware name: Dell Inc. Latitude E6530/07Y85M, BIOS A21 02/21/2018
[  680.692915] RIP: 0010:__get_request+0x31/0x7e0
[  680.692918] Code: 89 e5 41 57 41 56 41 55 49 89 fd 41 54 41 89 f4 53 48 83 ec 50 48 8b 1f 48 85 d2 48 89 55 b8 89 4d 
c0 44 89 45 c4 48 8b 43 18 <48> 8b 00 48 89 45 b0 0f 84 ba 03 00 00 48 8b 42 58 48 85 c0 48 89
[  680.692921] RSP: 0018:ffff9fa98d93f578 EFLAGS: 00010086
[  680.692925] RAX: 0000000000000000 RBX: ffff975ad40e7040 RCX: 0000000000000000
[  680.692927] RDX: ffff975aac306e00 RSI: 0000000000080000 RDI: ffff975acce39840
[  680.692930] RBP: ffff9fa98d93f5f0 R08: 0000000000600000 R09: 0000000000000001
[  680.692933] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000080000
[  680.692935] R13: ffff975acce39840 R14: ffff975aac306e00 R15: ffff975acce398c0
[  680.692938] FS:  00007f8fb7876740(0000) GS:ffff975adda00000(0000) knlGS:0000000000000000
[  680.692941] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  680.692944] CR2: 0000000000000000 CR3: 00000003ebc64006 CR4: 00000000001606e0
[  680.692946] Call Trace:
[  680.692957]  get_request+0x214/0x8b0
[  680.692964]  ? remove_wait_queue+0x70/0x70
[  680.692971]  blk_queue_bio+0x23b/0x760
[  680.692977]  generic_make_request+0x2fe/0x570
[  680.692983]  submit_bio+0x4d/0x190
[  680.692987]  ? submit_bio+0x4d/0x190
[  680.692992]  ? bio_add_page+0x4b/0x60
[  680.692997]  ext4_mpage_readpages+0x814/0xed4
[  680.693002]  ? get_page_from_freelist+0x42c/0x1bd0
[  680.693015]  ext4_readpages+0x55/0x60
[  680.693020]  read_pages+0x72/0x190
[  680.693031]  __do_page_cache_readahead+0x1f6/0x220
[  680.693045]  ondemand_readahead+0x2ae/0x4f0
[  680.693055]  page_cache_sync_readahead+0x112/0x250
[  680.693065]  generic_file_buffered_read+0x542/0xf70
[  680.693079]  ? _raw_spin_unlock_irqrestore+0x78/0xa0
[  680.693087]  ? avc_update_node+0x1b6/0x2c0
[  680.693095]  generic_file_read_iter+0xd0/0x140
[  680.693102]  ext4_file_read_iter+0x6c/0x80
[  680.693107]  new_sync_read+0x121/0x1a0
[  680.693116]  __vfs_read+0x49/0x60
[  680.693120]  vfs_read+0x152/0x250
[  680.693126]  kernel_read+0x43/0x60
[  680.693131]  prepare_binprm+0x19b/0x1f0
[  680.693136]  __do_execve_file+0x5ca/0xbc0
[  680.693142]  __x64_sys_execve+0x38/0x50
[  680.693148]  do_syscall_64+0x8f/0xa52
[  680.693152]  ? trace_hardirqs_off_caller+0x22/0x150
[  680.693156]  ? trace_hardirqs_off_thunk+0x1a/0x1c
[  680.693162]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
[  680.693165] RIP: 0033:0x7f8fb7942b5b
[  680.693169] Code: 41 89 01 eb da 66 2e 0f 1f 84 00 00 00 00 00 f7 d8 64 41 89 01 eb d6 0f 1f 84 00 00 00 00 00 f3 0f 
1e fa b8 3b 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d fd 62 0f 00 f7 d8 64 89 01 48

Re: [BUG] ext4/block null pointer crashes in linux-next

[Theodore Y. Ts'o]

On Mon, Oct 15, 2018 at 07:28:48PM -0400, valdis.kletnieks@vt.edu wrote:
> 
> Traceback of the rm crash (I have *no* idea why it has systemd-tmpfile as Comm:
> as none of the tmpfile config reference /usr/src at all, and the config says it
> shouldn't have been running at the time of the crash, and I can't replicate as
> the directory is now empty...)

Given the commit that it bisected down to, I very much doubt it has
anything to do with a specific directory or pathname.  Either you or
your distribution has enabled blk cgroup for I/O throttling, and
there's some race that you're tripping across.  What ext4 file or
directory happens to be accessed when you trip across the problem is
probably just pure luck.

If you can disable the block I/O throttling configuration (which may
very well be distro-specific), the problem will probably go away.  I
don't use blkcg at all, personally, and on a personal laptop
(especially if you have an SSD), I really don't see the point.

Still, I'm sure the people who *do* use blkcg for real (mostly in data
centers, in my experience) will probably thank you for being a great
guinea pig.  :-)

						- Ted

Re: [BUG] ext4/block null pointer crashes in linux-next

[valdis.kletnieks]

On Mon, 15 Oct 2018 21:52:01 -0400, "Theodore Y. Ts'o" said:
> Given the commit that it bisected down to, I very much doubt it has
> anything to do with a specific directory or pathname.  Either you or
> your distribution has enabled blk cgroup for I/O throttling, and

Bingo.

[~] zgrep CGROUP /proc/config.gz 
CONFIG_CGROUPS=y
CONFIG_BLK_CGROUP=y
# CONFIG_DEBUG_BLK_CGROUP is not set
(...)

> there's some race that you're tripping across.  What ext4 file or
> directory happens to be accessed when you trip across the problem is
> probably just pure luck.

I'm suspecting that my repeatable crash with rpm just does a *really*
good job of setting up the race.

> If you can disable the block I/O throttling configuration (which may
> very well be distro-specific), the problem will probably go away.  I
> don't use blkcg at all, personally, and on a personal laptop
> (especially if you have an SSD), I really don't see the point.

I often turn on new features just to watch the sparks fly.

> Still, I'm sure the people who *do* use blkcg for real (mostly in data
> centers, in my experience) will probably thank you for being a great
> guinea pig.  :-)

It's why I build a linux-next kernel every week. ;)

Looks like I should enable DEBUG_BLK_CGROUP and see what that says.

Re: [BUG] ext4/block null pointer crashes in linux-next

[valdis.kletnieks]

[-- Attachment #1: Type: text/plain, Size: 757 bytes --]

On Tue, 16 Oct 2018 08:42:14 -0400, valdis.kletnieks@vt.edu said:

> [~] zgrep CGROUP /proc/config.gz
> CONFIG_CGROUPS=y
> CONFIG_BLK_CGROUP=y
> # CONFIG_DEBUG_BLK_CGROUP is not set
> (...)

> Looks like I should enable DEBUG_BLK_CGROUP and see what that says.

Built next-20181016 with that enabled - and the exact same kablam.

Started looking at the code, and I noticed that if the .config has

CONFIG_IOSCHED_CFQ=y
# CONFIG_CFQ_GROUP_IOSCHED is not set
CONFIG_BLK_CGROUP=y

then the 'struct cfqg_stats' at line 185 of block/cfq-iosched.c ends up being
zero length (which hints that combo of config variables is a pathological
case). I haven't delved through all the #ifdef'ery, but I wonder if there
may be other corner-case issues with that combo....


[-- Attachment #2: Type: application/pgp-signature, Size: 486 bytes --]

Re: [BUG] ext4/block null pointer crashes in linux-next

[Dennis Zhou]

Hi Vladis,

On Mon, Oct 15, 2018 at 07:28:48PM -0400, valdis.kletnieks@vt.edu wrote:
> So I finally had a chance to find a replicator and finish bisecting this and:
> 
> [/usr/src/linux-next] git bisect good
> e2b0989954ae7c80609f77e7ce203bea6d2c54e1 is the first bad commit
> commit e2b0989954ae7c80609f77e7ce203bea6d2c54e1
> Author: Dennis Zhou (Facebook) <dennisszhou@gmail.com>
> Date:   Tue Sep 11 14:41:35 2018 -0400
> 
>     blkcg: cleanup and make blk_get_rl use blkg_lookup_create
> 
> I was able to do a bit of sleuthing with strace, and I tracked it down to one of
> several execve() calls that 'rpm' makes with my replicating test case.
> 
>  grep execve /root/rpm-exec-strace 
> execve("/usr/bin/rpm", ["rpm", "-Uvh", "--force", "dracut-049-4.git20181010.fc30.x8"...], 0x7ffc9d967d80 /* 33 vars */) = 0
> [pid 119212] execve("/bin/sh", ["/bin/sh", "/usr/src/redhat/tmp/rpm-tmp.w7fu"..., "0", "0"], 0x7ffdfe17d480 /* 33 vars */) = 0
> [pid 119213] execve("/sbin/ldconfig", ["/sbin/ldconfig"], 0x558ccf928ac0 /* 33 vars */) = 0
> [pid 119216] execve("/bin/sh", ["/bin/sh", "/usr/src/redhat/tmp/rpm-tmp.bIKt"..., "0", "0"], 0x7ffdfe17d480 /* 33 vars */) = 0
> [pid 119217] execve("/usr/bin/systemd-run", ["/usr/bin/systemd-run", "/usr/bin/systemctl", "start", "man-db-cache-update"], 0x56360645d290 /* 33 vars */) = 0
> [pid 119221] execve("/bin/sh", ["/bin/sh", "/usr/src/redhat/tmp/rpm-tmp.OGWg"..., "0", "0"], 0x7ffdfe17d480 /* 33 vars */) = 0
> [pid 119920] execve("/usr/bin/systemctl", ["/usr/bin/systemctl", "daemon-reload"], 0x55c0f5d43c30 /* 33 vars */) = 0
> 
> The ldconfig and systemctl commands run just fine stand-alone, so I'm suspecting the
> calls to run the temp files - it's quite possible that execve() gets invoked on them before
> writeback has actually gotten the data to the disk - though that shouldn't matter.
> 
> But I managed to trigger a different traceback. I cd /usr/src/redhat/tmp, and I
> did an 'rm *' - and never got a prompt back. Traceback out of pstore below.
> 
> Now here's the weird part - I'd already unmounted, fsck'ed, and remounted the
> file system before the 'rm *'.  And thinking that there was one file with a
> busted inode that passed fsck.ext4's sniff test, I did:
> 
> cd /usr/src/redhat/tmp
> for i in `find . -type f`; do sleep 5; echo $i; rm $i; done
> 
> and that worked just fine. Nothing left in that directory but . and ..  
> I then re-ran my rpm-based replicator and it blew up again.
> 
> Traceback of the rm crash (I have *no* idea why it has systemd-tmpfile as Comm:
> as none of the tmpfile config reference /usr/src at all, and the config says it
> shouldn't have been running at the time of the crash, and I can't replicate as
> the directory is now empty...)
> 

Thanks for testing and reporting this! Do you mind sending me your
reproducer?

Thanks,
Dennis

Re: [BUG] ext4/block null pointer crashes in linux-next

[Dennis Zhou]

On Tue, Oct 16, 2018 at 12:02:03PM -0400, Dennis Zhou wrote:
> Hi Vladis,
> 
> On Mon, Oct 15, 2018 at 07:28:48PM -0400, valdis.kletnieks@vt.edu wrote:
> > So I finally had a chance to find a replicator and finish bisecting this and:
> > 
> > [/usr/src/linux-next] git bisect good
> > e2b0989954ae7c80609f77e7ce203bea6d2c54e1 is the first bad commit
> > commit e2b0989954ae7c80609f77e7ce203bea6d2c54e1
> > Author: Dennis Zhou (Facebook) <dennisszhou@gmail.com>
> > Date:   Tue Sep 11 14:41:35 2018 -0400
> > 
> >     blkcg: cleanup and make blk_get_rl use blkg_lookup_create
> > 
> > I was able to do a bit of sleuthing with strace, and I tracked it down to one of
> > several execve() calls that 'rpm' makes with my replicating test case.
> > 
> >  grep execve /root/rpm-exec-strace 
> > execve("/usr/bin/rpm", ["rpm", "-Uvh", "--force", "dracut-049-4.git20181010.fc30.x8"...], 0x7ffc9d967d80 /* 33 vars */) = 0
> > [pid 119212] execve("/bin/sh", ["/bin/sh", "/usr/src/redhat/tmp/rpm-tmp.w7fu"..., "0", "0"], 0x7ffdfe17d480 /* 33 vars */) = 0
> > [pid 119213] execve("/sbin/ldconfig", ["/sbin/ldconfig"], 0x558ccf928ac0 /* 33 vars */) = 0
> > [pid 119216] execve("/bin/sh", ["/bin/sh", "/usr/src/redhat/tmp/rpm-tmp.bIKt"..., "0", "0"], 0x7ffdfe17d480 /* 33 vars */) = 0
> > [pid 119217] execve("/usr/bin/systemd-run", ["/usr/bin/systemd-run", "/usr/bin/systemctl", "start", "man-db-cache-update"], 0x56360645d290 /* 33 vars */) = 0
> > [pid 119221] execve("/bin/sh", ["/bin/sh", "/usr/src/redhat/tmp/rpm-tmp.OGWg"..., "0", "0"], 0x7ffdfe17d480 /* 33 vars */) = 0
> > [pid 119920] execve("/usr/bin/systemctl", ["/usr/bin/systemctl", "daemon-reload"], 0x55c0f5d43c30 /* 33 vars */) = 0
> > 
> > The ldconfig and systemctl commands run just fine stand-alone, so I'm suspecting the
> > calls to run the temp files - it's quite possible that execve() gets invoked on them before
> > writeback has actually gotten the data to the disk - though that shouldn't matter.
> > 
> > But I managed to trigger a different traceback. I cd /usr/src/redhat/tmp, and I
> > did an 'rm *' - and never got a prompt back. Traceback out of pstore below.
> > 
> > Now here's the weird part - I'd already unmounted, fsck'ed, and remounted the
> > file system before the 'rm *'.  And thinking that there was one file with a
> > busted inode that passed fsck.ext4's sniff test, I did:
> > 
> > cd /usr/src/redhat/tmp
> > for i in `find . -type f`; do sleep 5; echo $i; rm $i; done
> > 
> > and that worked just fine. Nothing left in that directory but . and ..  
> > I then re-ran my rpm-based replicator and it blew up again.
> > 
> > Traceback of the rm crash (I have *no* idea why it has systemd-tmpfile as Comm:
> > as none of the tmpfile config reference /usr/src at all, and the config says it
> > shouldn't have been running at the time of the crash, and I can't replicate as
> > the directory is now empty...)
> > 
> 
> Thanks for testing and reporting this! Do you mind sending me your
> reproducer?
> 
> Thanks,
> Dennis

I've spent some time thinking about this, and this is my guess at what
is happening without seeing your reproducer. The system is under memory
pressure and a new cgroup is being created. The cgroup allocation fails
causing the request_list code to fallback and walk up the blkg tree.
There is special handling for the root cgroup, but I missed that case
and it fails there I believe.

In addition to sending me the reproducer and your config, can you please
try the patch below?

Thanks,
Dennis

---
diff --git a/include/linux/blk-cgroup.h b/include/linux/blk-cgroup.h
index b7fd08013de2..1e76ceebeb5d 100644
--- a/include/linux/blk-cgroup.h
+++ b/include/linux/blk-cgroup.h
@@ -597,7 +597,7 @@ static inline struct request_list *blk_get_rl(struct request_queue *q,
 	if (unlikely(!blkg))
 		blkg = __blkg_lookup_create(blkcg, q);
 
-	if (!blkg_tryget(blkg))
+	if (blkg->blkcg == &blkcg_root || !blkg_tryget(blkg))
 		goto rl_use_root;
 
 	rcu_read_unlock();

Re: [BUG] ext4/block null pointer crashes in linux-next

[valdis.kletnieks]

[-- Attachment #1.1: Type: text/plain, Size: 1633 bytes --]

On Tue, 16 Oct 2018 14:25:13 -0400, Dennis Zhou said:

> > >  grep execve /root/rpm-exec-strace
> > > execve("/usr/bin/rpm", ["rpm", "-Uvh", "--force", "dracut-049-4.git20181010.fc30.x8"...], 0x7ffc9d967d80 /* 33 vars */) = 0

> > Thanks for testing and reporting this! Do you mind sending me your
> > reproducer?

See above. An 'rpm' command blows it up....

> I've spent some time thinking about this, and this is my guess at what
> is happening without seeing your reproducer. The system is under memory
> pressure and a new cgroup is being created. The cgroup allocation fails
> causing the request_list code to fallback and walk up the blkg tree.
> There is special handling for the root cgroup, but I missed that case
> and it fails there I believe.

Hmm... I boot to single-user, do a cd, and run 'rpm -Uvh --force' on an RPM
that was already installed. (I originally hit this with 'dnf', but running 'dnf
update' wouldn't trigger a crash if the system was up to date.  To make a
bisect workable, I ended up using RPM to re-install an already installed
package or 3 triggered it as well.

That's a consistent reproducer for me.  rpm does an execve() (actually,
it does 5), and one of them goes kablam.  I've also managed to hit it
once doing an 'rm'.

And my laptop has 16G of ram.  Shouldn't be any memory pressure at all in
single-user mode.  So it looks like you fixed a bug, but not the one I was hitting.

> In addition to sending me the reproducer and your config, can you please
> try the patch below?

Tried the patch, didn't make a difference. So there's at least one more bug
out there to find. :)

Config attached.

[-- Attachment #1.2: config-next-20181016.gz --]
[-- Type: application/gzip , Size: 28997 bytes --]

[-- Attachment #2: Type: application/pgp-signature, Size: 486 bytes --]

Re: [BUG] ext4/block null pointer crashes in linux-next

[Dennis Zhou]

On Wed, Oct 17, 2018 at 11:47:35AM -0400, valdis.kletnieks@vt.edu wrote:
> On Tue, 16 Oct 2018 14:25:13 -0400, Dennis Zhou said:
> 
> > > >  grep execve /root/rpm-exec-strace
> > > > execve("/usr/bin/rpm", ["rpm", "-Uvh", "--force", "dracut-049-4.git20181010.fc30.x8"...], 0x7ffc9d967d80 /* 33 vars */) = 0
> 
> > > Thanks for testing and reporting this! Do you mind sending me your
> > > reproducer?
> 
> See above. An 'rpm' command blows it up....
> 
> > I've spent some time thinking about this, and this is my guess at what
> > is happening without seeing your reproducer. The system is under memory
> > pressure and a new cgroup is being created. The cgroup allocation fails
> > causing the request_list code to fallback and walk up the blkg tree.
> > There is special handling for the root cgroup, but I missed that case
> > and it fails there I believe.
> 
> Hmm... I boot to single-user, do a cd, and run 'rpm -Uvh --force' on an RPM
> that was already installed. (I originally hit this with 'dnf', but running 'dnf
> update' wouldn't trigger a crash if the system was up to date.  To make a
> bisect workable, I ended up using RPM to re-install an already installed
> package or 3 triggered it as well.
> 
> That's a consistent reproducer for me.  rpm does an execve() (actually,
> it does 5), and one of them goes kablam.  I've also managed to hit it
> once doing an 'rm'.
> 
> And my laptop has 16G of ram.  Shouldn't be any memory pressure at all in
> single-user mode.  So it looks like you fixed a bug, but not the one I was hitting.
> 
> > In addition to sending me the reproducer and your config, can you please
> > try the patch below?
> 
> Tried the patch, didn't make a difference. So there's at least one more bug
> out there to find. :)
> 
> Config attached.

I apologize, but I'm having a hard time reproducing this myself. I am
not able to hit this issue in my qemu instance with linux-next built
with your config. I have been running 'rpm -Hvh --force fio.rpm' several
times and haven't seen the issue.

Would it be possible for you to create a minimal qemu image that
reproduces the issue as I'm having issues reproducing it with my setup?
Additionally, I've added some more debug text in the diff below. If you
could apply that and send me the full dmesg that would be great. Lastly,
can you just confirm for me that the commit before, f0fcb3ec89f3
"blkcg: remove additional reference to the css", isn't seeing this
issue?

Thanks,
Dennis
---
diff --git a/block/blk-core.c b/block/blk-core.c
index 4dbc93f43b38..1b56cec40301 100644
--- a/block/blk-core.c
+++ b/block/blk-core.c
@@ -1538,6 +1538,19 @@ static struct request *get_request(struct request_queue *q, unsigned int op,
 
 	rl = blk_get_rl(q, bio);	/* transferred to @rq on success */
 retry:
+	printk_once(KERN_INFO "dennis zhou");
+	if (q != rl->q) {
+		printk(KERN_INFO "dennis: q %px != rl->q %px", q, rl->q);
+		if (bio && bio->bi_blkg)
+			printk(KERN_INFO "dennis: bio: %px, root: %px",
+			       bio->bi_blkg->blkcg, &blkcg_root);
+	}
+	if (!q)
+		printk(KERN_INFO "dennis: q is null!");
+	if (!rl)
+		printk(KERN_INFO "dennis: rl is null!");
+	if (!rl->q)
+		printk(KERN_INFO "dennis: rl->q is null!");
 	rq = __get_request(rl, op, bio, flags, gfp);
 	if (!IS_ERR(rq))
 		return rq;

Re: [BUG] ext4/block null pointer crashes in linux-next

[valdis.kletnieks]

[-- Attachment #1.1: Type: text/plain, Size: 1975 bytes --]

On Wed, 17 Oct 2018 17:20:29 -0400, Dennis Zhou said:
>
> I apologize, but I'm having a hard time reproducing this myself. I am
> not able to hit this issue in my qemu instance with linux-next built
> with your config. I have been running 'rpm -Hvh --force fio.rpm' several
> times and haven't seen the issue.

I wouldn't be surprised if there's something oddball in my system config
that changes the situation.

> Would it be possible for you to create a minimal qemu image that
> reproduces the issue as I'm having issues reproducing it with my setup?

Hmm.. I'd first have to figure out how to build a qemu image at all..

> Additionally, I've added some more debug text in the diff below. If you
> could apply that and send me the full dmesg that would be great. Lastly,
> can you just confirm for me that the commit before, f0fcb3ec89f3
> "blkcg: remove additional reference to the css", isn't seeing this
> issue?

Full dmesg attached.  Had to piece it together from a 'dmesg' and what
got saved in pstore when it crashed.  I was surprised that the printk_once
popped during very early boot (2.88 seconds in), and then only 2 lines of output
right before the crash:

[  106.465848] audit: type=1130 audit(1539957798.984:101): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:syst
em_r:init_t:s0-s15:c0.c1023 msg='unit=run-r93ac4731e4724fd6a3670e7d0c417522 comm="systemd" exe="/usr/lib/systemd/systemd
" hostname=? addr=? terminal=? res=success'
[  106.564711] dennis: q ffff9e3c57152000 != rl->q ffff9e3a8fe48040
[  106.564713] dennis: bio: ffff9e3a8fcf5400, root: ffffffffbbdd89e0
[  106.564761] BUG: unable to handle kernel NULL pointer dereference at 0000000000000000
[  106.568786] PGD 0 P4D 0
[  106.570761] Oops: 0000 [#1] PREEMPT SMP PTI
[  106.573115] CPU: 2 PID: 1205 Comm: sh Tainted: G                T 4.19.0-rc8-next-20181016-dirty #639

I'll cook up a kernel checked out at that commit and test later today...

[-- Attachment #1.2: dmesg.all --]
[-- Type: text/plain , Size: 84826 bytes --]

[    0.000000] microcode: microcode updated early to revision 0x20, date = 2018-04-10
[    0.000000] Linux version 4.19.0-rc8-next-20181016-dirty (source@turing-police.cc.vt.edu) (gcc version 8.2.1 20181011 (Red Hat 8.2.1-4) (GCC)) #639 SMP PREEMPT Wed Oct 17 18:02:07 EDT 2018
[    0.000000] Command line: BOOT_IMAGE=/vmlinuz-4.19.0-rc8-next-20181016-dirty root=/dev/mapper/turing--police-root ro rd.md=0 rd.dm=0 rd.lvm.lv=turing-police/00 console.keymap= rd.luks.uuid=luks-665bb147-9e39-4003-b3ae-7be925f51a97 rd.lvm.lv=turing-police/swap rd.lvm.lv=turing-police/root quiet LANG=en_US.UTF-8 nouveau.modeset=0 video=vesa:off single
[    0.000000] KERNEL supported cpus:
[    0.000000]   Intel GenuineIntel
[    0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers'
[    0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers'
[    0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers'
[    0.000000] x86/fpu: xstate_offset[2]:  576, xstate_sizes[2]:  256
[    0.000000] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format.
[    0.000000] BIOS-provided physical RAM map:
[    0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009efff] usable
[    0.000000] BIOS-e820: [mem 0x000000000009f000-0x000000000009ffff] reserved
[    0.000000] BIOS-e820: [mem 0x0000000000100000-0x00000000ca709fff] usable
[    0.000000] BIOS-e820: [mem 0x00000000ca70a000-0x00000000ca7fffff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000ca800000-0x00000000caf52fff] usable
[    0.000000] BIOS-e820: [mem 0x00000000caf53000-0x00000000caffffff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000cb000000-0x00000000cb7b1fff] usable
[    0.000000] BIOS-e820: [mem 0x00000000cb7b2000-0x00000000cb7fffff] ACPI data
[    0.000000] BIOS-e820: [mem 0x00000000cb800000-0x00000000ccefdfff] usable
[    0.000000] BIOS-e820: [mem 0x00000000ccefe000-0x00000000ccffffff] ACPI NVS
[    0.000000] BIOS-e820: [mem 0x00000000cd000000-0x00000000ce59bfff] usable
[    0.000000] BIOS-e820: [mem 0x00000000ce59c000-0x00000000cefa3fff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000cefa4000-0x00000000cefe6fff] ACPI NVS
[    0.000000] BIOS-e820: [mem 0x00000000cefe7000-0x00000000cf2b0fff] usable
[    0.000000] BIOS-e820: [mem 0x00000000cf2b1000-0x00000000cf7effff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000cf7f0000-0x00000000cf7fffff] usable
[    0.000000] BIOS-e820: [mem 0x00000000f8000000-0x00000000fbffffff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000fec00000-0x00000000fec00fff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000fed00000-0x00000000fed03fff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000fed1c000-0x00000000fed1ffff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000fee00000-0x00000000fee00fff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000ff000000-0x00000000ffffffff] reserved
[    0.000000] BIOS-e820: [mem 0x0000000100000000-0x000000040dfacfff] usable
[    0.000000] BIOS-e820: [mem 0x000000040dfad000-0x000000040dfadfff] unusable
[    0.000000] BIOS-e820: [mem 0x000000040dfae000-0x000000040dfaefff] usable
[    0.000000] BIOS-e820: [mem 0x000000040dfaf000-0x000000040dfaffff] unusable
[    0.000000] BIOS-e820: [mem 0x000000040dfb0000-0x000000040dfeafff] usable
[    0.000000] BIOS-e820: [mem 0x000000040dfeb000-0x000000040dfebfff] unusable
[    0.000000] BIOS-e820: [mem 0x000000040dfec000-0x000000042dffffff] usable
[    0.000000] NX (Execute Disable) protection: active
[    0.000000] e820: update [mem 0xc7a9a018-0xc7ab6e57] usable ==> usable
[    0.000000] e820: update [mem 0xc7a9a018-0xc7ab6e57] usable ==> usable
[    0.000000] e820: update [mem 0xc7a8a018-0xc7a99c57] usable ==> usable
[    0.000000] e820: update [mem 0xc7a8a018-0xc7a99c57] usable ==> usable
[    0.000000] extended physical RAM map:
[    0.000000] reserve setup_data: [mem 0x0000000000000000-0x000000000009efff] usable
[    0.000000] reserve setup_data: [mem 0x000000000009f000-0x000000000009ffff] reserved
[    0.000000] reserve setup_data: [mem 0x0000000000100000-0x00000000c7a8a017] usable
[    0.000000] reserve setup_data: [mem 0x00000000c7a8a018-0x00000000c7a99c57] usable
[    0.000000] reserve setup_data: [mem 0x00000000c7a99c58-0x00000000c7a9a017] usable
[    0.000000] reserve setup_data: [mem 0x00000000c7a9a018-0x00000000c7ab6e57] usable
[    0.000000] reserve setup_data: [mem 0x00000000c7ab6e58-0x00000000ca709fff] usable
[    0.000000] reserve setup_data: [mem 0x00000000ca70a000-0x00000000ca7fffff] reserved
[    0.000000] reserve setup_data: [mem 0x00000000ca800000-0x00000000caf52fff] usable
[    0.000000] reserve setup_data: [mem 0x00000000caf53000-0x00000000caffffff] reserved
[    0.000000] reserve setup_data: [mem 0x00000000cb000000-0x00000000cb7b1fff] usable
[    0.000000] reserve setup_data: [mem 0x00000000cb7b2000-0x00000000cb7fffff] ACPI data
[    0.000000] reserve setup_data: [mem 0x00000000cb800000-0x00000000ccefdfff] usable
[    0.000000] reserve setup_data: [mem 0x00000000ccefe000-0x00000000ccffffff] ACPI NVS
[    0.000000] reserve setup_data: [mem 0x00000000cd000000-0x00000000ce59bfff] usable
[    0.000000] reserve setup_data: [mem 0x00000000ce59c000-0x00000000cefa3fff] reserved
[    0.000000] reserve setup_data: [mem 0x00000000cefa4000-0x00000000cefe6fff] ACPI NVS
[    0.000000] reserve setup_data: [mem 0x00000000cefe7000-0x00000000cf2b0fff] usable
[    0.000000] reserve setup_data: [mem 0x00000000cf2b1000-0x00000000cf7effff] reserved
[    0.000000] reserve setup_data: [mem 0x00000000cf7f0000-0x00000000cf7fffff] usable
[    0.000000] reserve setup_data: [mem 0x00000000f8000000-0x00000000fbffffff] reserved
[    0.000000] reserve setup_data: [mem 0x00000000fec00000-0x00000000fec00fff] reserved
[    0.000000] reserve setup_data: [mem 0x00000000fed00000-0x00000000fed03fff] reserved
[    0.000000] reserve setup_data: [mem 0x00000000fed1c000-0x00000000fed1ffff] reserved
[    0.000000] reserve setup_data: [mem 0x00000000fee00000-0x00000000fee00fff] reserved
[    0.000000] reserve setup_data: [mem 0x00000000ff000000-0x00000000ffffffff] reserved
[    0.000000] reserve setup_data: [mem 0x0000000100000000-0x000000040dfacfff] usable
[    0.000000] reserve setup_data: [mem 0x000000040dfad000-0x000000040dfadfff] unusable
[    0.000000] reserve setup_data: [mem 0x000000040dfae000-0x000000040dfaefff] usable
[    0.000000] reserve setup_data: [mem 0x000000040dfaf000-0x000000040dfaffff] unusable
[    0.000000] reserve setup_data: [mem 0x000000040dfb0000-0x000000040dfeafff] usable
[    0.000000] reserve setup_data: [mem 0x000000040dfeb000-0x000000040dfebfff] unusable
[    0.000000] reserve setup_data: [mem 0x000000040dfec000-0x000000042dffffff] usable
[    0.000000] efi: EFI v2.31 by American Megatrends
[    0.000000] efi:  ACPI=0xcb7f1000  ACPI 2.0=0xcb7f1000  SMBIOS=0xf04c0  MPS=0xfd6d0 
[    0.000000] SMBIOS 2.7 present.
[    0.000000] DMI: Dell Inc. Latitude E6530/07Y85M, BIOS A21 02/21/2018
[    0.000000] tsc: Fast TSC calibration using PIT
[    0.000000] tsc: Detected 2691.391 MHz processor
[    0.002646] e820: update [mem 0x00000000-0x00000fff] usable ==> reserved
[    0.002651] e820: remove [mem 0x000a0000-0x000fffff] usable
[    0.002667] last_pfn = 0x42e000 max_arch_pfn = 0x400000000
[    0.002672] MTRR default type: uncachable
[    0.002675] MTRR fixed ranges enabled:
[    0.002678]   00000-9FFFF write-back
[    0.002680]   A0000-BFFFF uncachable
[    0.002682]   C0000-CFFFF write-protect
[    0.002685]   D0000-DFFFF uncachable
[    0.002687]   E0000-FFFFF write-protect
[    0.002690] MTRR variable ranges enabled:
[    0.002693]   0 base 000000000 mask C00000000 write-back
[    0.002696]   1 base 400000000 mask FE0000000 write-back
[    0.002698]   2 base 420000000 mask FF8000000 write-back
[    0.002701]   3 base 428000000 mask FFC000000 write-back
[    0.002704]   4 base 42C000000 mask FFE000000 write-back
[    0.002706]   5 base 0E0000000 mask FE0000000 uncachable
[    0.002709]   6 base 0D0000000 mask FF0000000 uncachable
[    0.002711]   7 disabled
[    0.002713]   8 disabled
[    0.002715]   9 disabled
[    0.005256] x86/PAT: Configuration [0-7]: WB  WC  UC- UC  WB  WP  UC- WT  
[    0.009470] e820: update [mem 0xd0000000-0xffffffff] usable ==> reserved
[    0.009479] last_pfn = 0xcf800 max_arch_pfn = 0x400000000
[    0.018463] found SMP MP-table at [mem 0x000fda20-0x000fda2f] mapped at [(____ptrval____)]
[    0.018659] Base memory trampoline at [(____ptrval____)] 95000 size 24576
[    0.018672] BRK [0x250e01000, 0x250e01fff] PGTABLE
[    0.018676] BRK [0x250e02000, 0x250e02fff] PGTABLE
[    0.018678] BRK [0x250e03000, 0x250e03fff] PGTABLE
[    0.018736] BRK [0x250e04000, 0x250e04fff] PGTABLE
[    0.018741] BRK [0x250e05000, 0x250e05fff] PGTABLE
[    0.018981] BRK [0x250e06000, 0x250e06fff] PGTABLE
[    0.019579] BRK [0x250e07000, 0x250e07fff] PGTABLE
[    0.019740] BRK [0x250e08000, 0x250e08fff] PGTABLE
[    0.019902] BRK [0x250e09000, 0x250e09fff] PGTABLE
[    0.020010] BRK [0x250e0a000, 0x250e0afff] PGTABLE
[    0.020204] BRK [0x250e0b000, 0x250e0bfff] PGTABLE
[    0.020388] BRK [0x250e0c000, 0x250e0cfff] PGTABLE
[    0.023188] Secure boot disabled
[    0.023191] RAMDISK: [mem 0x5f379000-0x6003efff]
[    0.023203] ACPI: Early table checksum verification disabled
[    0.023208] ACPI: RSDP 0x00000000CB7F1000 000024 (v02 DELL  )
[    0.023214] ACPI: XSDT 0x00000000CB7F1088 000094 (v01 DELL   CBX3     01072009 AMI  00010013)
[    0.023223] ACPI: FACP 0x00000000CB7FB720 00010C (v05 DELL   CBX3     01072009 AMI  00010013)
[    0.023233] ACPI: DSDT 0x00000000CB7F11B0 00A56F (v02 DELL   CBX3     00000021 INTL 20091112)
[    0.023240] ACPI: FACS 0x00000000CCFED080 000040
[    0.023245] ACPI: APIC 0x00000000CB7FB830 000072 (v03 DELL   CBX3     01072009 AMI  00010013)
[    0.023251] ACPI: FPDT 0x00000000CB7FB8A8 000044 (v01 DELL   CBX3     01072009 AMI  00010013)
[    0.023257] ACPI: TCPA 0x00000000CB7FB8F0 000032 (v02 APTIO4 NAPAASF  00000001 MSFT 01000013)
[    0.023263] ACPI: MCFG 0x00000000CB7FB928 00003C (v01 DELL   CBX3     01072009 MSFT 00000097)
[    0.023269] ACPI: HPET 0x00000000CB7FB968 000038 (v01 DELL   CBX3     01072009 AMI. 00000005)
[    0.023275] ACPI: SSDT 0x00000000CB7FB9A0 000415 (v01 SataRe SataTabl 00001000 INTL 20091112)
[    0.023281] ACPI: SSDT 0x00000000CB7FBDB8 0009B9 (v01 PmRef  Cpu0Ist  00003000 INTL 20051117)
[    0.023287] ACPI: SSDT 0x00000000CB7FC778 000B22 (v01 PmRef  CpuPm    00003000 INTL 20051117)
[    0.023293] ACPI: DMAR 0x00000000CB7FD2A0 000080 (v01 INTEL  SNB      00000001 INTL 00000001)
[    0.023299] ACPI: ASF! 0x00000000CB7FD320 0000A5 (v32 INTEL   HCG     00000001 TFSM 000F4240)
[    0.023305] ACPI: SSDT 0x00000000CB7FD3C8 000579 (v01 AMITCG PROC     00000001 INTL 20051117)
[    0.023311] ACPI: BGRT 0x00000000CB7FD948 000038 (v00 ??              01072009 AMI  00010013)
[    0.023317] ACPI: SSDT 0x00000000CB7FD980 00198A (v01 NvdRef NvdTabl  00001000 INTL 20091112)
[    0.023329] ACPI: Local APIC address 0xfee00000
[    0.023418] Zone ranges:
[    0.023421]   DMA32    [mem 0x0000000000001000-0x00000000ffffffff]
[    0.023424]   Normal   [mem 0x0000000100000000-0x000000042dffffff]
[    0.023428] Movable zone start for each node
[    0.023430] Early memory node ranges
[    0.023432]   node   0: [mem 0x0000000000001000-0x000000000009efff]
[    0.023435]   node   0: [mem 0x0000000000100000-0x00000000ca709fff]
[    0.023437]   node   0: [mem 0x00000000ca800000-0x00000000caf52fff]
[    0.023440]   node   0: [mem 0x00000000cb000000-0x00000000cb7b1fff]
[    0.023442]   node   0: [mem 0x00000000cb800000-0x00000000ccefdfff]
[    0.023445]   node   0: [mem 0x00000000cd000000-0x00000000ce59bfff]
[    0.023447]   node   0: [mem 0x00000000cefe7000-0x00000000cf2b0fff]
[    0.023449]   node   0: [mem 0x00000000cf7f0000-0x00000000cf7fffff]
[    0.023452]   node   0: [mem 0x0000000100000000-0x000000040dfacfff]
[    0.023454]   node   0: [mem 0x000000040dfae000-0x000000040dfaefff]
[    0.023457]   node   0: [mem 0x000000040dfb0000-0x000000040dfeafff]
[    0.023459]   node   0: [mem 0x000000040dfec000-0x000000042dffffff]
[    0.023578] Zeroed struct page in unavailable ranges: 6882 pages
[    0.023579] Initmem setup node 0 [mem 0x0000000000001000-0x000000042dffffff]
[    0.023583] On node 0 totalpages: 4179230
[    0.023587]   DMA32 zone: 13205 pages used for memmap
[    0.023589]   DMA32 zone: 28 pages reserved
[    0.023592]   DMA32 zone: 845089 pages, LIFO batch:63
[    0.045332]   Normal zone: 52096 pages used for memmap
[    0.045337]   Normal zone: 3334141 pages, LIFO batch:63
[    0.046400] ACPI: PM-Timer IO Port: 0x408
[    0.046407] ACPI: Local APIC address 0xfee00000
[    0.046417] ACPI: LAPIC_NMI (acpi_id[0xff] high edge lint[0x1])
[    0.046444] IOAPIC[0]: apic_id 2, version 32, address 0xfec00000, GSI 0-23
[    0.046452] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
[    0.046456] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
[    0.046461] ACPI: IRQ0 used by override.
[    0.046465] ACPI: IRQ9 used by override.
[    0.046470] Using ACPI (MADT) for SMP configuration information
[    0.046474] ACPI: HPET id: 0x8086a701 base: 0xfed00000
[    0.046483] smpboot: Allowing 4 CPUs, 0 hotplug CPUs
[    0.046603] [mem 0xcf800000-0xf7ffffff] available for PCI devices
[    0.046611] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns
[    0.046637] random: get_random_bytes called from start_kernel+0xc4/0x7c7 with crng_init=0
[    0.046656] setup_percpu: NR_CPUS:4 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1
[    0.047933] percpu: Embedded 497 pages/cpu @(____ptrval____) s1997336 r8192 d30184 u2097152
[    0.047957] pcpu-alloc: s1997336 r8192 d30184 u2097152 alloc=1*2097152
[    0.047960] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 
[    0.048018] Built 1 zonelists, mobility grouping on.  Total pages: 4113901
[    0.048025] Kernel command line: BOOT_IMAGE=/vmlinuz-4.19.0-rc8-next-20181016-dirty root=/dev/mapper/turing--police-root ro rd.md=0 rd.dm=0 rd.lvm.lv=turing-police/00 console.keymap= rd.luks.uuid=luks-665bb147-9e39-4003-b3ae-7be925f51a97 rd.lvm.lv=turing-police/swap rd.lvm.lv=turing-police/root quiet LANG=en_US.UTF-8 nouveau.modeset=0 video=vesa:off single
[    0.049032] Dentry cache hash table entries: 2097152 (order: 12, 16777216 bytes)
[    0.049433] Inode-cache hash table entries: 1048576 (order: 11, 8388608 bytes)
[    0.148148] Memory: 3265348K/16716920K available (16388K kernel code, 3959K rwdata, 4556K rodata, 3680K init, 14740K bss, 588548K reserved, 0K cma-reserved)
[    0.148342] Kernel/User page tables isolation: enabled
[    0.148408] ftrace: allocating 37150 entries in 146 pages
[    0.165544] Running RCU self tests
[    0.165548] rcu: Preemptible hierarchical RCU implementation.
[    0.165550] rcu: 	RCU lockdep checking is enabled.
[    0.165553] rcu: 	RCU debug extended QS entry/exit.
[    0.165555] 	Tasks RCU enabled.
[    0.165558] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies.
[    0.166544] NR_IRQS: 4352, nr_irqs: 456, preallocated irqs: 16
[    0.167131] Console: colour dummy device 160x64
[    0.167142] printk: console [tty0] enabled
[    0.167147] Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar
[    0.167150] ... MAX_LOCKDEP_SUBCLASSES:  8
[    0.167152] ... MAX_LOCK_DEPTH:          48
[    0.167154] ... MAX_LOCKDEP_KEYS:        8191
[    0.167157] ... CLASSHASH_SIZE:          4096
[    0.167159] ... MAX_LOCKDEP_ENTRIES:     32768
[    0.167161] ... MAX_LOCKDEP_CHAINS:      65536
[    0.167164] ... CHAINHASH_SIZE:          32768
[    0.167166]  memory used by lock dependency info: 7775 kB
[    0.167168]  per task-struct memory footprint: 2688 bytes
[    0.167177] ACPI: Core revision 20181003
[    0.167543] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 133484882848 ns
[    0.167568] hpet clockevent registered
[    0.167581] APIC: Switch to symmetric I/O mode setup
[    0.167586] DMAR: Host address width 36
[    0.167589] DMAR: DRHD base: 0x000000fed90000 flags: 0x1
[    0.167606] DMAR: dmar0: reg_base_addr fed90000 ver 1:0 cap c9008020660262 ecap f0105a
[    0.167609] DMAR: RMRR base: 0x000000ce712000 end: 0x000000ce731fff
[    0.167614] DMAR-IR: IOAPIC id 2 under DRHD base  0xfed90000 IOMMU 0
[    0.167617] DMAR-IR: HPET id 0 under DRHD base 0xfed90000
[    0.167620] DMAR-IR: Queued invalidation will be enabled to support x2apic and Intr-remapping.
[    0.167796] DMAR: DRHD: handling fault status reg 2
[    0.167824] DMAR: [DMA Read] Request device [00:1f.2] fault addr ce6ce000 [fault reason 06] PTE Read access is not set
[    0.167945] DMAR-IR: Enabled IRQ remapping in x2apic mode
[    0.167947] x2apic enabled
[    0.167961] Switched APIC routing to cluster x2apic.
[    0.168637] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
[    0.173581] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x26cb79d2970, max_idle_ns: 440795288020 ns
[    0.173608] Calibrating delay loop (skipped), value calculated using timer frequency.. 5382.78 BogoMIPS (lpj=2691391)
[    0.173613] pid_max: default: 32768 minimum: 301
[    0.174378] LSM: Security Framework initializing
[    0.174383] Yama: becoming mindful.
[    0.174398] SELinux:  Initializing.
[    0.174476] *** VALIDATE SELinux ***
[    0.174553] Mount-cache hash table entries: 32768 (order: 6, 262144 bytes)
[    0.174609] Mountpoint-cache hash table entries: 32768 (order: 6, 262144 bytes)
[    0.175074] *** VALIDATE proc ***
[    0.175287] *** VALIDATE cgroup1 ***
[    0.175291] *** VALIDATE cgroup2 ***
[    0.175331] ENERGY_PERF_BIAS: Set to 'normal', was 'performance'
[    0.175334] ENERGY_PERF_BIAS: View and update with x86_energy_perf_policy(8)
[    0.175339] mce: CPU supports 7 MCE banks
[    0.175363] process: using mwait in idle threads
[    0.175368] Last level iTLB entries: 4KB 512, 2MB 8, 4MB 8
[    0.175371] Last level dTLB entries: 4KB 512, 2MB 32, 4MB 32, 1GB 0
[    0.175375] Spectre V2 : Mitigation: Full generic retpoline
[    0.175378] Spectre V2 : Spectre v2 / SpectreRSB mitigation: Filling RSB on context switch
[    0.175381] Spectre V2 : Spectre v2 mitigation: Enabling Indirect Branch Prediction Barrier
[    0.175383] Spectre V2 : Enabling Restricted Speculation for firmware calls
[    0.175391] Spectre V2 : Spectre v2 cross-process SMT mitigation: Enabling STIBP
[    0.175398] Speculative Store Bypass: Mitigation: Speculative Store Bypass disabled via prctl and seccomp
[    0.175635] Freeing SMP alternatives memory: 36K
[    0.206056] TSC deadline timer enabled
[    0.206069] smpboot: CPU0: Intel(R) Core(TM) i5-3340M CPU @ 2.70GHz (family: 0x6, model: 0x3a, stepping: 0x9)
[    0.206206] random: get_random_bytes called from cpu_startup_entry+0x2d/0x75 with crng_init=0
[    0.211653] Performance Events: PEBS fmt1+, IvyBridge events, 16-deep LBR, full-width counters, Intel PMU driver.
[    0.211688] ... version:                3
[    0.211691] ... bit width:              48
[    0.211694] ... generic registers:      4
[    0.211697] ... value mask:             0000ffffffffffff
[    0.211700] ... max period:             00007fffffffffff
[    0.211703] ... fixed-purpose events:   3
[    0.211706] ... event mask:             000000070000000f
[    0.213636] rcu: Hierarchical SRCU implementation.
[    0.216799] NMI watchdog: Enabled. Permanently consumes one hw-PMU counter.
[    0.218646] smp: Bringing up secondary CPUs ...
[    0.226875] x86: Booting SMP configuration:
[    0.226881] .... node  #0, CPUs:      #1
[    0.002792] random: get_random_bytes called from start_secondary+0x178/0x220 with crng_init=0
[    0.236854]  #2 #3
[    0.246791] smp: Brought up 1 node, 4 CPUs
[    0.246791] smpboot: Max logical packages: 1
[    0.246791] smpboot: Total of 4 processors activated (21531.12 BogoMIPS)
[    0.386688] node 0 initialised, 3215756 pages in 139ms
[    0.386860] pgdatinit0 (29) used greatest stack depth: 14672 bytes left
[    0.387859] devtmpfs: initialized
[    0.389105] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns
[    0.389105] futex hash table entries: 1024 (order: 5, 131072 bytes)
[    0.390379] NET: Registered protocol family 16
[    0.390985] audit: initializing netlink subsys (disabled)
[    0.391084] audit: type=2000 audit(1539957692.222:1): state=initialized audit_enabled=0 res=1
[    0.391084] cpuidle: using governor ladder
[    0.391084] cpuidle: using governor menu
[    0.391753] ACPI FADT declares the system doesn't support PCIe ASPM, so disable it
[    0.391764] ACPI: bus type PCI registered
[    0.391942] PCI: MMCONFIG for domain 0000 [bus 00-3f] at [mem 0xf8000000-0xfbffffff] (base 0xf8000000)
[    0.391949] PCI: MMCONFIG at [mem 0xf8000000-0xfbffffff] reserved in E820
[    0.391963] pmd_set_huge: Cannot satisfy [mem 0xf8000000-0xf8200000] with a huge-page mapping due to MTRR override.
[    0.392107] PCI: Using configuration type 1 for base access
[    0.392209] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on
[    0.401831] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages
[    0.402910] fbcon: Taking over console
[    0.403697] ACPI: Added _OSI(Module Device)
[    0.403697] ACPI: Added _OSI(Processor Device)
[    0.403697] ACPI: Added _OSI(3.0 _SCP Extensions)
[    0.403697] ACPI: Added _OSI(Processor Aggregator Device)
[    0.403697] ACPI: Added _OSI(Linux-Dell-Video)
[    0.403697] ACPI: Added _OSI(Linux-Lenovo-NV-HDMI-Audio)
[    0.441605] ACPI: 6 ACPI AML tables successfully acquired and loaded
[    0.458487] ACPI: [Firmware Bug]: BIOS _OSI(Linux) query ignored
[    0.465686] ACPI: Dynamic OEM Table Load:
[    0.465712] ACPI: SSDT 0xFFFF9E3A90EEA800 000523 (v01 PmRef  Cpu0Cst  00003001 INTL 20051117)
[    0.467507] ACPI: Dynamic OEM Table Load:
[    0.467531] ACPI: SSDT 0xFFFF9E39476CBC00 000303 (v01 PmRef  ApIst    00003000 INTL 20051117)
[    0.468611] ACPI: Dynamic OEM Table Load:
[    0.468635] ACPI: SSDT 0xFFFF9E3A90EE9200 000119 (v01 PmRef  ApCst    00003000 INTL 20051117)
[    0.472860] ACPI: EC: EC started
[    0.472867] ACPI: EC: interrupt blocked
[    0.478927] ACPI: \_SB_.PCI0.LPCB.ECDV: Used as first EC
[    0.478934] ACPI: \_SB_.PCI0.LPCB.ECDV: GPE=0x10, EC_CMD/EC_SC=0x934, EC_DATA=0x930
[    0.478940] ACPI: \_SB_.PCI0.LPCB.ECDV: Used as boot DSDT EC to handle transactions
[    0.478943] ACPI: Interpreter enabled
[    0.478963] ACPI: (supports S0 S5)
[    0.478968] ACPI: Using IOAPIC for interrupt routing
[    0.479066] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
[    0.480422] ACPI: Enabled 14 GPEs in block 00 to 3F
[    0.524862] acpi LNXIOBAY:00: ACPI dock station (docks/bays count: 1)
[    0.549633] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-3e])
[    0.549646] acpi PNP0A08:00: _OSC: OS supports [ExtendedConfig ASPM ClockPM Segments MSI]
[    0.550392] acpi PNP0A08:00: _OSC failed (AE_ERROR); disabling ASPM
[    0.551966] PCI host bridge to bus 0000:00
[    0.551972] pci_bus 0000:00: root bus resource [io  0x0000-0x0cf7 window]
[    0.551977] pci_bus 0000:00: root bus resource [io  0x0d00-0xffff window]
[    0.551982] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window]
[    0.551986] pci_bus 0000:00: root bus resource [mem 0x000d0000-0x000d3fff window]
[    0.551991] pci_bus 0000:00: root bus resource [mem 0x000d4000-0x000d7fff window]
[    0.551995] pci_bus 0000:00: root bus resource [mem 0x000d8000-0x000dbfff window]
[    0.552000] pci_bus 0000:00: root bus resource [mem 0x000dc000-0x000dffff window]
[    0.552004] pci_bus 0000:00: root bus resource [mem 0xd0000000-0xfeafffff window]
[    0.552010] pci_bus 0000:00: root bus resource [bus 00-3e]
[    0.552039] pci 0000:00:00.0: [8086:0154] type 00 class 0x060000
[    0.552599] pci 0000:00:01.0: [8086:0151] type 01 class 0x060400
[    0.552695] pci 0000:00:01.0: PME# supported from D0 D3hot D3cold
[    0.553332] pci 0000:00:14.0: [8086:1e31] type 00 class 0x0c0330
[    0.553385] pci 0000:00:14.0: reg 0x10: [mem 0xf7720000-0xf772ffff 64bit]
[    0.553540] pci 0000:00:14.0: PME# supported from D3hot D3cold
[    0.554066] pci 0000:00:16.0: [8086:1e3a] type 00 class 0x078000
[    0.554118] pci 0000:00:16.0: reg 0x10: [mem 0xf773c000-0xf773c00f 64bit]
[    0.554271] pci 0000:00:16.0: PME# supported from D0 D3hot D3cold
[    0.554786] pci 0000:00:19.0: [8086:1502] type 00 class 0x020000
[    0.554838] pci 0000:00:19.0: reg 0x10: [mem 0xf7700000-0xf771ffff]
[    0.554859] pci 0000:00:19.0: reg 0x14: [mem 0xf7739000-0xf7739fff]
[    0.554878] pci 0000:00:19.0: reg 0x18: [io  0xf040-0xf05f]
[    0.555028] pci 0000:00:19.0: PME# supported from D0 D3hot D3cold
[    0.555537] pci 0000:00:1a.0: [8086:1e2d] type 00 class 0x0c0320
[    0.555582] pci 0000:00:1a.0: reg 0x10: [mem 0xf7738000-0xf77383ff]
[    0.555767] pci 0000:00:1a.0: PME# supported from D0 D3hot D3cold
[    0.556286] pci 0000:00:1b.0: [8086:1e20] type 00 class 0x040300
[    0.556334] pci 0000:00:1b.0: reg 0x10: [mem 0xf7730000-0xf7733fff 64bit]
[    0.556514] pci 0000:00:1b.0: PME# supported from D0 D3hot D3cold
[    0.557058] pci 0000:00:1c.0: [8086:1e10] type 01 class 0x060400
[    0.557254] pci 0000:00:1c.0: PME# supported from D0 D3hot D3cold
[    0.557300] pci 0000:00:1c.0: Enabling MPC IRBNCE
[    0.557306] pci 0000:00:1c.0: Intel PCH root port ACS workaround enabled
[    0.557837] pci 0000:00:1c.1: [8086:1e12] type 01 class 0x060400
[    0.558033] pci 0000:00:1c.1: PME# supported from D0 D3hot D3cold
[    0.558079] pci 0000:00:1c.1: Enabling MPC IRBNCE
[    0.558086] pci 0000:00:1c.1: Intel PCH root port ACS workaround enabled
[    0.558589] pci 0000:00:1c.2: [8086:1e14] type 01 class 0x060400
[    0.558789] pci 0000:00:1c.2: PME# supported from D0 D3hot D3cold
[    0.558838] pci 0000:00:1c.2: Enabling MPC IRBNCE
[    0.558845] pci 0000:00:1c.2: Intel PCH root port ACS workaround enabled
[    0.559355] pci 0000:00:1c.3: [8086:1e16] type 01 class 0x060400
[    0.559544] pci 0000:00:1c.3: PME# supported from D0 D3hot D3cold
[    0.559588] pci 0000:00:1c.3: Enabling MPC IRBNCE
[    0.559589] pci 0000:00:1c.3: Intel PCH root port ACS workaround enabled
[    0.560131] pci 0000:00:1c.5: [8086:1e1a] type 01 class 0x060400
[    0.560325] pci 0000:00:1c.5: PME# supported from D0 D3hot D3cold
[    0.560370] pci 0000:00:1c.5: Enabling MPC IRBNCE
[    0.560378] pci 0000:00:1c.5: Intel PCH root port ACS workaround enabled
[    0.560923] pci 0000:00:1d.0: [8086:1e26] type 00 class 0x0c0320
[    0.560968] pci 0000:00:1d.0: reg 0x10: [mem 0xf7737000-0xf77373ff]
[    0.561145] pci 0000:00:1d.0: PME# supported from D0 D3hot D3cold
[    0.561655] pci 0000:00:1f.0: [8086:1e55] type 00 class 0x060100
[    0.562343] pci 0000:00:1f.2: [8086:1e03] type 00 class 0x010601
[    0.562391] pci 0000:00:1f.2: reg 0x10: [io  0xf090-0xf097]
[    0.562410] pci 0000:00:1f.2: reg 0x14: [io  0xf080-0xf083]
[    0.562429] pci 0000:00:1f.2: reg 0x18: [io  0xf070-0xf077]
[    0.562449] pci 0000:00:1f.2: reg 0x1c: [io  0xf060-0xf063]
[    0.562469] pci 0000:00:1f.2: reg 0x20: [io  0xf020-0xf03f]
[    0.562489] pci 0000:00:1f.2: reg 0x24: [mem 0xf7736000-0xf77367ff]
[    0.562605] pci 0000:00:1f.2: PME# supported from D3hot
[    0.563127] pci 0000:00:1f.3: [8086:1e22] type 00 class 0x0c0500
[    0.563171] pci 0000:00:1f.3: reg 0x10: [mem 0xf7735000-0xf77350ff 64bit]
[    0.563221] pci 0000:00:1f.3: reg 0x20: [io  0xf000-0xf01f]
[    0.563871] pci 0000:01:00.0: [10de:0dfc] type 00 class 0x030000
[    0.563900] pci 0000:01:00.0: reg 0x10: [mem 0xf5000000-0xf5ffffff]
[    0.563918] pci 0000:01:00.0: reg 0x14: [mem 0xe0000000-0xefffffff 64bit pref]
[    0.563935] pci 0000:01:00.0: reg 0x1c: [mem 0xf0000000-0xf1ffffff 64bit pref]
[    0.563948] pci 0000:01:00.0: reg 0x24: [io  0xe000-0xe07f]
[    0.563960] pci 0000:01:00.0: reg 0x30: [mem 0xf6000000-0xf607ffff pref]
[    0.563971] pci 0000:01:00.0: enabling Extended Tags
[    0.564000] pci 0000:01:00.0: BAR 3: assigned to efifb
[    0.564081] pci 0000:01:00.0: 64.000 Gb/s available PCIe bandwidth, limited by 5 GT/s x16 link at 0000:00:01.0 (capable of 126.016 Gb/s with 8 GT/s x16 link)
[    0.564754] pci 0000:01:00.1: [10de:0bea] type 00 class 0x040300
[    0.564777] pci 0000:01:00.1: reg 0x10: [mem 0xf6080000-0xf6083fff]
[    0.564831] pci 0000:01:00.1: enabling Extended Tags
[    0.565063] pci 0000:00:01.0: PCI bridge to [bus 01]
[    0.565069] pci 0000:00:01.0:   bridge window [io  0xe000-0xefff]
[    0.565075] pci 0000:00:01.0:   bridge window [mem 0xf5000000-0xf60fffff]
[    0.565082] pci 0000:00:01.0:   bridge window [mem 0xe0000000-0xf1ffffff 64bit pref]
[    0.565208] pci 0000:00:1c.0: PCI bridge to [bus 02]
[    0.565391] pci 0000:03:00.0: [14e4:4727] type 00 class 0x028000
[    0.565454] pci 0000:03:00.0: reg 0x10: [mem 0xf7600000-0xf7603fff 64bit]
[    0.565541] pci 0000:03:00.0: enabling Extended Tags
[    0.565722] pci 0000:03:00.0: supports D1 D2
[    0.565726] pci 0000:03:00.0: PME# supported from D0 D3hot D3cold
[    0.565790] pci 0000:03:00.0: 2.000 Gb/s available PCIe bandwidth, limited by 2.5 GT/s x1 link at 0000:00:1c.1 (capable of 7.876 Gb/s with 8 GT/s x1 link)
[    0.565976] pci 0000:00:1c.1: PCI bridge to [bus 03]
[    0.565989] pci 0000:00:1c.1:   bridge window [mem 0xf7600000-0xf76fffff]
[    0.566117] pci 0000:00:1c.2: PCI bridge to [bus 04-07]
[    0.566125] pci 0000:00:1c.2:   bridge window [io  0xd000-0xdfff]
[    0.566133] pci 0000:00:1c.2:   bridge window [mem 0xf6b00000-0xf74fffff]
[    0.566146] pci 0000:00:1c.2:   bridge window [mem 0xf2b00000-0xf34fffff 64bit pref]
[    0.566264] pci 0000:00:1c.3: PCI bridge to [bus 08-0b]
[    0.566272] pci 0000:00:1c.3:   bridge window [io  0xc000-0xcfff]
[    0.566280] pci 0000:00:1c.3:   bridge window [mem 0xf6100000-0xf6afffff]
[    0.566293] pci 0000:00:1c.3:   bridge window [mem 0xf2100000-0xf2afffff 64bit pref]
[    0.566546] pci 0000:0c:00.0: [1217:8221] type 00 class 0x080501
[    0.566645] pci 0000:0c:00.0: reg 0x10: [mem 0xf7500000-0xf75001ff]
[    0.567111] pci 0000:0c:00.0: supports D1 D2
[    0.567115] pci 0000:0c:00.0: PME# supported from D0 D1 D2 D3hot D3cold
[    0.567213] pci 0000:0c:00.0: 2.000 Gb/s available PCIe bandwidth, limited by 2.5 GT/s x1 link at 0000:00:1c.5 (capable of 7.876 Gb/s with 8 GT/s x1 link)
[    0.567406] pci 0000:00:1c.5: PCI bridge to [bus 0c]
[    0.567419] pci 0000:00:1c.5:   bridge window [mem 0xf7500000-0xf75fffff]
[    0.567497] pci_bus 0000:00: on NUMA node 0
[    0.574444] ACPI: PCI Interrupt Link [LNKA] (IRQs 3 4 5 6 10 *11 12 14 15)
[    0.574755] ACPI: PCI Interrupt Link [LNKB] (IRQs 3 4 5 6 *10 11 12 14 15)
[    0.575041] ACPI: PCI Interrupt Link [LNKC] (IRQs 3 4 5 6 *10 11 12 14 15)
[    0.575328] ACPI: PCI Interrupt Link [LNKD] (IRQs 3 4 *5 6 10 11 12 14 15)
[    0.575617] ACPI: PCI Interrupt Link [LNKE] (IRQs *3 4 5 6 10 11 12 14 15)
[    0.575910] ACPI: PCI Interrupt Link [LNKF] (IRQs 3 4 *5 6 10 11 12 14 15)
[    0.576197] ACPI: PCI Interrupt Link [LNKG] (IRQs 3 4 5 6 10 *11 12 14 15)
[    0.576482] ACPI: PCI Interrupt Link [LNKH] (IRQs 3 4 5 6 10 11 12 14 15) *0, disabled.
[    0.585257] ACPI: EC: interrupt unblocked
[    0.585291] ACPI: EC: event unblocked
[    0.585308] ACPI: \_SB_.PCI0.LPCB.ECDV: GPE=0x10, EC_CMD/EC_SC=0x934, EC_DATA=0x930
[    0.585316] ACPI: \_SB_.PCI0.LPCB.ECDV: Used as boot DSDT EC to handle transactions and events
[    0.585908] pci 0000:01:00.0: vgaarb: setting as boot VGA device
[    0.585908] pci 0000:01:00.0: vgaarb: VGA device added: decodes=io+mem,owns=io+mem,locks=none
[    0.585908] pci 0000:01:00.0: vgaarb: bridge control possible
[    0.585908] vgaarb: loaded
[    0.586705] SCSI subsystem initialized
[    0.586747] libata version 3.00 loaded.
[    0.586780] ACPI: bus type USB registered
[    0.586859] usbcore: registered new interface driver usbfs
[    0.586905] usbcore: registered new interface driver hub
[    0.587002] usbcore: registered new device driver usb
[    0.587065] videodev: Linux video capture interface: v2.00
[    0.587088] pps_core: LinuxPPS API ver. 1 registered
[    0.587091] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
[    0.587105] PTP clock support registered
[    0.587265] Registered efivars operations
[    0.597743] Advanced Linux Sound Architecture Driver Initialized.
[    0.597818] PCI: Using ACPI for IRQ routing
[    0.602339] PCI: pci_cache_line_size set to 64 bytes
[    0.602566] e820: reserve RAM buffer [mem 0x0009f000-0x0009ffff]
[    0.602573] e820: reserve RAM buffer [mem 0xc7a8a018-0xc7ffffff]
[    0.602578] e820: reserve RAM buffer [mem 0xc7a9a018-0xc7ffffff]
[    0.602583] e820: reserve RAM buffer [mem 0xca70a000-0xcbffffff]
[    0.602587] e820: reserve RAM buffer [mem 0xcaf53000-0xcbffffff]
[    0.602589] e820: reserve RAM buffer [mem 0xcb7b2000-0xcbffffff]
[    0.602600] e820: reserve RAM buffer [mem 0xccefe000-0xcfffffff]
[    0.602604] e820: reserve RAM buffer [mem 0xce59c000-0xcfffffff]
[    0.602609] e820: reserve RAM buffer [mem 0xcf2b1000-0xcfffffff]
[    0.602614] e820: reserve RAM buffer [mem 0xcf800000-0xcfffffff]
[    0.602619] e820: reserve RAM buffer [mem 0x40dfad000-0x40fffffff]
[    0.602624] e820: reserve RAM buffer [mem 0x40dfaf000-0x40fffffff]
[    0.602629] e820: reserve RAM buffer [mem 0x40dfeb000-0x40fffffff]
[    0.602633] e820: reserve RAM buffer [mem 0x42e000000-0x42fffffff]
[    0.603215] NetLabel: Initializing
[    0.603219] NetLabel:  domain hash size = 128
[    0.603222] NetLabel:  protocols = UNLABELED CIPSOv4 CALIPSO
[    0.603277] NetLabel:  unlabeled traffic allowed by default
[    0.603673] dcdbas dcdbas: Dell Systems Management Base Driver (version 5.6.0-3.3)
[    0.603971] wmi_bus wmi_bus-PNP0C14:00: WQBC data block query control method not found
[    0.604371] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0, 0, 0, 0, 0, 0
[    0.604383] hpet0: 8 comparators, 64-bit 14.318180 MHz counter
[    0.605673] clocksource: Switched to clocksource tsc-early
[    0.690896] Warning: could not register annotated branches stats
[    0.691272] VFS: Disk quotas dquot_6.6.0
[    0.691319] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[    0.691422] *** VALIDATE hugetlbfs ***
[    0.691562] pnp: PnP ACPI init
[    0.692050] system 00:00: [io  0x0680-0x069f] has been reserved
[    0.692057] system 00:00: [io  0x1000-0x100f] has been reserved
[    0.692065] system 00:00: [io  0x1100-0x1103] has been reserved
[    0.692071] system 00:00: [io  0xffff] has been reserved
[    0.692077] system 00:00: [io  0x0400-0x0453] has been reserved
[    0.692083] system 00:00: [io  0x0458-0x047f] has been reserved
[    0.692091] system 00:00: [io  0x0500-0x057f] has been reserved
[    0.692097] system 00:00: [io  0x164e-0x164f] has been reserved
[    0.692122] system 00:00: Plug and Play ACPI device, IDs PNP0c02 (active)
[    0.692225] pnp 00:01: Plug and Play ACPI device, IDs PNP0b00 (active)
[    0.692434] system 00:02: [io  0x0454-0x0457] has been reserved
[    0.692449] system 00:02: Plug and Play ACPI device, IDs INT3f0d PNP0c02 (active)
[    0.692677] system 00:03: [io  0x04d0-0x04d1] has been reserved
[    0.692692] system 00:03: Plug and Play ACPI device, IDs PNP0c02 (active)
[    0.692856] pnp 00:04: Plug and Play ACPI device, IDs PNP0303 (active)
[    0.692951] pnp 00:05: Plug and Play ACPI device, IDs DLL0535 PNP0f13 (active)
[    0.695944] pnp 00:06: Plug and Play ACPI device, IDs PNP0401 (disabled)
[    0.698387] system 00:07: [mem 0xfed1c000-0xfed1ffff] has been reserved
[    0.698394] system 00:07: [mem 0xfed10000-0xfed17fff] has been reserved
[    0.698400] system 00:07: [mem 0xfed18000-0xfed18fff] has been reserved
[    0.698407] system 00:07: [mem 0xfed19000-0xfed19fff] has been reserved
[    0.698413] system 00:07: [mem 0xf8000000-0xfbffffff] has been reserved
[    0.698419] system 00:07: [mem 0xfed20000-0xfed3ffff] has been reserved
[    0.698426] system 00:07: [mem 0xfed90000-0xfed93fff] could not be reserved
[    0.698432] system 00:07: [mem 0xfed45000-0xfed8ffff] has been reserved
[    0.698438] system 00:07: [mem 0xff000000-0xffffffff] has been reserved
[    0.698445] system 00:07: [mem 0xfee00000-0xfeefffff] could not be reserved
[    0.698451] system 00:07: [mem 0xd0000000-0xd0000fff] has been reserved
[    0.698465] system 00:07: Plug and Play ACPI device, IDs PNP0c02 (active)
[    0.707798] pnp 00:08: Plug and Play ACPI device, IDs PNP0c31 (active)
[    0.707821] pnp: PnP ACPI: found 9 devices
[    0.720225] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns
[    0.720319] pci 0000:00:01.0: PCI bridge to [bus 01]
[    0.720325] pci 0000:00:01.0:   bridge window [io  0xe000-0xefff]
[    0.720331] pci 0000:00:01.0:   bridge window [mem 0xf5000000-0xf60fffff]
[    0.720337] pci 0000:00:01.0:   bridge window [mem 0xe0000000-0xf1ffffff 64bit pref]
[    0.720344] pci 0000:00:1c.0: PCI bridge to [bus 02]
[    0.720371] pci 0000:00:1c.1: PCI bridge to [bus 03]
[    0.720381] pci 0000:00:1c.1:   bridge window [mem 0xf7600000-0xf76fffff]
[    0.720400] pci 0000:00:1c.2: PCI bridge to [bus 04-07]
[    0.720406] pci 0000:00:1c.2:   bridge window [io  0xd000-0xdfff]
[    0.720416] pci 0000:00:1c.2:   bridge window [mem 0xf6b00000-0xf74fffff]
[    0.720423] pci 0000:00:1c.2:   bridge window [mem 0xf2b00000-0xf34fffff 64bit pref]
[    0.720437] pci 0000:00:1c.3: PCI bridge to [bus 08-0b]
[    0.720444] pci 0000:00:1c.3:   bridge window [io  0xc000-0xcfff]
[    0.720454] pci 0000:00:1c.3:   bridge window [mem 0xf6100000-0xf6afffff]
[    0.720463] pci 0000:00:1c.3:   bridge window [mem 0xf2100000-0xf2afffff 64bit pref]
[    0.720476] pci 0000:00:1c.5: PCI bridge to [bus 0c]
[    0.720488] pci 0000:00:1c.5:   bridge window [mem 0xf7500000-0xf75fffff]
[    0.720507] pci_bus 0000:00: resource 4 [io  0x0000-0x0cf7 window]
[    0.720511] pci_bus 0000:00: resource 5 [io  0x0d00-0xffff window]
[    0.720515] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window]
[    0.720519] pci_bus 0000:00: resource 7 [mem 0x000d0000-0x000d3fff window]
[    0.720523] pci_bus 0000:00: resource 8 [mem 0x000d4000-0x000d7fff window]
[    0.720527] pci_bus 0000:00: resource 9 [mem 0x000d8000-0x000dbfff window]
[    0.720531] pci_bus 0000:00: resource 10 [mem 0x000dc000-0x000dffff window]
[    0.720535] pci_bus 0000:00: resource 11 [mem 0xd0000000-0xfeafffff window]
[    0.720538] pci_bus 0000:01: resource 0 [io  0xe000-0xefff]
[    0.720542] pci_bus 0000:01: resource 1 [mem 0xf5000000-0xf60fffff]
[    0.720546] pci_bus 0000:01: resource 2 [mem 0xe0000000-0xf1ffffff 64bit pref]
[    0.720550] pci_bus 0000:03: resource 1 [mem 0xf7600000-0xf76fffff]
[    0.720554] pci_bus 0000:04: resource 0 [io  0xd000-0xdfff]
[    0.720558] pci_bus 0000:04: resource 1 [mem 0xf6b00000-0xf74fffff]
[    0.720562] pci_bus 0000:04: resource 2 [mem 0xf2b00000-0xf34fffff 64bit pref]
[    0.720566] pci_bus 0000:08: resource 0 [io  0xc000-0xcfff]
[    0.720569] pci_bus 0000:08: resource 1 [mem 0xf6100000-0xf6afffff]
[    0.720573] pci_bus 0000:08: resource 2 [mem 0xf2100000-0xf2afffff 64bit pref]
[    0.720577] pci_bus 0000:0c: resource 1 [mem 0xf7500000-0xf75fffff]
[    0.721259] NET: Registered protocol family 2
[    0.721863] tcp_listen_portaddr_hash hash table entries: 8192 (order: 7, 720896 bytes)
[    0.722155] TCP established hash table entries: 131072 (order: 8, 1048576 bytes)
[    0.722504] TCP bind hash table entries: 32768 (order: 9, 2621440 bytes)
[    0.723553] TCP: Hash tables configured (established 131072 bind 32768)
[    0.723790] UDP hash table entries: 8192 (order: 8, 1572864 bytes)
[    0.724373] UDP-Lite hash table entries: 8192 (order: 8, 1572864 bytes)
[    0.725084] NET: Registered protocol family 1
[    0.725452] NET: Registered protocol family 44
[    0.753226] pci 0000:00:1a.0: quirk_usb_early_handoff+0x0/0x6dd took 17290 usecs
[    0.771219] pci 0000:00:1d.0: quirk_usb_early_handoff+0x0/0x6dd took 17528 usecs
[    0.771260] pci 0000:01:00.0: Video device with shadowed ROM at [mem 0x000c0000-0x000dffff]
[    0.771304] pci 0000:01:00.1: Linked as a consumer to 0000:01:00.0
[    0.771433] PCI: CLS mismatch (64 != 32), using 64 bytes
[    0.771804] Unpacking initramfs...
[    2.259557] Freeing initrd memory: 13080K
[    2.259702] DMAR: No ATSR found
[    2.259881] DMAR: dmar0: Using Queued invalidation
[    2.259924] DMAR: Setting RMRR:
[    2.260160] DMAR: Setting identity map for device 0000:00:14.0 [0xce712000 - 0xce731fff]
[    2.260337] DMAR: Setting identity map for device 0000:00:1a.0 [0xce712000 - 0xce731fff]
[    2.260480] DMAR: Setting identity map for device 0000:00:1d.0 [0xce712000 - 0xce731fff]
[    2.260500] DMAR: Prepare 0-16MiB unity mapping for LPC
[    2.260695] DMAR: Setting identity map for device 0000:00:1f.0 [0x0 - 0xffffff]
[    2.260810] DMAR: Intel(R) Virtualization Technology for Directed I/O
[    2.260995] iommu: Adding device 0000:00:00.0 to group 0
[    2.261077] iommu: Adding device 0000:00:01.0 to group 1
[    2.261133] iommu: Adding device 0000:00:14.0 to group 2
[    2.261208] iommu: Adding device 0000:00:16.0 to group 3
[    2.261262] iommu: Adding device 0000:00:19.0 to group 4
[    2.261320] iommu: Adding device 0000:00:1a.0 to group 5
[    2.261377] iommu: Adding device 0000:00:1b.0 to group 6
[    2.261432] iommu: Adding device 0000:00:1c.0 to group 7
[    2.261488] iommu: Adding device 0000:00:1c.1 to group 8
[    2.261543] iommu: Adding device 0000:00:1c.2 to group 9
[    2.261616] iommu: Adding device 0000:00:1c.3 to group 10
[    2.261674] iommu: Adding device 0000:00:1c.5 to group 11
[    2.261728] iommu: Adding device 0000:00:1d.0 to group 12
[    2.261843] iommu: Adding device 0000:00:1f.0 to group 13
[    2.261899] iommu: Adding device 0000:00:1f.2 to group 13
[    2.261952] iommu: Adding device 0000:00:1f.3 to group 13
[    2.261975] iommu: Adding device 0000:01:00.0 to group 1
[    2.261997] iommu: Adding device 0000:01:00.1 to group 1
[    2.262055] iommu: Adding device 0000:03:00.0 to group 14
[    2.262110] iommu: Adding device 0000:0c:00.0 to group 15
[    2.276371] RAPL PMU: API unit is 2^-32 Joules, 3 fixed counters, 163840 ms ovfl timer
[    2.276375] RAPL PMU: hw unit of domain pp0-core 2^-16 Joules
[    2.276378] RAPL PMU: hw unit of domain package 2^-16 Joules
[    2.276381] RAPL PMU: hw unit of domain pp1-gpu 2^-16 Joules
[    2.279367] _warn_unseeded_randomness: 6 callbacks suppressed
[    2.279373] random: get_random_bytes called from create_elf_tables+0xd1/0x9e0 with crng_init=0
[    2.281754] modprobe (50) used greatest stack depth: 8 bytes left
[    2.283784] Initialise system trusted keyrings
[    2.283808] random: get_random_bytes called from key_alloc+0x261/0x480 with crng_init=0
[    2.283991] workingset: timestamp_bits=47 max_order=22 bucket_order=0
[    2.284252] zbud: loaded
[    2.285260] pstore: using deflate compression
[    2.287134] random: get_random_bytes called from create_elf_tables+0xd1/0x9e0 with crng_init=0
[    2.418346] Key type asymmetric registered
[    2.418366] Asymmetric key parser 'x509' registered
[    2.418392] io scheduler noop registered
[    2.418398] io scheduler deadline registered
[    2.418432] io scheduler cfq registered (default)
[    2.418589] atomic64_test: passed for x86-64 platform with CX8 and with SSE
[    2.423165] efifb: probing for efifb
[    2.423222] efifb: framebuffer at 0xf1000000, using 9000k, total 9000k
[    2.423225] efifb: mode is 1920x1200x32, linelength=7680, pages=1
[    2.423228] efifb: scrolling: redraw
[    2.423232] efifb: Truecolor: size=8:8:8:8, shift=24:16:8:0
[    2.423748] Console: switching to colour frame buffer device 240x75
[    2.429379] fb0: EFI VGA frame buffer device
[    2.429410] intel_idle: MWAIT substates: 0x21120
[    2.429414] intel_idle: v0.4.1 model 0x3A
[    2.430309] intel_idle: lapic_timer_reliable_states 0xffffffff
[    2.432534] ACPI: AC Adapter [AC] (on-line)
[    2.432853] input: Lid Switch as /devices/LNXSYSTM:00/LNXSYBUS:00/PNP0C0D:00/input/input0
[    2.432861] ACPI: Lid Switch [LID0]
[    2.432997] input: Power Button as /devices/LNXSYSTM:00/LNXSYBUS:00/PNP0C0C:00/input/input1
[    2.433020] ACPI: Power Button [PBTN]
[    2.433153] input: Sleep Button as /devices/LNXSYSTM:00/LNXSYBUS:00/PNP0C0E:00/input/input2
[    2.433161] ACPI: Sleep Button [SBTN]
[    2.433295] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input3
[    2.433302] ACPI: Power Button [PWRF]
[    2.437875] ACPI: Video Device [VID] (multi-head: yes  rom: yes  post: no)
[    2.451855] acpi device:17: registered as cooling_device0
[    2.452879] input: Video Bus as /devices/LNXSYSTM:00/LNXSYBUS:00/PNP0A08:00/device:14/LNXVIDEO:00/input/input4
[    2.456772] thermal LNXTHERM:00: registered as thermal_zone0
[    2.456776] ACPI: Thermal Zone [THM] (60 C)
[    2.457537] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
[    2.461016] Hangcheck: starting hangcheck timer 0.9.1 (tick is 180 seconds, margin is 60 seconds).
[    2.462663] tpm_tis 00:08: 1.2 TPM (device-id 0x3204, rev-id 64)
[    2.509541] loop: module loaded
[    2.510640] zram: Added device: zram0
[    2.512735] ahci 0000:00:1f.2: version 3.0
[    2.515829] ahci 0000:00:1f.2: SSS flag set, parallel bus scan disabled
[    2.515876] ahci 0000:00:1f.2: AHCI 0001.0300 32 slots 6 ports 6 Gbps 0x33 impl SATA mode
[    2.515883] ahci 0000:00:1f.2: flags: 64bit ncq stag pm led clo pio slum part ems sxs apst 
[    2.536313] battery: ACPI: Battery Slot [BAT0] (battery present)
[    2.541779] battery: ACPI: Battery Slot [BAT1] (battery absent)
[    2.547900] battery: ACPI: Battery Slot [BAT2] (battery absent)
[    2.549761] scsi host0: ahci
[    2.550280] scsi host1: ahci
[    2.550756] scsi host2: ahci
[    2.551183] scsi host3: ahci
[    2.551680] scsi host4: ahci
[    2.552119] scsi host5: ahci
[    2.552312] ata1: SATA max UDMA/133 abar m2048@0xf7736000 port 0xf7736100 irq 26
[    2.552317] ata2: SATA max UDMA/133 abar m2048@0xf7736000 port 0xf7736180 irq 26
[    2.552320] ata3: DUMMY
[    2.552324] ata4: DUMMY
[    2.552331] ata5: SATA max UDMA/133 abar m2048@0xf7736000 port 0xf7736300 irq 26
[    2.552336] ata6: SATA max UDMA/133 abar m2048@0xf7736000 port 0xf7736380 irq 26
[    2.553172] e1000e: Intel(R) PRO/1000 Network Driver - 3.2.6-k
[    2.553177] e1000e: Copyright(c) 1999 - 2015 Intel Corporation.
[    2.553983] e1000e 0000:00:19.0: Interrupt Throttling Rate (ints/sec) set to dynamic conservative mode
[    2.693051] e1000e 0000:00:19.0 0000:00:19.0 (uninitialized): registered PHC clock
[    2.813563] e1000e 0000:00:19.0 eth0: (PCI Express:2.5GT/s:Width x1) f0:1f:af:0c:8a:da
[    2.813630] e1000e 0000:00:19.0 eth0: Intel(R) PRO/1000 Network Connection
[    2.813673] e1000e 0000:00:19.0 eth0: MAC: 10, PHY: 11, PBA No: 7011FF-0FF
[    2.813759] PPP generic driver version 2.4.2
[    2.814281] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[    2.814288] ehci-pci: EHCI PCI platform driver
[    2.815054] ehci-pci 0000:00:1a.0: EHCI Host Controller
[    2.815469] ehci-pci 0000:00:1a.0: new USB bus registered, assigned bus number 1
[    2.815518] ehci-pci 0000:00:1a.0: debug port 2
[    2.819518] ehci-pci 0000:00:1a.0: cache line size of 64 is not supported
[    2.819622] ehci-pci 0000:00:1a.0: irq 16, io mem 0xf7738000
[    2.826734] ehci-pci 0000:00:1a.0: USB 2.0 started, EHCI 1.00
[    2.827152] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 4.19
[    2.827163] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    2.827167] usb usb1: Product: EHCI Host Controller
[    2.827171] usb usb1: Manufacturer: Linux 4.19.0-rc8-next-20181016-dirty ehci_hcd
[    2.827175] usb usb1: SerialNumber: 0000:00:1a.0
[    2.828016] hub 1-0:1.0: USB hub found
[    2.828069] hub 1-0:1.0: 2 ports detected
[    2.829651] ehci-pci 0000:00:1d.0: EHCI Host Controller
[    2.829878] ehci-pci 0000:00:1d.0: new USB bus registered, assigned bus number 2
[    2.829905] ehci-pci 0000:00:1d.0: debug port 2
[    2.833861] ehci-pci 0000:00:1d.0: cache line size of 64 is not supported
[    2.833915] ehci-pci 0000:00:1d.0: irq 21, io mem 0xf7737000
[    2.840738] ehci-pci 0000:00:1d.0: USB 2.0 started, EHCI 1.00
[    2.841011] usb usb2: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 4.19
[    2.841019] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    2.841023] usb usb2: Product: EHCI Host Controller
[    2.841027] usb usb2: Manufacturer: Linux 4.19.0-rc8-next-20181016-dirty ehci_hcd
[    2.841032] usb usb2: SerialNumber: 0000:00:1d.0
[    2.841752] hub 2-0:1.0: USB hub found
[    2.841794] hub 2-0:1.0: 2 ports detected
[    2.842495] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
[    2.842525] ohci-pci: OHCI PCI platform driver
[    2.842576] uhci_hcd: USB Universal Host Controller Interface driver
[    2.843337] xhci_hcd 0000:00:14.0: xHCI Host Controller
[    2.843633] xhci_hcd 0000:00:14.0: new USB bus registered, assigned bus number 3
[    2.844824] xhci_hcd 0000:00:14.0: hcc params 0x20007181 hci version 0x100 quirks 0x000000000000b930
[    2.844838] xhci_hcd 0000:00:14.0: cache line size of 64 is not supported
[    2.845790] usb usb3: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 4.19
[    2.845795] usb usb3: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    2.845799] usb usb3: Product: xHCI Host Controller
[    2.845803] usb usb3: Manufacturer: Linux 4.19.0-rc8-next-20181016-dirty xhci-hcd
[    2.845807] usb usb3: SerialNumber: 0000:00:14.0
[    2.846316] hub 3-0:1.0: USB hub found
[    2.846384] hub 3-0:1.0: 4 ports detected
[    2.848316] xhci_hcd 0000:00:14.0: xHCI Host Controller
[    2.848634] xhci_hcd 0000:00:14.0: new USB bus registered, assigned bus number 4
[    2.848646] xhci_hcd 0000:00:14.0: Host supports USB 3.0  SuperSpeed
[    2.848879] usb usb4: New USB device found, idVendor=1d6b, idProduct=0003, bcdDevice= 4.19
[    2.848885] usb usb4: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    2.848889] usb usb4: Product: xHCI Host Controller
[    2.848893] usb usb4: Manufacturer: Linux 4.19.0-rc8-next-20181016-dirty xhci-hcd
[    2.848897] usb usb4: SerialNumber: 0000:00:14.0
[    2.849493] hub 4-0:1.0: USB hub found
[    2.849550] hub 4-0:1.0: 4 ports detected
[    2.851682] usbcore: registered new interface driver usb-storage
[    2.851774] i8042: PNP: PS/2 Controller [PNP0303:PS2K,PNP0f13:PS2M] at 0x60,0x64 irq 1,12
[    2.852320] i8042: Warning: Keylock active
[    2.855957] serio: i8042 KBD port at 0x60,0x64 irq 1
[    2.856176] serio: i8042 AUX port at 0x60,0x64 irq 12
[    2.856516] mousedev: PS/2 mouse device common for all mice
[    2.857987] rtc_cmos 00:01: RTC can wake from S4
[    2.858366] rtc_cmos 00:01: registered as rtc0
[    2.858486] rtc_cmos 00:01: alarms up to one month, y3k, 242 bytes nvram, hpet irqs
[    2.858541] i2c /dev entries driver
[    2.859158] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input5
[    2.860221] i801_smbus 0000:00:1f.3: SMBus using PCI interrupt
[    2.863101] ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
[    2.867342] ata1.00: ACPI cmd ef/10:06:00:00:00:00 (SET FEATURES) succeeded
[    2.867355] ata1.00: ACPI cmd f5/00:00:00:00:00:00 (SECURITY FREEZE LOCK) filtered out
[    2.867365] ata1.00: ACPI cmd b1/c1:00:00:00:00:00 (DEVICE CONFIGURATION OVERLAY) filtered out
[    2.867761] ata1.00: ACPI cmd 00/00:00:00:00:00:a0 (NOP) rejected by device (Stat=0x51 Err=0x04)
[    2.872850] ata1.00: ATA-8: ST500LX003-1AC15G, DEM4, max UDMA/133
[    2.872858] ata1.00: 976773168 sectors, multi 16: LBA48 NCQ (depth 32)
[    2.882631] ata1.00: ACPI cmd ef/10:06:00:00:00:00 (SET FEATURES) succeeded
[    2.882639] ata1.00: ACPI cmd f5/00:00:00:00:00:00 (SECURITY FREEZE LOCK) filtered out
[    2.882646] ata1.00: ACPI cmd b1/c1:00:00:00:00:00 (DEVICE CONFIGURATION OVERLAY) filtered out
[    2.882999] ata1.00: ACPI cmd 00/00:00:00:00:00:a0 (NOP) rejected by device (Stat=0x51 Err=0x04)
[    2.885351] ata1.00: configured for UDMA/133
[    2.886809] dennis zhou
[    2.887146] scsi 0:0:0:0: Direct-Access     ATA      ST500LX003-1AC15 DEM4 PQ: 0 ANSI: 5
[    2.889016] sd 0:0:0:0: [sda] 976773168 512-byte logical blocks: (500 GB/466 GiB)
[    2.889032] sd 0:0:0:0: [sda] 4096-byte physical blocks
[    2.889134] sd 0:0:0:0: [sda] Write Protect is off
[    2.889141] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
[    2.889312] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[    2.895403] usbcore: registered new interface driver uvcvideo
[    2.895409] USB Video Class driver (1.1.1)
[    2.897342]  sda: sda1 sda2 sda3
[    2.899459] sd 0:0:0:0: [sda] Attached SCSI disk
[    2.899569] iTCO_wdt: Intel TCO WatchDog Timer Driver v1.11
[    2.899677] iTCO_wdt: Found a Panther Point TCO device (Version=2, TCOBASE=0x0460)
[    2.900126] iTCO_wdt: initialized. heartbeat=30 sec (nowayout=0)
[    2.900157] iTCO_vendor_support: vendor-support=0
[    2.900188] device-mapper: uevent: version 1.0.3
[    2.900384] device-mapper: ioctl: 4.39.0-ioctl (2018-04-03) initialised: dm-devel@redhat.com
[    2.900403] intel_pstate: Intel P-state driver initializing
[    2.901073] sdhci: Secure Digital Host Controller Interface driver
[    2.901080] sdhci: Copyright(c) Pierre Ossman
[    2.901195] sdhci-pci 0000:0c:00.0: SDHCI controller found [1217:8221] (rev 5)
[    2.902398] mmc0 bounce up to 128 segments into one, max segment size 65536 bytes
[    2.904036] mmc0: SDHCI controller on PCI [0000:0c:00.0] using DMA
[    2.904456] sdhci-pltfm: SDHCI platform and OF driver helper
[    2.904488] EFI Variables Facility v0.08 2004-May-17
[    2.925204] pstore: Registered efi as persistent store backend
[    2.925251] hidraw: raw HID events driver (C) Jiri Kosina
[    2.925351] usbcore: registered new interface driver usbhid
[    2.925354] usbhid: USB HID core driver
[    2.928122] snd_hda_intel 0000:01:00.1: enabling device (0000 -> 0002)
[    2.928302] snd_hda_intel 0000:01:00.1: Disabling MSI
[    2.929982] Initializing XFRM netlink socket
[    2.930135] NET: Registered protocol family 10
[    2.931380] Segment Routing with IPv6
[    2.931720] NET: Registered protocol family 17
[    2.931800] NET: Registered protocol family 15
[    2.932246] sctp: Hash tables configured (bind 32/51)
[    2.932568] Key type dns_resolver registered
[    2.932581] start plist test
[    2.937258] snd_hda_codec_idt hdaudioC0D0: autoconfig for 92HD93BXX: line_outs=1 (0xe/0x0/0x0/0x0/0x0) type:line
[    2.937265] snd_hda_codec_idt hdaudioC0D0:    speaker_outs=1 (0xd/0x0/0x0/0x0/0x0)
[    2.937268] snd_hda_codec_idt hdaudioC0D0:    hp_outs=1 (0xb/0x0/0x0/0x0/0x0)
[    2.937272] snd_hda_codec_idt hdaudioC0D0:    mono: mono_out=0x0
[    2.937275] snd_hda_codec_idt hdaudioC0D0:    inputs:
[    2.937278] snd_hda_codec_idt hdaudioC0D0:      Dock Mic=0xf
[    2.937282] snd_hda_codec_idt hdaudioC0D0:      Internal Mic=0x11
[    2.937285] snd_hda_codec_idt hdaudioC0D0:      Headset Mic=0xa
[    2.937983] random: fast init done
[    2.938929] end plist test
[    2.940007] microcode: sig=0x306a9, pf=0x10, revision=0x20
[    2.940267] microcode: Microcode Update Driver: v2.2.
[    2.940370] sched_clock: Marking stable (2938446773, 1792880)->(2957124626, -16884973)
[    2.941452] registered taskstats version 1
[    2.941501] Loading compiled-in X.509 certificates
[    2.946421] Loaded X.509 cert 'Magrathea: Glacier signing key: bb72777f81e5af93500bb2beebab944a32df62b5'
[    2.946557] zswap: loaded using pool lzo/zbud
[    2.968266] input: HDA Intel PCH Dock Mic as /devices/pci0000:00/0000:00:1b.0/sound/card0/input8
[    2.968545] input: HDA Intel PCH Headset Mic as /devices/pci0000:00/0000:00:1b.0/sound/card0/input9
[    2.968913] input: HDA Intel PCH Dock Line Out as /devices/pci0000:00/0000:00:1b.0/sound/card0/input10
[    2.969197] input: HDA Intel PCH Headphone as /devices/pci0000:00/0000:00:1b.0/sound/card0/input11
[    2.969764] Key type big_key registered
[    2.977941] Key type encrypted registered
[    2.980754] printk: console [netcon0] enabled
[    2.980759] netconsole: network logging started
[    2.980866] rtc_cmos 00:01: setting system clock to 2018-10-19 14:01:35 UTC (1539957695)
[    2.981448] cfg80211: Loading compiled-in X.509 certificates for regulatory database
[    2.986344] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
[    2.986880] platform regulatory.0: Direct firmware load for regulatory.db failed with error -2
[    2.986921] cfg80211: failed to load regulatory.db
[    2.987054] ALSA device list:
[    2.987060]   #0: HDA Intel PCH at 0xf7730000 irq 29
[    3.154776] usb 1-1: new high-speed USB device number 2 using ehci-pci
[    3.162733] usb 2-1: new high-speed USB device number 2 using ehci-pci
[    3.172264] usb 4-4: new SuperSpeed Gen 1 USB device number 2 using xhci_hcd
[    3.183842] snd_hda_codec_generic hdaudioC1D0: autoconfig for Generic: line_outs=0 (0x0/0x0/0x0/0x0/0x0) type:line
[    3.183865] snd_hda_codec_generic hdaudioC1D0:    speaker_outs=0 (0x0/0x0/0x0/0x0/0x0)
[    3.183882] snd_hda_codec_generic hdaudioC1D0:    hp_outs=0 (0x0/0x0/0x0/0x0/0x0)
[    3.183899] snd_hda_codec_generic hdaudioC1D0:    mono: mono_out=0x0
[    3.183921] snd_hda_codec_generic hdaudioC1D0:    dig-out=0x5/0x0
[    3.183945] snd_hda_codec_generic hdaudioC1D0:    inputs:
[    3.185792] usb 4-4: New USB device found, idVendor=413c, idProduct=5534, bcdDevice=41.00
[    3.185824] usb 4-4: New USB device strings: Mfr=2, Product=3, SerialNumber=0
[    3.185832] usb 4-4: Product: USB5534
[    3.185840] usb 4-4: Manufacturer: SMSC
[    3.188714] hub 4-4:1.0: USB hub found
[    3.189352] hub 4-4:1.0: 3 ports detected
[    3.200013] ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[    3.201796] ata2.00: ATAPI: MATSHITA DVD+/-RW UJ8C2, 1.02, max UDMA/133
[    3.204440] ata2.00: configured for UDMA/133
[    3.210037] scsi 1:0:0:0: CD-ROM            MATSHITA DVD+-RW UJ8C2    1.02 PQ: 0 ANSI: 5
[    3.221864] snd_hda_codec_generic hdaudioC1D1: autoconfig for Generic: line_outs=0 (0x0/0x0/0x0/0x0/0x0) type:line
[    3.221886] snd_hda_codec_generic hdaudioC1D1:    speaker_outs=0 (0x0/0x0/0x0/0x0/0x0)
[    3.221901] snd_hda_codec_generic hdaudioC1D1:    hp_outs=0 (0x0/0x0/0x0/0x0/0x0)
[    3.221916] snd_hda_codec_generic hdaudioC1D1:    mono: mono_out=0x0
[    3.221930] snd_hda_codec_generic hdaudioC1D1:    dig-out=0x5/0x0
[    3.221946] snd_hda_codec_generic hdaudioC1D1:    inputs:
[    3.255312] sr 1:0:0:0: [sr0] scsi3-mmc drive: 24x/24x writer dvd-ram cd/rw xa/form2 cdda tray
[    3.255343] cdrom: Uniform CD-ROM driver Revision: 3.20
[    3.257591] sr 1:0:0:0: Attached scsi CD-ROM sr0
[    3.259740] snd_hda_codec_generic hdaudioC1D2: autoconfig for Generic: line_outs=0 (0x0/0x0/0x0/0x0/0x0) type:line
[    3.259755] snd_hda_codec_generic hdaudioC1D2:    speaker_outs=0 (0x0/0x0/0x0/0x0/0x0)
[    3.259763] snd_hda_codec_generic hdaudioC1D2:    hp_outs=0 (0x0/0x0/0x0/0x0/0x0)
[    3.259771] snd_hda_codec_generic hdaudioC1D2:    mono: mono_out=0x0
[    3.259780] snd_hda_codec_generic hdaudioC1D2:    dig-out=0x5/0x0
[    3.259790] snd_hda_codec_generic hdaudioC1D2:    inputs:
[    3.283726] usb 1-1: New USB device found, idVendor=8087, idProduct=0024, bcdDevice= 0.00
[    3.283749] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    3.285887] hub 1-1:1.0: USB hub found
[    3.286163] hub 1-1:1.0: 6 ports detected
[    3.291057] usb 2-1: New USB device found, idVendor=8087, idProduct=0024, bcdDevice= 0.00
[    3.291065] usb 2-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    3.291990] hub 2-1:1.0: USB hub found
[    3.292248] hub 2-1:1.0: 8 ports detected
[    3.297687] snd_hda_codec_generic hdaudioC1D3: autoconfig for Generic: line_outs=0 (0x0/0x0/0x0/0x0/0x0) type:line
[    3.297701] snd_hda_codec_generic hdaudioC1D3:    speaker_outs=0 (0x0/0x0/0x0/0x0/0x0)
[    3.297713] snd_hda_codec_generic hdaudioC1D3:    hp_outs=0 (0x0/0x0/0x0/0x0/0x0)
[    3.297723] snd_hda_codec_generic hdaudioC1D3:    mono: mono_out=0x0
[    3.297733] snd_hda_codec_generic hdaudioC1D3:    dig-out=0x5/0x0
[    3.297743] snd_hda_codec_generic hdaudioC1D3:    inputs:
[    3.298653] usb 3-1: new low-speed USB device number 2 using xhci_hcd
[    3.333463] input: HDA NVidia HDMI as /devices/pci0000:00/0000:00:01.0/0000:01:00.1/sound/card1/input12
[    3.334126] input: HDA NVidia HDMI as /devices/pci0000:00/0000:00:01.0/0000:01:00.1/sound/card1/input13
[    3.334764] input: HDA NVidia HDMI as /devices/pci0000:00/0000:00:01.0/0000:01:00.1/sound/card1/input14
[    3.335346] input: HDA NVidia HDMI as /devices/pci0000:00/0000:00:01.0/0000:01:00.1/sound/card1/input15
[    3.336779] tsc: Refined TSC clocksource calibration: 2691.256 MHz
[    3.336815] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x26caf9f5a53, max_idle_ns: 440795206420 ns
[    3.337011] clocksource: Switched to clocksource tsc
[    3.441596] usb 3-1: New USB device found, idVendor=045e, idProduct=0023, bcdDevice= 1.21
[    3.441669] usb 3-1: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[    3.441679] usb 3-1: Product: Microsoft Trackball Optical®
[    3.441687] usb 3-1: Manufacturer: Microsoft
[    3.454548] input: Microsoft Microsoft Trackball Optical® as /devices/pci0000:00/0000:00:14.0/usb3/3-1/3-1:1.0/0003:045E:0023.0001/input/input16
[    3.455854] hid-generic 0003:045E:0023.0001: input,hidraw0: USB HID v1.00 Mouse [Microsoft Microsoft Trackball Optical®] on usb-0000:00:14.0-1/input0
[    3.466643] input: PS/2 Generic Mouse as /devices/platform/i8042/serio1/input/input7
[    3.567983] ata5: SATA link down (SStatus 0 SControl 300)
[    3.568709] usb 2-1.7: new high-speed USB device number 3 using ehci-pci
[    3.570679] usb 3-4: new high-speed USB device number 3 using xhci_hcd
[    3.647356] usb 2-1.7: New USB device found, idVendor=413c, idProduct=2513, bcdDevice=a0.05
[    3.647372] usb 2-1.7: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[    3.648557] hub 2-1.7:1.0: USB hub found
[    3.648899] hub 2-1.7:1.0: 3 ports detected
[    3.698323] usb 3-4: New USB device found, idVendor=413c, idProduct=2134, bcdDevice=41.00
[    3.698335] usb 3-4: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[    3.698343] usb 3-4: Product: USB2134
[    3.698351] usb 3-4: Manufacturer: SMSC
[    3.699809] hub 3-4:1.0: USB hub found
[    3.699913] hub 3-4:1.0: 3 ports detected
[    3.714700] usb 2-1.8: new full-speed USB device number 4 using ehci-pci
[    3.816333] usb 2-1.8: New USB device found, idVendor=0a5c, idProduct=5801, bcdDevice= 1.01
[    3.816347] usb 2-1.8: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[    3.816355] usb 2-1.8: Product: 5880
[    3.816364] usb 2-1.8: Manufacturer: Broadcom Corp
[    3.816372] usb 2-1.8: SerialNumber: 0123456789ABCD
[    3.817239] usb 2-1.8: config 0 descriptor??
[    3.880427] ata6: SATA link down (SStatus 0 SControl 300)
[    3.892097] Freeing unused kernel image memory: 3680K
[    3.893840] Write protecting the kernel read-only data: 24576k
[    3.895534] Freeing unused kernel image memory: 2016K
[    3.896452] Freeing unused kernel image memory: 1588K
[    3.896952] x86/mm: Checked W+X mappings: passed, no W+X pages found.
[    3.896955] x86/mm: Checking user space page tables
[    3.897018] x86/mm: Checked W+X mappings: passed, no W+X pages found.
[    3.897020] Run /init as init process
[    3.897567] _warn_unseeded_randomness: 12 callbacks suppressed
[    3.897578] random: get_random_bytes called from create_elf_tables+0xd1/0x9e0 with crng_init=1
[    3.973093] systemd[1]: systemd 239 running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=hybrid)
[    3.984945] systemd[1]: Detected architecture x86-64.
[    3.984956] systemd[1]: Running in initial RAM disk.
[    3.988645] usb 3-4.1: new low-speed USB device number 4 using xhci_hcd
[    3.992564] systemd[1]: Set hostname to <turing-police.cc.vt.edu>.
[    4.081566] input: PS/2 Generic Mouse as /devices/platform/i8042/serio1/input/input18
[    4.084418] usb 3-4.1: New USB device found, idVendor=0e8f, idProduct=0020, bcdDevice= 2.80
[    4.084440] usb 3-4.1: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[    4.084451] usb 3-4.1: Product: PS2toUSB Adapter
[    4.084462] usb 3-4.1: Manufacturer: GASIA
[    4.093887] input: GASIA PS2toUSB Adapter as /devices/pci0000:00/0000:00:14.0/usb3/3-4/3-4.1/3-4.1:1.0/0003:0E8F:0020.0002/input/input19
[    4.147871] hid-generic 0003:0E8F:0020.0002: input,hidraw1: USB HID v1.10 Keyboard [GASIA PS2toUSB Adapter] on usb-0000:00:14.0-4.1/input0
[    4.153269] input: GASIA PS2toUSB Adapter Mouse as /devices/pci0000:00/0000:00:14.0/usb3/3-4/3-4.1/3-4.1:1.1/0003:0E8F:0020.0003/input/input20
[    4.153942] input: GASIA PS2toUSB Adapter System Control as /devices/pci0000:00/0000:00:14.0/usb3/3-4/3-4.1/3-4.1:1.1/0003:0E8F:0020.0003/input/input21
[    4.165872] random: systemd: uninitialized urandom read (16 bytes read)
[    4.166315] systemd[1]: Listening on Journal Socket.
[    4.166434] random: systemd: uninitialized urandom read (16 bytes read)
[    4.166450] systemd[1]: Reached target Swap.
[    4.166486] random: systemd: uninitialized urandom read (16 bytes read)
[    4.166671] systemd[1]: Listening on udev Kernel Socket.
[    4.167001] systemd[1]: Listening on udev Control Socket.
[    4.173342] systemd[1]: Starting Apply Kernel Variables...
[    4.174204] systemd[1]: Listening on Journal Audit Socket.
[    4.177208] random: get_random_bytes called from key_alloc+0x261/0x480 with crng_init=1
[    4.179580] random: get_random_bytes called from create_elf_tables+0xd1/0x9e0 with crng_init=1
[    4.214314] input: GASIA PS2toUSB Adapter Consumer Control as /devices/pci0000:00/0000:00:14.0/usb3/3-4/3-4.1/3-4.1:1.1/0003:0E8F:0020.0003/input/input22
[    4.214951] hid-generic 0003:0E8F:0020.0003: input,hidraw2: USB HID v1.10 Mouse [GASIA PS2toUSB Adapter] on usb-0000:00:14.0-4.1/input1
[    4.252545] audit: type=1130 audit(1539957696.770:2): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=systemd-tmpfiles-setup-dev comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[    4.352372] audit: type=1130 audit(1539957696.870:3): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=systemd-vconsole-setup comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[    4.352417] audit: type=1131 audit(1539957696.870:4): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=systemd-vconsole-setup comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[    4.466994] audit: type=1130 audit(1539957696.985:5): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=systemd-journald comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[    4.873193] audit: type=1130 audit(1539957697.391:6): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=dracut-cmdline comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[    4.910667] audit: type=1130 audit(1539957697.429:7): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=systemd-udevd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[    4.921454] _warn_unseeded_randomness: 11 callbacks suppressed
[    4.921462] random: get_random_bytes called from key_alloc+0x261/0x480 with crng_init=1
[    4.923808] random: get_random_bytes called from create_elf_tables+0xd1/0x9e0 with crng_init=1
[    4.998200] random: get_random_bytes called from key_alloc+0x261/0x480 with crng_init=1
[    5.361765] audit: type=1130 audit(1539957697.880:8): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=systemd-udev-trigger comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[    5.427646] audit: type=1130 audit(1539957697.945:9): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=plymouth-start comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[    5.497621] e1000e 0000:00:19.0 eno1: renamed from eth0
[    6.142415] _warn_unseeded_randomness: 7 callbacks suppressed
[    6.142423] random: get_random_bytes called from key_alloc+0x261/0x480 with crng_init=1
[    6.144353] random: get_random_bytes called from create_elf_tables+0xd1/0x9e0 with crng_init=1
[    6.172968] random: get_random_bytes called from key_alloc+0x261/0x480 with crng_init=1
[    6.177829] audit: type=1130 audit(1539957698.696:10): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=systemd-ask-password-plymouth comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[    6.323550] audit: type=1130 audit(1539957698.841:11): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=systemd-vconsole-setup comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[    6.323573] audit: type=1131 audit(1539957698.841:12): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=systemd-vconsole-setup comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[    9.620451] random: crng init done
[    9.620491] random: 3 get_random_xx warning(s) missed due to ratelimiting
[    9.620497] random: 7 urandom warning(s) missed due to ratelimiting
[   17.294623] audit: type=1130 audit(1539957709.812:13): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=systemd-cryptsetup@luks\x2d665bb147\x2d9e39\x2d4003\x2db3ae\x2d7be925f51a97 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[   18.310262] audit: type=1130 audit(1539957710.828:14): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=dracut-initqueue comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[   18.439865] audit: type=1130 audit(1539957710.958:15): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=systemd-fsck-root comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[   18.491117] EXT4-fs (dm-3): mounted filesystem with ordered data mode. Opts: (null)
[   18.812684] audit: type=1130 audit(1539957711.330:16): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=initrd-parse-etc comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[   18.812835] audit: type=1131 audit(1539957711.331:17): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=initrd-parse-etc comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[   19.010976] audit: type=1130 audit(1539957711.529:18): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=systemd-fsck@dev-mapper-turing\x2d\x2dpolice\x2d00 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[   19.041197] EXT4-fs (dm-1): mounted filesystem with ordered data mode. Opts: (null)
[   19.092825] audit: type=1130 audit(1539957711.611:19): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=dracut-cmdline comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[   19.092983] audit: type=1131 audit(1539957711.611:20): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=dracut-cmdline comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[   19.099864] audit: type=1130 audit(1539957711.618:21): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=dracut-initqueue comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[   19.099888] audit: type=1131 audit(1539957711.618:22): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=dracut-initqueue comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[   19.335138] systemd-journald[238]: Received SIGTERM from PID 1 (systemd).
[   19.446220] printk: systemd: 16 output lines suppressed due to ratelimiting
[   20.125159] SELinux:  Class xdp_socket not defined in policy.
[   20.125182] SELinux: the above unknown classes and permissions will be denied
[   20.125211] SELinux:  policy capability network_peer_controls=1
[   20.125214] SELinux:  policy capability open_perms=1
[   20.125216] SELinux:  policy capability extended_socket_class=1
[   20.125218] SELinux:  policy capability always_check_network=0
[   20.125220] SELinux:  policy capability cgroup_seclabel=1
[   20.125222] SELinux:  policy capability nnp_nosuid_transition=1
[   20.178695] SELinux:  Context unconfined_u:object_r:etc_t:s0 is not valid (left unmapped).
[   20.213990] systemd[1]: Successfully loaded SELinux policy in 299.965ms.
[   20.343167] systemd[1]: Relabelled /dev, /run and /sys/fs/cgroup in 52.448ms.
[   20.353859] systemd[1]: systemd 239 running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=hybrid)
[   20.367005] systemd[1]: Detected architecture x86-64.
[   20.372240] systemd[1]: Set hostname to <turing-police.cc.vt.edu>.
[   20.444199] SELinux:  Context unconfined_u:object_r:default_t:s0 is not valid (left unmapped).
[   21.216349] systemd[1]: Stopped Switch Root.
[   21.217202] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart.
[   21.217256] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1.
[   21.217325] systemd[1]: Stopped Journal Service.
[   21.221802] systemd[1]: Starting Journal Service...
[   21.232387] systemd[1]: Listening on LVM2 poll daemon socket.
[   21.238978] systemd[1]: Listening on LVM2 metadata daemon socket.
[   21.301767] Adding 4079612k swap on /dev/mapper/turing--police-swap.  Priority:-2 extents:1 across:4079612k FS
[   21.388446] EXT4-fs (dm-1): re-mounted. Opts: (null)
[   21.396950] EXT4-fs (dm-3): re-mounted. Opts: (null)
[   21.996389] EXT4-fs (sda2): mounted filesystem with ordered data mode. Opts: (null)
[   22.156899] FAT-fs (sda1): Volume was not properly unmounted. Some data may be corrupt. Please run fsck.
[   22.508322] bcma-pci-bridge 0000:03:00.0: enabling device (0100 -> 0102)
[   22.510902] bcma: bus0: Found chip with id 0x4313, rev 0x01 and package 0x08
[   22.510946] bcma: bus0: Core 0 found: ChipCommon (manuf 0x4BF, id 0x800, rev 0x24, class 0x0)
[   22.510981] bcma: bus0: Core 1 found: IEEE 802.11 (manuf 0x4BF, id 0x812, rev 0x18, class 0x0)
[   22.511046] bcma: bus0: Core 2 found: PCIe (manuf 0x4BF, id 0x820, rev 0x11, class 0x0)
[   22.532872] bcma: bus0: Bus registered
[   22.582835] e1000e 0000:00:19.0 eth0: renamed from eno1
[   22.734308] kauditd_printk_skb: 55 callbacks suppressed
[   22.734312] audit: type=1400 audit(1539957715.252:67): avc:  denied  { execute_no_trans } for  pid=842 comm="(spawn)" path="/usr/lib/virtualbox/VBoxCreateUSBNode.sh" dev="dm-1" ino=1748 scontext=system_u:system_r:udev_t:s0-s15:c0.c1023 tcontext=system_u:object_r:textrel_shlib_t:s0 tclass=file permissive=1
[   22.737040] audit: type=1400 audit(1539957715.255:68): avc:  denied  { search } for  pid=790 comm="systemd-udevd" name="/" dev="efivarfs" ino=10399 scontext=system_u:system_r:udev_t:s0-s15:c0.c1023 tcontext=system_u:object_r:efivarfs_t:s0 tclass=dir permissive=1
[   22.737367] audit: type=1300 audit(1539957715.255:68): arch=c000003e syscall=257 success=no exit=-2 a0=ffffff9c a1=55696d5e8530 a2=80100 a3=0 items=0 ppid=784 pid=790 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="systemd-udevd" exe="/usr/lib/systemd/systemd-udevd" subj=system_u:system_r:udev_t:s0-s15:c0.c1023 key=(null)
[   22.737638] audit: type=1327 audit(1539957715.255:68): proctitle="/usr/lib/systemd/systemd-udevd"
[   22.746591] audit: type=1300 audit(1539957715.252:67): arch=c000003e syscall=59 success=yes exit=0 a0=7ffe2c867fa0 a1=7ffe2c867ba0 a2=55696d5a9c10 a3=8 items=0 ppid=800 pid=842 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="VBoxCreateUSBNo" exe="/usr/bin/bash" subj=system_u:system_r:udev_t:s0-s15:c0.c1023 key=(null)
[   22.751829] audit: type=1327 audit(1539957715.252:67): proctitle=2F62696E2F7368002F7573722F6C69622F7669727475616C626F782F56426F784372656174655553424E6F64652E7368003138390030003039
[   22.854935] cryptd: max_cpu_qlen set to 1000
[   22.888986] input: Dell WMI hotkeys as /devices/platform/PNP0C14:00/wmi_bus/wmi_bus-PNP0C14:00/9DBB5994-A997-11DA-B012-B622A1EF5492/input/input23
[   23.269914] audit: type=1400 audit(1539957715.785:69): avc:  denied  { execute_no_trans } for  pid=899 comm="(spawn)" path="/usr/lib/virtualbox/VBoxCreateUSBNode.sh" dev="dm-1" ino=1748 scontext=system_u:system_r:udev_t:s0-s15:c0.c1023 tcontext=system_u:object_r:textrel_shlib_t:s0 tclass=file permissive=1
[   23.272750] audit: type=1300 audit(1539957715.785:69): arch=c000003e syscall=59 success=yes exit=0 a0=7ffe2c868060 a1=7ffe2c867c60 a2=55696d5b6830 a3=8 items=0 ppid=788 pid=899 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="VBoxCreateUSBNo" exe="/usr/bin/bash" subj=system_u:system_r:udev_t:s0-s15:c0.c1023 key=(null)
[   23.272832] audit: type=1327 audit(1539957715.785:69): proctitle=2F62696E2F7368002F7573722F6C69622F7669727475616C626F782F56426F784372656174655553424E6F64652E73680031383900333835003039
[   23.279855] dell_laptop: Using dell-rbtn acpi driver for receiving events
[   23.402242] audit: type=1130 audit(1539957715.920:70): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0-s15:c0.c1023 msg='unit=lvm2-lvmetad comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[   23.456203] brcmsmac bcma0:1: mfg 4bf core 812 rev 24 class 0 irq 17
[   23.459893] ieee80211 phy0: Selected rate control algorithm 'minstrel_ht'
[   25.034192] EXT4-fs (dm-11): mounted filesystem with ordered data mode. Opts: (null)
[   25.178789] EXT4-fs (dm-5): mounted filesystem with ordered data mode. Opts: (null)
[   25.269434] EXT4-fs (dm-6): mounted filesystem with ordered data mode. Opts: (null)
[   25.293041] EXT4-fs (dm-9): mounted filesystem with ordered data mode. Opts: (null)
[   25.365755] EXT4-fs (dm-8): mounted filesystem with ordered data mode. Opts: (null)
[   25.391504] EXT4-fs (dm-4): mounted filesystem with ordered data mode. Opts: (null)
[   25.425652] EXT4-fs (dm-12): mounted filesystem with ordered data mode. Opts: (null)
[   25.465811] EXT4-fs (dm-10): mounted filesystem with ordered data mode. Opts: (null)
[   25.536588] systemd-journald[765]: Received request to flush runtime journal from PID 1
[   25.622039] EXT4-fs (dm-7): mounted filesystem with ordered data mode. Opts: (null)
[   30.728066] kauditd_printk_skb: 31 callbacks suppressed
[   30.728071] audit: type=1131 audit(1539957723.246:100): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0-s15:c0.c1023 msg='unit=systemd-rfkill comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[  106.465848] audit: type=1130 audit(1539957798.984:101): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0-s15:c0.c1023 msg='unit=run-r93ac4731e4724fd6a3670e7d0c417522 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[  106.564711] dennis: q ffff9e3c57152000 != rl->q ffff9e3a8fe48040
[  106.564713] dennis: bio: ffff9e3a8fcf5400, root: ffffffffbbdd89e0
[  106.564761] BUG: unable to handle kernel NULL pointer dereference at 0000000000000000
[  106.568786] PGD 0 P4D 0 
[  106.570761] Oops: 0000 [#1] PREEMPT SMP PTI
[  106.573115] CPU: 2 PID: 1205 Comm: sh Tainted: G                T 4.19.0-rc8-next-20181016-dirty #639
[  106.575617] Hardware name: Dell Inc. Latitude E6530/07Y85M, BIOS A21 02/21/2018
[  106.578184] RIP: 0010:__get_request+0x31/0x7e0
[  106.580389] Code: 89 e5 41 57 41 56 41 55 49 89 fd 41 54 41 89 f4 53 48 83 ec 50 48 8b 1f 48 85 d2 48 89 55 b8 89 4d c0 44 89 45 c4 48 8b 43 18 <48> 8b 00 48 89 45 b0 0f 84 ba 03 00 00 48 8b 42 58 48 85 c0 48 89
[  106.582244] RSP: 0018:ffffbb0081f0f570 EFLAGS: 00010086
[  106.584014] RAX: 0000000000000000 RBX: ffff9e3a8fe48040 RCX: 0000000000000000
[  106.585775] RDX: ffff9e3c54b0ba00 RSI: 0000000000080000 RDI: ffff9e3c5a427840
[  106.587520] RBP: ffffbb0081f0f5e8 R08: 0000000000600000 R09: 0000000000000001
[  106.589271] R10: 0000000000000001 R11: 0000000000000000 R12: 0000000000080000
[  106.591026] R13: ffff9e3c5a427840 R14: 0000000000000001 R15: ffff9e3c54b0ba00
[  106.592775] FS:  00007fa7d28f2740(0000) GS:ffff9e3c5d800000(0000) knlGS:0000000000000000
[  106.594531] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  106.596289] CR2: 0000000000000000 CR3: 000000041b34a001 CR4: 00000000001606e0
[  106.598056] Call Trace:
[  106.599813]  ? printk+0x59/0x75
[  106.601566]  get_request+0x40a/0xb70
[  106.603331]  ? remove_wait_queue+0x70/0x70
[  106.605091]  blk_queue_bio+0x23b/0x760
[  106.606844]  generic_make_request+0x2fe/0x570
[  106.608591]  submit_bio+0x4d/0x190
[  106.610335]  ? submit_bio+0x4d/0x190
[  106.612077]  ? bio_add_page+0x4b/0x60
[  106.613813]  ext4_mpage_readpages+0x814/0xed4
[  106.615540]  ext4_readpages+0x55/0x60
[  106.617270]  read_pages+0x72/0x190
[  106.618987]  __do_page_cache_readahead+0x1f6/0x220
[  106.620709]  ondemand_readahead+0x2ae/0x4f0
[  106.622425]  page_cache_sync_readahead+0x112/0x250
[  106.624149]  generic_file_buffered_read+0x542/0xf70
[  106.625875]  ? mark_held_locks+0x52/0x80
[  106.627605]  generic_file_read_iter+0xd0/0x140
[  106.629335]  ext4_file_read_iter+0x6c/0x80
[  106.631073]  new_sync_read+0x121/0x1a0
[  106.632858]  __vfs_read+0x49/0x60
[  106.634563]  vfs_read+0x152/0x250
[  106.636254]  kernel_read+0x43/0x60
[  106.637928]  prepare_binprm+0x19b/0x1f0
[  106.639570]  __do_execve_file+0x5ca/0xbc0
[  106.641200]  __x64_sys_execve+0x38/0x50
[  106.642808]  do_syscall_64+0x8f/0xa52
[  106.644376]  ? trace_hardirqs_off_thunk+0x1a/0x1c
[  106.645928]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
[  106.647439] RIP: 0033:0x7fa7d29beb5b
[  106.648934] Code: 41 89 01 eb da 66 2e 0f 1f 84 00 00 00 00 00 f7 d8 64 41 89 01 eb d6 0f 1f 84 00 00 00 00 00 f3 0f 1e fa b8 3b 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d fd 62 0f 00 f7 d8 64 89 01 48
[  106.650516] RSP: 002b:00007ffdb151b488 EFLAGS: 00000246 ORIG_RAX: 000000000000003b
[  106.652086] RAX: ffffffffffffffda RBX: 000056104981a570 RCX: 00007fa7d29beb5b
[  106.653633] RDX: 0000561049818140 RSI: 000056104981a180 RDI: 000056104981a570
[  106.655149] RBP: 0000000000000000 R08: 00007fa7d2aba710 R09: 0000000000000000
[  106.656681] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000008
[  106.658197] R13: 000056104981a180 R14: 0000561049818140 R15: 0000000000000000
[  106.659724] Modules linked in: brcmsmac cordic brcmutil x86_pkg_temp_thermal dell_laptop crct10dif_pclmul dell_smm_hwmon crc32_pclmul crc32c_intel dell_wmi ghash_clmulni_intel cryptd dell_smbios dell_wmi_descriptor bcma dell_smo8800 dell_rbtn mei_wdt vfat fat
[  106.662984] CR2: 0000000000000000
[  106.664598] ---[ end trace e53d8917bc40055f ]---

[-- Attachment #2: Type: application/pgp-signature, Size: 486 bytes --]

Re: [BUG] ext4/block null pointer crashes in linux-next

[Dennis Zhou]

On Fri, Oct 19, 2018 at 11:52:36AM -0400, valdis.kletnieks@vt.edu wrote:
> On Wed, 17 Oct 2018 17:20:29 -0400, Dennis Zhou said:
> >
> > I apologize, but I'm having a hard time reproducing this myself. I am
> > not able to hit this issue in my qemu instance with linux-next built
> > with your config. I have been running 'rpm -Hvh --force fio.rpm' several
> > times and haven't seen the issue.
> 
> I wouldn't be surprised if there's something oddball in my system config
> that changes the situation.
> 

Do you by chance run any encryption or anything on top of your hard
drive or ssd?

> > Would it be possible for you to create a minimal qemu image that
> > reproduces the issue as I'm having issues reproducing it with my setup?
> 
> Hmm.. I'd first have to figure out how to build a qemu image at all..
> 
> > Additionally, I've added some more debug text in the diff below. If you
> > could apply that and send me the full dmesg that would be great. Lastly,
> > can you just confirm for me that the commit before, f0fcb3ec89f3
> > "blkcg: remove additional reference to the css", isn't seeing this
> > issue?
> 
> Full dmesg attached.  Had to piece it together from a 'dmesg' and what
> got saved in pstore when it crashed.  I was surprised that the printk_once
> popped during very early boot (2.88 seconds in), and then only 2 lines of output
> right before the crash:
> 
> [  106.465848] audit: type=1130 audit(1539957798.984:101): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:syst
> em_r:init_t:s0-s15:c0.c1023 msg='unit=run-r93ac4731e4724fd6a3670e7d0c417522 comm="systemd" exe="/usr/lib/systemd/systemd
> " hostname=? addr=? terminal=? res=success'
> [  106.564711] dennis: q ffff9e3c57152000 != rl->q ffff9e3a8fe48040
> [  106.564713] dennis: bio: ffff9e3a8fcf5400, root: ffffffffbbdd89e0
> [  106.564761] BUG: unable to handle kernel NULL pointer dereference at 0000000000000000
> [  106.568786] PGD 0 P4D 0
> [  106.570761] Oops: 0000 [#1] PREEMPT SMP PTI
> [  106.573115] CPU: 2 PID: 1205 Comm: sh Tainted: G                T 4.19.0-rc8-next-20181016-dirty #639
> 
> I'll cook up a kernel checked out at that commit and test later today...

I thought of another issue that may explain what's going on. It has to
do with how a bio can go through make_request() several times. However,
I do association on the first entry, but subsequent requests may go to
separate queues. Therefore association and the blk_get_rl() returns the
wrong request_list. It may be that a particular blkg doesn't have a
fully initialized request_list.

I've currently only been testing on a drive directly, but my try with md
still worked.. So I am still trying other ways to reproduce it.

Thanks for being patient with me. Would you be able to try the following
on Jens' for-4.20/block branch? His tree is available here:
https://git.kernel.org/pub/scm/linux/kernel/git/axboe/linux-block.git

Thanks,
Dennis

---
 block/bio.c         | 20 ++++++++++++++++++++
 block/blk-core.c    |  1 +
 include/linux/bio.h |  3 +++
 3 files changed, 24 insertions(+)

diff --git a/block/bio.c b/block/bio.c
index 17a8b0aa7050..bbfeb4ee2892 100644
--- a/block/bio.c
+++ b/block/bio.c
@@ -2083,6 +2083,26 @@ int bio_associate_create_blkg(struct request_queue *q, struct bio *bio)
 	return ret;
 }
 
+/**
+ * bio_reassociate_blkg - reassociate a bio with a blkg from q
+ * @q: request_queue where bio is going
+ * @bio: target bio
+ *
+ * When submitting a bio, multiple recursive calls to make_request() may occur.
+ * This causes the initial associate done in blkcg_bio_issue_check() to be
+ * incorrect and reference the prior request_queue.  This performs reassociation
+ * when this situation happens.
+ */
+int bio_reassociate_blkg(struct request_queue *q, struct bio *bio)
+{
+	if (bio->bi_blkg) {
+		blkg_put(bio->bi_blkg);
+		bio->bi_blkg = NULL;
+	}
+
+	return bio_associate_create_blkg(q, bio);
+}
+
 /**
  * bio_disassociate_task - undo bio_associate_current()
  * @bio: target bio
diff --git a/block/blk-core.c b/block/blk-core.c
index cdfabc5646da..3ed60723e242 100644
--- a/block/blk-core.c
+++ b/block/blk-core.c
@@ -2433,6 +2433,7 @@ blk_qc_t generic_make_request(struct bio *bio)
 			if (q)
 				blk_queue_exit(q);
 			q = bio->bi_disk->queue;
+			bio_reassociate_blkg(q, bio);
 			flags = 0;
 			if (bio->bi_opf & REQ_NOWAIT)
 				flags = BLK_MQ_REQ_NOWAIT;
diff --git a/include/linux/bio.h b/include/linux/bio.h
index f447b0ebb288..b47c7f716731 100644
--- a/include/linux/bio.h
+++ b/include/linux/bio.h
@@ -514,6 +514,7 @@ int bio_associate_blkg(struct bio *bio, struct blkcg_gq *blkg);
 int bio_associate_blkg_from_css(struct bio *bio,
 				struct cgroup_subsys_state *css);
 int bio_associate_create_blkg(struct request_queue *q, struct bio *bio);
+int bio_reassociate_blkg(struct request_queue *q, struct bio *bio);
 void bio_disassociate_task(struct bio *bio);
 void bio_clone_blkg_association(struct bio *dst, struct bio *src);
 #else	/* CONFIG_BLK_CGROUP */
@@ -522,6 +523,8 @@ static inline int bio_associate_blkg_from_css(struct bio *bio,
 { return 0; }
 static inline int bio_associate_create_blkg(struct request_queue *q,
 					    struct bio *bio) { return 0; }
+static inline int bio_reassociate_blkg(struct request_queue *q, struct bio *bio)
+{ return 0; }
 static inline void bio_disassociate_task(struct bio *bio) { }
 static inline void bio_clone_blkg_association(struct bio *dst,
 					      struct bio *src) { }
-- 
2.17.1

Re: [BUG] ext4/block null pointer crashes in linux-next

[valdis.kletnieks]

[-- Attachment #1: Type: text/plain, Size: 5055 bytes --]

On Fri, 19 Oct 2018 18:21:00 -0400, Dennis Zhou said:

> Do you by chance run any encryption or anything on top of your hard
> drive or ssd?

ext4 on an LVM LV that's part of a PV that's inside a cryptLUKS partition on a hard drive..

So lots of nested levels there.

> I thought of another issue that may explain what's going on. It has to
> do with how a bio can go through make_request() several times. However,
> I do association on the first entry, but subsequent requests may go to
> separate queues. Therefore association and the blk_get_rl() returns the
> wrong request_list. It may be that a particular blkg doesn't have a
> fully initialized request_list.

> Thanks for being patient with me. Would you be able to try the following
> on Jens' for-4.20/block branch? His tree is available here:
> https://git.kernel.org/pub/scm/linux/kernel/git/axboe/linux-block.git

No problem.  I've managed to trip over issues that took a *lot* longer to resolve
(I think back around 2.5.47 or so, the PCMCIA slot in my Dell Latitude kept finding
different ways to explode the kernel for close to 8-9 months...)

I checked, and linux-next was all of 1 commit behind jens' for-4.20 tree, so
I applied it to that (I had a linux-next tree that works, but I'm a git idiot so
figuring out how to graft that tree on was going to take a while...)

Result:

Script started on 2018-10-19 22:29:32-04:00
[root@turing-police x86_64]# uname -a
Linux turing-police.cc.vt.edu 4.19.0-rc8-next-20181019-dirty #641 SMP PREEMPT Fri Oct 19 21:18:19 EDT 2018 x86_64 x86_64 x86_64 GNU/Linux
[root@turing-police x86_64]# rpm -Uvh --force dracut-049-4.git20181010.fc30.x86_64.rpm
Verifying...                          ################################# [100%]
warning: Unable to get systemd shutdown inhibition lock: Failed to connect to socket /run/dbus/system_bus_socket: No such file or directory
Preparing...                          ################################# [100%]
Updating / installing...
   1:dracut-049-4.git20181010.fc30    ################################# [100%]
[root@turing-police x86_64]# exit
exit

Script done on 2018-10-19 22:29:59-04:00

System stable, RPM works, dnf works, some good-sized compiles worked.

Looks like it's time to commit that, and add these:

Reported-by: Valdis Kletnieks <valdis.kletnieks@vt.edu>
Tested-by: Valdis Kletnieks <valdis.kletnieks@vt.edu>

:)

> ---
>  block/bio.c         | 20 ++++++++++++++++++++
>  block/blk-core.c    |  1 +
>  include/linux/bio.h |  3 +++
>  3 files changed, 24 insertions(+)
>
> diff --git a/block/bio.c b/block/bio.c
> index 17a8b0aa7050..bbfeb4ee2892 100644
> --- a/block/bio.c
> +++ b/block/bio.c
> @@ -2083,6 +2083,26 @@ int bio_associate_create_blkg(struct request_queue *q, struct bio *bio)
>  	return ret;
>  }
>
> +/**
> + * bio_reassociate_blkg - reassociate a bio with a blkg from q
> + * @q: request_queue where bio is going
> + * @bio: target bio
> + *
> + * When submitting a bio, multiple recursive calls to make_request() may occur.
> + * This causes the initial associate done in blkcg_bio_issue_check() to be
> + * incorrect and reference the prior request_queue.  This performs reassociation
> + * when this situation happens.
> + */
> +int bio_reassociate_blkg(struct request_queue *q, struct bio *bio)
> +{
> +	if (bio->bi_blkg) {
> +		blkg_put(bio->bi_blkg);
> +		bio->bi_blkg = NULL;
> +	}
> +
> +	return bio_associate_create_blkg(q, bio);
> +}
> +
>  /**
>   * bio_disassociate_task - undo bio_associate_current()
>   * @bio: target bio
> diff --git a/block/blk-core.c b/block/blk-core.c
> index cdfabc5646da..3ed60723e242 100644
> --- a/block/blk-core.c
> +++ b/block/blk-core.c
> @@ -2433,6 +2433,7 @@ blk_qc_t generic_make_request(struct bio *bio)
>  			if (q)
>  				blk_queue_exit(q);
>  			q = bio->bi_disk->queue;
> +			bio_reassociate_blkg(q, bio);
>  			flags = 0;
>  			if (bio->bi_opf & REQ_NOWAIT)
>  				flags = BLK_MQ_REQ_NOWAIT;
> diff --git a/include/linux/bio.h b/include/linux/bio.h
> index f447b0ebb288..b47c7f716731 100644
> --- a/include/linux/bio.h
> +++ b/include/linux/bio.h
> @@ -514,6 +514,7 @@ int bio_associate_blkg(struct bio *bio, struct blkcg_gq *blkg);
>  int bio_associate_blkg_from_css(struct bio *bio,
>  				struct cgroup_subsys_state *css);
>  int bio_associate_create_blkg(struct request_queue *q, struct bio *bio);
> +int bio_reassociate_blkg(struct request_queue *q, struct bio *bio);
>  void bio_disassociate_task(struct bio *bio);
>  void bio_clone_blkg_association(struct bio *dst, struct bio *src);
>  #else	/* CONFIG_BLK_CGROUP */
> @@ -522,6 +523,8 @@ static inline int bio_associate_blkg_from_css(struct bio *bio,
>  { return 0; }
>  static inline int bio_associate_create_blkg(struct request_queue *q,
>  					    struct bio *bio) { return 0; }
> +static inline int bio_reassociate_blkg(struct request_queue *q, struct bio *bio)
> +{ return 0; }
>  static inline void bio_disassociate_task(struct bio *bio) { }
>  static inline void bio_clone_blkg_association(struct bio *dst,
>  					      struct bio *src) { }
> --
> 2.17.1
>


[-- Attachment #2: Type: application/pgp-signature, Size: 486 bytes --]

Re: [BUG] ext4/block null pointer crashes in linux-next

[Dennis Zhou]

On Fri, Oct 19, 2018 at 10:47:19PM -0400, valdis.kletnieks@vt.edu wrote:
> On Fri, 19 Oct 2018 18:21:00 -0400, Dennis Zhou said:
> 
> > Do you by chance run any encryption or anything on top of your hard
> > drive or ssd?
> 
> ext4 on an LVM LV that's part of a PV that's inside a cryptLUKS partition on a hard drive..
> 
> So lots of nested levels there.
> 

Awesome, that explains why I wasn't able to easily reproduce the bug!

> > I thought of another issue that may explain what's going on. It has to
> > do with how a bio can go through make_request() several times. However,
> > I do association on the first entry, but subsequent requests may go to
> > separate queues. Therefore association and the blk_get_rl() returns the
> > wrong request_list. It may be that a particular blkg doesn't have a
> > fully initialized request_list.
> 
> > Thanks for being patient with me. Would you be able to try the following
> > on Jens' for-4.20/block branch? His tree is available here:
> > https://git.kernel.org/pub/scm/linux/kernel/git/axboe/linux-block.git
> 
> No problem.  I've managed to trip over issues that took a *lot* longer to resolve
> (I think back around 2.5.47 or so, the PCMCIA slot in my Dell Latitude kept finding
> different ways to explode the kernel for close to 8-9 months...)
> 
> I checked, and linux-next was all of 1 commit behind jens' for-4.20 tree, so
> I applied it to that (I had a linux-next tree that works, but I'm a git idiot so
> figuring out how to graft that tree on was going to take a while...)
> 

That's great it worked this time, but in the future it may be worth
taking the time to switch trees. As for-next carries a lot of stuff that
has limited testing, it is nice to help limit the footprint of possible
adverse interactions and to for sure determine it exists solely say
within Jens' for-4.20/block tree.

For future reference, something like the following works as a way to
keep multiple remotes in the same repo.

git remote add block https://git.kernel.org/pub/scm/linux/kernel/git/axboe/linux-block.git
git fetch
git checkout -b for-4.20/block -t block/for-4.20/block

This checks out the for-4.20/block branch from the remote block as a
local branch called for-4.20/block.

> Result:
> 
> Script started on 2018-10-19 22:29:32-04:00
> [root@turing-police x86_64]# uname -a
> Linux turing-police.cc.vt.edu 4.19.0-rc8-next-20181019-dirty #641 SMP PREEMPT Fri Oct 19 21:18:19 EDT 2018 x86_64 x86_64 x86_64 GNU/Linux
> [root@turing-police x86_64]# rpm -Uvh --force dracut-049-4.git20181010.fc30.x86_64.rpm
> Verifying...                          ################################# [100%]
> warning: Unable to get systemd shutdown inhibition lock: Failed to connect to socket /run/dbus/system_bus_socket: No such file or directory
> Preparing...                          ################################# [100%]
> Updating / installing...
>    1:dracut-049-4.git20181010.fc30    ################################# [100%]
> [root@turing-police x86_64]# exit
> exit
> 
> Script done on 2018-10-19 22:29:59-04:00
> 
> System stable, RPM works, dnf works, some good-sized compiles worked.
> 
> Looks like it's time to commit that, and add these:
> 
> Reported-by: Valdis Kletnieks <valdis.kletnieks@vt.edu>
> Tested-by: Valdis Kletnieks <valdis.kletnieks@vt.edu>
> 
> :)

Fantastic! Thanks for working with me and reporting the issue on
for-next. I'll run the series with the above tomorrow to Jens.

Thanks,
Dennis

Re: [BUG] ext4/block null pointer crashes in linux-next

[valdis.kletnieks]

[-- Attachment #1: Type: text/plain, Size: 1153 bytes --]

On Wed, 17 Oct 2018 17:20:29 -0400, Dennis Zhou said:

> could apply that and send me the full dmesg that would be great. Lastly,
> can you just confirm for me that the commit before, f0fcb3ec89f3
> "blkcg: remove additional reference to the css", isn't seeing this
> issue?

Script started on 2018-10-19 18:53:41-04:00
[root@turing-police x86_64]# uname -a
Linux turing-police.cc.vt.edu 4.19.0-rc2-00202-gf0fcb3ec89f3 #640 SMP PREEMPT Fri Oct 19 14:20:22 EDT 2018 x86_64 x86_64 x86_64 GNU/Linux
[root@turing-police x86_64]# rpm -Uvh --force dracut-049-4.git20181010.fc30.x86_64.rpm
Verifying...                          ################################# [100%]
warning: Unable to get systemd shutdown inhibition lock: Failed to connect to socket /run/dbus/system_bus_socket: No such file or directory
Preparing...                          ################################# [100%]
Updating / installing...
   1:dracut-049-4.git20181010.fc30    ################################# [100%]
[root@turing-police x86_64]# exit
exit

Script done on 2018-10-19 18:54:09-04:00

That commit comes up "good" - broken kernels die before I ever get the prompt back...

[-- Attachment #2: Type: application/pgp-signature, Size: 486 bytes --]