Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

usb issue #136

Closed
dudducat opened this issue Oct 16, 2012 · 32 comments
Closed

usb issue #136

dudducat opened this issue Oct 16, 2012 · 32 comments
Assignees

Comments

@dudducat
Copy link

My configuration:
headless PI powered up by powered usb hub (belkin F5U404PerBLK).

with a fat32 8gb pen connected to the pi everything works fine.
When I try to use an external USB disk, I lost ethernet when I start mlnet using disk to store files.
I've tested the proposed solution on elinux.org:
Changed

vm.min_free_kbytes = 32768 in /etc/sysctl.conf
smsc95xx.turbo_mode=N in /boot/cmdline.txt

Connected Y cable to router's usb to avoid power problems.
Changed cable that connects hub and mini usb in RPI.

This is the result:

root@raspberrypi:/home/pi# cat /var/log/messages | grep -i erro
Oct 14 15:09:18 raspberrypi kernel: [148561.433141] ERROR::dwc_otg_hcd_urb_enqueue:477: Not connected
Oct 14 15:09:18 raspberrypi kernel: [148561.433239] ERROR::dwc_otg_hcd_urb_enqueue:477: Not connected
Oct 14 15:09:18 raspberrypi kernel: [148561.433270] ERROR::dwc_otg_hcd_urb_enqueue:477: Not connected
Oct 14 15:09:18 raspberrypi kernel: [148561.433297] ERROR::dwc_otg_hcd_urb_enqueue:477: Not connected
Oct 14 15:09:19 raspberrypi kernel: [148562.357473] sd 1:0:0:0: [sdb] Unhandled error code
Oct 14 15:09:19 raspberrypi kernel: [148562.457463] sd 1:0:0:0: [sdb] Unhandled error code
Oct 14 15:09:19 raspberrypi kernel: [148562.457601] lost page write due to I/O error on sdb1
Oct 14 15:09:19 raspberrypi kernel: [148562.557449] sd 1:0:0:0: [sdb] Unhandled error code
Oct 14 15:09:19 raspberrypi kernel: [148562.557564] lost page write due to I/O error on sdb1
Oct 15 21:48:54 raspberrypi kernel: [ 4308.835089] ERROR::dwc_otg_hcd_urb_enqueue:477: Not connected
Oct 15 21:48:54 raspberrypi kernel: [ 4308.835501] ERROR::dwc_otg_hcd_urb_enqueue:477: Not connected
Oct 15 21:48:54 raspberrypi kernel: [ 4308.835534] ERROR::dwc_otg_hcd_urb_enqueue:477: Not connected
Oct 15 21:48:54 raspberrypi kernel: [ 4308.835563] ERROR::dwc_otg_hcd_urb_enqueue:477: Not connected
Oct 15 21:48:55 raspberrypi kernel: [ 4310.181327] EXT4-fs warning (device sdb1): ext4_end_bio:251: I/O error writing to inode 524294 (offset 80220160 size 4096 starting block 66697)
Oct 15 21:48:55 raspberrypi kernel: [ 4310.181722] JBD2: Detected IO errors while flushing file data on sdb1-8

Oct 15 21:48:54 raspberrypi kernel: [ 4308.835089] ERROR::dwc_otg_hcd_urb_enqueue:477: Not connected
Oct 15 21:48:54 raspberrypi kernel: [ 4308.835501] ERROR::dwc_otg_hcd_urb_enqueue:477: Not connected
Oct 15 21:48:54 raspberrypi kernel: [ 4308.835534] ERROR::dwc_otg_hcd_urb_enqueue:477: Not connected
Oct 15 21:48:54 raspberrypi kernel: [ 4308.835563] ERROR::dwc_otg_hcd_urb_enqueue:477: Not connected
Oct 15 21:48:55 raspberrypi kernel: [ 4310.181327] EXT4-fs warning (device sdb1): ext4_end_bio:251: I/O error writing to inode 524294 (offset 80220160 size 4096 starting block 66697)
Oct 15 21:48:55 raspberrypi kernel: [ 4310.181722] JBD2: Detected IO errors while flushing file data on sdb1-8

root@raspberrypi:/home/pi# cat /var/log/syslog | grep -i erro
Oct 15 20:37:13 raspberrypi ntpd[2033]: restrict: error in address '::' on line 38. Ignoring...
Oct 15 20:37:13 raspberrypi ntpd[2033]: restrict: error in address '::1' on line 42. Ignoring...
Oct 15 21:48:54 raspberrypi kernel: [ 4308.835089] ERROR::dwc_otg_hcd_urb_enqueue:477: Not connected
Oct 15 21:48:54 raspberrypi kernel: [ 4308.835501] ERROR::dwc_otg_hcd_urb_enqueue:477: Not connected
Oct 15 21:48:54 raspberrypi kernel: [ 4308.835534] ERROR::dwc_otg_hcd_urb_enqueue:477: Not connected
Oct 15 21:48:54 raspberrypi kernel: [ 4308.835563] ERROR::dwc_otg_hcd_urb_enqueue:477: Not connected
Oct 15 21:48:55 raspberrypi kernel: [ 4310.181289] Buffer I/O error on device sdb1, logical block 66689
Oct 15 21:48:55 raspberrypi kernel: [ 4310.181327] EXT4-fs warning (device sdb1): ext4_end_bio:251: I/O error writing to inode 524294 (offset 80220160 size 4096 starting block 66697)
Oct 15 21:48:55 raspberrypi kernel: [ 4310.181494] JBD2: I/O error detected when updating journal superblock for sdb1-8.
Oct 15 21:48:55 raspberrypi kernel: [ 4310.181722] JBD2: Detected IO errors while flushing file data on sdb1-8
Oct 15 21:48:55 raspberrypi kernel: [ 4310.181838] JBD2: I/O error detected when updating journal superblock for sdb1-8.
Oct 15 21:49:22 raspberrypi kernel: [ 4337.351179] EXT4-fs error (device sdb1): ext4_find_entry:935: inode #524289: comm mlnet: reading directory lblock 0
Oct 15 21:49:22 raspberrypi kernel: [ 4337.386202] EXT4-fs error (device sdb1): ext4_journal_start_sb:327: Detected aborted journal
Oct 15 21:49:24 raspberrypi kernel: [ 4338.946361] EXT4-fs error (device sdb1): ext4_read_block_bitmap:394: comm mlnet: Cannot read block bitmap - block_group = 2, block_bitmap = 1027
Oct 15 21:49:24 raspberrypi kernel: [ 4338.965416] EXT4-fs error (device sdb1): ext4_discard_preallocations:3892: comm mlnet: Error reading block bitmap for 2

I think that there is something wrong with the usb driver .... Am I wrong ?
Thanks a lot,
Ste

PS already posted on troubleshooting section of pi forum with no success.
http://www.raspberrypi.org/phpBB3/viewtopic.php?f=28&t=19974

@ghollingworth
Copy link

ERROR::dwc_otg_hcd_urb_enqueue:477: Not connected

What this means is that the USB device has been disconnected (in a logical
rather than physical sense), so the most likely explanation is that the
drive power has dropped out...

Not absolutely sure that is the problem, but it doesn't seem likely to be a
protocol related problem because as you say a different mass storage scsi
device works fine (the USB protocol is after all the same...)

Can you connect it through an externally powered hub (making sure you don't
use one that powers the host through the hub!)

Gordon

On 16 October 2012 09:03, dudducat notifications@github.com wrote:

My configuration:
headless PI powered up by powered usb hub (belkin F5U404PerBLK).

with a fat32 8gb pen connected to the pi everything works fine.
When I try to use an external USB disk, I lost ethernet when I start mlnet
using disk to store files.
I've tested the proposed solution on elinux.org:
Changed

vm.min_free_kbytes = 32768 in /etc/sysctl.conf
smsc95xx.turbo_mode=N in /boot/cmdline.txt

Connected Y cable to router's usb to avoid power problems.
Changed cable that connects hub and mini usb in RPI.

This is the result:

root@raspberrypi:/home/pi# cat /var/log/messages | grep -i erro
Oct 14 15:09:18 raspberrypi kernel: [148561.433141]
ERROR::dwc_otg_hcd_urb_enqueue:477: Not connected
Oct 14 15:09:18 raspberrypi kernel: [148561.433239]
ERROR::dwc_otg_hcd_urb_enqueue:477: Not connected
Oct 14 15:09:18 raspberrypi kernel: [148561.433270]
ERROR::dwc_otg_hcd_urb_enqueue:477: Not connected
Oct 14 15:09:18 raspberrypi kernel: [148561.433297]
ERROR::dwc_otg_hcd_urb_enqueue:477: Not connected
Oct 14 15:09:19 raspberrypi kernel: [148562.357473] sd 1:0:0:0: [sdb]
Unhandled error code
Oct 14 15:09:19 raspberrypi kernel: [148562.457463] sd 1:0:0:0: [sdb]
Unhandled error code
Oct 14 15:09:19 raspberrypi kernel: [148562.457601] lost page write due to
I/O error on sdb1
Oct 14 15:09:19 raspberrypi kernel: [148562.557449] sd 1:0:0:0: [sdb]
Unhandled error code
Oct 14 15:09:19 raspberrypi kernel: [148562.557564] lost page write due to
I/O error on sdb1
Oct 15 21:48:54 raspberrypi kernel: [ 4308.835089]
ERROR::dwc_otg_hcd_urb_enqueue:477: Not connected
Oct 15 21:48:54 raspberrypi kernel: [ 4308.835501]
ERROR::dwc_otg_hcd_urb_enqueue:477: Not connected
Oct 15 21:48:54 raspberrypi kernel: [ 4308.835534]
ERROR::dwc_otg_hcd_urb_enqueue:477: Not connected
Oct 15 21:48:54 raspberrypi kernel: [ 4308.835563]
ERROR::dwc_otg_hcd_urb_enqueue:477: Not connected
Oct 15 21:48:55 raspberrypi kernel: [ 4310.181327] EXT4-fs warning (device
sdb1): ext4_end_bio:251: I/O error writing to inode 524294 (offset 80220160
size 4096 starting block 66697)
Oct 15 21:48:55 raspberrypi kernel: [ 4310.181722] JBD2: Detected IO
errors while flushing file data on sdb1-8

Oct 15 21:48:54 raspberrypi kernel: [ 4308.835089]
ERROR::dwc_otg_hcd_urb_enqueue:477: Not connected
Oct 15 21:48:54 raspberrypi kernel: [ 4308.835501]
ERROR::dwc_otg_hcd_urb_enqueue:477: Not connected
Oct 15 21:48:54 raspberrypi kernel: [ 4308.835534]
ERROR::dwc_otg_hcd_urb_enqueue:477: Not connected
Oct 15 21:48:54 raspberrypi kernel: [ 4308.835563]
ERROR::dwc_otg_hcd_urb_enqueue:477: Not connected
Oct 15 21:48:55 raspberrypi kernel: [ 4310.181327] EXT4-fs warning (device
sdb1): ext4_end_bio:251: I/O error writing to inode 524294 (offset 80220160
size 4096 starting block 66697)
Oct 15 21:48:55 raspberrypi kernel: [ 4310.181722] JBD2: Detected IO
errors while flushing file data on sdb1-8

root@raspberrypi:/home/pi# cat /var/log/syslog | grep -i erro
Oct 15 20:37:13 raspberrypi ntpd[2033]: restrict: error in address '::' on
line 38. Ignoring...
Oct 15 20:37:13 raspberrypi ntpd[2033]: restrict: error in address '::1'
on line 42. Ignoring...
Oct 15 21:48:54 raspberrypi kernel: [ 4308.835089]
ERROR::dwc_otg_hcd_urb_enqueue:477: Not connected
Oct 15 21:48:54 raspberrypi kernel: [ 4308.835501]
ERROR::dwc_otg_hcd_urb_enqueue:477: Not connected
Oct 15 21:48:54 raspberrypi kernel: [ 4308.835534]
ERROR::dwc_otg_hcd_urb_enqueue:477: Not connected
Oct 15 21:48:54 raspberrypi kernel: [ 4308.835563]
ERROR::dwc_otg_hcd_urb_enqueue:477: Not connected
Oct 15 21:48:55 raspberrypi kernel: [ 4310.181289] Buffer I/O error on
device sdb1, logical block 66689
Oct 15 21:48:55 raspberrypi kernel: [ 4310.181327] EXT4-fs warning (device
sdb1): ext4_end_bio:251: I/O error writing to inode 524294 (offset 80220160
size 4096 starting block 66697)
Oct 15 21:48:55 raspberrypi kernel: [ 4310.181494] JBD2: I/O error
detected when updating journal superblock for sdb1-8.
Oct 15 21:48:55 raspberrypi kernel: [ 4310.181722] JBD2: Detected IO
errors while flushing file data on sdb1-8
Oct 15 21:48:55 raspberrypi kernel: [ 4310.181838] JBD2: I/O error
detected when updating journal superblock for sdb1-8.
Oct 15 21:49:22 raspberrypi kernel: [ 4337.351179] EXT4-fs error (device
sdb1): ext4_find_entry:935: inode #524289: comm mlnet: reading directory
lblock 0
Oct 15 21:49:22 raspberrypi kernel: [ 4337.386202] EXT4-fs error (device
sdb1): ext4_journal_start_sb:327: Detected aborted journal
Oct 15 21:49:24 raspberrypi kernel: [ 4338.946361] EXT4-fs error (device
sdb1): ext4_read_block_bitmap:394: comm mlnet: Cannot read block bitmap -
block_group = 2, block_bitmap = 1027
Oct 15 21:49:24 raspberrypi kernel: [ 4338.965416] EXT4-fs error (device
sdb1): ext4_discard_preallocations:3892: comm mlnet: Error reading block
bitmap for 2

I think that there is something wrong with the usb driver .... Am I wrong ?
Thanks a lot,
Ste

PS already posted on troubleshooting section of pi forum with no success.
http://www.raspberrypi.org/phpBB3/viewtopic.php?f=28&t=19974


Reply to this email directly or view it on GitHubhttps://github.com//issues/136.

@dudducat
Copy link
Author

I'm not sure to understand your point

now I'm in this condition

Power -> Hub

Hub -> host USB of PI

first hub USB -> to power mini usb on PI
second hub USB -> 8GB PEN
third hub USB -> 60GB HD (connected with an Y cable .... the power part of the cable connected to USB port of my router)
fourth hub USB -> empty

You say to power up pi from a different power source ?
Then leave the rest untouched ?
Thanks a lot,
Ste

@ghollingworth
Copy link

Sorry your ascii art doesn't make sense in a gmail browser!

Can you describe what the setup is?

Is the hard drive self powered?

Gordon

@dudducat
Copy link
Author

I've just modified the post ... you could see it correct using
#136

I saw late that my ascii was orrible :)

@dudducat
Copy link
Author

Ops I forgot to say that drive is self powered, this is the reason why I use an Y cable connected to the hub and to the usb port of my router

@gholling
Copy link

I assume it all works fine if you connect the HD to the PI directly?

What's the rating on the hub power supply? You are powering the PI (which can take up to 1A) + the pen drive and the hub power, all together it's going to be fairly large...

Try powering the PI from a known good PS and just connect to the HD (with the Y cable to a known good PSU)

@dudducat
Copy link
Author

Thanks a lot I'll do the test tonight and I will report the results tomorrow.

@dudducat
Copy link
Author

Test done.
Using 1A power source for pi, connecting hd directly to the pi: pi doesn't see hd
Using 1A power source for pi, connecting powered usb hub, and hd to the hub, everything works fine till now.

Thanks a lot for the support.
You're great.
Ste

@dudducat dudducat reopened this Oct 20, 2012
@dudducat
Copy link
Author

Hi,
this error happens last night after three days with no errors:

/var/log/syslog.1:Oct 19 21:22:08 raspberrypi kernel: [84472.468113] ERROR::dwc_otg_hcd_urb_enqueue:477: Not connected
/var/log/syslog.1:Oct 19 21:22:08 raspberrypi kernel: [84472.468240] ERROR::dwc_otg_hcd_urb_enqueue:477: Not connected
/var/log/syslog.1:Oct 19 21:22:08 raspberrypi kernel: [84472.468277] ERROR::dwc_otg_hcd_urb_enqueue:477: Not connected
/var/log/syslog.1:Oct 19 21:22:08 raspberrypi kernel: [84472.468307] ERROR::dwc_otg_hcd_urb_enqueue:477: Not connected
/var/log/syslog.1:Oct 19 21:22:35 raspberrypi kernel: [84499.825538] EXT4-fs error (device sda1): ext4_find_entry:935: inode #2: comm mlnet: reading directory lblock 0

So power was not the only element involved. I think that there must be something more.
Anyway I've just downloaded the last firmware, so let's see what happens in the next few days.
Bye,
Ste

@nixnodes
Copy link

I can confirm this:

Oct 24 22:35:00 raspberrypi kernel: [ 1154.962940] ERROR::dwc_otg_hcd_urb_enqueue:477: Not connected
Oct 24 22:35:00 raspberrypi kernel: [ 1154.963429] ERROR::dwc_otg_hcd_urb_enqueue:477: Not connected
Oct 24 22:35:00 raspberrypi kernel: [ 1154.963470] ERROR::dwc_otg_hcd_urb_enqueue:477: Not connected

USB driver reconnects after dying.

The device was running normally for about a month, then this started happening, only when the ethernet adapter is in heavy use.

At this point I've ruled out power issues (replaced the previous PSU with a 2.5A one), I also did:

vm.min_free_kbytes = 32768 in /etc/sysctl.conf
smsc95xx.turbo_mode=N in /boot/cmdline.txt

and a firmware upgrade, problem didn't go away..

Using raspbian: Linux raspberrypi 3.2.27+ #250 PREEMPT Thu Oct 18 19:03:02 BST 2012 armv6l GNU/Linux

It doesn't seem to be a software issue either, I restored a backup image, even brought back the base image and configured it from scratch again, nothing seems to help..

At this point, it's getting a bit concerning, smells like shitty,buggy hardware, if anyone cares to correct this opinion, please, I'd be more than glad to be proven wrong.

@ghost ghost assigned ghollingworth Oct 25, 2012
@nixnodes
Copy link

@dudducat:

This seems to help with the disconnects:

dwc_otg.microframe_schedule=1 sdhci-bcm2708.enable_llm=1 (in /boot/cmdline.txt)

dwc_otg.speed=1 might help also, but this brings your USB port (and ethernet) down to full speed (12Mbit).

The power cable (if using microusb port) could be to blame also, if it's resistance happens to be too high, it's also possible there's a blown polyfuse, read here:

