SPI errors on Fritzbox 4040

Hardware Questions and Recommendations
1

Got these errors yesterday before the router (fritzbox 4040) rebooted itself:

Jun  8 18:24:07 router-casa-andrea kernel: [2872350.491148] SQUASHFS error: Unable to read metadata cache entry [9ec781]
Jun  8 18:24:07 router-casa-andrea kernel: [2872350.496272] SQUASHFS error: Unable to read directory block [9ec781:1a0d]
Jun  8 18:32:45 router-casa-andrea kernel: [2872868.579090] spi-nor spi0.0: SPI transfer failed: -110
Jun  8 18:32:45 router-casa-andrea kernel: [2872868.579173] spi_master spi0: failed to transfer one message from queue
Jun  8 18:32:45 router-casa-andrea kernel: [2872868.583167] blk_update_request: I/O error, dev mtdblock13, sector 6304 op 0x0:(READ) flags 0x800 phys_seg 18 prio class 0
Jun  8 18:32:46 router-casa-andrea kernel: [2872869.619124] spi-nor spi0.0: SPI transfer failed: -110
Jun  8 18:32:46 router-casa-andrea kernel: [2872869.619207] spi_master spi0: failed to transfer one message from queue
Jun  8 18:32:46 router-casa-andrea kernel: [2872869.623198] blk_update_request: I/O error, dev mtdblock13, sector 6312 op 0x0:(READ) flags 0x800 phys_seg 17 prio class 0
Jun  8 18:32:47 router-casa-andrea kernel: [2872870.659048] spi-nor spi0.0: SPI transfer failed: -110
Jun  8 18:32:47 router-casa-andrea kernel: [2872870.659133] spi_master spi0: failed to transfer one message from queue
Jun  8 18:32:47 router-casa-andrea kernel: [2872870.663133] blk_update_request: I/O error, dev mtdblock13, sector 6320 op 0x0:(READ) flags 0x800 phys_seg 16 prio class 0
Jun  8 18:32:48 router-casa-andrea kernel: [2872871.699113] spi-nor spi0.0: SPI transfer failed: -110
Jun  8 18:32:48 router-casa-andrea kernel: [2872871.699192] spi_master spi0: failed to transfer one message from queue
Jun  8 18:32:48 router-casa-andrea kernel: [2872871.703194] blk_update_request: I/O error, dev mtdblock13, sector 6328 op 0x0:(READ) flags 0x800 phys_seg 15 prio class 0
Jun  8 18:32:49 router-casa-andrea kernel: [2872872.739062] spi-nor spi0.0: SPI transfer failed: -110
Jun  8 18:32:49 router-casa-andrea kernel: [2872872.739153] spi_master spi0: failed to transfer one message from queue
Jun  8 18:32:49 router-casa-andrea kernel: [2872872.743143] blk_update_request: I/O error, dev mtdblock13, sector 6336 op 0x0:(READ) flags 0x800 phys_seg 14 prio class 0
Jun  8 18:32:50 router-casa-andrea kernel: [2872873.779134] spi-nor spi0.0: SPI transfer failed: -110
Jun  8 18:32:50 router-casa-andrea kernel: [2872873.779284] spi_master spi0: failed to transfer one message from queue
Jun  8 18:32:50 router-casa-andrea kernel: [2872873.783273] blk_update_request: I/O error, dev mtdblock13, sector 6344 op 0x0:(READ) flags 0x800 phys_seg 13 prio class 0
Jun  8 18:32:51 router-casa-andrea kernel: [2872874.819134] spi-nor spi0.0: SPI transfer failed: -110
Jun  8 18:32:51 router-casa-andrea kernel: [2872874.819279] spi_master spi0: failed to transfer one message from queue
Jun  8 18:32:51 router-casa-andrea kernel: [2872874.823350] blk_update_request: I/O error, dev mtdblock13, sector 6352 op 0x0:(READ) flags 0x800 phys_seg 12 prio class 0
Jun  8 18:32:52 router-casa-andrea kernel: [2872875.859004] spi-nor spi0.0: SPI transfer failed: -110
Jun  8 18:32:52 router-casa-andrea kernel: [2872875.859092] spi_master spi0: failed to transfer one message from queue
Jun  8 18:32:52 router-casa-andrea kernel: [2872875.863122] blk_update_request: I/O error, dev mtdblock13, sector 6360 op 0x0:(READ) flags 0x800 phys_seg 11 prio class 0
Jun  8 18:32:53 router-casa-andrea kernel: [2872876.899124] spi-nor spi0.0: SPI transfer failed: -110
Jun  8 18:32:53 router-casa-andrea kernel: [2872876.899271] spi_master spi0: failed to transfer one message from queue
Jun  8 18:32:53 router-casa-andrea kernel: [2872876.903265] blk_update_request: I/O error, dev mtdblock13, sector 6368 op 0x0:(READ) flags 0x800 phys_seg 10 prio class 0
Jun  8 18:32:54 router-casa-andrea kernel: [2872877.949064] spi-nor spi0.0: SPI transfer failed: -110
Jun  8 18:32:54 router-casa-andrea kernel: [2872877.949206] spi_master spi0: failed to transfer one message from queue
Jun  8 18:32:54 router-casa-andrea kernel: [2872877.953363] blk_update_request: I/O error, dev mtdblock13, sector 6376 op 0x0:(READ) flags 0x800 phys_seg 9 prio class 0
Jun  8 18:32:55 router-casa-andrea kernel: [2872878.978966] spi-nor spi0.0: SPI transfer failed: -110
Jun  8 18:32:55 router-casa-andrea kernel: [2872878.979048] spi_master spi0: failed to transfer one message from queue
Jun  8 18:32:55 router-casa-andrea kernel: [2872878.983139] blk_update_request: I/O error, dev mtdblock13, sector 6384 op 0x0:(READ) flags 0x800 phys_seg 8 prio class 0
Jun  8 18:32:56 router-casa-andrea kernel: [2872880.018946] spi-nor spi0.0: SPI transfer failed: -110
Jun  8 18:32:56 router-casa-andrea kernel: [2872880.019029] spi_master spi0: failed to transfer one message from queue
Jun  8 18:32:56 router-casa-andrea kernel: [2872880.023027] blk_update_request: I/O error, dev mtdblock13, sector 6392 op 0x0:(READ) flags 0x800 phys_seg 7 prio class 0
Jun  8 18:32:56 router-casa-andrea kernel: [2872880.052201] SQUASHFS error: Failed to read block 0x3142ba: -5
Jun  8 18:32:56 router-casa-andrea kernel: [2872880.052255] SQUASHFS error: Unable to read fragment cache entry [3142ba]
Jun  8 18:32:56 router-casa-andrea kernel: [2872880.056951] SQUASHFS error: Unable to read page, block 3142ba, size 10df8
Jun  8 18:32:56 router-casa-andrea kernel: [2872880.064963] SQUASHFS error: Unable to read fragment cache entry [3142ba]
Jun  8 18:32:56 router-casa-andrea kernel: [2872880.070807] SQUASHFS error: Unable to read page, block 3142ba, size 10df8
Jun  8 18:32:56 router-casa-andrea kernel: [2872880.077766] SQUASHFS error: Unable to read fragment cache entry [3142ba]
Jun  8 18:32:56 router-casa-andrea kernel: [2872880.084601] SQUASHFS error: Unable to read page, block 3142ba, size 10df8

