SD-card driver is working incorrectly

[konachan700]

Hello!

I find a bug in SD-card driver.

When system going to poweroff/reboot, the sd card will shudown too early, before unmounting the FS. It's broke a filesystem. This bug is present on all systems (debian, slakware, buildroot, ...), what used sd-card as root partition.

It's critical bug, bacause the spi flash too slow and small for many use case.

mmcblk0: error -110 sending stop command, original cmd response 0x900, card status 0xd00

[....] All processes ended within 1 seconds...[ ok done.
Sending command 18 as 0x9069203, arg = 0x0001801A, blocks = 6, length = 512
SDH - Reading 3072 bytes [phy_addr = 0x39e0000]
Sending command 13 as 0x9008D03, arg = 0xE6240000, blocks = 0, length = 0
Sending command 12 as 0x9008C03, arg = 0x00000000, blocks = 0, length = 0
mmcblk0: error -110 sending stop command, original cmd response 0xb00, card status 0xb00
Sending command 18 as 0x9069203, arg = 0x0001801A, blocks = 6, length = 512
SDH - Reading 3072 bytes [phy_addr = 0x39e0000]
Sending command 13 as 0x9008D03, arg = 0xE6240000, blocks = 0, length = 0
Sending command 12 as 0x9008C03, arg = 0x00000000, blocks = 0, length = 0
mmcblk0: error -110 sending stop command, original cmd response 0xb00, card status 0xb00 

Full log here: http://pastebin.com/1k6xpewX http://pastebin.com/mULmYQc3

[yachen]

Hi,

So the file system is broke because SD is shut down while there're data waiting to be flushed out? Can you try to issue a sync command before power off/reboot the system?

Sincerely,

Yi-An Chen

[konachan700]

Yes. Yes, i do "sync", it hasn't any effect. And when I am mount rootfs as readonly, I see many reading error and stop of poweroff/reboot process. Problem is appears when one of mmc kernel process gets a SIGTERM/SIGKILL/SIGCONT/... signals, e.g. on killall -s SIGKILL -1

root@slackware:~# kill -s SIGCONT -1
root@slackware:~# dd if=/dev/mmcblk0 of=/dev/null bs=1M count=10 skip=17 
Bus error
root@slackware:~# EXT4-fs error (device mmcblk0p3): __ext4_get_inode_loc:4027: inode #21989: block 1521: comm syslogd: unable to read itable block
EXT4-fs (mmcblk0p3): Remounting filesystem read-only
EXT4-fs error (device mmcblk0p3) in ext4_reserve_inode_write:4950: IO failure
EXT4-fs error (device mmcblk0p3) in ext4_dirty_inode:5069: IO failure
EXT4-fs error (device mmcblk0p3): ext4_wait_block_bitmap:466: comm syslogd: Cannot read block bitmap - block_group = 0, block_bitmap = 115
EXT4-fs error (device mmcblk0p3): ext4_discard_preallocations:3935: comm syslogd: Error loading buddy information for 0

Problem is present on many different SD-card, it's no broken card.

[jury093]

Hi! I have similar bug. ARM - nuc976. Kernel version "Linux version 3.10.101 (jury093@ubuntu64) (gcc version 4.3.4 (GCC) )" bootargs 'console=ttyS0,115200n8 root=/dev/mmcblk0p1 rw rootwait' Debian-7-armel (generated by standart debootstrap utility). After "reboot" or "poweroff" and cycle power off/on:

SDH - Reading 2048 bytes [phy_addr = 0x39e0000]
SDH xfer done.
[ ok done.
[....] All processes ended within 1 seconds...[ ok done.
Sending command 18 as 0x9069203, arg = 0x0001801A, blocks = 6, length = 512
SDH - Reading 3072 bytes [phy_addr = 0x39e0000]
Sending command 13 as 0x9008D03, arg = 0xE6240000, blocks = 0, length = 0
Sending command 12 as 0x9008C03, arg = 0x00000000, blocks = 0, length = 0
mmcblk0: error -110 sending stop command, original cmd response 0xb00, card status 0xb00
Sending command 18 as 0x9069203, arg = 0x0001801A, blocks = 6, length = 512
SDH - Reading 3072 bytes [phy_addr = 0x39e0000]
Sending command 13 as 0x9008D03, arg = 0xE6240000, blocks = 0, length = 0
Sending command 12 as 0x9008C03, arg = 0x00000000, blocks = 0, length = 0
mmcblk0: error -110 sending stop command, original cmd response 0xb00, card status 0xb00
Sending command 18 as 0x9069203, arg = 0x0001801A, blocks = 6, length = 512
SDH - Reading 3072 bytes [phy_addr = 0x39e0000]
Sending command 13 as 0x9008D03, arg = 0xE6240000, blocks = 0, length = 0
Sending command 12 as 0x9008C03, arg = 0x00000000, blocks = 0, length = 0
mmcblk0: error -110 sending stop command, original cmd response 0xb00, card status 0xb00
Sending command 18 as 0x9069203, arg = 0x0001801A, blocks = 6, length = 512
SDH - Reading 3072 bytes [phy_addr = 0x39e0000]
Sending command 13 as 0x9008D03, arg = 0xE6240000, blocks = 0, length = 0
mmcblk0: error -110 sending stop command, original cmd response 0xb00, card status 0x400900
Sending command 18 as 0x9069203, arg = 0x0001801A, blocks = 6, length = 512
SDH - Reading 3072 bytes [phy_addr = 0x39e0000]
Sending command 18 as 0x9069203, arg = 0x0001801A, blocks = 6, length = 512
SDH - Reading 3072 bytes [phy_addr = 0x39e0000]
end_request: I/O error, dev mmcblk0, sector 98330
Sending command 18 as 0x9069203, arg = 0x0001801A, blocks = 6, length = 512
SDH - Reading 3072 bytes [phy_addr = 0x39e0000]
Sending command 18 as 0x9069203, arg = 0x0001801A, blocks = 6, length = 512
SDH - Reading 3072 bytes [phy_addr = 0x39e0000]
Sending command 18 as 0x9069203, arg = 0x0001801A, blocks = 6, length = 512
SDH - Reading 3072 bytes [phy_addr = 0x39e0000]
Sending command 18 as 0x9069203, arg = 0x0001801A, blocks = 6, length = 512
SDH - Reading 3072 bytes [phy_addr = 0x39e0000]
Sending command 18 as 0x9069203, arg = 0x0001801A, blocks = 6, length = 512
SDH - Reading 3072 bytes [phy_addr = 0x39e0000]
Sending command 18 as 0x9069203, arg = 0x0001801A, blocks = 6, length = 512
SDH - Reading 3072 bytes [phy_addr = 0x39e0000]
end_request: I/O error, dev mmcblk0, sector 98330
rsyslog: Input/output error

Volume can't mount (no table of partitions)..

PS ups.. sorry for log - i can't make normal view (update - I fix log output =))

[schung1218]

Hi, I tried to replicate the problem. system going to reboot, the file system as root partition is work in sd card .

https://github.com/schung1218/temp/blob/master/putty.log

[jury093]

I tried to replicate the problem. system going to reboot, the file system as root partition is work in sd card

Your right, but your system busybox-based: BusyBox v1.22.1 (2015-04Sending command 18 and never use "command 12".. Problem exist for Debian/Ubuntu with full function rootfs

[yachen]

Hi,

So you're executing Ubuntu for ARM on NUC976, except the kernel is replaced with the one built from Nuvoton's tree?

Sincerely,

Yi-An Chen

[konachan700]

Yes. I am tried a ubuntu arm, debian arm, slackware arm, buildroot. I am replaced default kernel to Nuvoton's kernel on all this systems.

[yachen]

Hi,

So you can reproduce this issue with buildroot as well? Can you share your buildroot configuration with us? It's more convenient for us to check this issue using buildroot than Ubuntu/Debian...

Sincerely,

Yi-An Chen

[yachen]

Hi @konachan700 ,

It would be really helpful if you could provide us your buildroot setting. We have a buildroot framework under testing now but are unable to reproduce the problem.

Sincerely,

Yi-An Chen

[konachan700]

link to BR and kernel configs

In BR i don't see any error in dmesg, but reboot process is stopping where SIGTERM sent to all processes. I am share the full BR binary image and configs. Source code is too big for sharing (4GB+ zipped).

[jury093]

So you're executing Ubuntu for ARM on NUC976, except the kernel is replaced with the one built from Nuvoton's tree?

yes. I try attach rootfs tarball with Debian-7-armel (aprox 64MB) .. hmm.. "Try again with a file smaller than 10MB" https://drive.google.com/file/d/0BximTd_xFGq8d3ZrYzhwRERHUXM/view?usp=sharing download and unpack to free part of SD card. try to load: username - root and password - password. This rootfs work perfectly with 9260/9g45/am335x/imx6 etc, but crashed with nuc976 kernel after "poweroff" or "reboot" command..

update after unpack, please, change into file /etc/inittab from T0:123:respawn:/sbin/getty 115200 ttymxc0 to T0:123:respawn:/sbin/getty 115200 ttyS0

[yachen]

Hi @jury093,

Thanks. Will test this issue based on the file system you provided.

Sincerely,

Yi-An Chen

[yachen]

Hi @jury093 ,

After reboot command, I see kernel stop output after following message. But didn't see any I/O error.

Sincerely,

Yi-An Chen

root@armets:~# reboot [ 677.570000] Sending command 18 as 0x9209203, arg = 0x00843420, blocks = 32, length = 512 [ 677.580000] SDH - Reading 16384 bytes [phy_addr = 0x3a20000] [ 677.590000] SDH xfer done. [ 677.610000] Sending command 18 as 0x9209203, arg = 0x00842DF0, blocks = 32, length = 512 [ 677.610000] SDH - Reading 16384 bytes [phy_addr = 0x3a20000] [ 677.620000] SDH xfer done. [ 677.630000] Sending command 18 as 0x9109203, arg = 0x00842E10, blocks = 16, length = 512 [ 677.640000] SDH - Reading 8192 bytes [phy_addr = 0x3a20000] [ 677.640000] SDH xfer done. [ 677.670000] Sending command 18 as 0x9089203, arg = 0x00487078, blocks = 8, length = 512 [ 677.680000] SDH - Reading 4096 bytes [phy_addr = 0x3a20000] [ 677.690000] SDH xfer done. [ 677.700000] Sending command 25 as 0x9109903, arg = 0x00485B00, blocks = 16, length = 512 [ 677.700000] SDH - Transmitting 8192 bytes [ 677.710000] SDH xfer done.

Broadcast message from root@armets ([ 677.720000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 677.730000] Sending command 25 as 0x9109903, arg = 0x00071458, blocks = 16, length = 512

The sys[ 677.730000] SDH - Transmitting 8192 bytes tem is going down for re[ 677.740000] SDH xfer done. boot NOW! [ 677.750000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 677.760000] Sending command 25 as 0x9189903, arg = 0x00488310, blocks = 24, length = 512 [ 677.770000] SDH - Transmitting 12288 bytes [ 677.770000] SDH xfer done. [ 677.780000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 677.790000] Sending command 25 as 0x9089903, arg = 0x00402140, blocks = 8, length = 512 [ 677.790000] SDH - Transmitting 4096 bytes [ 677.800000] SDH xfer done. [ 677.800000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 677.810000] Sending command 25 as 0x9089903, arg = 0x00482E98, blocks = 8, length = 512 [ 677.820000] SDH - Transmitting 4096 bytes [ 677.830000] SDH xfer done. [ 677.830000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 677.840000] Sending command 25 as 0x9809903, arg = 0x00443700, blocks = 128, length = 512 [ 677.850000] SDH - Transmitting 65536 bytes [ 677.860000] SDH xfer done. [ 677.860000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 677.870000] Sending command 25 as 0x9089903, arg = 0x00443780, blocks = 8, length = 512 [ 677.880000] SDH - Transmitting 4096 bytes [ 677.890000] SDH xfer done. [ 677.890000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 677.910000] Sending command 25 as 0x9089903, arg = 0x00002008, blocks = 8, length = 512 [ 677.910000] SDH - Transmitting 4096 bytes [ 677.920000] SDH xfer done. [ 677.920000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 677.930000] Sending command 25 as 0x9089903, arg = 0x00002ED0, blocks = 8, length = 512 [ 677.940000] SDH - Transmitting 4096 bytes [ 677.950000] SDH xfer done. [ 677.950000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 677.960000] Sending command 25 as 0x9089903, arg = 0x00402010, blocks = 8, length = 512 [ 677.970000] SDH - Transmitting 4096 bytes [ 677.980000] SDH xfer done. [ 677.980000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 678.000000] Sending command 25 as 0x9089903, arg = 0x00486018, blocks = 8, length = 512 [ 678.000000] SDH - Transmitting 4096 bytes [ 678.010000] SDH xfer done. [ 678.010000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 678.020000] Sending command 25 as 0x9109903, arg = 0x00802110, blocks = 16, length = 512 [ 678.030000] SDH - Transmitting 8192 bytes [ 678.040000] SDH xfer done. [ 678.040000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 678.050000] Sending command 25 as 0x9089903, arg = 0x00802128, blocks = 8, length = 512 [ 678.060000] SDH - Transmitting 4096 bytes [ 678.060000] SDH xfer done. [ 678.070000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 678.080000] Sending command 25 as 0x9089903, arg = 0x008021C8, blocks = 8, length = 512 [ 678.090000] SDH - Transmitting 4096 bytes [ 678.090000] SDH xfer done. [ 678.100000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 678.100000] Sending command 25 as 0x9189903, arg = 0x008021E0, blocks = 24, length = 512 [ 678.110000] SDH - Transmitting 12288 bytes [ 678.120000] SDH xfer done. [ 678.120000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 678.130000] Sending command 25 as 0x9189903, arg = 0x00802200, blocks = 24, length = 512 [ 678.140000] SDH - Transmitting 12288 bytes [ 678.140000] SDH xfer done. [ 678.150000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 INIT: Sending processes the TERM signal [ 678.200000] Sending command 18 as 0x9089203, arg = 0x00486098, blocks = 8, length = 512 [ 678.200000] SDH - Reading 4096 bytes [phy_addr = 0x3a20000] [ 678.210000] SDH xfer done. [info] Using makefile-style concurrent boot in runlevel 6. [ 679.450000] Sending command 18 as 0x9089203, arg = 0x00045928, blocks = 8, length = 512 [ 679.460000] SDH - Reading 4096 bytes [phy_addr = 0x3a20000] [ 679.460000] SDH xfer done. [ 679.470000] Sending command 18 as 0x9089203, arg = 0x00013108, blocks = 8, length = 512 [ 679.480000] SDH - Reading 4096 bytes [phy_addr = 0x3a20000] [ 679.490000] SDH xfer done. [ 679.520000] Sending command 18 as 0x9089203, arg = 0x00045880, blocks = 8, length = 512 [ 679.530000] SDH - Reading 4096 bytes [phy_addr = 0x3a20000] [ 679.530000] SDH xfer done. [ 679.550000] Sending command 18 as 0x9089203, arg = 0x00045810, blocks = 8, length = 512 [ 679.550000] SDH - Reading 4096 bytes [phy_addr = 0x3a20000] [ 679.560000] SDH xfer done. [ 679.710000] Sending command 18 as 0x9209203, arg = 0x0084A800, blocks = 32, length = 512 [ 679.720000] SDH - Reading 16384 bytes [phy_addr = 0x3a20000] [ 679.730000] SDH xfer done. [ 679.740000] Sending command 18 as 0x9109203, arg = 0x0084A820, blocks = 16, length = 512 [ 679.750000] SDH - Reading 8192 bytes [phy_addr = 0x3a20000] [ 679.750000] SDH xfer done. [ 679.770000] Sending command 25 as 0x9089903, arg = 0x00487078, blocks = 8, length = 512 [ 679.780000] SDH - Transmitting 4096 bytes [ 679.790000] SDH xfer done. [ 679.790000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 679.800000] Sending command 25 as 0x9189903, arg = 0x00488320, blocks = 24, length = 512 [ 679.810000] SDH - Transmitting 12288 bytes [ 679.810000] SDH xfer done. [ 679.820000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 679.830000] Sending command 25 as 0x9189903, arg = 0x00485B08, blocks = 24, length = 512 [ 679.840000] SDH - Transmitting 12288 bytes [ 679.840000] SDH xfer done. [ 679.850000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 679.860000] Sending command 25 as 0x9189903, arg = 0x00071460, blocks = 24, length = 512 [ 679.870000] SDH - Transmitting 12288 bytes [ 679.870000] SDH xfer done. [ 679.880000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 679.880000] Sending command 25 as 0x9089903, arg = 0x00485960, blocks = 8, length = 512 [ 679.890000] SDH - Transmitting 4096 bytes [ 679.900000] SDH xfer done. [ 679.900000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 679.910000] Sending command 25 as 0x9089903, arg = 0x00487020, blocks = 8, length = 512 [ 679.920000] SDH - Transmitting 4096 bytes [ 679.930000] SDH xfer done. [ 679.930000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 679.940000] Sending command 25 as 0x9089903, arg = 0x00486098, blocks = 8, length = 512 [ 679.950000] SDH - Transmitting 4096 bytes [ 679.950000] SDH xfer done. [ 679.960000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 679.960000] Sending command 25 as 0x9089903, arg = 0x00045E98, blocks = 8, length = 512 [ 679.970000] SDH - Transmitting 4096 bytes [ 679.980000] SDH xfer done. [ 679.990000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 680.000000] Sending command 25 as 0x9D89903, arg = 0x00443788, blocks = 216, length = 512 [ 680.010000] SDH - Transmitting 110592 bytes [ 680.050000] SDH xfer done. [ 680.060000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 680.070000] Sending command 25 as 0x9089903, arg = 0x00443860, blocks = 8, length = 512 [ 680.080000] SDH - Transmitting 4096 bytes [ 680.090000] SDH xfer done. [ 680.130000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 680.170000] Sending command 25 as 0x9089903, arg = 0x00489010, blocks = 8, length = 512 [ 680.170000] SDH - Transmitting 4096 bytes [ 680.180000] SDH xfer done. [ 680.220000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 680.230000] Sending command 25 as 0x9609903, arg = 0x00443868, blocks = 96, length = 512 [ 680.240000] SDH - Transmitting 49152 bytes [ 680.250000] SDH xfer done. [ 680.250000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 680.260000] Sending command 25 as 0x9089903, arg = 0x004438C8, blocks = 8, length = 512 [ 680.270000] SDH - Transmitting 4096 bytes [ 680.270000] SDH xfer done. [ 680.310000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 680.320000] Sending command 25 as 0x9109903, arg = 0x004438D0, blocks = 16, length = 512 [ 680.330000] SDH - Transmitting 8192 bytes [ 680.340000] SDH xfer done. [ 680.380000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 680.390000] Sending command 25 as 0x9089903, arg = 0x004438E0, blocks = 8, length = 512 [ 680.390000] SDH - Transmitting 4096 bytes [ 680.400000] SDH xfer done. [ 680.440000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 680.450000] Sending command 25 as 0x9109903, arg = 0x004438E8, blocks = 16, length = 512 [ 680.460000] SDH - Transmitting 8192 bytes [ 680.470000] SDH xfer done. [ 680.510000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 680.520000] Sending command 25 as 0x9089903, arg = 0x004438F8, blocks = 8, length = 512 [ 680.520000] SDH - Transmitting 4096 bytes [ 680.530000] SDH xfer done. [ 680.570000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 680.580000] Sending command 25 as 0x9109903, arg = 0x00443900, blocks = 16, length = 512 [ 680.590000] SDH - Transmitting 8192 bytes [ 680.590000] SDH xfer done. [ 680.610000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 680.610000] Sending command 25 as 0x9089903, arg = 0x00443910, blocks = 8, length = 512 [ 680.620000] SDH - Transmitting 4096 bytes [ 680.630000] SDH xfer done. [ 680.660000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 680.670000] Sending command 25 as 0x9109903, arg = 0x00443918, blocks = 16, length = 512 [ 680.680000] SDH - Transmitting 8192 bytes [ 680.680000] SDH xfer done. [ 680.690000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 680.700000] Sending command 25 as 0x9089903, arg = 0x00443928, blocks = 8, length = 512 [ 680.700000] SDH - Transmitting 4096 bytes [ 680.710000] SDH xfer done. [ 680.710000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 680.720000] Sending command 25 as 0x9109903, arg = 0x00443930, blocks = 16, length = 512 [ 680.730000] SDH - Transmitting 8192 bytes [ 680.740000] SDH xfer done. [ 680.740000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 680.750000] Sending command 25 as 0x9089903, arg = 0x00443940, blocks = 8, length = 512 [ 680.760000] SDH - Transmitting 4096 bytes [ 680.760000] SDH xfer done. [ 680.770000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 680.780000] Sending command 25 as 0x9109903, arg = 0x00443948, blocks = 16, length = 512 [ 680.790000] SDH - Transmitting 8192 bytes [ 680.800000] SDH xfer done. [ 680.800000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 680.810000] Sending command 25 as 0x9089903, arg = 0x00443958, blocks = 8, length = 512 [ 680.820000] SDH - Transmitting 4096 bytes [ 680.830000] SDH xfer done. [ 680.830000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 680.840000] Sending command 25 as 0x9109903, arg = 0x00443960, blocks = 16, length = 512 [ 680.850000] SDH - Transmitting 8192 bytes [ 680.860000] SDH xfer done. [ 680.860000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 680.870000] Sending command 25 as 0x9089903, arg = 0x00443970, blocks = 8, length = 512 [ 680.880000] SDH - Transmitting 4096 bytes [ 680.880000] SDH xfer done. [ 680.890000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 680.900000] Sending command 25 as 0x9109903, arg = 0x00443978, blocks = 16, length = 512 [ 680.910000] SDH - Transmitting 8192 bytes [ 680.920000] SDH xfer done. [ 680.920000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 680.930000] Sending command 25 as 0x9089903, arg = 0x00443988, blocks = 8, length = 512 [ 680.940000] SDH - Transmitting 4096 bytes [ 680.940000] SDH xfer done. [ 680.950000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 680.960000] Sending command 25 as 0x9109903, arg = 0x00443990, blocks = 16, length = 512 [ 680.970000] SDH - Transmitting 8192 bytes [ 680.970000] SDH xfer done. [ 680.980000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 680.990000] Sending command 25 as 0x9089903, arg = 0x004439A0, blocks = 8, length = 512 [ 681.000000] SDH - Transmitting 4096 bytes [ 681.000000] SDH xfer done. [ 681.010000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 681.020000] Sending command 25 as 0x9109903, arg = 0x004439A8, blocks = 16, length = 512 [ 681.030000] SDH - Transmitting 8192 bytes [ 681.030000] SDH xfer done. [ 681.040000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 681.050000] Sending command 25 as 0x9089903, arg = 0x004439B8, blocks = 8, length = 512 [ 681.060000] SDH - Transmitting 4096 bytes [ 681.060000] SDH xfer done. [ 681.070000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 681.070000] Sending command 25 as 0x9109903, arg = 0x004439C0, blocks = 16, length = 512 [ 681.080000] SDH - Transmitting 8192 bytes [ 681.090000] SDH xfer done. [ 681.100000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 681.110000] Sending command 25 as 0x9089903, arg = 0x004439D0, blocks = 8, length = 512 [ 681.110000] SDH - Transmitting 4096 bytes [ 681.120000] SDH xfer done. [ 681.120000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 681.130000] Sending command 25 as 0x9109903, arg = 0x004439D8, blocks = 16, length = 512 [ 681.140000] SDH - Transmitting 8192 bytes [ 681.150000] SDH xfer done. [ 681.150000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 681.160000] Sending command 25 as 0x9089903, arg = 0x004439E8, blocks = 8, length = 512 [ 681.170000] SDH - Transmitting 4096 bytes [ 681.180000] SDH xfer done. [ 681.180000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 681.190000] Sending command 25 as 0x9109903, arg = 0x004439F0, blocks = 16, length = 512 [ 681.200000] SDH - Transmitting 8192 bytes [ 681.210000] SDH xfer done. [ 681.210000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 681.220000] Sending command 25 as 0x9089903, arg = 0x00443A00, blocks = 8, length = 512 [ 681.230000] SDH - Transmitting 4096 bytes [ 681.240000] SDH xfer done. [ 681.240000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 681.250000] Sending command 25 as 0x9109903, arg = 0x00443A08, blocks = 16, length = 512 [ 681.260000] SDH - Transmitting 8192 bytes [ 681.270000] SDH xfer done. [ 681.270000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 681.280000] Sending command 25 as 0x9089903, arg = 0x00443A18, blocks = 8, length = 512 [ 681.290000] SDH - Transmitting 4096 bytes [ 681.300000] SDH xfer done. [ 681.300000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 681.310000] Sending command 25 as 0x9109903, arg = 0x00443A20, blocks = 16, length = 512 [ 681.320000] SDH - Transmitting 8192 bytes [ 681.330000] SDH xfer done. [ 681.330000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 681.340000] Sending command 25 as 0x9089903, arg = 0x00443A30, blocks = 8, length = 512 [ 681.350000] SDH - Transmitting 4096 bytes [ 681.360000] SDH xfer done. [ 681.360000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 681.370000] Sending command 25 as 0x9109903, arg = 0x00443A38, blocks = 16, length = 512 [ 681.380000] SDH - Transmitting 8192 bytes [ 681.390000] SDH xfer done. [ 681.390000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 681.410000] Sending command 25 as 0x9089903, arg = 0x00443A48, blocks = 8, length = 512 [ 681.420000] SDH - Transmitting 4096 bytes [ 681.420000] SDH xfer done. [ 681.430000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 681.440000] Sending command 25 as 0x9109903, arg = 0x00443A50, blocks = 16, length = 512 [ 681.440000] SDH - Transmitting 8192 bytes [ 681.450000] SDH xfer done. [ 681.450000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 681.460000] Sending command 25 as 0x9089903, arg = 0x00443A60, blocks = 8, length = 512 [ 681.470000] SDH - Transmitting 4096 bytes [ 681.480000] SDH xfer done. [ 681.480000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 681.500000] Sending command 25 as 0x9109903, arg = 0x00443A68, blocks = 16, length = 512 [ 681.500000] SDH - Transmitting 8192 bytes [ 681.510000] SDH xfer done. [ 681.510000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 681.520000] Sending command 25 as 0x9089903, arg = 0x00443A78, blocks = 8, length = 512 [ 681.530000] SDH - Transmitting 4096 bytes [ 681.540000] SDH xfer done. [ 681.540000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 681.550000] Sending command 25 as 0x9109903, arg = 0x00443A80, blocks = 16, length = 512 [ 681.560000] SDH - Transmitting 8192 bytes [ 681.560000] SDH xfer done. [ 681.570000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 681.580000] Sending command 25 as 0x9089903, arg = 0x00443A90, blocks = 8, length = 512 [ 681.590000] SDH - Transmitting 4096 bytes [ 681.590000] SDH xfer done. [ 681.600000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 681.610000] Sending command 25 as 0x9109903, arg = 0x00443A98, blocks = 16, length = 512 [ 681.620000] SDH - Transmitting 8192 bytes [ 681.620000] SDH xfer done. [ 681.630000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 681.630000] Sending command 25 as 0x9089903, arg = 0x00443AA8, blocks = 8, length = 512 [ 681.640000] SDH - Transmitting 4096 bytes [ 681.650000] SDH xfer done. [ 681.650000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 681.660000] Sending command 25 as 0x9109903, arg = 0x00443AB0, blocks = 16, length = 512 [ 681.670000] SDH - Transmitting 8192 bytes [ 681.680000] SDH xfer done. [ 681.680000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 681.690000] Sending command 25 as 0x9089903, arg = 0x00443AC0, blocks = 8, length = 512 [ 681.700000] SDH - Transmitting 4096 bytes [ 681.700000] SDH xfer done. [ 681.710000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 681.720000] Sending command 25 as 0x9109903, arg = 0x00443AC8, blocks = 16, length = 512 [ 681.730000] SDH - Transmitting 8192 bytes [ 681.740000] SDH xfer done. [ 681.740000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 681.750000] Sending command 25 as 0x9089903, arg = 0x00443AD8, blocks = 8, length = 512 [ 681.760000] SDH - Transmitting 4096 bytes [ 681.770000] SDH xfer done. [ 681.770000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 681.790000] Sending command 25 as 0x9109903, arg = 0x00443AE0, blocks = 16, length = 512 [ 681.790000] SDH - Transmitting 8192 bytes [ 681.800000] SDH xfer done. [ 681.800000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 681.810000] Sending command 25 as 0x9089903, arg = 0x00443AF0, blocks = 8, length = 512 [ 681.820000] SDH - Transmitting 4096 bytes [ 681.830000] SDH xfer done. [ 681.830000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 681.850000] Sending command 25 as 0x9109903, arg = 0x00443AF8, blocks = 16, length = 512 [ 681.850000] SDH - Transmitting 8192 bytes [ 681.860000] SDH xfer done. [ 681.870000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 681.880000] Sending command 25 as 0x9089903, arg = 0x00443B08, blocks = 8, length = 512 [ 681.880000] SDH - Transmitting 4096 bytes [ 681.890000] SDH xfer done. [ 681.890000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 681.900000] Sending command 25 as 0x9109903, arg = 0x00443B10, blocks = 16, length = 512 [ 681.910000] SDH - Transmitting 8192 bytes [ 681.920000] SDH xfer done. [ 681.920000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 681.930000] Sending command 25 as 0x9089903, arg = 0x00443B20, blocks = 8, length = 512 [ 681.940000] SDH - Transmitting 4096 bytes [ 681.950000] SDH xfer done. [ 681.950000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 681.960000] Sending command 25 as 0x9109903, arg = 0x00443B28, blocks = 16, length = 512 [ 681.970000] SDH - Transmitting 8192 bytes [ 681.980000] SDH xfer done. [ 681.980000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 681.990000] Sending command 25 as 0x9089903, arg = 0x00443B38, blocks = 8, length = 512 [ 682.000000] SDH - Transmitting 4096 bytes [ 682.010000] SDH xfer done. [ 682.010000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 682.020000] Sending command 25 as 0x9109903, arg = 0x00002000, blocks = 16, length = 512 [ 682.030000] SDH - Transmitting 8192 bytes [ 682.040000] SDH xfer done. [ 682.040000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 682.060000] Sending command 25 as 0x9089903, arg = 0x00002ED0, blocks = 8, length = 512 [ 682.070000] SDH - Transmitting 4096 bytes [ 682.070000] SDH xfer done. [ 682.080000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 682.080000] Sending command 25 as 0x9089903, arg = 0x00003048, blocks = 8, length = 512 [ 682.090000] SDH - Transmitting 4096 bytes [ 682.100000] SDH xfer done. [ 682.100000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 682.110000] Sending command 25 as 0x9089903, arg = 0x00003090, blocks = 8, length = 512 [ 682.120000] SDH - Transmitting 4096 bytes [ 682.120000] SDH xfer done. [ 682.130000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 682.140000] Sending command 25 as 0x9089903, arg = 0x000030A8, blocks = 8, length = 512 [ 682.150000] SDH - Transmitting 4096 bytes [ 682.150000] SDH xfer done. [ 682.160000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 682.170000] Sending command 25 as 0x9089903, arg = 0x00402010, blocks = 8, length = 512 [ 682.170000] SDH - Transmitting 4096 bytes [ 682.180000] SDH xfer done. [ 682.180000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 682.190000] Sending command 25 as 0x9089903, arg = 0x00402140, blocks = 8, length = 512 [ 682.200000] SDH - Transmitting 4096 bytes [ 682.210000] SDH xfer done. [ 682.210000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 682.230000] Sending command 25 as 0x9089903, arg = 0x004022A8, blocks = 8, length = 512 [ 682.230000] SDH - Transmitting 4096 bytes [ 682.240000] SDH xfer done. [ 682.240000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 682.250000] Sending command 25 as 0x9089903, arg = 0x00482E98, blocks = 8, length = 512 [ 682.260000] SDH - Transmitting 4096 bytes [ 682.270000] SDH xfer done. [ 682.270000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 682.280000] Sending command 25 as 0x9089903, arg = 0x00486018, blocks = 8, length = 512 [ 682.290000] SDH - Transmitting 4096 bytes [ 682.290000] SDH xfer done. [ 682.300000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 682.310000] Sending command 25 as 0x9089903, arg = 0x00802118, blocks = 8, length = 512 [ 682.320000] SDH - Transmitting 4096 bytes [ 682.330000] SDH xfer done. [ 682.330000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 682.340000] Sending command 25 as 0x9089903, arg = 0x00802128, blocks = 8, length = 512 [ 682.350000] SDH - Transmitting 4096 bytes [ 682.350000] SDH xfer done. [ 682.360000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 682.370000] Sending command 25 as 0x9089903, arg = 0x008021A8, blocks = 8, length = 512 [ 682.380000] SDH - Transmitting 4096 bytes [ 682.380000] SDH xfer done. [ 682.390000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 682.400000] Sending command 25 as 0x9089903, arg = 0x008021B8, blocks = 8, length = 512 [ 682.400000] SDH - Transmitting 4096 bytes [ 682.410000] SDH xfer done. [ 682.410000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 682.420000] Sending command 25 as 0x9089903, arg = 0x008021C8, blocks = 8, length = 512 [ 682.430000] SDH - Transmitting 4096 bytes [ 682.440000] SDH xfer done. [ 682.440000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 682.450000] Sending command 25 as 0x9189903, arg = 0x008021E0, blocks = 24, length = 512 [ 682.460000] SDH - Transmitting 12288 bytes [ 682.460000] SDH xfer done. [ 682.470000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 682.480000] Sending command 25 as 0x9189903, arg = 0x00802200, blocks = 24, length = 512 [ 682.490000] SDH - Transmitting 12288 bytes [ 682.490000] SDH xfer done. [ 682.500000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 682.510000] Sending command 25 as 0x9209903, arg = 0x00802238, blocks = 32, length = 512 [ 682.520000] SDH - Transmitting 16384 bytes [ 682.520000] SDH xfer done. [ 682.530000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [ 682.540000] Sending command 25 as 0x9089903, arg = 0x00C02220, blocks = 8, length = 512 [ 682.540000] SDH - Transmitting 4096 bytes [ 682.550000] SDH xfer done. [ 682.560000] Sending command 13 as 0x9018D03, arg = 0x59B40000, blocks = 0, length = 0 [....] Asking all remaining processes to terminate...[ 682.650000] Sending command 18 as 0x9209203, arg = 0x00842240, blocks = 32, length = 512 [ 682.650000] SDH - Reading 16384 bytes [phy_addr = 0x3a20000] [ 682.660000] SDH xfer done. [ 682.670000] Sending command 18 as 0x9089203, arg = 0x00842260, blocks = 8, length = 512 [ 682.680000] SDH - Reading 4096 bytes [phy_addr = 0x3a20000] [ 682.680000] SDH xfer done.

[jury093]

Hi yachen!

1. please, try make 2-3 cycles to boot system and "poweroff" command
2. what flash card your used? I use uSD (2GB, 4GB and 8GB).. Thank you

[yachen]

Hi @jury093 ,

1. Ok
2. I'm using 8GB micro SD.

Sincerely,

Yi-An Chen

[yachen]

Hi @jury093 ,

I've tested more than 50 times yet cannot reproduce the problem. There are some debug messages were comment out ( //nuc970_sd_debug()) in driver, could you un-comment them and log the console message after issue poweroff command for me? Thanks.

Sincerely,

Yi-An Chen

[jury093]

Hi yachen! sorry for delay - local holyday :) I get fresh kernel "git clone https://github.com/OpenNuvoton/NUC970_Linux_Kernel.git" new uSD, ext4, kernel with debug output for mmc, boot full log at http://pastebin.com/xPx0qWJB

[yachen]

Hi,

Did you un-comment the//nuc970_sd_debug() in driver? I cannot find and message print out from line 584. //nuc970_sd_debug("Event = 0x%0X [0x%08X 0x%08X] <0x%x>\n", status, cmd->resp[0], cmd->resp[1], err);

Sincerely,

Yi-An Chen

[jury093]

Hi yachen! yes, I uncomment for debug.. sorry for long log stuff cleared

[jury093]

Oh! I stupid :) see new log for debug and uncommented 584 string: http://pastebin.com/HPxwaPe8

[yachen]

Many thanks jury093, Our engineer find some incorrect SD state change in the log and is checking the root cause.

[yachen]

Hi @jury093,

Can you modify nuc970_sd_completed_command() and test again? We guess the take was interrupted by signal instead of transfer complete thus cause the state error.

    if (data)
    {

• wait_event_interruptible(sd_wq_xfer, (sd_state_xfer != 0))
• if (wait_event_interruptible(sd_wq_xfer, (sd_state_xfer != 0)))
• {
• nuc970_sd_debug("\ndata: interrupted by signal !!!\n\n");
• return -ERESTARTSYS;
• } }

Thanks,

Yi-An Chen

[jury093]

Hi Yi-An Chen! I can make this test only tommorow, sorry..

[jury093]

Hi Yi-An Chen! I make modification for nuc970_sd_completed_command() function: `// if (data)

// {

// wait_event_interruptible(sd_wq_xfer, (sd_state_xfer != 0));

// }

    if (data)

    {

        wait_event_interruptible(sd_wq_xfer, (sd_state_xfer != 0));

        if(wait_event_interruptible(sd_wq_xfer, (sd_state_xfer != 0)))

    {

    nuc970_sd_debug("\ndata: interrupted by signal !!!\n\n");

    return -ERESTARTSYS;

    }

    }`

rebuild with warning: CALL scripts/checksyscalls.sh GEN scripts/mod/devicetable-offsets.h HOSTCC scripts/mod/file2alias.o HOSTLD scripts/mod/modpost CHK include/generated/compile.h CC drivers/mmc/host/nuc970_sd.o drivers/mmc/host/nuc970_sd.c: In function 'nuc970_sd_completed_command': drivers/mmc/host/nuc970_sd.c:615: warning: 'return' with a value, in function returning void and boot from mmc (until boot I run e2fsck for clear mmcblk0p1 for errors) Full log: http://pastebin.com/24qzmTS5 after "poweroff" command system is make shutdown to strings: data: interrupted by signal !!! SDH xfer done. and freezed. But for normal shutdown I can't "Will now halt" message and insert this uSD to USB Flash reader I check filesystem: ~# e2fsck /dev/sda1 e2fsck 1.42.12 (29-Aug-2014) /dev/sda1: recovering journal Setting free blocks count to 385353 (was 385562) /dev/sda1: clean, 13819/118800 files, 89391/474744 blocks

[yachen]

Hi @jury093 ,

This log confirms the root cause of file system corruption. The wait_event_interruptible() was waked by a signal instead of transfer complete interrupt which the design is expect. So the following transfer are corrupted due to state error. We'll check how to recover from this state. Maybe replace it with a wait_event_timeout() so the transfer will not interrupt by signal while the timeout guarantees the code won't block forever,

Sincerely,

Yi-An Chen

[jury093]

Hi Yi-An Chen! A week ago I clone kernel sources from https://github.com/OpenNuvoton/NUC970_Linux_Kernel, build uImage and boot with Debian 7 armel rootFS.. I make test for 3 card: Kingston 2GB uSD Transcend 2GB uSD SunDisk Ultra 8GB uSD HCI No errors after ~20 cycles reboot/powerdown each of these cards. I think, this bug (distruction rootfs/partition after reboot/powerdown) can be close Thank