http://elinux.org/RPi_Hardware#Power
http://elinux.org/Polyfuses_explained

@piotr-e
Copy link

piotr-e commented Oct 27, 2012

I added all above option and video0 file isn't created.

edit:
If I add dwc_otg.speed=1 , video0 will not create after reboot for stk1160(easycap).

@nixnodes
Copy link

@piotr-e

try only dwc_otg.microframe_schedule=1 sdhci-bcm2708.enable_llm=1 smsc95xx.turbo_mode=N, dwc_otg.speed=1 is a last resort, it will severely decrease ethernet/usb port speed

what kernel version are you running?

@piotr-e
Copy link

piotr-e commented Nov 1, 2012

I have 3.2.27+.

After insert above option and restart still video0 file not create but without dwc_otg.speed=1 video0 is create.

@piotr-e
Copy link

piotr-e commented Nov 1, 2012

So, You decrease USB speed to ver. 1.1. For Stk1160 driver must be USB 2.0.

popcornmix pushed a commit that referenced this issue May 8, 2013
commit a75ae78 upstream.

Otherwise destroyed ext_sb_info will be part of global shinker list
and result in the following OOPS:

JBD2: corrupted journal superblock
JBD2: recovery failed
EXT4-fs (dm-2): error loading journal
general protection fault: 0000 [#1] SMP
Modules linked in: fuse acpi_cpufreq freq_table mperf coretemp kvm_intel kvm crc32c_intel microcode sg button sd_mod crc_t10dif ahci libahci pata_acpi ata_generic dm_mirror dm_region_hash dm_log dm_\
mod
CPU 1
Pid: 2758, comm: mount Not tainted 3.8.0-rc3+ #136                  /DH55TC
RIP: 0010:[<ffffffff811bfb2d>]  [<ffffffff811bfb2d>] unregister_shrinker+0xad/0xe0
RSP: 0000:ffff88011d5cbcd8  EFLAGS: 00010207
RAX: 6b6b6b6b6b6b6b6b RBX: 6b6b6b6b6b6b6b53 RCX: 0000000000000006
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000246
RBP: ffff88011d5cbce8 R08: 0000000000000002 R09: 0000000000000001
R10: 0000000000000001 R11: 0000000000000000 R12: ffff88011cd3f848
R13: ffff88011cd3f830 R14: ffff88011cd3f000 R15: 0000000000000000
FS:  00007f7b721dd7e0(0000) GS:ffff880121a00000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
CR2: 00007fffa6f75038 CR3: 000000011bc1c000 CR4: 00000000000007e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Process mount (pid: 2758, threadinfo ffff88011d5ca000, task ffff880116aacb80)
Stack:
ffff88011cd3f000 ffffffff8209b6c0 ffff88011d5cbd18 ffffffff812482f1
00000000000003f3 00000000ffffffea ffff880115f4c200 0000000000000000
ffff88011d5cbda8 ffffffff81249381 ffff8801219d8bf8 ffffffff00000000
Call Trace:
[<ffffffff812482f1>] deactivate_locked_super+0x91/0xb0
[<ffffffff81249381>] mount_bdev+0x331/0x340
[<ffffffff81376730>] ? ext4_alloc_flex_bg_array+0x180/0x180
[<ffffffff81362035>] ext4_mount+0x15/0x20
[<ffffffff8124869a>] mount_fs+0x9a/0x2e0
[<ffffffff81277e25>] vfs_kern_mount+0xc5/0x170
[<ffffffff81279c02>] do_new_mount+0x172/0x2e0
[<ffffffff8127aa56>] do_mount+0x376/0x380
[<ffffffff8127ab98>] sys_mount+0x138/0x150
[<ffffffff818ffed9>] system_call_fastpath+0x16/0x1b
Code: 8b 05 88 04 eb 00 48 3d 90 ff 06 82 48 8d 58 e8 75 19 4c 89 e7 e8 e4 d7 2c 00 48 c7 c7 00 ff 06 82 e8 58 5f ef ff 5b 41 5c c9 c3 <48> 8b 4b 18 48 8b 73 20 48 89 da 31 c0 48 c7 c7 c5 a0 e4 81 e\
8
RIP  [<ffffffff811bfb2d>] unregister_shrinker+0xad/0xe0
RSP <ffff88011d5cbcd8>

Signed-off-by: Dmitry Monakhov <dmonakhov@openvz.org>
Signed-off-by: "Theodore Ts'o" <tytso@mit.edu>
Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
@ghollingworth
Copy link

Can you check this again with the latest kernel?

sudo rpi-update

@ghollingworth
Copy link

OK, assume it's fixed

@dudducat
Copy link
Author

Finally back home

just updated my pi to the last firmware. The problem that seemed solved with the previous version is here again:

uname -a
Linux raspberrypi 3.6.11+ #541 PREEMPT Sat Sep 7 19:46:21 BST 2013 armv6l GNU/Linux

Sep 15 08:29:09 raspberrypi kernel: [32973.128557] smsc95xx 1-1.1:1.0: eth0: kev
ent 2 may have been dropped
Sep 15 08:29:09 raspberrypi kernel: [32973.128582] smsc95xx 1-1.1:1.0: eth0: kev
ent 2 may have been dropped
Sep 17 13:51:57 raspberrypi kernel: [225143.095511] ERROR::dwc_otg_hcd_urb_enque
ue:514: Not connected
Sep 17 13:51:57 raspberrypi kernel: [225143.095511]
Sep 17 13:51:57 raspberrypi kernel: [225143.103816] ERROR::dwc_otg_hcd_urb_enque
ue:514: Not connected

The current config is

PowerSupply 0.9A (previous one was a 2A but it's dead after less than a year), ethernet cable, usb connected to an external powered harddisk

Bye,
Ste

@P33M
Copy link
Contributor

P33M commented Sep 17, 2013

Your "not connected" messages are due to URBs being submitted while the driver thinks the root port has been disconnected, and the hardware is idle.

Please pastebin the full dmesg output, from boot until the time the problem starts occurring.

@P33M P33M reopened this Sep 17, 2013
@dudducat
Copy link
Author

Now disconnected usb drive to recover it on my laptop, this is a full kern.log

Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] Booting Linux on physical CPU 0
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] Initializing cgroup subsys cpu
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] Linux version 3.6.11+ (dc4@dc4-arm-01) (gcc version 4.7.2 20120731 (prerelease) (crosstool-NG linaro-1.13.1+bzr2458 - Linaro GCC 2012.08) ) #541 PREEMPT Sat Sep 7 19:46:21 BST 2013
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] CPU: ARMv6-compatible processor [410fb767] revision 7 (ARMv7), cr=00c5387d
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT nonaliasing instruction cache
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] Machine: BCM2708
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] cma: CMA: reserved 16 MiB at 0b000000
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] Memory policy: ECC disabled, Data cache writeback
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] On node 0 totalpages: 49152
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] free_area_init_node: node 0, pgdat c0545b54, node_mem_map c05f0000
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] Normal zone: 384 pages used for memmap
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] Normal zone: 0 pages reserved
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] Normal zone: 48768 pages, LIFO batch:15
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] pcpu-alloc: s0 r0 d32768 u32768 alloc=1_32768
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] pcpu-alloc: [0] 0
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] Built 1 zonelists in Zone order, mobility grouping on. Total pages: 48768
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] Kernel command line: dma.dmachans=0x7f35 bcm2708_fb.fbwidth=656 bcm2708_fb.fbheight=416 bcm2708.boardrev=0x2 bcm2708.serial=0xdb911dbf smsc95xx.macaddr=B8:27:EB:91:1D:BF sdhci-bcm2708.emmc_clock_freq=100000000 vc_mem.mem_base=0xec00000 vc_mem.mem_size=0x10000000 dwc_otg.lpm_enable=0 console=ttyAMA0,115200 kgdboc=ttyAMA0,115200 console=tty1 root=/dev/mmcblk0p2 rootfstype=ext4 elevator=deadline rootwait
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] PID hash table entries: 1024 (order: 0, 4096 bytes)
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] Dentry cache hash table entries: 32768 (order: 5, 131072 bytes)
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] Inode-cache hash table entries: 16384 (order: 4, 65536 bytes)
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] Memory: 192MB = 192MB total
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] Memory: 172324k/172324k available, 24284k reserved, 0K highmem
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] Virtual kernel memory layout:
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] vector : 0xffff0000 - 0xffff1000 ( 4 kB)
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] fixmap : 0xfff00000 - 0xfffe0000 ( 896 kB)
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] vmalloc : 0xcc800000 - 0xff000000 ( 808 MB)
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] lowmem : 0xc0000000 - 0xcc000000 ( 192 MB)
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] modules : 0xbf000000 - 0xc0000000 ( 16 MB)
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] .text : 0xc0008000 - 0xc04ef844 (5023 kB)
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] .init : 0xc04f0000 - 0xc05111f0 ( 133 kB)
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] .data : 0xc0512000 - 0xc0546560 ( 210 kB)
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] .bss : 0xc0546584 - 0xc05ef738 ( 677 kB)
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] SLUB: Genslabs=13, HWalign=32, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] NR_IRQS:330
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] sched_clock: 32 bits at 1000kHz, resolution 1000ns, wraps every 4294967ms
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] Console: colour dummy device 80x30
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] console [tty1] enabled
Sep 17 21:03:20 raspberrypi kernel: [ 0.000969] Calibrating delay loop... 697.95 BogoMIPS (lpj=3489792)
Sep 17 21:03:20 raspberrypi kernel: [ 0.060125] pid_max: default: 32768 minimum: 301
Sep 17 21:03:20 raspberrypi kernel: [ 0.060609] Mount-cache hash table entries: 512
Sep 17 21:03:20 raspberrypi kernel: [ 0.061417] Initializing cgroup subsys cpuacct
Sep 17 21:03:20 raspberrypi kernel: [ 0.061472] Initializing cgroup subsys devices
Sep 17 21:03:20 raspberrypi kernel: [ 0.061507] Initializing cgroup subsys freezer
Sep 17 21:03:20 raspberrypi kernel: [ 0.061537] Initializing cgroup subsys blkio
Sep 17 21:03:20 raspberrypi kernel: [ 0.061679] CPU: Testing write buffer coherency: ok
Sep 17 21:03:20 raspberrypi kernel: [ 0.062000] hw perfevents: enabled with v6 PMU driver, 3 counters available
Sep 17 21:03:20 raspberrypi kernel: [ 0.062150] Setting up static identity map for 0x3a5238 - 0x3a5294
Sep 17 21:03:20 raspberrypi kernel: [ 0.063620] devtmpfs: initialized
Sep 17 21:03:20 raspberrypi kernel: [ 0.075049] NET: Registered protocol family 16
Sep 17 21:03:20 raspberrypi kernel: [ 0.081421] DMA: preallocated 4096 KiB pool for atomic coherent allocations
Sep 17 21:03:20 raspberrypi kernel: [ 0.082483] bcm2708.uart_clock = 0
Sep 17 21:03:20 raspberrypi kernel: [ 0.083845] hw-breakpoint: found 6 breakpoint and 1 watchpoint registers.
Sep 17 21:03:20 raspberrypi kernel: [ 0.083899] hw-breakpoint: maximum watchpoint size is 4 bytes.
Sep 17 21:03:20 raspberrypi kernel: [ 0.083935] mailbox: Broadcom VideoCore Mailbox driver
Sep 17 21:03:20 raspberrypi kernel: [ 0.084025] bcm2708_vcio: mailbox at f200b880
Sep 17 21:03:20 raspberrypi kernel: [ 0.084136] bcm_power: Broadcom power driver
Sep 17 21:03:20 raspberrypi kernel: [ 0.084172] bcm_power_open() -> 0
Sep 17 21:03:20 raspberrypi kernel: [ 0.084197] bcm_power_request(0, 8)
Sep 17 21:03:20 raspberrypi kernel: [ 0.584881] bcm_mailbox_read -> 00000080, 0
Sep 17 21:03:20 raspberrypi kernel: [ 0.584919] bcm_power_request -> 0
Sep 17 21:03:20 raspberrypi kernel: [ 0.584944] Serial: AMBA PL011 UART driver
Sep 17 21:03:20 raspberrypi kernel: [ 0.585068] dev:f1: ttyAMA0 at MMIO 0x20201000 (irq = 83) is a PL011 rev3
Sep 17 21:03:20 raspberrypi kernel: [ 0.916201] console [ttyAMA0] enabled
Sep 17 21:03:20 raspberrypi kernel: [ 0.940464] bio: create slab at 0
Sep 17 21:03:20 raspberrypi kernel: [ 0.945372] SCSI subsystem initialized
Sep 17 21:03:20 raspberrypi kernel: [ 0.949438] usbcore: registered new interface driver usbfs
Sep 17 21:03:20 raspberrypi kernel: [ 0.955029] usbcore: registered new interface driver hub
Sep 17 21:03:20 raspberrypi kernel: [ 0.960624] usbcore: registered new device driver usb
Sep 17 21:03:20 raspberrypi kernel: [ 0.966966] Switching to clocksource stc
Sep 17 21:03:20 raspberrypi kernel: [ 0.971258] FS-Cache: Loaded
Sep 17 21:03:20 raspberrypi kernel: [ 0.974416] CacheFiles: Loaded
Sep 17 21:03:20 raspberrypi kernel: [ 0.989382] NET: Registered protocol family 2
Sep 17 21:03:20 raspberrypi kernel: [ 0.994647] TCP established hash table entries: 8192 (order: 4, 65536 bytes)
Sep 17 21:03:20 raspberrypi kernel: [ 1.001998] TCP bind hash table entries: 8192 (order: 3, 32768 bytes)
Sep 17 21:03:20 raspberrypi kernel: [ 1.008577] TCP: Hash tables configured (established 8192 bind 8192)
Sep 17 21:03:20 raspberrypi kernel: [ 1.015002] TCP: reno registered
Sep 17 21:03:20 raspberrypi kernel: [ 1.018253] UDP hash table entries: 256 (order: 0, 4096 bytes)
Sep 17 21:03:20 raspberrypi kernel: [ 1.024148] UDP-Lite hash table entries: 256 (order: 0, 4096 bytes)
Sep 17 21:03:20 raspberrypi kernel: [ 1.030763] NET: Registered protocol family 1
Sep 17 21:03:20 raspberrypi kernel: [ 1.035683] RPC: Registered named UNIX socket transport module.
Sep 17 21:03:20 raspberrypi kernel: [ 1.041728] RPC: Registered udp transport module.
Sep 17 21:03:20 raspberrypi kernel: [ 1.046450] RPC: Registered tcp transport module.
Sep 17 21:03:20 raspberrypi kernel: [ 1.051195] RPC: Registered tcp NFSv4.1 backchannel transport module.
Sep 17 21:03:20 raspberrypi kernel: [ 1.058311] bcm2708_dma: DMA manager at f2007000
Sep 17 21:03:20 raspberrypi kernel: [ 1.063091] bcm2708_gpio: bcm2708_gpio_probe c051fdf8
Sep 17 21:03:20 raspberrypi kernel: [ 1.068541] vc-mem: phys_addr:0x00000000 mem_base=0x0ec00000 mem_size:0x10000000(256 MiB)
Sep 17 21:03:20 raspberrypi kernel: [ 1.077743] audit: initializing netlink socket (disabled)
Sep 17 21:03:20 raspberrypi kernel: [ 1.083341] type=2000 audit(0.940:1): initialized
Sep 17 21:03:20 raspberrypi kernel: [ 1.215711] VFS: Disk quotas dquot_6.5.2
Sep 17 21:03:20 raspberrypi kernel: [ 1.219958] Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
Sep 17 21:03:20 raspberrypi kernel: [ 1.229149] FS-Cache: Netfs 'nfs' registered for caching
Sep 17 21:03:20 raspberrypi kernel: [ 1.235801] NFS: Registering the id_resolver key type
Sep 17 21:03:20 raspberrypi kernel: [ 1.240960] Key type id_resolver registered
Sep 17 21:03:20 raspberrypi kernel: [ 1.245264] Key type id_legacy registered
Sep 17 21:03:20 raspberrypi kernel: [ 1.249626] msgmni has been set to 368
Sep 17 21:03:20 raspberrypi kernel: [ 1.255621] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 252)
Sep 17 21:03:20 raspberrypi kernel: [ 1.263441] io scheduler noop registered
Sep 17 21:03:20 raspberrypi kernel: [ 1.267395] io scheduler deadline registered (default)
Sep 17 21:03:20 raspberrypi kernel: [ 1.272721] io scheduler cfq registered
Sep 17 21:03:20 raspberrypi kernel: [ 1.287563] Console: switching to colour frame buffer device 82x26
Sep 17 21:03:20 raspberrypi kernel: [ 1.297696] kgdb: Registered I/O driver kgdboc.
Sep 17 21:03:20 raspberrypi kernel: [ 1.304341] vc-cma: Videocore CMA driver
Sep 17 21:03:20 raspberrypi kernel: [ 1.309678] vc-cma: vc_cma_base = 0x00000000
Sep 17 21:03:20 raspberrypi kernel: [ 1.315819] vc-cma: vc_cma_size = 0x00000000 (0 MiB)
Sep 17 21:03:20 raspberrypi kernel: [ 1.322586] vc-cma: vc_cma_initial = 0x00000000 (0 MiB)
Sep 17 21:03:20 raspberrypi kernel: [ 1.337912] brd: module loaded
Sep 17 21:03:20 raspberrypi kernel: [ 1.347331] loop: module loaded
Sep 17 21:03:20 raspberrypi kernel: [ 1.352158] vchiq: vchiq_init_state: slot_zero = 0xcb000000, is_master = 0
Sep 17 21:03:20 raspberrypi kernel: [ 1.361082] Loading iSCSI transport class v2.0-870.
Sep 17 21:03:20 raspberrypi kernel: [ 1.368229] usbcore: registered new interface driver smsc95xx
Sep 17 21:03:20 raspberrypi kernel: [ 1.375682] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
Sep 17 21:03:20 raspberrypi kernel: [ 1.587921] Core Release: 2.80a
Sep 17 21:03:20 raspberrypi kernel: [ 1.592456] Setting default values for core params
Sep 17 21:03:20 raspberrypi kernel: [ 1.598549] Finished setting default values for core params
Sep 17 21:03:20 raspberrypi kernel: [ 1.810479] Using Buffer DMA mode
Sep 17 21:03:20 raspberrypi kernel: [ 1.815110] Periodic Transfer Interrupt Enhancement - disabled
Sep 17 21:03:20 raspberrypi kernel: [ 1.822221] Multiprocessor Interrupt Enhancement - disabled
Sep 17 21:03:20 raspberrypi kernel: [ 1.829046] OTG VER PARAM: 0, OTG VER FLAG: 0
Sep 17 21:03:20 raspberrypi kernel: [ 1.834674] Dedicated Tx FIFOs mode
Sep 17 21:03:20 raspberrypi kernel: [ 1.840268] dwc_otg: Microframe scheduler enabled
Sep 17 21:03:20 raspberrypi kernel: [ 1.840635] dwc_otg bcm2708_usb: DWC OTG Controller
Sep 17 21:03:20 raspberrypi kernel: [ 1.846942] dwc_otg bcm2708_usb: new USB bus registered, assigned bus number 1
Sep 17 21:03:20 raspberrypi kernel: [ 1.855548] dwc_otg bcm2708_usb: irq 32, io mem 0x00000000
Sep 17 21:03:20 raspberrypi kernel: [ 1.862404] Init: Port Power? op_state=1
Sep 17 21:03:20 raspberrypi kernel: [ 1.867583] Init: Power Port (0)
Sep 17 21:03:20 raspberrypi kernel: [ 1.872251] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
Sep 17 21:03:20 raspberrypi kernel: [ 1.880424] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
Sep 17 21:03:20 raspberrypi kernel: [ 1.889044] usb usb1: Product: DWC OTG Controller
Sep 17 21:03:20 raspberrypi kernel: [ 1.895155] usb usb1: Manufacturer: Linux 3.6.11+ dwc_otg_hcd
Sep 17 21:03:20 raspberrypi kernel: [ 1.902291] usb usb1: SerialNumber: bcm2708_usb
Sep 17 21:03:20 raspberrypi kernel: [ 1.908857] hub 1-0:1.0: USB hub found
Sep 17 21:03:20 raspberrypi kernel: [ 1.914039] hub 1-0:1.0: 1 port detected
Sep 17 21:03:20 raspberrypi kernel: [ 1.919564] dwc_otg: FIQ enabled
Sep 17 21:03:20 raspberrypi kernel: [ 1.919579] dwc_otg: NAK holdoff enabled
Sep 17 21:03:20 raspberrypi kernel: [ 1.919587] dwc_otg: FIQ split fix enabled
Sep 17 21:03:20 raspberrypi kernel: [ 1.919605] Module dwc_common_port init
Sep 17 21:03:20 raspberrypi kernel: [ 1.919826] Initializing USB Mass Storage driver...
Sep 17 21:03:20 raspberrypi kernel: [ 1.926275] usbcore: registered new interface driver usb-storage
Sep 17 21:03:20 raspberrypi kernel: [ 1.933646] USB Mass Storage support registered.
Sep 17 21:03:20 raspberrypi kernel: [ 1.939686] usbcore: registered new interface driver libusual
Sep 17 21:03:20 raspberrypi kernel: [ 1.947061] mousedev: PS/2 mouse device common for all mice
Sep 17 21:03:20 raspberrypi kernel: [ 1.954686] bcm2835-cpufreq: min=700000 max=800000 cur=700000
Sep 17 21:03:20 raspberrypi kernel: [ 1.961892] bcm2835-cpufreq: switching to governor powersave
Sep 17 21:03:20 raspberrypi kernel: [ 1.968831] bcm2835-cpufreq: switching to governor powersave
Sep 17 21:03:20 raspberrypi kernel: [ 1.975770] cpuidle: using governor ladder
Sep 17 21:03:20 raspberrypi kernel: [ 1.981132] cpuidle: using governor menu
Sep 17 21:03:20 raspberrypi kernel: [ 1.986298] sdhci: Secure Digital Host Controller Interface driver
Sep 17 21:03:20 raspberrypi kernel: [ 1.993710] sdhci: Copyright(c) Pierre Ossman
Sep 17 21:03:20 raspberrypi kernel: [ 1.999349] sdhci: Enable low-latency mode
Sep 17 21:03:20 raspberrypi kernel: [ 2.041257] mmc0: SDHCI controller on BCM2708_Arasan [platform] using platform's DMA
Sep 17 21:03:20 raspberrypi kernel: [ 2.051709] mmc0: BCM2708 SDHC host at 0x20300000 DMA 2 IRQ 77
Sep 17 21:03:20 raspberrypi kernel: [ 2.061092] sdhci-pltfm: SDHCI platform and OF driver helper
Sep 17 21:03:20 raspberrypi kernel: [ 2.073815] usbcore: registered new interface driver usbhid
Sep 17 21:03:20 raspberrypi kernel: [ 2.080729] usbhid: USB HID core driver
Sep 17 21:03:20 raspberrypi kernel: [ 2.088632] TCP: cubic registered
Sep 17 21:03:20 raspberrypi kernel: [ 2.095451] Initializing XFRM netlink socket
Sep 17 21:03:20 raspberrypi kernel: [ 2.103215] NET: Registered protocol family 17
Sep 17 21:03:20 raspberrypi kernel: [ 2.111228] Indeed it is in host mode hprt0 = 00021501
Sep 17 21:03:20 raspberrypi kernel: [ 2.117956] Key type dns_resolver registered
Sep 17 21:03:20 raspberrypi kernel: [ 2.131566] VFP support v0.3: implementor 41 architecture 1 part 20 variant b rev 5
Sep 17 21:03:20 raspberrypi kernel: [ 2.152494] registered taskstats version 1
Sep 17 21:03:20 raspberrypi kernel: [ 2.166859] Waiting for root device /dev/mmcblk0p2...
Sep 17 21:03:20 raspberrypi kernel: [ 2.173676] mmc0: new high speed SDHC card at address e624
Sep 17 21:03:20 raspberrypi kernel: [ 2.191374] mmcblk0: mmc0:e624 SU16G 14.8 GiB
Sep 17 21:03:20 raspberrypi kernel: [ 2.200654] mmcblk0: p1 p2
Sep 17 21:03:20 raspberrypi kernel: [ 2.328644] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
Sep 17 21:03:20 raspberrypi kernel: [ 2.339834] VFS: Mounted root (ext4 filesystem) on device 179:2.
Sep 17 21:03:20 raspberrypi kernel: [ 2.347441] usb 1-1: new high-speed USB device number 2 using dwc_otg
Sep 17 21:03:20 raspberrypi kernel: [ 2.355856] Indeed it is in host mode hprt0 = 00001101
Sep 17 21:03:20 raspberrypi kernel: [ 2.370220] devtmpfs: mounted
Sep 17 21:03:20 raspberrypi kernel: [ 2.381497] Freeing init memory: 132K
Sep 17 21:03:20 raspberrypi kernel: [ 2.571778] usb 1-1: New USB device found, idVendor=0424, idProduct=9512
Sep 17 21:03:20 raspberrypi kernel: [ 2.580071] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Sep 17 21:03:20 raspberrypi kernel: [ 2.592859] hub 1-1:1.0: USB hub found
Sep 17 21:03:20 raspberrypi kernel: [ 2.598472] hub 1-1:1.0: 3 ports detected
Sep 17 21:03:20 raspberrypi kernel: [ 2.881365] usb 1-1.1: new high-speed USB device number 3 using dwc_otg
Sep 17 21:03:20 raspberrypi kernel: [ 2.991890] usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00
Sep 17 21:03:20 raspberrypi kernel: [ 3.000369] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Sep 17 21:03:20 raspberrypi kernel: [ 3.016211] smsc95xx v1.0.4
Sep 17 21:03:20 raspberrypi kernel: [ 3.086076] smsc95xx 1-1.1:1.0: eth0: register 'smsc95xx' at usb-bcm2708_usb-1.1, smsc95xx USB 2.0 Ethernet, b8:27:eb:91:1d:bf
Sep 17 21:03:20 raspberrypi kernel: [ 5.125489] Registered led device: led0
Sep 17 21:03:20 raspberrypi kernel: [ 9.040573] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
Sep 17 21:03:20 raspberrypi kernel: [ 17.729958] Installing knfsd (copyright (C) 1996 okir@monad.swb.de).
Sep 17 21:03:20 raspberrypi kernel: [ 18.118838] smsc95xx 1-1.1:1.0: eth0: link up, 100Mbps, full-duplex, lpa 0xDDE1
Sep 17 21:03:20 raspberrypi kernel: [ 20.719081] bcm2835-cpufreq: switching to governor ondemand
Sep 17 21:03:20 raspberrypi kernel: [ 20.719110] bcm2835-cpufreq: switching to governor ondemand
Sep 17 21:03:22 raspberrypi kernel: [ 25.496175] Adding 102396k swap on /var/swap. Priority:-1 extents:1 across:102396k SS
root@raspberrypi:/var/log# grep "Sep 17 21" kern.log
Sep 17 21:01:01 raspberrypi kernel: [ 141.506159] smsc95xx 1-1.1:1.0: eth0: kevent 2 may have been dropped
Sep 17 21:01:01 raspberrypi kernel: [ 141.506301] smsc95xx 1-1.1:1.0: eth0: kevent 2 may have been dropped
Sep 17 21:01:01 raspberrypi kernel: [ 141.506339] smsc95xx 1-1.1:1.0: eth0: kevent 2 may have been dropped
Sep 17 21:01:01 raspberrypi kernel: [ 141.506371] smsc95xx 1-1.1:1.0: eth0: kevent 2 may have been dropped
Sep 17 21:01:01 raspberrypi kernel: [ 141.506404] smsc95xx 1-1.1:1.0: eth0: kevent 2 may have been dropped
Sep 17 21:01:01 raspberrypi kernel: [ 141.506436] smsc95xx 1-1.1:1.0: eth0: kevent 2 may have been dropped
Sep 17 21:01:01 raspberrypi kernel: [ 141.506466] smsc95xx 1-1.1:1.0: eth0: kevent 2 may have been dropped
Sep 17 21:01:01 raspberrypi kernel: [ 141.506499] smsc95xx 1-1.1:1.0: eth0: kevent 2 may have been dropped
Sep 17 21:01:01 raspberrypi kernel: [ 141.506593] smsc95xx 1-1.1:1.0: eth0: kevent 2 may have been dropped
Sep 17 21:01:01 raspberrypi kernel: [ 141.507065] smsc95xx 1-1.1:1.0: eth0: kevent 2 may have been dropped
Sep 17 21:01:44 raspberrypi kernel: [ 184.456837] EXT4-fs (sda1): mounted filesystem with ordered data mode. Opts: (null)
Sep 17 21:03:04 raspberrypi kernel: [ 264.445981] ERROR::dwc_otg_hcd_urb_enqueue:514: Not connected
Sep 17 21:03:04 raspberrypi kernel: [ 264.445981]
Sep 17 21:03:04 raspberrypi kernel: [ 264.450895] ERROR::dwc_otg_hcd_urb_enqueue:514: Not connected
Sep 17 21:03:04 raspberrypi kernel: [ 264.450895]
Sep 17 21:03:04 raspberrypi kernel: [ 264.684766] usb 1-1: USB disconnect, device number 2
Sep 17 21:03:04 raspberrypi kernel: [ 264.684799] usb 1-1.1: USB disconnect, device number 3
Sep 17 21:03:04 raspberrypi kernel: [ 264.685076] smsc95xx 1-1.1:1.0: eth0: unregister 'smsc95xx' usb-bcm2708_usb-1.1, smsc95xx USB 2.0 Ethernet
Sep 17 21:03:05 raspberrypi kernel: [ 265.174789] sd 0:0:0:0: [sda] Unhandled error code
Sep 17 21:03:05 raspberrypi kernel: [ 265.174819] sd 0:0:0:0: [sda]
Sep 17 21:03:05 raspberrypi kernel: [ 265.174831] Result: hostbyte=0x07 driverbyte=0x00
Sep 17 21:03:05 raspberrypi kernel: [ 265.174843] sd 0:0:0:0: [sda] CDB:
Sep 17 21:03:05 raspberrypi kernel: [ 265.174852] cdb[0]=0x2a: 2a 00 01 80 61 3f 00 00 f0 00
Sep 17 21:03:05 raspberrypi kernel: [ 265.174886] end_request: I/O error, dev sda, sector 25190719
Sep 17 21:03:05 raspberrypi kernel: [ 265.274848] sd 0:0:0:0: [sda] Unhandled error code
Sep 17 21:03:05 raspberrypi kernel: [ 265.274877] sd 0:0:0:0: [sda]
Sep 17 21:03:05 raspberrypi kernel: [ 265.274889] Result: hostbyte=0x07 driverbyte=0x00
Sep 17 21:03:05 raspberrypi kernel: [ 265.274901] sd 0:0:0:0: [sda] CDB:
Sep 17 21:03:05 raspberrypi kernel: [ 265.274909] cdb[0]=0x2a: 2a 00 01 80 62 2f 00 00 f0 00
Sep 17 21:03:05 raspberrypi kernel: [ 265.274944] end_request: I/O error, dev sda, sector 25190959
Sep 17 21:03:05 raspberrypi kernel: [ 265.374821] sd 0:0:0:0: [sda] Unhandled error code
Sep 17 21:03:05 raspberrypi kernel: [ 265.374851] sd 0:0:0:0: [sda]
Sep 17 21:03:05 raspberrypi kernel: [ 265.374864] Result: hostbyte=0x07 driverbyte=0x00
Sep 17 21:03:05 raspberrypi kernel: [ 265.374876] sd 0:0:0:0: [sda] CDB:
Sep 17 21:03:05 raspberrypi kernel: [ 265.374885] cdb[0]=0x2a: 2a 00 01 80 63 1f 00 00 f0 00
Sep 17 21:03:05 raspberrypi kernel: [ 265.374920] end_request: I/O error, dev sda, sector 25191199
Sep 17 21:03:05 raspberrypi kernel: [ 265.476734] sd 0:0:0:0: [sda] Unhandled error code
Sep 17 21:03:05 raspberrypi kernel: [ 265.476766] sd 0:0:0:0: [sda]
Sep 17 21:03:05 raspberrypi kernel: [ 265.476777] Result: hostbyte=0x07 driverbyte=0x00
Sep 17 21:03:05 raspberrypi kernel: [ 265.476789] sd 0:0:0:0: [sda] CDB:
Sep 17 21:03:05 raspberrypi kernel: [ 265.476798] cdb[0]=0x2a: 2a 00 01 80 64 0f 00 00 f0 00
Sep 17 21:03:05 raspberrypi kernel: [ 265.476834] end_request: I/O error, dev sda, sector 25191439
Sep 17 21:03:05 raspberrypi kernel: [ 265.477266] usb 1-1.3: USB disconnect, device number 4
Sep 17 21:03:05 raspberrypi kernel: [ 265.494773] sd 0:0:0:0: [sda] Unhandled error code
Sep 17 21:03:05 raspberrypi kernel: [ 265.494806] sd 0:0:0:0: [sda]
Sep 17 21:03:05 raspberrypi kernel: [ 265.494817] Result: hostbyte=0x01 driverbyte=0x00
Sep 17 21:03:05 raspberrypi kernel: [ 265.494829] sd 0:0:0:0: [sda] CDB:
Sep 17 21:03:05 raspberrypi kernel: [ 265.494837] cdb[0]=0x2a: 2a 00 01 80 64 ff 00 00 f0 00
Sep 17 21:03:05 raspberrypi kernel: [ 265.494873] end_request: I/O error, dev sda, sector 25191679
Sep 17 21:03:05 raspberrypi kernel: [ 265.495034] sd 0:0:0:0: [sda] Unhandled error code
Sep 17 21:03:05 raspberrypi kernel: [ 265.495053] sd 0:0:0:0: [sda]
Sep 17 21:03:05 raspberrypi kernel: [ 265.495063] Result: hostbyte=0x01 driverbyte=0x00
Sep 17 21:03:05 raspberrypi kernel: [ 265.495074] sd 0:0:0:0: [sda] CDB:
Sep 17 21:03:05 raspberrypi kernel: [ 265.495081] cdb[0]=0x2a: 2a 00 01 80 65 ef 00 00 f0 00
Sep 17 21:03:05 raspberrypi kernel: [ 265.495112] end_request: I/O error, dev sda, sector 25191919
Sep 17 21:03:05 raspberrypi kernel: [ 265.495496] Aborting journal on device sda1-8.
Sep 17 21:03:05 raspberrypi kernel: [ 265.495554] JBD2: Error -5 detected when updating journal superblock for sda1-8.
Sep 17 21:03:05 raspberrypi kernel: [ 265.495605] journal commit I/O error
Sep 17 21:03:05 raspberrypi kernel: [ 265.674828] Indeed it is in host mode hprt0 = 00021501
Sep 17 21:03:05 raspberrypi kernel: [ 265.864734] usb 1-1: new high-speed USB device number 5 using dwc_otg
Sep 17 21:03:05 raspberrypi kernel: [ 265.864943] Indeed it is in host mode hprt0 = 00001101
Sep 17 21:03:06 raspberrypi kernel: [ 266.105307] usb 1-1: New USB device found, idVendor=0424, idProduct=9512
Sep 17 21:03:06 raspberrypi kernel: [ 266.105339] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Sep 17 21:03:06 raspberrypi kernel: [ 266.116125] hub 1-1:1.0: USB hub found
Sep 17 21:03:06 raspberrypi kernel: [ 266.116426] hub 1-1:1.0: 3 ports detected
Sep 17 21:03:06 raspberrypi kernel: [ 266.394964] usb 1-1.1: new high-speed USB device number 6 using dwc_otg
Sep 17 21:03:06 raspberrypi kernel: [ 266.495317] usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00
Sep 17 21:03:06 raspberrypi kernel: [ 266.495346] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Sep 17 21:03:06 raspberrypi kernel: [ 266.498277] smsc95xx v1.0.4
Sep 17 21:03:06 raspberrypi kernel: [ 266.559393] smsc95xx 1-1.1:1.0: eth0: register 'smsc95xx' at usb-bcm2708_usb-1.1, smsc95xx USB 2.0 Ethernet, b8:27:eb:91:1d:bf
Sep 17 21:03:06 raspberrypi kernel: [ 266.654985] usb 1-1.3: new high-speed USB device number 7 using dwc_otg
Sep 17 21:03:06 raspberrypi kernel: [ 266.757562] usb 1-1.3: New USB device found, idVendor=067b, idProduct=2507
Sep 17 21:03:06 raspberrypi kernel: [ 266.757576] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Sep 17 21:03:06 raspberrypi kernel: [ 266.757585] usb 1-1.3: Product: Mass Storage Device
Sep 17 21:03:06 raspberrypi kernel: [ 266.757592] usb 1-1.3: Manufacturer: Prolific Technology Inc.
Sep 17 21:03:06 raspberrypi kernel: [ 266.757601] usb 1-1.3: SerialNumber: 0
Sep 17 21:03:06 raspberrypi kernel: [ 266.761894] usb-storage 1-1.3:1.0: Quirks match for vid 067b pid 2507: 110
Sep 17 21:03:06 raspberrypi kernel: [ 266.762093] scsi1 : usb-storage 1-1.3:1.0
Sep 17 21:03:08 raspberrypi kernel: [ 268.335486] smsc95xx 1-1.1:1.0: eth0: link up, 100Mbps, full-duplex, lpa 0xDDE1
Sep 17 21:03:09 raspberrypi kernel: [ 269.652706] ERROR::dwc_otg_hcd_urb_enqueue:514: Not connected
Sep 17 21:03:09 raspberrypi kernel: [ 269.652706]
Sep 17 21:03:09 raspberrypi kernel: [ 269.653025] ERROR::dwc_otg_hcd_urb_enqueue:514: Not connected
Sep 17 21:03:09 raspberrypi kernel: [ 269.653025]
Sep 17 21:03:09 raspberrypi kernel: [ 269.653076] ERROR::dwc_otg_hcd_urb_enqueue:514: Not connected
Sep 17 21:03:09 raspberrypi kernel: [ 269.653076]
Sep 17 21:03:09 raspberrypi kernel: [ 269.653100] hub 1-1:1.0: cannot reset port 3 (err = -19)
Sep 17 21:03:09 raspberrypi kernel: [ 269.653114] ERROR::dwc_otg_hcd_urb_enqueue:514: Not connected
Sep 17 21:03:09 raspberrypi kernel: [ 269.653114]
Sep 17 21:03:09 raspberrypi kernel: [ 269.653132] ERROR::dwc_otg_hcd_urb_enqueue:514: Not connected
Sep 17 21:03:09 raspberrypi kernel: [ 269.653132]
Sep 17 21:03:09 raspberrypi kernel: [ 269.653145] hub 1-1:1.0: cannot disable port 3 (err = -19)
Sep 17 21:03:09 raspberrypi kernel: [ 269.653159] ERROR::dwc_otg_hcd_urb_enqueue:514: Not connected
Sep 17 21:03:09 raspberrypi kernel: [ 269.653159]
Sep 17 21:03:09 raspberrypi kernel: [ 269.653171] hub 1-1:1.0: cannot disable port 3 (err = -19)
Sep 17 21:03:09 raspberrypi kernel: [ 269.653304] ERROR::dwc_otg_hcd_urb_enqueue:514: Not connected
Sep 17 21:03:09 raspberrypi kernel: [ 269.653304]
Sep 17 21:03:09 raspberrypi kernel: [ 269.653324] hub 1-1:1.0: hub_port_status failed (err = -19)
Sep 17 21:03:09 raspberrypi kernel: [ 269.684838] usb 1-1: USB disconnect, device number 5
Sep 17 21:03:09 raspberrypi kernel: [ 269.684870] usb 1-1.1: USB disconnect, device number 6
Sep 17 21:03:09 raspberrypi kernel: [ 269.685116] smsc95xx 1-1.1:1.0: eth0: unregister 'smsc95xx' usb-bcm2708_usb-1.1, smsc95xx USB 2.0 Ethernet
Sep 17 21:03:09 raspberrypi kernel: [ 269.696417] usb 1-1.3: USB disconnect, device number 7
Sep 17 21:03:09 raspberrypi kernel: [ 269.864832] Indeed it is in host mode hprt0 = 00021501
Sep 17 21:03:10 raspberrypi kernel: [ 270.174846] usb 1-1: new high-speed USB device number 8 using dwc_otg
Sep 17 21:03:10 raspberrypi kernel: [ 270.175114] Indeed it is in host mode hprt0 = 00001101
Sep 17 21:03:10 raspberrypi kernel: [ 270.515346] usb 1-1: New USB device found, idVendor=0424, idProduct=9512
Sep 17 21:03:10 raspberrypi kernel: [ 270.515387] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Sep 17 21:03:10 raspberrypi kernel: [ 270.516160] hub 1-1:1.0: USB hub found
Sep 17 21:03:10 raspberrypi kernel: [ 270.516318] hub 1-1:1.0: 3 ports detected
Sep 17 21:03:10 raspberrypi kernel: [ 270.794872] usb 1-1.1: new high-speed USB device number 9 using dwc_otg
Sep 17 21:03:10 raspberrypi kernel: [ 270.895427] usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00
Sep 17 21:03:10 raspberrypi kernel: [ 270.895456] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Sep 17 21:03:10 raspberrypi kernel: [ 270.898394] smsc95xx v1.0.4
Sep 17 21:03:11 raspberrypi kernel: [ 270.959600] smsc95xx 1-1.1:1.0: eth0: register 'smsc95xx' at usb-bcm2708_usb-1.1, smsc95xx USB 2.0 Ethernet, b8:27:eb:91:1d:bf
Sep 17 21:03:11 raspberrypi kernel: [ 271.054927] usb 1-1.3: new high-speed USB device number 10 using dwc_otg
Sep 17 21:03:11 raspberrypi kernel: [ 271.134933] usb 1-1.3: device descriptor read/64, error -71
Sep 17 21:03:11 raspberrypi kernel: [ 271.324995] usb 1-1.3: device descriptor read/64, error -71
Sep 17 21:03:11 raspberrypi kernel: [ 271.514859] usb 1-1.3: new high-speed USB device number 11 using dwc_otg
Sep 17 21:03:11 raspberrypi kernel: [ 271.595020] usb 1-1.3: device descriptor read/64, error -71
Sep 17 21:03:20 raspberrypi kernel: imklog 5.8.11, log source = /proc/kmsg started.
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] Booting Linux on physical CPU 0
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] Initializing cgroup subsys cpu
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] Linux version 3.6.11+ (dc4@dc4-arm-01) (gcc version 4.7.2 20120731 (prerelease) (crosstool-NG linaro-1.13.1+bzr2458 - Linaro GCC 2012.08) ) #541 PREEMPT Sat Sep 7 19:46:21 BST 2013
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] CPU: ARMv6-compatible processor [410fb767] revision 7 (ARMv7), cr=00c5387d
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT nonaliasing instruction cache
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] Machine: BCM2708
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] cma: CMA: reserved 16 MiB at 0b000000
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] Memory policy: ECC disabled, Data cache writeback
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] On node 0 totalpages: 49152
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] free_area_init_node: node 0, pgdat c0545b54, node_mem_map c05f0000
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] Normal zone: 384 pages used for memmap
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] Normal zone: 0 pages reserved
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] Normal zone: 48768 pages, LIFO batch:15
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] pcpu-alloc: s0 r0 d32768 u32768 alloc=1_32768
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] pcpu-alloc: [0] 0
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] Built 1 zonelists in Zone order, mobility grouping on. Total pages: 48768
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] Kernel command line: dma.dmachans=0x7f35 bcm2708_fb.fbwidth=656 bcm2708_fb.fbheight=416 bcm2708.boardrev=0x2 bcm2708.serial=0xdb911dbf smsc95xx.macaddr=B8:27:EB:91:1D:BF sdhci-bcm2708.emmc_clock_freq=100000000 vc_mem.mem_base=0xec00000 vc_mem.mem_size=0x10000000 dwc_otg.lpm_enable=0 console=ttyAMA0,115200 kgdboc=ttyAMA0,115200 console=tty1 root=/dev/mmcblk0p2 rootfstype=ext4 elevator=deadline rootwait
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] PID hash table entries: 1024 (order: 0, 4096 bytes)
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] Dentry cache hash table entries: 32768 (order: 5, 131072 bytes)
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] Inode-cache hash table entries: 16384 (order: 4, 65536 bytes)
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] Memory: 192MB = 192MB total
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] Memory: 172324k/172324k available, 24284k reserved, 0K highmem
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] Virtual kernel memory layout:
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] vector : 0xffff0000 - 0xffff1000 ( 4 kB)
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] fixmap : 0xfff00000 - 0xfffe0000 ( 896 kB)
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] vmalloc : 0xcc800000 - 0xff000000 ( 808 MB)
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] lowmem : 0xc0000000 - 0xcc000000 ( 192 MB)
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] modules : 0xbf000000 - 0xc0000000 ( 16 MB)
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] .text : 0xc0008000 - 0xc04ef844 (5023 kB)
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] .init : 0xc04f0000 - 0xc05111f0 ( 133 kB)
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] .data : 0xc0512000 - 0xc0546560 ( 210 kB)
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] .bss : 0xc0546584 - 0xc05ef738 ( 677 kB)
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] SLUB: Genslabs=13, HWalign=32, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] NR_IRQS:330
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] sched_clock: 32 bits at 1000kHz, resolution 1000ns, wraps every 4294967ms
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] Console: colour dummy device 80x30
Sep 17 21:03:20 raspberrypi kernel: [ 0.000000] console [tty1] enabled
Sep 17 21:03:20 raspberrypi kernel: [ 0.000969] Calibrating delay loop... 697.95 BogoMIPS (lpj=3489792)
Sep 17 21:03:20 raspberrypi kernel: [ 0.060125] pid_max: default: 32768 minimum: 301
Sep 17 21:03:20 raspberrypi kernel: [ 0.060609] Mount-cache hash table entries: 512
Sep 17 21:03:20 raspberrypi kernel: [ 0.061417] Initializing cgroup subsys cpuacct
Sep 17 21:03:20 raspberrypi kernel: [ 0.061472] Initializing cgroup subsys devices
Sep 17 21:03:20 raspberrypi kernel: [ 0.061507] Initializing cgroup subsys freezer
Sep 17 21:03:20 raspberrypi kernel: [ 0.061537] Initializing cgroup subsys blkio
Sep 17 21:03:20 raspberrypi kernel: [ 0.061679] CPU: Testing write buffer coherency: ok
Sep 17 21:03:20 raspberrypi kernel: [ 0.062000] hw perfevents: enabled with v6 PMU driver, 3 counters available
Sep 17 21:03:20 raspberrypi kernel: [ 0.062150] Setting up static identity map for 0x3a5238 - 0x3a5294
Sep 17 21:03:20 raspberrypi kernel: [ 0.063620] devtmpfs: initialized
Sep 17 21:03:20 raspberrypi kernel: [ 0.075049] NET: Registered protocol family 16
Sep 17 21:03:20 raspberrypi kernel: [ 0.081421] DMA: preallocated 4096 KiB pool for atomic coherent allocations
Sep 17 21:03:20 raspberrypi kernel: [ 0.082483] bcm2708.uart_clock = 0
Sep 17 21:03:20 raspberrypi kernel: [ 0.083845] hw-breakpoint: found 6 breakpoint and 1 watchpoint registers.
Sep 17 21:03:20 raspberrypi kernel: [ 0.083899] hw-breakpoint: maximum watchpoint size is 4 bytes.
Sep 17 21:03:20 raspberrypi kernel: [ 0.083935] mailbox: Broadcom VideoCore Mailbox driver
Sep 17 21:03:20 raspberrypi kernel: [ 0.084025] bcm2708_vcio: mailbox at f200b880
Sep 17 21:03:20 raspberrypi kernel: [ 0.084136] bcm_power: Broadcom power driver
Sep 17 21:03:20 raspberrypi kernel: [ 0.084172] bcm_power_open() -> 0
Sep 17 21:03:20 raspberrypi kernel: [ 0.084197] bcm_power_request(0, 8)
Sep 17 21:03:20 raspberrypi kernel: [ 0.584881] bcm_mailbox_read -> 00000080, 0
Sep 17 21:03:20 raspberrypi kernel: [ 0.584919] bcm_power_request -> 0
Sep 17 21:03:20 raspberrypi kernel: [ 0.584944] Serial: AMBA PL011 UART driver
Sep 17 21:03:20 raspberrypi kernel: [ 0.585068] dev:f1: ttyAMA0 at MMIO 0x20201000 (irq = 83) is a PL011 rev3
Sep 17 21:03:20 raspberrypi kernel: [ 0.916201] console [ttyAMA0] enabled
Sep 17 21:03:20 raspberrypi kernel: [ 0.940464] bio: create slab at 0
Sep 17 21:03:20 raspberrypi kernel: [ 0.945372] SCSI subsystem initialized
Sep 17 21:03:20 raspberrypi kernel: [ 0.949438] usbcore: registered new interface driver usbfs
Sep 17 21:03:20 raspberrypi kernel: [ 0.955029] usbcore: registered new interface driver hub
Sep 17 21:03:20 raspberrypi kernel: [ 0.960624] usbcore: registered new device driver usb
Sep 17 21:03:20 raspberrypi kernel: [ 0.966966] Switching to clocksource stc
Sep 17 21:03:20 raspberrypi kernel: [ 0.971258] FS-Cache: Loaded
Sep 17 21:03:20 raspberrypi kernel: [ 0.974416] CacheFiles: Loaded
Sep 17 21:03:20 raspberrypi kernel: [ 0.989382] NET: Registered protocol family 2
Sep 17 21:03:20 raspberrypi kernel: [ 0.994647] TCP established hash table entries: 8192 (order: 4, 65536 bytes)
Sep 17 21:03:20 raspberrypi kernel: [ 1.001998] TCP bind hash table entries: 8192 (order: 3, 32768 bytes)
Sep 17 21:03:20 raspberrypi kernel: [ 1.008577] TCP: Hash tables configured (established 8192 bind 8192)
Sep 17 21:03:20 raspberrypi kernel: [ 1.015002] TCP: reno registered
Sep 17 21:03:20 raspberrypi kernel: [ 1.018253] UDP hash table entries: 256 (order: 0, 4096 bytes)
Sep 17 21:03:20 raspberrypi kernel: [ 1.024148] UDP-Lite hash table entries: 256 (order: 0, 4096 bytes)
Sep 17 21:03:20 raspberrypi kernel: [ 1.030763] NET: Registered protocol family 1
Sep 17 21:03:20 raspberrypi kernel: [ 1.035683] RPC: Registered named UNIX socket transport module.
Sep 17 21:03:20 raspberrypi kernel: [ 1.041728] RPC: Registered udp transport module.
Sep 17 21:03:20 raspberrypi kernel: [ 1.046450] RPC: Registered tcp transport module.
Sep 17 21:03:20 raspberrypi kernel: [ 1.051195] RPC: Registered tcp NFSv4.1 backchannel transport module.
Sep 17 21:03:20 raspberrypi kernel: [ 1.058311] bcm2708_dma: DMA manager at f2007000
Sep 17 21:03:20 raspberrypi kernel: [ 1.063091] bcm2708_gpio: bcm2708_gpio_probe c051fdf8
Sep 17 21:03:20 raspberrypi kernel: [ 1.068541] vc-mem: phys_addr:0x00000000 mem_base=0x0ec00000 mem_size:0x10000000(256 MiB)
Sep 17 21:03:20 raspberrypi kernel: [ 1.077743] audit: initializing netlink socket (disabled)
Sep 17 21:03:20 raspberrypi kernel: [ 1.083341] type=2000 audit(0.940:1): initialized
Sep 17 21:03:20 raspberrypi kernel: [ 1.215711] VFS: Disk quotas dquot_6.5.2
Sep 17 21:03:20 raspberrypi kernel: [ 1.219958] Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
Sep 17 21:03:20 raspberrypi kernel: [ 1.229149] FS-Cache: Netfs 'nfs' registered for caching
Sep 17 21:03:20 raspberrypi kernel: [ 1.235801] NFS: Registering the id_resolver key type
Sep 17 21:03:20 raspberrypi kernel: [ 1.240960] Key type id_resolver registered
Sep 17 21:03:20 raspberrypi kernel: [ 1.245264] Key type id_legacy registered
Sep 17 21:03:20 raspberrypi kernel: [ 1.249626] msgmni has been set to 368
Sep 17 21:03:20 raspberrypi kernel: [ 1.255621] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 252)
Sep 17 21:03:20 raspberrypi kernel: [ 1.263441] io scheduler noop registered
Sep 17 21:03:20 raspberrypi kernel: [ 1.267395] io scheduler deadline registered (default)
Sep 17 21:03:20 raspberrypi kernel: [ 1.272721] io scheduler cfq registered
Sep 17 21:03:20 raspberrypi kernel: [ 1.287563] Console: switching to colour frame buffer device 82x26
Sep 17 21:03:20 raspberrypi kernel: [ 1.297696] kgdb: Registered I/O driver kgdboc.
Sep 17 21:03:20 raspberrypi kernel: [ 1.304341] vc-cma: Videocore CMA driver
Sep 17 21:03:20 raspberrypi kernel: [ 1.309678] vc-cma: vc_cma_base = 0x00000000
Sep 17 21:03:20 raspberrypi kernel: [ 1.315819] vc-cma: vc_cma_size = 0x00000000 (0 MiB)
Sep 17 21:03:20 raspberrypi kernel: [ 1.322586] vc-cma: vc_cma_initial = 0x00000000 (0 MiB)
Sep 17 21:03:20 raspberrypi kernel: [ 1.337912] brd: module loaded
Sep 17 21:03:20 raspberrypi kernel: [ 1.347331] loop: module loaded
Sep 17 21:03:20 raspberrypi kernel: [ 1.352158] vchiq: vchiq_init_state: slot_zero = 0xcb000000, is_master = 0
Sep 17 21:03:20 raspberrypi kernel: [ 1.361082] Loading iSCSI transport class v2.0-870.
Sep 17 21:03:20 raspberrypi kernel: [ 1.368229] usbcore: registered new interface driver smsc95xx
Sep 17 21:03:20 raspberrypi kernel: [ 1.375682] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
Sep 17 21:03:20 raspberrypi kernel: [ 1.587921] Core Release: 2.80a
Sep 17 21:03:20 raspberrypi kernel: [ 1.592456] Setting default values for core params
Sep 17 21:03:20 raspberrypi kernel: [ 1.598549] Finished setting default values for core params
Sep 17 21:03:20 raspberrypi kernel: [ 1.810479] Using Buffer DMA mode
Sep 17 21:03:20 raspberrypi kernel: [ 1.815110] Periodic Transfer Interrupt Enhancement - disabled
Sep 17 21:03:20 raspberrypi kernel: [ 1.822221] Multiprocessor Interrupt Enhancement - disabled
Sep 17 21:03:20 raspberrypi kernel: [ 1.829046] OTG VER PARAM: 0, OTG VER FLAG: 0
Sep 17 21:03:20 raspberrypi kernel: [ 1.834674] Dedicated Tx FIFOs mode
Sep 17 21:03:20 raspberrypi kernel: [ 1.840268] dwc_otg: Microframe scheduler enabled
Sep 17 21:03:20 raspberrypi kernel: [ 1.840635] dwc_otg bcm2708_usb: DWC OTG Controller
Sep 17 21:03:20 raspberrypi kernel: [ 1.846942] dwc_otg bcm2708_usb: new USB bus registered, assigned bus number 1
Sep 17 21:03:20 raspberrypi kernel: [ 1.855548] dwc_otg bcm2708_usb: irq 32, io mem 0x00000000
Sep 17 21:03:20 raspberrypi kernel: [ 1.862404] Init: Port Power? op_state=1
Sep 17 21:03:20 raspberrypi kernel: [ 1.867583] Init: Power Port (0)
Sep 17 21:03:20 raspberrypi kernel: [ 1.872251] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
Sep 17 21:03:20 raspberrypi kernel: [ 1.880424] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
Sep 17 21:03:20 raspberrypi kernel: [ 1.889044] usb usb1: Product: DWC OTG Controller
Sep 17 21:03:20 raspberrypi kernel: [ 1.895155] usb usb1: Manufacturer: Linux 3.6.11+ dwc_otg_hcd
Sep 17 21:03:20 raspberrypi kernel: [ 1.902291] usb usb1: SerialNumber: bcm2708_usb
Sep 17 21:03:20 raspberrypi kernel: [ 1.908857] hub 1-0:1.0: USB hub found
Sep 17 21:03:20 raspberrypi kernel: [ 1.914039] hub 1-0:1.0: 1 port detected
Sep 17 21:03:20 raspberrypi kernel: [ 1.919564] dwc_otg: FIQ enabled
Sep 17 21:03:20 raspberrypi kernel: [ 1.919579] dwc_otg: NAK holdoff enabled
Sep 17 21:03:20 raspberrypi kernel: [ 1.919587] dwc_otg: FIQ split fix enabled
Sep 17 21:03:20 raspberrypi kernel: [ 1.919605] Module dwc_common_port init
Sep 17 21:03:20 raspberrypi kernel: [ 1.919826] Initializing USB Mass Storage driver...
Sep 17 21:03:20 raspberrypi kernel: [ 1.926275] usbcore: registered new interface driver usb-storage
Sep 17 21:03:20 raspberrypi kernel: [ 1.933646] USB Mass Storage support registered.
Sep 17 21:03:20 raspberrypi kernel: [ 1.939686] usbcore: registered new interface driver libusual
Sep 17 21:03:20 raspberrypi kernel: [ 1.947061] mousedev: PS/2 mouse device common for all mice
Sep 17 21:03:20 raspberrypi kernel: [ 1.954686] bcm2835-cpufreq: min=700000 max=800000 cur=700000
Sep 17 21:03:20 raspberrypi kernel: [ 1.961892] bcm2835-cpufreq: switching to governor powersave
Sep 17 21:03:20 raspberrypi kernel: [ 1.968831] bcm2835-cpufreq: switching to governor powersave
Sep 17 21:03:20 raspberrypi kernel: [ 1.975770] cpuidle: using governor ladder
Sep 17 21:03:20 raspberrypi kernel: [ 1.981132] cpuidle: using governor menu
Sep 17 21:03:20 raspberrypi kernel: [ 1.986298] sdhci: Secure Digital Host Controller Interface driver
Sep 17 21:03:20 raspberrypi kernel: [ 1.993710] sdhci: Copyright(c) Pierre Ossman
Sep 17 21:03:20 raspberrypi kernel: [ 1.999349] sdhci: Enable low-latency mode
Sep 17 21:03:20 raspberrypi kernel: [ 2.041257] mmc0: SDHCI controller on BCM2708_Arasan [platform] using platform's DMA
Sep 17 21:03:20 raspberrypi kernel: [ 2.051709] mmc0: BCM2708 SDHC host at 0x20300000 DMA 2 IRQ 77
Sep 17 21:03:20 raspberrypi kernel: [ 2.061092] sdhci-pltfm: SDHCI platform and OF driver helper
Sep 17 21:03:20 raspberrypi kernel: [ 2.073815] usbcore: registered new interface driver usbhid
Sep 17 21:03:20 raspberrypi kernel: [ 2.080729] usbhid: USB HID core driver
Sep 17 21:03:20 raspberrypi kernel: [ 2.088632] TCP: cubic registered
Sep 17 21:03:20 raspberrypi kernel: [ 2.095451] Initializing XFRM netlink socket
Sep 17 21:03:20 raspberrypi kernel: [ 2.103215] NET: Registered protocol family 17
Sep 17 21:03:20 raspberrypi kernel: [ 2.111228] Indeed it is in host mode hprt0 = 00021501
Sep 17 21:03:20 raspberrypi kernel: [ 2.117956] Key type dns_resolver registered
Sep 17 21:03:20 raspberrypi kernel: [ 2.131566] VFP support v0.3: implementor 41 architecture 1 part 20 variant b rev 5
Sep 17 21:03:20 raspberrypi kernel: [ 2.152494] registered taskstats version 1
Sep 17 21:03:20 raspberrypi kernel: [ 2.166859] Waiting for root device /dev/mmcblk0p2...
Sep 17 21:03:20 raspberrypi kernel: [ 2.173676] mmc0: new high speed SDHC card at address e624
Sep 17 21:03:20 raspberrypi kernel: [ 2.191374] mmcblk0: mmc0:e624 SU16G 14.8 GiB
Sep 17 21:03:20 raspberrypi kernel: [ 2.200654] mmcblk0: p1 p2
Sep 17 21:03:20 raspberrypi kernel: [ 2.328644] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
Sep 17 21:03:20 raspberrypi kernel: [ 2.339834] VFS: Mounted root (ext4 filesystem) on device 179:2.
Sep 17 21:03:20 raspberrypi kernel: [ 2.347441] usb 1-1: new high-speed USB device number 2 using dwc_otg
Sep 17 21:03:20 raspberrypi kernel: [ 2.355856] Indeed it is in host mode hprt0 = 00001101
Sep 17 21:03:20 raspberrypi kernel: [ 2.370220] devtmpfs: mounted
Sep 17 21:03:20 raspberrypi kernel: [ 2.381497] Freeing init memory: 132K
Sep 17 21:03:20 raspberrypi kernel: [ 2.571778] usb 1-1: New USB device found, idVendor=0424, idProduct=9512
Sep 17 21:03:20 raspberrypi kernel: [ 2.580071] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Sep 17 21:03:20 raspberrypi kernel: [ 2.592859] hub 1-1:1.0: USB hub found
Sep 17 21:03:20 raspberrypi kernel: [ 2.598472] hub 1-1:1.0: 3 ports detected
Sep 17 21:03:20 raspberrypi kernel: [ 2.881365] usb 1-1.1: new high-speed USB device number 3 using dwc_otg
Sep 17 21:03:20 raspberrypi kernel: [ 2.991890] usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00
Sep 17 21:03:20 raspberrypi kernel: [ 3.000369] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
Sep 17 21:03:20 raspberrypi kernel: [ 3.016211] smsc95xx v1.0.4
Sep 17 21:03:20 raspberrypi kernel: [ 3.086076] smsc95xx 1-1.1:1.0: eth0: register 'smsc95xx' at usb-bcm2708_usb-1.1, smsc95xx USB 2.0 Ethernet, b8:27:eb:91:1d:bf
Sep 17 21:03:20 raspberrypi kernel: [ 5.125489] Registered led device: led0
Sep 17 21:03:20 raspberrypi kernel: [ 9.040573] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
Sep 17 21:03:20 raspberrypi kernel: [ 17.729958] Installing knfsd (copyright (C) 1996 okir@monad.swb.de).
Sep 17 21:03:20 raspberrypi kernel: [ 18.118838] smsc95xx 1-1.1:1.0: eth0: link up, 100Mbps, full-duplex, lpa 0xDDE1
Sep 17 21:03:20 raspberrypi kernel: [ 20.719081] bcm2835-cpufreq: switching to governor ondemand
Sep 17 21:03:20 raspberrypi kernel: [ 20.719110] bcm2835-cpufreq: switching to governor ondemand
Sep 17 21:03:22 raspberrypi kernel: [ 25.496175] Adding 102396k swap on /var/swap. Priority:-1 extents:1 across:102396k SS