Is it something than can be fixed, perhaps from the bootloader, or is the flash on its last legs?

2

I just encountered the same issue with my AVM FRITZ!Box 4040 running OpenWrt 22.03.3 r20028-43d71ad93e / LuCI openwrt-22.03 branch git-23.119.80898-65ef406:

[15415.626982] EXT4-fs (sda1): mounted filesystem with ordered data mode. Opts: 
[17122.834289] spi-nor spi0.0: SPI transfer failed: -110
[17122.834355] spi_master spi0: failed to transfer one message from queue
[17122.838358] blk_update_request: I/O error, dev mtdblock13, sector 20080 op 0x0:(READ) flags 0x800 phys_seg 11 prio class 0
[17123.874422] spi-nor spi0.0: SPI transfer failed: -110
[17123.874502] spi_master spi0: failed to transfer one message from queue
[17123.878500] blk_update_request: I/O error, dev mtdblock13, sector 20088 op 0x0:(READ) flags 0x800 phys_seg 10 prio class 0
[17124.914525] spi-nor spi0.0: SPI transfer failed: -110
[17124.914609] spi_master spi0: failed to transfer one message from queue
[17124.918640] blk_update_request: I/O error, dev mtdblock13, sector 20096 op 0x0:(READ) flags 0x800 phys_seg 9 prio class 0
[17125.954418] spi-nor spi0.0: SPI transfer failed: -110
[17125.954505] spi_master spi0: failed to transfer one message from queue
[17125.958495] blk_update_request: I/O error, dev mtdblock13, sector 20104 op 0x0:(READ) flags 0x800 phys_seg 8 prio class 0
[17126.994429] spi-nor spi0.0: SPI transfer failed: -110
[17126.994531] spi_master spi0: failed to transfer one message from queue
[17126.998515] blk_update_request: I/O error, dev mtdblock13, sector 20112 op 0x0:(READ) flags 0x800 phys_seg 7 prio class 0
[17128.034216] spi-nor spi0.0: SPI transfer failed: -110
[17128.034297] spi_master spi0: failed to transfer one message from queue
[17128.038304] blk_update_request: I/O error, dev mtdblock13, sector 20120 op 0x0:(READ) flags 0x800 phys_seg 6 prio class 0
[17129.074195] spi-nor spi0.0: SPI transfer failed: -110
[17129.074277] spi_master spi0: failed to transfer one message from queue
[17129.078268] blk_update_request: I/O error, dev mtdblock13, sector 20128 op 0x0:(READ) flags 0x800 phys_seg 5 prio class 0
[17130.114296] spi-nor spi0.0: SPI transfer failed: -110
[17130.114370] spi_master spi0: failed to transfer one message from queue
[17130.118375] blk_update_request: I/O error, dev mtdblock13, sector 20136 op 0x0:(READ) flags 0x800 phys_seg 4 prio class 0
[17131.154164] spi-nor spi0.0: SPI transfer failed: -110
[17131.154245] spi_master spi0: failed to transfer one message from queue
[17131.158259] blk_update_request: I/O error, dev mtdblock13, sector 20144 op 0x0:(READ) flags 0x800 phys_seg 3 prio class 0
[17132.195503] spi-nor spi0.0: SPI transfer failed: -110
[17132.196020] spi_master spi0: failed to transfer one message from queue
[17132.200981] blk_update_request: I/O error, dev mtdblock13, sector 20152 op 0x0:(READ) flags 0x800 phys_seg 2 prio class 0
[17133.234138] spi-nor spi0.0: SPI transfer failed: -110
[17133.234212] spi_master spi0: failed to transfer one message from queue
[17133.238209] blk_update_request: I/O error, dev mtdblock13, sector 20160 op 0x0:(READ) flags 0x800 phys_seg 1 prio class 0
[17133.244889] SQUASHFS error: Failed to read block 0x9c91fe: -5
[17133.255702] SQUASHFS error: Unable to read data cache entry [9c91fe]
[17133.261364] SQUASHFS error: Unable to read page, block 9c91fe, size fc8c
[17133.268082] SQUASHFS error: Unable to read data cache entry [9c91fe]
[17133.274520] SQUASHFS error: Unable to read page, block 9c91fe, size fc8c
[17133.281212] SQUASHFS error: Unable to read data cache entry [9c91fe]
[17133.287707] SQUASHFS error: Unable to read page, block 9c91fe, size fc8c
[17133.294279] SQUASHFS error: Unable to read data cache entry [9c91fe]
[17133.300521] SQUASHFS error: Unable to read page, block 9c91fe, size fc8c
[17133.307491] SQUASHFS error: Unable to read data cache entry [9c91fe]
[17133.313541] SQUASHFS error: Unable to read page, block 9c91fe, size fc8c
[17133.320334] SQUASHFS error: Unable to read data cache entry [9c91fe]
[17133.326615] SQUASHFS error: Unable to read page, block 9c91fe, size fc8c
[17133.333041] SQUASHFS error: Unable to read data cache entry [9c91fe]
[17133.339786] SQUASHFS error: Unable to read page, block 9c91fe, size fc8c
[17133.346116] SQUASHFS error: Unable to read data cache entry [9c91fe]
[17133.352603] SQUASHFS error: Unable to read page, block 9c91fe, size fc8c
[17133.359332] SQUASHFS error: Unable to read data cache entry [9c91fe]
[17133.365680] SQUASHFS error: Unable to read page, block 9c91fe, size fc8c