@dudducat
Copy link
Author

is the previous post ok or do you need more ?
Thanks a lot,
Ste

@P33M
Copy link
Contributor

P33M commented Sep 17, 2013

Your dmesg logs indicate that your SMSC chip is disappearing from the bus - this can be caused by several things, usually inadequate power, but in this case your SMSC chip has decided to stop working presumably without much else going on.

There have been cases where the SMSC chip will stop responding due to faulty soldering on X2 (or a faulty X2 itself), the crystal oscillator responsible for the SMSC chip clock. Is the failure always coincident with starting an application/program or at random?

@dudducat
Copy link
Author

random .... now pi is on but with no disk mounted and seems ok
uptime
22:35:32 up 1:31, 1 user, load average: 0.00, 0.01, 0.05

It usually appear when I mount the disk and start mlnet (anyway these are the only and first action I do when it starts)

@dudducat
Copy link
Author

Used pi without disk for 1 day, ok
Then connected HD and mounted, started minidlna .... another 1 day of uptime
Yesterday started mlnet and limited cpu usage to 50% for mlnet process, till now it's working ....
Can't understand

@P33M
Copy link
Contributor

P33M commented Sep 20, 2013

What happens if you allow the Pi to get warmer? I.e. put it in a box?

@dudducat
Copy link
Author

It's in a case covered by a box with HD and router there are windows for
air
Il giorno 20/set/2013 17:15, "P33M" notifications@github.com ha scritto:

What happens if you allow the Pi to get warmer? I.e. put it in a box?


Reply to this email directly or view it on GitHubhttps://github.com//issues/136#issuecomment-24817591
.

@P33M
Copy link
Contributor

P33M commented Sep 23, 2013

I mean, if you change the temperature of your Pi, does the behaviour change? Can you compare the length of time that it works for with the pi "cold" versus "warm"?

@dudducat
Copy link
Author

Not using cpulimit with ml et pi due quite suddenly. With CPU limit now the
uptime is of five days
Il giorno 23/set/2013 18:49, "P33M" notifications@github.com ha scritto:

I mean, if you change the temperature of your Pi, does the behaviour
change? Can you compare the length of time that it works for with the pi
"cold" versus "warm"?


Reply to this email directly or view it on GitHubhttps://github.com//issues/136#issuecomment-24934588
.

@dudducat
Copy link
Author

dudducat commented Oct 3, 2013

With CPULIMIT my uptime is now of 10 days, so heat or cpu load must be my problem
I'm happy with this solution

@dudducat
Copy link
Author

dudducat commented Oct 7, 2013

an update, yesterday after two weeks of uptime I made an
apt-get update
apt-get upgrade
rpi-update