It happened when I was trying to do a PXE boot (using the 4040 as bootserver) with a 700mb image. There wasn't a huge amount else going on, though (there's only one wired client and a couple of wifi clients connected).

I've got tailscaled running on here and it seems to be a bit of a memory hog. I note that after recovering from the squashfs blip, the system was reporting 87% memory in use. Perhaps memory pressure triggers this problem?

3

me too (same model), but it's a random problem (it happened to me only once) and it never came back.

on OpenWrt 23.05.0-rc1, r23069-e2701e0f33

4

Hm, failing SPI transfers could be caused by a too high frequency set in the dts. Maybe AVM has switched manufacturer for the flash and the new flash requires a slightly lower frequency? However, this is pure guesswork ...

1 Like
5

I would like to point out that this too (I assume related):

6

That looks like a "normal" message when installing the firmware: Overwriting the old firmware renders existing files inaccessible, hence the error messages. The poster also mentions no negative effects of the message. There are no errors related to the SPI transfer.

Both log files posted here contain explicit error messages on failed SPI transfers and all posts mention that the problems occur intermittently.

7

okay

having had a similar problem i thought it might be related,
but not having a specific log of that event

I can't figure out anything else...

8

It happened again for me a few minutes ago. Again - only when putting the router under extra load (serving up a 700mb file for an iPXE boot, via uHTTPd), the router runs otherwise continuously without issue. So I now have a 75% confidence level that this issue is triggered by CPU/memory pressure.