during rpi-update pi hanged .... restarted, using a new psu (2.1A) but today it is die again.
Sob ....
Bye,
Ste

@P33M
Copy link
Contributor

P33M commented May 5, 2014

Not a software issue: inadequate power or sleepy SMSC crystal.

@P33M P33M closed this as completed May 5, 2014
popcornmix pushed a commit that referenced this issue Oct 8, 2014
In the loop of ftrace_save_ops_tramp_hash(), it adds all the recs
to the ops hash if the rec has only one callback attached and the
ops is connected to the rec. It gives a nasty warning and shuts down
ftrace if the rec doesn't have a trampoline set for it. But this
can happen with the following scenario:

  # cd /sys/kernel/debug/tracing
  # echo schedule do_IRQ > set_ftrace_filter
  # mkdir instances/foo
  # echo schedule > instances/foo/set_ftrace_filter
  # echo function_graph > current_function
  # echo function > instances/foo/current_function
  # echo nop > instances/foo/current_function

The above would then trigger the following warning and disable
ftrace:

 ------------[ cut here ]------------
 WARNING: CPU: 0 PID: 3145 at kernel/trace/ftrace.c:2212 ftrace_run_update_code+0xe4/0x15b()
 Modules linked in: ipt_MASQUERADE sunrpc ip6t_REJECT nf_conntrack_ipv6 nf_defrag_ip [...]
 CPU: 1 PID: 3145 Comm: bash Not tainted 3.16.0-rc3-test+ #136
 Hardware name: To Be Filled By O.E.M. To Be Filled By O.E.M./To be filled by O.E.M., BIOS SDBLI944.86P 05/08/2007
  0000000000000000 ffffffff81808a88 ffffffff81502130 0000000000000000
  ffffffff81040ca1 ffff880077c08000 ffffffff810bd286 0000000000000001
  ffffffff81a56830 ffff88007a041be0 ffff88007a872d60 00000000000001be
 Call Trace:
  [<ffffffff81502130>] ? dump_stack+0x4a/0x75
  [<ffffffff81040ca1>] ? warn_slowpath_common+0x7e/0x97
  [<ffffffff810bd286>] ? ftrace_run_update_code+0xe4/0x15b
  [<ffffffff810bd286>] ? ftrace_run_update_code+0xe4/0x15b
  [<ffffffff810bda1a>] ? ftrace_shutdown+0x11c/0x16b
  [<ffffffff810bda87>] ? unregister_ftrace_function+0x1e/0x38
  [<ffffffff810cc7e1>] ? function_trace_reset+0x1a/0x28
  [<ffffffff810c924f>] ? tracing_set_tracer+0xc1/0x276
  [<ffffffff810c9477>] ? tracing_set_trace_write+0x73/0x91
  [<ffffffff81132383>] ? __sb_start_write+0x9a/0xcc
  [<ffffffff8120478f>] ? security_file_permission+0x1b/0x31
  [<ffffffff81130e49>] ? vfs_write+0xac/0x11c
  [<ffffffff8113115d>] ? SyS_write+0x60/0x8e
  [<ffffffff81508112>] ? system_call_fastpath+0x16/0x1b
 ---[ end trace 938c4415cbc7dc96 ]---
 ------------[ cut here ]------------

Link: http://lkml.kernel.org/r/20140723120805.GB21376@redhat.com

Reported-by: Oleg Nesterov <oleg@redhat.com>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
@alevchuk
Copy link

alevchuk commented Feb 8, 2015

I'm (on B+) getting "dwc_otg_hcd_urb_enqueue:505: Not connected" as soon as I try to use the camera module.

(http://picamera.readthedocs.org/en/release-1.9/recipes1.html) camera.start_preview()

An other times when I try to run camera, the kernel crashes with kernel panic (but I can save the exact error messages).

I have kernel 3.18.6+ #1 PREEMPT with latest firmware.

giraldeau pushed a commit to giraldeau/linux that referenced this issue Apr 12, 2016
rcu_nocb_gp_cleanup() is called while holding rnp->lock. Currently,
this is okay because the wake_up_all() in rcu_nocb_gp_cleanup() will
not enable the IRQs. lockdep is happy.

By switching over using swait this is not true anymore. swake_up_all()
enables the IRQs while processing the waiters. __do_softirq() can now
run and will eventually call rcu_process_callbacks() which wants to
grap nrp->lock.

Let's move the rcu_nocb_gp_cleanup() call outside the lock before we
switch over to swait.

If we would hold the rnp->lock and use swait, lockdep reports
following:

 =================================
 [ INFO: inconsistent lock state ]
 4.2.0-rc5-00025-g9a73ba0 raspberrypi#136 Not tainted
 ---------------------------------
 inconsistent {IN-SOFTIRQ-W} -> {SOFTIRQ-ON-W} usage.
 rcu_preempt/8 [HC0[0]:SC0[0]:HE1:SE1] takes:
  (rcu_node_1){+.?...}, at: [<ffffffff811387c7>] rcu_gp_kthread+0xb97/0xeb0
 {IN-SOFTIRQ-W} state was registered at:
   [<ffffffff81109b9f>] __lock_acquire+0xd5f/0x21e0
   [<ffffffff8110be0f>] lock_acquire+0xdf/0x2b0
   [<ffffffff81841cc9>] _raw_spin_lock_irqsave+0x59/0xa0
   [<ffffffff81136991>] rcu_process_callbacks+0x141/0x3c0
   [<ffffffff810b1a9d>] __do_softirq+0x14d/0x670
   [<ffffffff810b2214>] irq_exit+0x104/0x110
   [<ffffffff81844e96>] smp_apic_timer_interrupt+0x46/0x60
   [<ffffffff81842e70>] apic_timer_interrupt+0x70/0x80
   [<ffffffff810dba66>] rq_attach_root+0xa6/0x100
   [<ffffffff810dbc2d>] cpu_attach_domain+0x16d/0x650
   [<ffffffff810e4b42>] build_sched_domains+0x942/0xb00
   [<ffffffff821777c2>] sched_init_smp+0x509/0x5c1
   [<ffffffff821551e3>] kernel_init_freeable+0x172/0x28f
   [<ffffffff8182cdce>] kernel_init+0xe/0xe0
   [<ffffffff8184231f>] ret_from_fork+0x3f/0x70
 irq event stamp: 76
 hardirqs last  enabled at (75): [<ffffffff81841330>] _raw_spin_unlock_irq+0x30/0x60
 hardirqs last disabled at (76): [<ffffffff8184116f>] _raw_spin_lock_irq+0x1f/0x90
 softirqs last  enabled at (0): [<ffffffff810a8df2>] copy_process.part.26+0x602/0x1cf0
 softirqs last disabled at (0): [<          (null)>]           (null)
 other info that might help us debug this:
  Possible unsafe locking scenario:
        CPU0
        ----
   lock(rcu_node_1);
   <Interrupt>
     lock(rcu_node_1);
  *** DEADLOCK ***
 1 lock held by rcu_preempt/8:
  #0:  (rcu_node_1){+.?...}, at: [<ffffffff811387c7>] rcu_gp_kthread+0xb97/0xeb0
 stack backtrace:
 CPU: 0 PID: 8 Comm: rcu_preempt Not tainted 4.2.0-rc5-00025-g9a73ba0 raspberrypi#136
 Hardware name: Dell Inc. PowerEdge R820/066N7P, BIOS 2.0.20 01/16/2014
  0000000000000000 000000006d7e67d8 ffff881fb081fbd8 ffffffff818379e0
  0000000000000000 ffff881fb0812a00 ffff881fb081fc38 ffffffff8110813b
  0000000000000000 0000000000000001 ffff881f00000001 ffffffff8102fa4f
 Call Trace:
  [<ffffffff818379e0>] dump_stack+0x4f/0x7b
  [<ffffffff8110813b>] print_usage_bug+0x1db/0x1e0
  [<ffffffff8102fa4f>] ? save_stack_trace+0x2f/0x50
  [<ffffffff811087ad>] mark_lock+0x66d/0x6e0
  [<ffffffff81107790>] ? check_usage_forwards+0x150/0x150
  [<ffffffff81108898>] mark_held_locks+0x78/0xa0
  [<ffffffff81841330>] ? _raw_spin_unlock_irq+0x30/0x60
  [<ffffffff81108a28>] trace_hardirqs_on_caller+0x168/0x220
  [<ffffffff81108aed>] trace_hardirqs_on+0xd/0x10
  [<ffffffff81841330>] _raw_spin_unlock_irq+0x30/0x60
  [<ffffffff810fd1c7>] swake_up_all+0xb7/0xe0
  [<ffffffff811386e1>] rcu_gp_kthread+0xab1/0xeb0
  [<ffffffff811089bf>] ? trace_hardirqs_on_caller+0xff/0x220
  [<ffffffff81841341>] ? _raw_spin_unlock_irq+0x41/0x60
  [<ffffffff81137c30>] ? rcu_barrier+0x20/0x20
  [<ffffffff810d2014>] kthread+0x104/0x120
  [<ffffffff81841330>] ? _raw_spin_unlock_irq+0x30/0x60
  [<ffffffff810d1f10>] ? kthread_create_on_node+0x260/0x260
  [<ffffffff8184231f>] ret_from_fork+0x3f/0x70
  [<ffffffff810d1f10>] ? kthread_create_on_node+0x260/0x260

Signed-off-by: Daniel Wagner <daniel.wagner@bmw-carit.de>
Acked-by: Peter Zijlstra (Intel) <peterz@infradead.org>
Cc: linux-rt-users@vger.kernel.org
Cc: Boqun Feng <boqun.feng@gmail.com>
Cc: Marcelo Tosatti <mtosatti@redhat.com>
Cc: Steven Rostedt <rostedt@goodmis.org>
Cc: Paul Gortmaker <paul.gortmaker@windriver.com>
Cc: Paolo Bonzini <pbonzini@redhat.com>
Cc: "Paul E. McKenney" <paulmck@linux.vnet.ibm.com>
Link: http://lkml.kernel.org/r/1455871601-27484-5-git-send-email-wagi@monom.org
Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
popcornmix pushed a commit that referenced this issue Jul 30, 2018
vma_is_anonymous() relies on ->vm_ops being NULL to detect anonymous
VMA.  This is unreliable as ->mmap may not set ->vm_ops.

False-positive vma_is_anonymous() may lead to crashes:

	next ffff8801ce5e7040 prev ffff8801d20eca50 mm ffff88019c1e13c0
	prot 27 anon_vma ffff88019680cdd8 vm_ops 0000000000000000
	pgoff 0 file ffff8801b2ec2d00 private_data 0000000000000000
	flags: 0xff(read|write|exec|shared|mayread|maywrite|mayexec|mayshare)
	------------[ cut here ]------------
	kernel BUG at mm/memory.c:1422!
	invalid opcode: 0000 [#1] SMP KASAN
	CPU: 0 PID: 18486 Comm: syz-executor3 Not tainted 4.18.0-rc3+ #136
	Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google
	01/01/2011
	RIP: 0010:zap_pmd_range mm/memory.c:1421 [inline]
	RIP: 0010:zap_pud_range mm/memory.c:1466 [inline]
	RIP: 0010:zap_p4d_range mm/memory.c:1487 [inline]
	RIP: 0010:unmap_page_range+0x1c18/0x2220 mm/memory.c:1508
	Call Trace:
	 unmap_single_vma+0x1a0/0x310 mm/memory.c:1553
	 zap_page_range_single+0x3cc/0x580 mm/memory.c:1644
	 unmap_mapping_range_vma mm/memory.c:2792 [inline]
	 unmap_mapping_range_tree mm/memory.c:2813 [inline]
	 unmap_mapping_pages+0x3a7/0x5b0 mm/memory.c:2845
	 unmap_mapping_range+0x48/0x60 mm/memory.c:2880
	 truncate_pagecache+0x54/0x90 mm/truncate.c:800
	 truncate_setsize+0x70/0xb0 mm/truncate.c:826
	 simple_setattr+0xe9/0x110 fs/libfs.c:409
	 notify_change+0xf13/0x10f0 fs/attr.c:335
	 do_truncate+0x1ac/0x2b0 fs/open.c:63
	 do_sys_ftruncate+0x492/0x560 fs/open.c:205
	 __do_sys_ftruncate fs/open.c:215 [inline]
	 __se_sys_ftruncate fs/open.c:213 [inline]
	 __x64_sys_ftruncate+0x59/0x80 fs/open.c:213
	 do_syscall_64+0x1b9/0x820 arch/x86/entry/common.c:290
	 entry_SYSCALL_64_after_hwframe+0x49/0xbe

Reproducer:

	#include <stdio.h>
	#include <stddef.h>
	#include <stdint.h>
	#include <stdlib.h>
	#include <string.h>
	#include <sys/types.h>
	#include <sys/stat.h>
	#include <sys/ioctl.h>
	#include <sys/mman.h>
	#include <unistd.h>
	#include <fcntl.h>

	#define KCOV_INIT_TRACE			_IOR('c', 1, unsigned long)
	#define KCOV_ENABLE			_IO('c', 100)
	#define KCOV_DISABLE			_IO('c', 101)
	#define COVER_SIZE			(1024<<10)

	#define KCOV_TRACE_PC  0
	#define KCOV_TRACE_CMP 1

	int main(int argc, char **argv)
	{
		int fd;
		unsigned long *cover;

		system("mount -t debugfs none /sys/kernel/debug");
		fd = open("/sys/kernel/debug/kcov", O_RDWR);
		ioctl(fd, KCOV_INIT_TRACE, COVER_SIZE);
		cover = mmap(NULL, COVER_SIZE * sizeof(unsigned long),
				PROT_READ | PROT_WRITE, MAP_SHARED, fd, 0);
		munmap(cover, COVER_SIZE * sizeof(unsigned long));
		cover = mmap(NULL, COVER_SIZE * sizeof(unsigned long),
				PROT_READ | PROT_WRITE, MAP_PRIVATE, fd, 0);
		memset(cover, 0, COVER_SIZE * sizeof(unsigned long));
		ftruncate(fd, 3UL << 20);
		return 0;
	}

This can be fixed by assigning anonymous VMAs own vm_ops and not relying
on it being NULL.

If ->mmap() failed to set ->vm_ops, mmap_region() will set it to
dummy_vm_ops.  This way we will have non-NULL ->vm_ops for all VMAs.

Link: http://lkml.kernel.org/r/20180724121139.62570-4-kirill.shutemov@linux.intel.com
Signed-off-by: Kirill A. Shutemov <kirill.shutemov@linux.intel.com>
Reported-by: syzbot+3f84280d52be9b7083cc@syzkaller.appspotmail.com
Acked-by: Linus Torvalds <torvalds@linux-foundation.org>
Reviewed-by: Andrew Morton <akpm@linux-foundation.org>
Cc: Dmitry Vyukov <dvyukov@google.com>
Cc: Oleg Nesterov <oleg@redhat.com>
Cc: Andrea Arcangeli <aarcange@redhat.com>
Cc: <stable@vger.kernel.org>
Signed-off-by: Andrew Morton <akpm@linux-foundation.org>
Signed-off-by: Linus Torvalds <torvalds@linux-foundation.org>
popcornmix pushed a commit that referenced this issue Apr 23, 2019
[ Upstream commit 6a3b45a ]

MIXER on Exynos5 SoCs uses different synchronisation method than Exynos4
to update internal state (shadow registers).
Apparently the driver implements it incorrectly. The rule should be
as follows:
- do not request updating registers until previous request was finished,
  ie. MXR_CFG_LAYER_UPDATE_COUNT must be 0.
- before setting registers synchronisation on VSYNC should be turned off,
  ie. MXR_STATUS_SYNC_ENABLE should be reset,
- after finishing MXR_STATUS_SYNC_ENABLE should be set again.
The patch hopefully implements it correctly.
Below sample kernel log from page fault caused by the bug:

[   25.670038] exynos-sysmmu 14650000.sysmmu: 14450000.mixer: PAGE FAULT occurred at 0x2247b800
[   25.677888] ------------[ cut here ]------------
[   25.682164] kernel BUG at ../drivers/iommu/exynos-iommu.c:450!
[   25.687971] Internal error: Oops - BUG: 0 [#1] PREEMPT SMP ARM
[   25.693778] Modules linked in:
[   25.696816] CPU: 5 PID: 1553 Comm: fb-release_test Not tainted 5.0.0-rc7-01157-g5f86b1566bdd #136
[   25.705646] Hardware name: SAMSUNG EXYNOS (Flattened Device Tree)
[   25.711710] PC is at exynos_sysmmu_irq+0x1c0/0x264
[   25.716470] LR is at lock_is_held_type+0x44/0x64

v2: added missing MXR_CFG_LAYER_UPDATE bit setting in mixer_enable_sync

Reported-by: Marian Mihailescu <mihailescu2m@gmail.com>
Signed-off-by: Andrzej Hajda <a.hajda@samsung.com>
Signed-off-by: Inki Dae <inki.dae@samsung.com>
Signed-off-by: Sasha Levin <sashal@kernel.org>
popcornmix pushed a commit that referenced this issue Apr 23, 2019
[ Upstream commit 6a3b45a ]

MIXER on Exynos5 SoCs uses different synchronisation method than Exynos4
to update internal state (shadow registers).
Apparently the driver implements it incorrectly. The rule should be
as follows:
- do not request updating registers until previous request was finished,
  ie. MXR_CFG_LAYER_UPDATE_COUNT must be 0.
- before setting registers synchronisation on VSYNC should be turned off,
  ie. MXR_STATUS_SYNC_ENABLE should be reset,
- after finishing MXR_STATUS_SYNC_ENABLE should be set again.
The patch hopefully implements it correctly.
Below sample kernel log from page fault caused by the bug:

[   25.670038] exynos-sysmmu 14650000.sysmmu: 14450000.mixer: PAGE FAULT occurred at 0x2247b800
[   25.677888] ------------[ cut here ]------------
[   25.682164] kernel BUG at ../drivers/iommu/exynos-iommu.c:450!
[   25.687971] Internal error: Oops - BUG: 0 [#1] PREEMPT SMP ARM
[   25.693778] Modules linked in:
[   25.696816] CPU: 5 PID: 1553 Comm: fb-release_test Not tainted 5.0.0-rc7-01157-g5f86b1566bdd #136
[   25.705646] Hardware name: SAMSUNG EXYNOS (Flattened Device Tree)
[   25.711710] PC is at exynos_sysmmu_irq+0x1c0/0x264
[   25.716470] LR is at lock_is_held_type+0x44/0x64

v2: added missing MXR_CFG_LAYER_UPDATE bit setting in mixer_enable_sync

Reported-by: Marian Mihailescu <mihailescu2m@gmail.com>
Signed-off-by: Andrzej Hajda <a.hajda@samsung.com>
Signed-off-by: Inki Dae <inki.dae@samsung.com>
Signed-off-by: Sasha Levin <sashal@kernel.org>
herrnst pushed a commit to herrnst/linux-raspberrypi that referenced this issue Apr 14, 2022
commit 3c69611 upstream.

In commit 9a69e2b ("bpf: Make remote_port field in struct
bpf_sk_lookup 16-bit wide") ->remote_port field changed from __u32 to
__be16.

However, narrow load tests which exercise 1-byte sized loads from
offsetof(struct bpf_sk_lookup, remote_port) were not adopted to reflect the
change.

As a result, on little-endian we continue testing loads from addresses:

 - (__u8 *)&ctx->remote_port + 3
 - (__u8 *)&ctx->remote_port + 4

which map to the zero padding following the remote_port field, and don't
break the tests because there is no observable change.

While on big-endian, we observe breakage because tests expect to see zeros
for values loaded from:

 - (__u8 *)&ctx->remote_port - 1
 - (__u8 *)&ctx->remote_port - 2

Above addresses map to ->remote_ip6 field, which precedes ->remote_port,
and are populated during the bpf_sk_lookup IPv6 tests.

Unsurprisingly, on s390x we observe:

  raspberrypi#136/38 sk_lookup/narrow access to ctx v4:OK
  raspberrypi#136/39 sk_lookup/narrow access to ctx v6:FAIL

Fix it by removing the checks for 1-byte loads from offsets outside of the
->remote_port field.

Fixes: 9a69e2b ("bpf: Make remote_port field in struct bpf_sk_lookup 16-bit wide")
Suggested-by: Ilya Leoshkevich <iii@linux.ibm.com>
Signed-off-by: Jakub Sitnicki <jakub@cloudflare.com>
Signed-off-by: Alexei Starovoitov <ast@kernel.org>
Acked-by: Martin KaFai Lau <kafai@fb.com>
Link: https://lore.kernel.org/bpf/20220319183356.233666-3-jakub@cloudflare.com
Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
popcornmix pushed a commit that referenced this issue Apr 19, 2022
commit 3c69611 upstream.

In commit 9a69e2b ("bpf: Make remote_port field in struct
bpf_sk_lookup 16-bit wide") ->remote_port field changed from __u32 to
__be16.

However, narrow load tests which exercise 1-byte sized loads from
offsetof(struct bpf_sk_lookup, remote_port) were not adopted to reflect the
change.

As a result, on little-endian we continue testing loads from addresses:

 - (__u8 *)&ctx->remote_port + 3
 - (__u8 *)&ctx->remote_port + 4

which map to the zero padding following the remote_port field, and don't
break the tests because there is no observable change.

While on big-endian, we observe breakage because tests expect to see zeros
for values loaded from:

 - (__u8 *)&ctx->remote_port - 1
 - (__u8 *)&ctx->remote_port - 2

Above addresses map to ->remote_ip6 field, which precedes ->remote_port,
and are populated during the bpf_sk_lookup IPv6 tests.

Unsurprisingly, on s390x we observe:

  #136/38 sk_lookup/narrow access to ctx v4:OK
  #136/39 sk_lookup/narrow access to ctx v6:FAIL

Fix it by removing the checks for 1-byte loads from offsets outside of the
->remote_port field.

Fixes: 9a69e2b ("bpf: Make remote_port field in struct bpf_sk_lookup 16-bit wide")
Suggested-by: Ilya Leoshkevich <iii@linux.ibm.com>
Signed-off-by: Jakub Sitnicki <jakub@cloudflare.com>
Signed-off-by: Alexei Starovoitov <ast@kernel.org>
Acked-by: Martin KaFai Lau <kafai@fb.com>
Link: https://lore.kernel.org/bpf/20220319183356.233666-3-jakub@cloudflare.com
Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
popcornmix pushed a commit that referenced this issue Apr 19, 2022
commit 3c69611 upstream.

In commit 9a69e2b ("bpf: Make remote_port field in struct
bpf_sk_lookup 16-bit wide") ->remote_port field changed from __u32 to
__be16.

However, narrow load tests which exercise 1-byte sized loads from
offsetof(struct bpf_sk_lookup, remote_port) were not adopted to reflect the
change.

As a result, on little-endian we continue testing loads from addresses:

 - (__u8 *)&ctx->remote_port + 3
 - (__u8 *)&ctx->remote_port + 4

which map to the zero padding following the remote_port field, and don't
break the tests because there is no observable change.

While on big-endian, we observe breakage because tests expect to see zeros
for values loaded from:

 - (__u8 *)&ctx->remote_port - 1
 - (__u8 *)&ctx->remote_port - 2

Above addresses map to ->remote_ip6 field, which precedes ->remote_port,
and are populated during the bpf_sk_lookup IPv6 tests.

Unsurprisingly, on s390x we observe:

  #136/38 sk_lookup/narrow access to ctx v4:OK
  #136/39 sk_lookup/narrow access to ctx v6:FAIL

Fix it by removing the checks for 1-byte loads from offsets outside of the
->remote_port field.

Fixes: 9a69e2b ("bpf: Make remote_port field in struct bpf_sk_lookup 16-bit wide")
Suggested-by: Ilya Leoshkevich <iii@linux.ibm.com>
Signed-off-by: Jakub Sitnicki <jakub@cloudflare.com>
Signed-off-by: Alexei Starovoitov <ast@kernel.org>
Acked-by: Martin KaFai Lau <kafai@fb.com>
Link: https://lore.kernel.org/bpf/20220319183356.233666-3-jakub@cloudflare.com
Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
popcornmix pushed a commit that referenced this issue Jun 20, 2022
Fix our pointer offset usage in error_state_read
when there is no i915_gpu_coredump but buf offset
is non-zero.

This fixes a kernel page fault can happen when
multiple tests are running concurrently in a loop
and one is producing engine resets and consuming
the i915 error_state dump while the other is
forcing full GT resets. (takes a while to trigger).

The dmesg call trace:

[ 5590.803000] BUG: unable to handle page fault for address:
               ffffffffa0b0e000
[ 5590.803009] #PF: supervisor read access in kernel mode
[ 5590.803013] #PF: error_code(0x0000) - not-present page
[ 5590.803016] PGD 5814067 P4D 5814067 PUD 5815063 PMD 109de4067
               PTE 0
[ 5590.803022] Oops: 0000 [#1] PREEMPT SMP NOPTI
[ 5590.803026] CPU: 5 PID: 13656 Comm: i915_hangman Tainted: G U
                    5.17.0-rc5-ups69-guc-err-capt-rev6+ #136
[ 5590.803033] Hardware name: Intel Corporation Alder Lake Client
                    Platform/AlderLake-M LP4x RVP, BIOS ADLPFWI1.R00.
                    3031.A02.2201171222	01/17/2022
[ 5590.803039] RIP: 0010:memcpy_erms+0x6/0x10
[ 5590.803045] Code: fe ff ff cc eb 1e 0f 1f 00 48 89 f8 48 89 d1
                     48 c1 e9 03 83 e2 07 f3 48 a5 89 d1 f3 a4 c3
                     66 0f 1f 44 00 00 48 89 f8 48 89 d1 <f3> a4
                     c3 0f 1f 80 00 00 00 00 48 89 f8 48 83 fa 20
                     72 7e 40 38 fe
[ 5590.803054] RSP: 0018:ffffc90003a8fdf0 EFLAGS: 00010282
[ 5590.803057] RAX: ffff888107ee9000 RBX: ffff888108cb1a00
               RCX: 0000000000000f8f
[ 5590.803061] RDX: 0000000000001000 RSI: ffffffffa0b0e000
               RDI: ffff888107ee9071
[ 5590.803065] RBP: 0000000000000000 R08: 0000000000000001
               R09: 0000000000000001
[ 5590.803069] R10: 0000000000000001 R11: 0000000000000002
               R12: 0000000000000019
[ 5590.803073] R13: 0000000000174fff R14: 0000000000001000
               R15: ffff888107ee9000
[ 5590.803077] FS: 00007f62a99bee80(0000) GS:ffff88849f880000(0000)
               knlGS:0000000000000000
[ 5590.803082] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 5590.803085] CR2: ffffffffa0b0e000 CR3: 000000010a1a8004
               CR4: 0000000000770ee0
[ 5590.803089] PKRU: 55555554
[ 5590.803091] Call Trace:
[ 5590.803093] <TASK>
[ 5590.803096] error_state_read+0xa1/0xd0 [i915]
[ 5590.803175] kernfs_fop_read_iter+0xb2/0x1b0
[ 5590.803180] new_sync_read+0x116/0x1a0
[ 5590.803185] vfs_read+0x114/0x1b0
[ 5590.803189] ksys_read+0x63/0xe0
[ 5590.803193] do_syscall_64+0x38/0xc0
[ 5590.803197] entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 5590.803201] RIP: 0033:0x7f62aaea5912
[ 5590.803204] Code: c0 e9 b2 fe ff ff 50 48 8d 3d 5a b9 0c 00 e8 05
                     19 02 00 0f 1f 44 00 00 f3 0f 1e fa 64 8b 04 25
                     18 00 00 00 85 c0 75 10 0f 05 <48> 3d 00 f0 ff
                     ff 77 56 c3 0f 1f 44 00 00 48 83 ec 28 48 89 54 24
[ 5590.803213] RSP: 002b:00007fff5b659ae8 EFLAGS: 00000246
               ORIG_RAX: 0000000000000000
[ 5590.803218] RAX: ffffffffffffffda RBX: 0000000000100000
               RCX: 00007f62aaea5912
[ 5590.803221] RDX: 000000000008b000 RSI: 00007f62a8c4000f
               RDI: 0000000000000006
[ 5590.803225] RBP: 00007f62a8bcb00f R08: 0000000000200010
               R09: 0000000000101000
[ 5590.803229] R10: 0000000000000001 R11: 0000000000000246
               R12: 0000000000000006
[ 5590.803233] R13: 0000000000075000 R14: 00007f62a8acb010
               R15: 0000000000200000
[ 5590.803238] </TASK>
[ 5590.803240] Modules linked in: i915 ttm drm_buddy drm_dp_helper
                        drm_kms_helper syscopyarea sysfillrect sysimgblt
                        fb_sys_fops prime_numbers nfnetlink br_netfilter
                        overlay mei_pxp mei_hdcp x86_pkg_temp_thermal
                        coretemp kvm_intel snd_hda_codec_hdmi snd_hda_intel
                        snd_intel_dspcfg snd_hda_codec snd_hwdep
                        snd_hda_core snd_pcm mei_me mei fuse ip_tables
                        x_tables crct10dif_pclmul e1000e crc32_pclmul ptp
                        i2c_i801 ghash_clmulni_intel i2c_smbus pps_core
                        [last unloa ded: ttm]
[ 5590.803277] CR2: ffffffffa0b0e000
[ 5590.803280] ---[ end trace 0000000000000000 ]---

Fixes: 0e39037 ("drm/i915: Cache the error string")
Signed-off-by: Alan Previn <alan.previn.teres.alexis@intel.com>
Reviewed-by: John Harrison <John.C.Harrison@Intel.com>
Signed-off-by: John Harrison <John.C.Harrison@Intel.com>
Link: https://patchwork.freedesktop.org/patch/msgid/20220311004311.514198-2-alan.previn.teres.alexis@intel.com
(cherry picked from commit 3304033)
Signed-off-by: Jani Nikula <jani.nikula@intel.com>
popcornmix pushed a commit that referenced this issue Jun 24, 2022
[ Upstream commit c9b576d ]

Fix our pointer offset usage in error_state_read
when there is no i915_gpu_coredump but buf offset
is non-zero.

This fixes a kernel page fault can happen when
multiple tests are running concurrently in a loop
and one is producing engine resets and consuming
the i915 error_state dump while the other is
forcing full GT resets. (takes a while to trigger).

The dmesg call trace:

[ 5590.803000] BUG: unable to handle page fault for address:
               ffffffffa0b0e000
[ 5590.803009] #PF: supervisor read access in kernel mode
[ 5590.803013] #PF: error_code(0x0000) - not-present page
[ 5590.803016] PGD 5814067 P4D 5814067 PUD 5815063 PMD 109de4067
               PTE 0
[ 5590.803022] Oops: 0000 [#1] PREEMPT SMP NOPTI
[ 5590.803026] CPU: 5 PID: 13656 Comm: i915_hangman Tainted: G U
                    5.17.0-rc5-ups69-guc-err-capt-rev6+ #136
[ 5590.803033] Hardware name: Intel Corporation Alder Lake Client
                    Platform/AlderLake-M LP4x RVP, BIOS ADLPFWI1.R00.
                    3031.A02.2201171222	01/17/2022
[ 5590.803039] RIP: 0010:memcpy_erms+0x6/0x10
[ 5590.803045] Code: fe ff ff cc eb 1e 0f 1f 00 48 89 f8 48 89 d1
                     48 c1 e9 03 83 e2 07 f3 48 a5 89 d1 f3 a4 c3
                     66 0f 1f 44 00 00 48 89 f8 48 89 d1 <f3> a4
                     c3 0f 1f 80 00 00 00 00 48 89 f8 48 83 fa 20
                     72 7e 40 38 fe
[ 5590.803054] RSP: 0018:ffffc90003a8fdf0 EFLAGS: 00010282
[ 5590.803057] RAX: ffff888107ee9000 RBX: ffff888108cb1a00
               RCX: 0000000000000f8f
[ 5590.803061] RDX: 0000000000001000 RSI: ffffffffa0b0e000
               RDI: ffff888107ee9071
[ 5590.803065] RBP: 0000000000000000 R08: 0000000000000001
               R09: 0000000000000001
[ 5590.803069] R10: 0000000000000001 R11: 0000000000000002
               R12: 0000000000000019
[ 5590.803073] R13: 0000000000174fff R14: 0000000000001000
               R15: ffff888107ee9000
[ 5590.803077] FS: 00007f62a99bee80(0000) GS:ffff88849f880000(0000)
               knlGS:0000000000000000
[ 5590.803082] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 5590.803085] CR2: ffffffffa0b0e000 CR3: 000000010a1a8004
               CR4: 0000000000770ee0
[ 5590.803089] PKRU: 55555554
[ 5590.803091] Call Trace:
[ 5590.803093] <TASK>
[ 5590.803096] error_state_read+0xa1/0xd0 [i915]
[ 5590.803175] kernfs_fop_read_iter+0xb2/0x1b0
[ 5590.803180] new_sync_read+0x116/0x1a0
[ 5590.803185] vfs_read+0x114/0x1b0
[ 5590.803189] ksys_read+0x63/0xe0
[ 5590.803193] do_syscall_64+0x38/0xc0
[ 5590.803197] entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 5590.803201] RIP: 0033:0x7f62aaea5912
[ 5590.803204] Code: c0 e9 b2 fe ff ff 50 48 8d 3d 5a b9 0c 00 e8 05
                     19 02 00 0f 1f 44 00 00 f3 0f 1e fa 64 8b 04 25
                     18 00 00 00 85 c0 75 10 0f 05 <48> 3d 00 f0 ff
                     ff 77 56 c3 0f 1f 44 00 00 48 83 ec 28 48 89 54 24
[ 5590.803213] RSP: 002b:00007fff5b659ae8 EFLAGS: 00000246
               ORIG_RAX: 0000000000000000
[ 5590.803218] RAX: ffffffffffffffda RBX: 0000000000100000
               RCX: 00007f62aaea5912
[ 5590.803221] RDX: 000000000008b000 RSI: 00007f62a8c4000f
               RDI: 0000000000000006
[ 5590.803225] RBP: 00007f62a8bcb00f R08: 0000000000200010
               R09: 0000000000101000
[ 5590.803229] R10: 0000000000000001 R11: 0000000000000246
               R12: 0000000000000006
[ 5590.803233] R13: 0000000000075000 R14: 00007f62a8acb010
               R15: 0000000000200000
[ 5590.803238] </TASK>
[ 5590.803240] Modules linked in: i915 ttm drm_buddy drm_dp_helper
                        drm_kms_helper syscopyarea sysfillrect sysimgblt
                        fb_sys_fops prime_numbers nfnetlink br_netfilter
                        overlay mei_pxp mei_hdcp x86_pkg_temp_thermal
                        coretemp kvm_intel snd_hda_codec_hdmi snd_hda_intel
                        snd_intel_dspcfg snd_hda_codec snd_hwdep
                        snd_hda_core snd_pcm mei_me mei fuse ip_tables
                        x_tables crct10dif_pclmul e1000e crc32_pclmul ptp
                        i2c_i801 ghash_clmulni_intel i2c_smbus pps_core
                        [last unloa ded: ttm]
[ 5590.803277] CR2: ffffffffa0b0e000
[ 5590.803280] ---[ end trace 0000000000000000 ]---

Fixes: 0e39037 ("drm/i915: Cache the error string")
Signed-off-by: Alan Previn <alan.previn.teres.alexis@intel.com>
Reviewed-by: John Harrison <John.C.Harrison@Intel.com>
Signed-off-by: John Harrison <John.C.Harrison@Intel.com>
Link: https://patchwork.freedesktop.org/patch/msgid/20220311004311.514198-2-alan.previn.teres.alexis@intel.com
(cherry picked from commit 3304033)
Signed-off-by: Jani Nikula <jani.nikula@intel.com>
Signed-off-by: Sasha Levin <sashal@kernel.org>
herrnst pushed a commit to herrnst/linux-raspberrypi that referenced this issue Jul 10, 2022
[ Upstream commit c9b576d ]

Fix our pointer offset usage in error_state_read
when there is no i915_gpu_coredump but buf offset
is non-zero.

This fixes a kernel page fault can happen when
multiple tests are running concurrently in a loop
and one is producing engine resets and consuming
the i915 error_state dump while the other is
forcing full GT resets. (takes a while to trigger).

The dmesg call trace:

[ 5590.803000] BUG: unable to handle page fault for address:
               ffffffffa0b0e000
[ 5590.803009] #PF: supervisor read access in kernel mode
[ 5590.803013] #PF: error_code(0x0000) - not-present page
[ 5590.803016] PGD 5814067 P4D 5814067 PUD 5815063 PMD 109de4067
               PTE 0
[ 5590.803022] Oops: 0000 [raspberrypi#1] PREEMPT SMP NOPTI
[ 5590.803026] CPU: 5 PID: 13656 Comm: i915_hangman Tainted: G U
                    5.17.0-rc5-ups69-guc-err-capt-rev6+ raspberrypi#136
[ 5590.803033] Hardware name: Intel Corporation Alder Lake Client
                    Platform/AlderLake-M LP4x RVP, BIOS ADLPFWI1.R00.
                    3031.A02.2201171222	01/17/2022
[ 5590.803039] RIP: 0010:memcpy_erms+0x6/0x10
[ 5590.803045] Code: fe ff ff cc eb 1e 0f 1f 00 48 89 f8 48 89 d1
                     48 c1 e9 03 83 e2 07 f3 48 a5 89 d1 f3 a4 c3
                     66 0f 1f 44 00 00 48 89 f8 48 89 d1 <f3> a4
                     c3 0f 1f 80 00 00 00 00 48 89 f8 48 83 fa 20
                     72 7e 40 38 fe
[ 5590.803054] RSP: 0018:ffffc90003a8fdf0 EFLAGS: 00010282
[ 5590.803057] RAX: ffff888107ee9000 RBX: ffff888108cb1a00
               RCX: 0000000000000f8f
[ 5590.803061] RDX: 0000000000001000 RSI: ffffffffa0b0e000
               RDI: ffff888107ee9071
[ 5590.803065] RBP: 0000000000000000 R08: 0000000000000001
               R09: 0000000000000001
[ 5590.803069] R10: 0000000000000001 R11: 0000000000000002
               R12: 0000000000000019
[ 5590.803073] R13: 0000000000174fff R14: 0000000000001000
               R15: ffff888107ee9000
[ 5590.803077] FS: 00007f62a99bee80(0000) GS:ffff88849f880000(0000)
               knlGS:0000000000000000
[ 5590.803082] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 5590.803085] CR2: ffffffffa0b0e000 CR3: 000000010a1a8004
               CR4: 0000000000770ee0
[ 5590.803089] PKRU: 55555554
[ 5590.803091] Call Trace:
[ 5590.803093] <TASK>
[ 5590.803096] error_state_read+0xa1/0xd0 [i915]
[ 5590.803175] kernfs_fop_read_iter+0xb2/0x1b0
[ 5590.803180] new_sync_read+0x116/0x1a0
[ 5590.803185] vfs_read+0x114/0x1b0
[ 5590.803189] ksys_read+0x63/0xe0
[ 5590.803193] do_syscall_64+0x38/0xc0
[ 5590.803197] entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 5590.803201] RIP: 0033:0x7f62aaea5912
[ 5590.803204] Code: c0 e9 b2 fe ff ff 50 48 8d 3d 5a b9 0c 00 e8 05
                     19 02 00 0f 1f 44 00 00 f3 0f 1e fa 64 8b 04 25
                     18 00 00 00 85 c0 75 10 0f 05 <48> 3d 00 f0 ff
                     ff 77 56 c3 0f 1f 44 00 00 48 83 ec 28 48 89 54 24
[ 5590.803213] RSP: 002b:00007fff5b659ae8 EFLAGS: 00000246
               ORIG_RAX: 0000000000000000
[ 5590.803218] RAX: ffffffffffffffda RBX: 0000000000100000
               RCX: 00007f62aaea5912
[ 5590.803221] RDX: 000000000008b000 RSI: 00007f62a8c4000f
               RDI: 0000000000000006
[ 5590.803225] RBP: 00007f62a8bcb00f R08: 0000000000200010
               R09: 0000000000101000
[ 5590.803229] R10: 0000000000000001 R11: 0000000000000246
               R12: 0000000000000006
[ 5590.803233] R13: 0000000000075000 R14: 00007f62a8acb010
               R15: 0000000000200000
[ 5590.803238] </TASK>
[ 5590.803240] Modules linked in: i915 ttm drm_buddy drm_dp_helper
                        drm_kms_helper syscopyarea sysfillrect sysimgblt
                        fb_sys_fops prime_numbers nfnetlink br_netfilter
                        overlay mei_pxp mei_hdcp x86_pkg_temp_thermal
                        coretemp kvm_intel snd_hda_codec_hdmi snd_hda_intel
                        snd_intel_dspcfg snd_hda_codec snd_hwdep
                        snd_hda_core snd_pcm mei_me mei fuse ip_tables
                        x_tables crct10dif_pclmul e1000e crc32_pclmul ptp
                        i2c_i801 ghash_clmulni_intel i2c_smbus pps_core
                        [last unloa ded: ttm]
[ 5590.803277] CR2: ffffffffa0b0e000
[ 5590.803280] ---[ end trace 0000000000000000 ]---

Fixes: 0e39037 ("drm/i915: Cache the error string")
Signed-off-by: Alan Previn <alan.previn.teres.alexis@intel.com>
Reviewed-by: John Harrison <John.C.Harrison@Intel.com>
Signed-off-by: John Harrison <John.C.Harrison@Intel.com>
Link: https://patchwork.freedesktop.org/patch/msgid/20220311004311.514198-2-alan.previn.teres.alexis@intel.com
(cherry picked from commit 3304033)
Signed-off-by: Jani Nikula <jani.nikula@intel.com>
Signed-off-by: Sasha Levin <sashal@kernel.org>
popcornmix pushed a commit that referenced this issue Sep 13, 2023
[ Upstream commit 7f74563 ]

LE Create CIS command shall not be sent before all CIS Established
events from its previous invocation have been processed. Currently it is
sent via hci_sync but that only waits for the first event, but there can
be multiple.

Make it wait for all events, and simplify the CIS creation as follows:

Add new flag HCI_CONN_CREATE_CIS, which is set if Create CIS has been
sent for the connection but it is not yet completed.

Make BT_CONNECT state to mean the connection wants Create CIS.

On events after which new Create CIS may need to be sent, send it if
possible and some connections need it. These events are:
hci_connect_cis, iso_connect_cfm, hci_cs_le_create_cis,
hci_le_cis_estabilished_evt.

The Create CIS status/completion events shall queue new Create CIS only
if at least one of the connections transitions away from BT_CONNECT, so
that we don't loop if controller is sending bogus events.

This fixes sending multiple CIS Create for the same CIS in the
"ISO AC 6(i) - Success" BlueZ test case:

< HCI Command: LE Create Co.. (0x08|0x0064) plen 9  #129 [hci0]
        Number of CIS: 2
        CIS Handle: 257
        ACL Handle: 42
        CIS Handle: 258
        ACL Handle: 42
> HCI Event: Command Status (0x0f) plen 4           #130 [hci0]
      LE Create Connected Isochronous Stream (0x08|0x0064) ncmd 1
        Status: Success (0x00)
> HCI Event: LE Meta Event (0x3e) plen 29           #131 [hci0]
      LE Connected Isochronous Stream Established (0x19)
        Status: Success (0x00)
        Connection Handle: 257
        ...
< HCI Command: LE Setup Is.. (0x08|0x006e) plen 13  #132 [hci0]
        ...
> HCI Event: Command Complete (0x0e) plen 6         #133 [hci0]
      LE Setup Isochronous Data Path (0x08|0x006e) ncmd 1
        ...
< HCI Command: LE Create Co.. (0x08|0x0064) plen 5  #134 [hci0]
        Number of CIS: 1
        CIS Handle: 258
        ACL Handle: 42
> HCI Event: Command Status (0x0f) plen 4           #135 [hci0]
      LE Create Connected Isochronous Stream (0x08|0x0064) ncmd 1
        Status: ACL Connection Already Exists (0x0b)
> HCI Event: LE Meta Event (0x3e) plen 29           #136 [hci0]
      LE Connected Isochronous Stream Established (0x19)
        Status: Success (0x00)
        Connection Handle: 258
        ...

Fixes: c09b80b ("Bluetooth: hci_conn: Fix not waiting for HCI_EVT_LE_CIS_ESTABLISHED")
Signed-off-by: Pauli Virtanen <pav@iki.fi>
Signed-off-by: Luiz Augusto von Dentz <luiz.von.dentz@intel.com>
Signed-off-by: Sasha Levin <sashal@kernel.org>
popcornmix pushed a commit that referenced this issue Sep 13, 2023
[ Upstream commit 7f74563 ]

LE Create CIS command shall not be sent before all CIS Established
events from its previous invocation have been processed. Currently it is
sent via hci_sync but that only waits for the first event, but there can
be multiple.

Make it wait for all events, and simplify the CIS creation as follows:

Add new flag HCI_CONN_CREATE_CIS, which is set if Create CIS has been
sent for the connection but it is not yet completed.

Make BT_CONNECT state to mean the connection wants Create CIS.

On events after which new Create CIS may need to be sent, send it if
possible and some connections need it. These events are:
hci_connect_cis, iso_connect_cfm, hci_cs_le_create_cis,
hci_le_cis_estabilished_evt.

The Create CIS status/completion events shall queue new Create CIS only
if at least one of the connections transitions away from BT_CONNECT, so
that we don't loop if controller is sending bogus events.

This fixes sending multiple CIS Create for the same CIS in the
"ISO AC 6(i) - Success" BlueZ test case:

< HCI Command: LE Create Co.. (0x08|0x0064) plen 9  #129 [hci0]
        Number of CIS: 2
        CIS Handle: 257
        ACL Handle: 42
        CIS Handle: 258
        ACL Handle: 42
> HCI Event: Command Status (0x0f) plen 4           #130 [hci0]
      LE Create Connected Isochronous Stream (0x08|0x0064) ncmd 1
        Status: Success (0x00)
> HCI Event: LE Meta Event (0x3e) plen 29           #131 [hci0]
      LE Connected Isochronous Stream Established (0x19)
        Status: Success (0x00)
        Connection Handle: 257
        ...
< HCI Command: LE Setup Is.. (0x08|0x006e) plen 13  #132 [hci0]
        ...
> HCI Event: Command Complete (0x0e) plen 6         #133 [hci0]
      LE Setup Isochronous Data Path (0x08|0x006e) ncmd 1
        ...
< HCI Command: LE Create Co.. (0x08|0x0064) plen 5  #134 [hci0]
        Number of CIS: 1
        CIS Handle: 258
        ACL Handle: 42
> HCI Event: Command Status (0x0f) plen 4           #135 [hci0]
      LE Create Connected Isochronous Stream (0x08|0x0064) ncmd 1
        Status: ACL Connection Already Exists (0x0b)
> HCI Event: LE Meta Event (0x3e) plen 29           #136 [hci0]
      LE Connected Isochronous Stream Established (0x19)
        Status: Success (0x00)
        Connection Handle: 258
        ...

Fixes: c09b80b ("Bluetooth: hci_conn: Fix not waiting for HCI_EVT_LE_CIS_ESTABLISHED")
Signed-off-by: Pauli Virtanen <pav@iki.fi>
Signed-off-by: Luiz Augusto von Dentz <luiz.von.dentz@intel.com>
Signed-off-by: Sasha Levin <sashal@kernel.org>
popcornmix pushed a commit that referenced this issue Sep 19, 2023
Inject fault while probing kunit-example-test.ko, if kstrdup()
fails in mod_sysfs_setup() in load_module(), the mod->state will
switch from MODULE_STATE_COMING to MODULE_STATE_GOING instead of
from MODULE_STATE_LIVE to MODULE_STATE_GOING, so only
kunit_module_exit() will be called without kunit_module_init(), and
the mod->kunit_suites is no set correctly and the free in
kunit_free_suite_set() will cause below wild-memory-access bug.

The mod->state state machine when load_module() succeeds:

MODULE_STATE_UNFORMED ---> MODULE_STATE_COMING ---> MODULE_STATE_LIVE
	 ^						|
	 |						| delete_module
	 +---------------- MODULE_STATE_GOING <---------+

The mod->state state machine when load_module() fails at
mod_sysfs_setup():

MODULE_STATE_UNFORMED ---> MODULE_STATE_COMING ---> MODULE_STATE_GOING
	^						|
	|						|
	+-----------------------------------------------+

Call kunit_module_init() at MODULE_STATE_COMING state to fix the issue
because MODULE_STATE_LIVE is transformed from it.

 Unable to handle kernel paging request at virtual address ffffff341e942a88
 KASAN: maybe wild-memory-access in range [0x0003f9a0f4a15440-0x0003f9a0f4a15447]
 Mem abort info:
   ESR = 0x0000000096000004
   EC = 0x25: DABT (current EL), IL = 32 bits
   SET = 0, FnV = 0
   EA = 0, S1PTW = 0
   FSC = 0x04: level 0 translation fault
 Data abort info:
   ISV = 0, ISS = 0x00000004, ISS2 = 0x00000000
   CM = 0, WnR = 0, TnD = 0, TagAccess = 0
   GCS = 0, Overlay = 0, DirtyBit = 0, Xs = 0
 swapper pgtable: 4k pages, 48-bit VAs, pgdp=00000000441ea000
 [ffffff341e942a88] pgd=0000000000000000, p4d=0000000000000000
 Internal error: Oops: 0000000096000004 [#1] PREEMPT SMP
 Modules linked in: kunit_example_test(-) cfg80211 rfkill 8021q garp mrp stp llc ipv6 [last unloaded: kunit_example_test]
 CPU: 3 PID: 2035 Comm: modprobe Tainted: G        W        N 6.5.0-next-20230828+ #136
 Hardware name: linux,dummy-virt (DT)
 pstate: a0000005 (NzCv daif -PAN -UAO -TCO -DIT -SSBS BTYPE=--)
 pc : kfree+0x2c/0x70
 lr : kunit_free_suite_set+0xcc/0x13c
 sp : ffff8000829b75b0
 x29: ffff8000829b75b0 x28: ffff8000829b7b90 x27: 0000000000000000
 x26: dfff800000000000 x25: ffffcd07c82a7280 x24: ffffcd07a50ab300
 x23: ffffcd07a50ab2e8 x22: 1ffff00010536ec0 x21: dfff800000000000
 x20: ffffcd07a50ab2f0 x19: ffffcd07a50ab2f0 x18: 0000000000000000
 x17: 0000000000000000 x16: 0000000000000000 x15: ffffcd07c24b6764
 x14: ffffcd07c24b63c0 x13: ffffcd07c4cebb94 x12: ffff700010536ec7
 x11: 1ffff00010536ec6 x10: ffff700010536ec6 x9 : dfff800000000000
 x8 : 00008fffefac913a x7 : 0000000041b58ab3 x6 : 0000000000000000
 x5 : 1ffff00010536ec5 x4 : ffff8000829b7628 x3 : dfff800000000000
 x2 : ffffff341e942a80 x1 : ffffcd07a50aa000 x0 : fffffc0000000000
 Call trace:
  kfree+0x2c/0x70
  kunit_free_suite_set+0xcc/0x13c
  kunit_module_notify+0xd8/0x360
  blocking_notifier_call_chain+0xc4/0x128
  load_module+0x382c/0x44a4
  init_module_from_file+0xd4/0x128
  idempotent_init_module+0x2c8/0x524
  __arm64_sys_finit_module+0xac/0x100
  invoke_syscall+0x6c/0x258
  el0_svc_common.constprop.0+0x160/0x22c
  do_el0_svc+0x44/0x5c
  el0_svc+0x38/0x78
  el0t_64_sync_handler+0x13c/0x158
  el0t_64_sync+0x190/0x194
 Code: aa0003e1 b25657e0 d34cfc42 8b021802 (f9400440)
 ---[ end trace 0000000000000000 ]---
 Kernel panic - not syncing: Oops: Fatal exception
 SMP: stopping secondary CPUs
 Kernel Offset: 0x4d0742200000 from 0xffff800080000000
 PHYS_OFFSET: 0xffffee43c0000000
 CPU features: 0x88000203,3c020000,1000421b
 Memory Limit: none
 Rebooting in 1 seconds..

Fixes: 3d6e446 ("kunit: unify module and builtin suite definitions")
Signed-off-by: Jinjie Ruan <ruanjinjie@huawei.com>
Reviewed-by: Rae Moar <rmoar@google.com>
Reviewed-by: David Gow <davidgow@google.com>
Signed-off-by: Shuah Khan <skhan@linuxfoundation.org>
popcornmix pushed a commit that referenced this issue Sep 19, 2023
[ Upstream commit 2810c1e ]

Inject fault while probing kunit-example-test.ko, if kstrdup()
fails in mod_sysfs_setup() in load_module(), the mod->state will
switch from MODULE_STATE_COMING to MODULE_STATE_GOING instead of
from MODULE_STATE_LIVE to MODULE_STATE_GOING, so only
kunit_module_exit() will be called without kunit_module_init(), and
the mod->kunit_suites is no set correctly and the free in
kunit_free_suite_set() will cause below wild-memory-access bug.

The mod->state state machine when load_module() succeeds:

MODULE_STATE_UNFORMED ---> MODULE_STATE_COMING ---> MODULE_STATE_LIVE
	 ^						|
	 |						| delete_module
	 +---------------- MODULE_STATE_GOING <---------+

The mod->state state machine when load_module() fails at
mod_sysfs_setup():

MODULE_STATE_UNFORMED ---> MODULE_STATE_COMING ---> MODULE_STATE_GOING
	^						|
	|						|
	+-----------------------------------------------+

Call kunit_module_init() at MODULE_STATE_COMING state to fix the issue
because MODULE_STATE_LIVE is transformed from it.

 Unable to handle kernel paging request at virtual address ffffff341e942a88
 KASAN: maybe wild-memory-access in range [0x0003f9a0f4a15440-0x0003f9a0f4a15447]
 Mem abort info:
   ESR = 0x0000000096000004
   EC = 0x25: DABT (current EL), IL = 32 bits
   SET = 0, FnV = 0
   EA = 0, S1PTW = 0
   FSC = 0x04: level 0 translation fault
 Data abort info:
   ISV = 0, ISS = 0x00000004, ISS2 = 0x00000000
   CM = 0, WnR = 0, TnD = 0, TagAccess = 0
   GCS = 0, Overlay = 0, DirtyBit = 0, Xs = 0
 swapper pgtable: 4k pages, 48-bit VAs, pgdp=00000000441ea000
 [ffffff341e942a88] pgd=0000000000000000, p4d=0000000000000000
 Internal error: Oops: 0000000096000004 [#1] PREEMPT SMP
 Modules linked in: kunit_example_test(-) cfg80211 rfkill 8021q garp mrp stp llc ipv6 [last unloaded: kunit_example_test]
 CPU: 3 PID: 2035 Comm: modprobe Tainted: G        W        N 6.5.0-next-20230828+ #136
 Hardware name: linux,dummy-virt (DT)
 pstate: a0000005 (NzCv daif -PAN -UAO -TCO -DIT -SSBS BTYPE=--)
 pc : kfree+0x2c/0x70
 lr : kunit_free_suite_set+0xcc/0x13c
 sp : ffff8000829b75b0
 x29: ffff8000829b75b0 x28: ffff8000829b7b90 x27: 0000000000000000
 x26: dfff800000000000 x25: ffffcd07c82a7280 x24: ffffcd07a50ab300
 x23: ffffcd07a50ab2e8 x22: 1ffff00010536ec0 x21: dfff800000000000
 x20: ffffcd07a50ab2f0 x19: ffffcd07a50ab2f0 x18: 0000000000000000
 x17: 0000000000000000 x16: 0000000000000000 x15: ffffcd07c24b6764
 x14: ffffcd07c24b63c0 x13: ffffcd07c4cebb94 x12: ffff700010536ec7
 x11: 1ffff00010536ec6 x10: ffff700010536ec6 x9 : dfff800000000000
 x8 : 00008fffefac913a x7 : 0000000041b58ab3 x6 : 0000000000000000
 x5 : 1ffff00010536ec5 x4 : ffff8000829b7628 x3 : dfff800000000000
 x2 : ffffff341e942a80 x1 : ffffcd07a50aa000 x0 : fffffc0000000000
 Call trace:
  kfree+0x2c/0x70
  kunit_free_suite_set+0xcc/0x13c
  kunit_module_notify+0xd8/0x360
  blocking_notifier_call_chain+0xc4/0x128
  load_module+0x382c/0x44a4
  init_module_from_file+0xd4/0x128
  idempotent_init_module+0x2c8/0x524
  __arm64_sys_finit_module+0xac/0x100
  invoke_syscall+0x6c/0x258
  el0_svc_common.constprop.0+0x160/0x22c
  do_el0_svc+0x44/0x5c
  el0_svc+0x38/0x78
  el0t_64_sync_handler+0x13c/0x158
  el0t_64_sync+0x190/0x194
 Code: aa0003e1 b25657e0 d34cfc42 8b021802 (f9400440)
 ---[ end trace 0000000000000000 ]---
 Kernel panic - not syncing: Oops: Fatal exception
 SMP: stopping secondary CPUs
 Kernel Offset: 0x4d0742200000 from 0xffff800080000000
 PHYS_OFFSET: 0xffffee43c0000000
 CPU features: 0x88000203,3c020000,1000421b
 Memory Limit: none
 Rebooting in 1 seconds..

Fixes: 3d6e446 ("kunit: unify module and builtin suite definitions")
Signed-off-by: Jinjie Ruan <ruanjinjie@huawei.com>
Reviewed-by: Rae Moar <rmoar@google.com>
Reviewed-by: David Gow <davidgow@google.com>
Signed-off-by: Shuah Khan <skhan@linuxfoundation.org>
Signed-off-by: Sasha Levin <sashal@kernel.org>
popcornmix pushed a commit that referenced this issue Sep 19, 2023
[ Upstream commit 2810c1e ]

Inject fault while probing kunit-example-test.ko, if kstrdup()
fails in mod_sysfs_setup() in load_module(), the mod->state will
switch from MODULE_STATE_COMING to MODULE_STATE_GOING instead of
from MODULE_STATE_LIVE to MODULE_STATE_GOING, so only
kunit_module_exit() will be called without kunit_module_init(), and
the mod->kunit_suites is no set correctly and the free in
kunit_free_suite_set() will cause below wild-memory-access bug.

The mod->state state machine when load_module() succeeds:

MODULE_STATE_UNFORMED ---> MODULE_STATE_COMING ---> MODULE_STATE_LIVE
	 ^						|
	 |						| delete_module
	 +---------------- MODULE_STATE_GOING <---------+

The mod->state state machine when load_module() fails at
mod_sysfs_setup():

MODULE_STATE_UNFORMED ---> MODULE_STATE_COMING ---> MODULE_STATE_GOING
	^						|
	|						|
	+-----------------------------------------------+

Call kunit_module_init() at MODULE_STATE_COMING state to fix the issue
because MODULE_STATE_LIVE is transformed from it.

 Unable to handle kernel paging request at virtual address ffffff341e942a88
 KASAN: maybe wild-memory-access in range [0x0003f9a0f4a15440-0x0003f9a0f4a15447]
 Mem abort info:
   ESR = 0x0000000096000004
   EC = 0x25: DABT (current EL), IL = 32 bits
   SET = 0, FnV = 0
   EA = 0, S1PTW = 0
   FSC = 0x04: level 0 translation fault
 Data abort info:
   ISV = 0, ISS = 0x00000004, ISS2 = 0x00000000
   CM = 0, WnR = 0, TnD = 0, TagAccess = 0
   GCS = 0, Overlay = 0, DirtyBit = 0, Xs = 0
 swapper pgtable: 4k pages, 48-bit VAs, pgdp=00000000441ea000
 [ffffff341e942a88] pgd=0000000000000000, p4d=0000000000000000
 Internal error: Oops: 0000000096000004 [#1] PREEMPT SMP
 Modules linked in: kunit_example_test(-) cfg80211 rfkill 8021q garp mrp stp llc ipv6 [last unloaded: kunit_example_test]
 CPU: 3 PID: 2035 Comm: modprobe Tainted: G        W        N 6.5.0-next-20230828+ #136
 Hardware name: linux,dummy-virt (DT)
 pstate: a0000005 (NzCv daif -PAN -UAO -TCO -DIT -SSBS BTYPE=--)
 pc : kfree+0x2c/0x70
 lr : kunit_free_suite_set+0xcc/0x13c
 sp : ffff8000829b75b0
 x29: ffff8000829b75b0 x28: ffff8000829b7b90 x27: 0000000000000000
 x26: dfff800000000000 x25: ffffcd07c82a7280 x24: ffffcd07a50ab300
 x23: ffffcd07a50ab2e8 x22: 1ffff00010536ec0 x21: dfff800000000000
 x20: ffffcd07a50ab2f0 x19: ffffcd07a50ab2f0 x18: 0000000000000000
 x17: 0000000000000000 x16: 0000000000000000 x15: ffffcd07c24b6764
 x14: ffffcd07c24b63c0 x13: ffffcd07c4cebb94 x12: ffff700010536ec7
 x11: 1ffff00010536ec6 x10: ffff700010536ec6 x9 : dfff800000000000
 x8 : 00008fffefac913a x7 : 0000000041b58ab3 x6 : 0000000000000000
 x5 : 1ffff00010536ec5 x4 : ffff8000829b7628 x3 : dfff800000000000
 x2 : ffffff341e942a80 x1 : ffffcd07a50aa000 x0 : fffffc0000000000
 Call trace:
  kfree+0x2c/0x70
  kunit_free_suite_set+0xcc/0x13c
  kunit_module_notify+0xd8/0x360
  blocking_notifier_call_chain+0xc4/0x128
  load_module+0x382c/0x44a4
  init_module_from_file+0xd4/0x128
  idempotent_init_module+0x2c8/0x524
  __arm64_sys_finit_module+0xac/0x100
  invoke_syscall+0x6c/0x258
  el0_svc_common.constprop.0+0x160/0x22c
  do_el0_svc+0x44/0x5c
  el0_svc+0x38/0x78
  el0t_64_sync_handler+0x13c/0x158
  el0t_64_sync+0x190/0x194
 Code: aa0003e1 b25657e0 d34cfc42 8b021802 (f9400440)
 ---[ end trace 0000000000000000 ]---
 Kernel panic - not syncing: Oops: Fatal exception
 SMP: stopping secondary CPUs
 Kernel Offset: 0x4d0742200000 from 0xffff800080000000
 PHYS_OFFSET: 0xffffee43c0000000
 CPU features: 0x88000203,3c020000,1000421b
 Memory Limit: none
 Rebooting in 1 seconds..

Fixes: 3d6e446 ("kunit: unify module and builtin suite definitions")
Signed-off-by: Jinjie Ruan <ruanjinjie@huawei.com>
Reviewed-by: Rae Moar <rmoar@google.com>
Reviewed-by: David Gow <davidgow@google.com>
Signed-off-by: Shuah Khan <skhan@linuxfoundation.org>
Signed-off-by: Sasha Levin <sashal@kernel.org>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

7 participants