@andyboeh would you expect a too-high frequency set in the device tree to result in this kind of behaviour? My expectation would be that pushing the SPI too hard would result in this issue occurring intermittently, right?

9

Hm, I don't know for sure. I would try reducing the SPI frequency, it's a one-liner in the dts:

But to be sure, could you check which SPI flash chip is on your board? The kernel reports that in the boot log, could you check after a reboot which IC is reported? The box with which support was added for had a MX25L25635FMI flash chip as reported in the original commit.

I suppose you were serving this file from a USB drive, right? The USB3 ports on these devices is known to cause problems with WiFi, maybe it also causes problems with the SPI bus? Pure guesswork from my side!

10

Here's what I'm seeing:

$ dmesg | grep spi
[    0.783180] spi_qup 78b5000.spi: IN:block:16, fifo:64, OUT:block:16, fifo:64
[    0.786288] spi-nor spi0.0: mx25l25635e (32768 Kbytes)
[    0.791345] 13 fixed-partitions partitions found on MTD device spi0.0
[    0.796318] OF: Bad cell count for /soc/spi@78b5000/flash@0/partitions
[    0.802751] OF: Bad cell count for /soc/spi@78b5000/flash@0/partitions
[    0.809429] Creating 13 MTD partitions on "spi0.0":

Good catch - looks like it's a slightly different chip? Though based on the datasheet for the original MX25L25635F I don't really understand how one arrives at the 24Mhz max freq in the current dts. Of course, I'm not a knowledgeable low-level hardware hacker :slight_smile:

11

Yep - serving the TFTP + HTTP stuff from a USB flash drive.

That linked page is interesting, very plausible that some EM interference on the USB traces is also wreaking havoc on the SOCs line to the SPI (based on my very beginner understanding of this stuff).