Zero Divide in Kernel 3.12-rc4

Zero Divide in Kernel 3.12-rc4

[Ingo Jürgensmann]

Hi!

I'm testing the ESP SCSI driver port by Tuomas and Michael to 3.12-rc4 
and got now this kernel panic during heavy disk activity (apt-get 
dist-upgrade and parallel a rsync backup by BackupPC):

Debian GNU/Linux jessie/sid spice ttyS0

spice login: [77568.070000] *** ZERO DIVIDE ***   FORMAT=2
[77568.080000] Current process id is 0
[77568.090000] BAD KERNEL TRAP: 00000000
[77568.100000] Modules linked in: xt_multiport iptable_filter ip_tables 
x_tables ipv6 8390 loop evdev dmasound_paula mac_hid dmasound_core 
parport_amiga soundcore parport amimouse ext3 mbcache jbd dm_mod nbd sg 
sd_mod zorro7xx 53c700 hydra amiflop a3000
[77568.320000] PC: [<0484c33a>] sd_completed_bytes+0x90/0xe8 [sd_mod]
[77568.330000] SR: 2000  SP: 00277e58  a2: 0027e2e4
[77568.340000] d0: 00000000    d1: 007735a0    d2: 00000000    d3: 
00000001
[77568.350000] d4: 00000000    d5: 007735a8    a0: 024dd000    a1: 
024a0ea0
[77568.360000] Process swapper (pid: 0, task=0027e2e4)
[77568.370000] Frame format=2 instr addr=0484c336
[77568.390000] Stack from 00277e90:
         00000000 08100002 00000000 00000001 00200028 00000004 0249d120 
02be3090
         0272c9e0 00000000 007735a0 00277f04 0484c5f8 0249d120 00277f30 
0000000a
         00276000 00000100 00200000 00000004 0249d120 00001000 02460614 
002b9480
         00002002 00000bb8 0249d100 70040200 00000000 024dd400 0013f838 
0249d120
         00277f30 002b9480 00276000 001d38e2 000e1cec 0249d120 00000001 
00276000
         00277f30 00277f30 0002c8da 002b9480 00272704 0000000f 00002598 
08031470
[77568.950000] Call Trace: [<0484c5f8>] sd_done+0x1d6/0x2aa [sd_mod]
[77568.970000]  [<00001000>] kernel_pg_dir+0x0/0x1000
[77568.980000]  [<00002002>] _start+0x2/0x8
[77568.990000]  [<0013f838>] scsi_finish_command+0x8e/0xb2
[77569.000000]  [<001d38e2>] printk+0x0/0x24
[77569.010000]  [<000e1cec>] blk_done_softirq+0x90/0x9c
[77569.020000]  [<0002c8da>] __do_softirq+0xa2/0x12a
[77569.030000]  [<00002598>] badsys+0x6/0xa
[77569.040000]  [<00012b08>] slognd+0x74/0x8a
[77569.050000]  [<0000ffff>] res_func+0x101f/0x141a
[77569.060000]  [<001d6944>] schedule_preempt_disabled+0x0/0xe
[77569.070000]  [<0002ca04>] do_softirq+0x2c/0x32
[77569.080000]  [<0000264c>] ret_from_exception+0x0/0xc
[77569.090000]  [<00002598>] badsys+0x6/0xa
[77569.100000]  [<000454d6>] cpu_startup_entry+0x74/0xd6
[77569.110000]  [<0002721c>] kernel_thread+0x0/0x24
[77569.120000]  [<000f0abc>] strlen+0x0/0x14
[77569.130000]  [<001d307a>] rest_init+0x5e/0x66
[77569.140000]  [<002ca6e6>] start_kernel+0x38c/0x398
[77569.150000]  [<000037ee>] setup_rt_frame+0x400/0x4be
[77569.160000]  [<000037ee>] setup_rt_frame+0x400/0x4be
[77569.170000]  [<002c8854>] _sinittext+0x854/0x11ac
[77569.180000]
[77569.190000] Code: 4a80 6704 4c42 0001 2c01 2207 4c42 1406 <2c00> 2e01 
2004 2204 6704 4c42 0001 2801 2205 4c42 1404 2800 2a01 202e fff8 222e
[77569.350000] Disabling lock debugging due to kernel taint
[77569.360000] Kernel panic - not syncing: Aiee, killing interrupt 
handler!
[77611.970000] amikbd: Ctrl-Amiga-Amiga reset warning!!


I don't know whether this is related to the ESP driver or not, but maybe 
someone is better at reading this kind of output and can judge on 
this... :-)

-- 
Ciao...          //    Fon: 0381-2744150
.     Ingo     \X/     http://blog.windfluechter.net

gpg pubkey: http://www.juergensmann.de/ij_public_key.

Re: Zero Divide in Kernel 3.12-rc4

[Geert Uytterhoeven]

On Sun, Oct 20, 2013 at 11:37 AM, Ingo Jürgensmann
<ij@2013.bluespice.org> wrote:
> I'm testing the ESP SCSI driver port by Tuomas and Michael to 3.12-rc4 and
> got now this kernel panic during heavy disk activity (apt-get dist-upgrade
> and parallel a rsync backup by BackupPC):
>
> Debian GNU/Linux jessie/sid spice ttyS0
>
> spice login: [77568.070000] *** ZERO DIVIDE ***   FORMAT=2
> [77568.080000] Current process id is 0
> [77568.090000] BAD KERNEL TRAP: 00000000
> [77568.100000] Modules linked in: xt_multiport iptable_filter ip_tables
> x_tables ipv6 8390 loop evdev dmasound_paula mac_hid dmasound_core
> parport_amiga soundcore parport amimouse ext3 mbcache jbd dm_mod nbd sg
> sd_mod zorro7xx 53c700 hydra amiflop a3000
> [77568.320000] PC: [<0484c33a>] sd_completed_bytes+0x90/0xe8 [sd_mod]
> [77568.330000] SR: 2000  SP: 00277e58  a2: 0027e2e4
> [77568.340000] d0: 00000000    d1: 007735a0    d2: 00000000    d3: 00000001
> [77568.350000] d4: 00000000    d5: 007735a8    a0: 024dd000    a1: 024a0ea0
> [77568.360000] Process swapper (pid: 0, task=0027e2e4)
> [77568.370000] Frame format=2 instr addr=0484c336
> [77568.390000] Stack from 00277e90:
>         00000000 08100002 00000000 00000001 00200028 00000004 0249d120
> 02be3090
>         0272c9e0 00000000 007735a0 00277f04 0484c5f8 0249d120 00277f30
> 0000000a
>         00276000 00000100 00200000 00000004 0249d120 00001000 02460614
> 002b9480
>         00002002 00000bb8 0249d100 70040200 00000000 024dd400 0013f838
> 0249d120
>         00277f30 002b9480 00276000 001d38e2 000e1cec 0249d120 00000001
> 00276000
>         00277f30 00277f30 0002c8da 002b9480 00272704 0000000f 00002598
> 08031470
> [77568.950000] Call Trace: [<0484c5f8>] sd_done+0x1d6/0x2aa [sd_mod]

My first guess was that commit ea077b1b96e073eac5c3c5590529e964767fc5f7
("m68k: Truncate base in do_div()") was missing, but this is 3.12-rc4, so it
should be included.

BIG FAT WARNING for Thorsten: 3.10.7 does _not_ have this fix!
It was only backported ase5a16a446ef5bdb37214b100b93e59ac75e8a445 in
3.10.8.

> [77569.190000] Code: 4a80 6704 4c42 0001 2c01 2207 4c42 1406 <2c00> 2e01 2004 2204 6704 4c42 0001 2801 2205 4c42 1404 2800 2a01 202e fff8 222e

However, the addresses and the code above don't match the kernel image in
linux-3.12.0-rc4-amiga-m68k.tar.gz?

Can we get the image somewhere?

Apart from that, since the division is:

                /* be careful ... don't want any overflows */
                u64 factor = scmd->device->sector_size / 512;
                do_div(start_lba, factor);
                do_div(end_lba, factor);

(yes, the "u64 factor" is the issue without Andreas's fix), it could still be
an ESP bug, if scmd->device->sector_size turns out to be less than 512
(e.g. 0).

Gr{oetje,eeting}s,

                        Geert

--
Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org

In personal conversations with technical people, I call myself a hacker. But
when I'm talking to journalists I just say "programmer" or something like that.
                                -- Linus Torvalds

Re: Zero Divide in Kernel 3.12-rc4

[Ingo Jürgensmann]

Am 20.10.2013 um 12:10 schrieb Geert Uytterhoeven <geert@linux-m68k.org>:

> However, the addresses and the code above don't match the kernel image in
> linux-3.12.0-rc4-amiga-m68k.tar.gz?
> Can we get the image somewhere?

I can give you access to the VM with the (patched) kernel source where I crosscompiled the image. Just send me your SSH pubkey... 
When it helps, here's the binary tarball: https://silverhaze.org/public.php?service=files&t=4701b07462fbbe06516b9433f3084e4c

> Apart from that, since the division is:
> 
>                /* be careful ... don't want any overflows */
>                u64 factor = scmd->device->sector_size / 512;
>                do_div(start_lba, factor);
>                do_div(end_lba, factor);
> 
> (yes, the "u64 factor" is the issue without Andreas's fix), it could still be
> an ESP bug, if scmd->device->sector_size turns out to be less than 512
> (e.g. 0).


At least this time the filesystem survived the kernel crash. Maybe Michael can have a look at the source as well when the sun rises in *.nz... ;)

-- 
Ciao...            //      Fon: 0381-2744150
      Ingo       \X/       http://blog.windfluechter.net


gpg pubkey:  http://www.juergensmann.de/ij_public_key.asc

Re: Zero Divide in Kernel 3.12-rc4

[Geert Uytterhoeven]

On Sun, Oct 20, 2013 at 12:25 PM, Ingo Jürgensmann
<ij@2013.bluespice.org> wrote:
>> However, the addresses and the code above don't match the kernel image in
>> linux-3.12.0-rc4-amiga-m68k.tar.gz?
>> Can we get the image somewhere?
>
> I can give you access to the VM with the (patched) kernel source where I crosscompiled the image. Just send me your SSH pubkey...

Will see later, have to cook (food, not code :-) now...
Can you email me the patch?

> When it helps, here's the binary tarball: https://silverhaze.org/public.php?service=files&t=4701b07462fbbe06516b9433f3084e4c

That's the same binary as before, which doesn't match?

Gr{oetje,eeting}s,

                        Geert

--
Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org

In personal conversations with technical people, I call myself a hacker. But
when I'm talking to journalists I just say "programmer" or something like that.
                                -- Linus Torvalds

Re: Zero Divide in Kernel 3.12-rc4

[Thorsten Glaser]

Geert Uytterhoeven dixit:

>BIG FAT WARNING for Thorsten: 3.10.7 does _not_ have this fix!

Debian 3.10.7-1 does have it (as Debian-specific patch).
Otherwise my buildd couldn’t run that kernel as it uses btrfs.

bye,
//mirabilos
-- 
<diogenese> Beware of ritual lest you forget the meaning behind it.
<igli> yeah but it means if you really care about something, don't
    ritualise it, or you will lose it. don't fetishise it, don't
    obsess. or you'll forget why you love it in the first place.

Re: Zero Divide in Kernel 3.12-rc4

[Michael Schmitz]

Ingo,

this looks like it might be related to the ESP driver - 
scsi_finish_command called from the swapper process during apt-get 
dist-upgrade does seem plausible.

Some of the Amiga SCSI drivers did fiddle with the chip interrupt 
enable on SCSI interrupt entry, but I'd have thought the ESP core is 
reasonably thread-safe these days.

To pinpoint where in sd_completed_bytes this happens, I'd need the 
sd_mod module and the module symbol map.

Cheers,

	MIchael

> I'm testing the ESP SCSI driver port by Tuomas and Michael to 3.12-rc4 
> and got now this kernel panic during heavy disk activity (apt-get 
> dist-upgrade and parallel a rsync backup by BackupPC):
>
> Debian GNU/Linux jessie/sid spice ttyS0
>
> spice login: [77568.070000] *** ZERO DIVIDE ***   FORMAT=2
> [77568.080000] Current process id is 0
> [77568.090000] BAD KERNEL TRAP: 00000000
> [77568.100000] Modules linked in: xt_multiport iptable_filter 
> ip_tables x_tables ipv6 8390 loop evdev dmasound_paula mac_hid 
> dmasound_core parport_amiga soundcore parport amimouse ext3 mbcache 
> jbd dm_mod nbd sg sd_mod zorro7xx 53c700 hydra amiflop a3000
> [77568.320000] PC: [<0484c33a>] sd_completed_bytes+0x90/0xe8 [sd_mod]
> [77568.330000] SR: 2000  SP: 00277e58  a2: 0027e2e4
> [77568.340000] d0: 00000000    d1: 007735a0    d2: 00000000    d3: 
> 00000001
> [77568.350000] d4: 00000000    d5: 007735a8    a0: 024dd000    a1: 
> 024a0ea0
> [77568.360000] Process swapper (pid: 0, task=0027e2e4)
> [77568.370000] Frame format=2 instr addr=0484c336
> [77568.390000] Stack from 00277e90:
>         00000000 08100002 00000000 00000001 00200028 00000004 0249d120 
> 02be3090
>         0272c9e0 00000000 007735a0 00277f04 0484c5f8 0249d120 00277f30 
> 0000000a
>         00276000 00000100 00200000 00000004 0249d120 00001000 02460614 
> 002b9480
>         00002002 00000bb8 0249d100 70040200 00000000 024dd400 0013f838 
> 0249d120
>         00277f30 002b9480 00276000 001d38e2 000e1cec 0249d120 00000001 
> 00276000
>         00277f30 00277f30 0002c8da 002b9480 00272704 0000000f 00002598 
> 08031470
> [77568.950000] Call Trace: [<0484c5f8>] sd_done+0x1d6/0x2aa [sd_mod]
> [77568.970000]  [<00001000>] kernel_pg_dir+0x0/0x1000
> [77568.980000]  [<00002002>] _start+0x2/0x8
> [77568.990000]  [<0013f838>] scsi_finish_command+0x8e/0xb2
> [77569.000000]  [<001d38e2>] printk+0x0/0x24
> [77569.010000]  [<000e1cec>] blk_done_softirq+0x90/0x9c
> [77569.020000]  [<0002c8da>] __do_softirq+0xa2/0x12a
> [77569.030000]  [<00002598>] badsys+0x6/0xa
> [77569.040000]  [<00012b08>] slognd+0x74/0x8a
> [77569.050000]  [<0000ffff>] res_func+0x101f/0x141a
> [77569.060000]  [<001d6944>] schedule_preempt_disabled+0x0/0xe
> [77569.070000]  [<0002ca04>] do_softirq+0x2c/0x32
> [77569.080000]  [<0000264c>] ret_from_exception+0x0/0xc
> [77569.090000]  [<00002598>] badsys+0x6/0xa
> [77569.100000]  [<000454d6>] cpu_startup_entry+0x74/0xd6
> [77569.110000]  [<0002721c>] kernel_thread+0x0/0x24
> [77569.120000]  [<000f0abc>] strlen+0x0/0x14
> [77569.130000]  [<001d307a>] rest_init+0x5e/0x66
> [77569.140000]  [<002ca6e6>] start_kernel+0x38c/0x398
> [77569.150000]  [<000037ee>] setup_rt_frame+0x400/0x4be
> [77569.160000]  [<000037ee>] setup_rt_frame+0x400/0x4be
> [77569.170000]  [<002c8854>] _sinittext+0x854/0x11ac
> [77569.180000]
> [77569.190000] Code: 4a80 6704 4c42 0001 2c01 2207 4c42 1406 <2c00> 
> 2e01 2004 2204 6704 4c42 0001 2801 2205 4c42 1404 2800 2a01 202e fff8 
> 222e
> [77569.350000] Disabling lock debugging due to kernel taint
> [77569.360000] Kernel panic - not syncing: Aiee, killing interrupt 
> handler!
> [77611.970000] amikbd: Ctrl-Amiga-Amiga reset warning!!
>
>
> I don't know whether this is related to the ESP driver or not, but 
> maybe someone is better at reading this kind of output and can judge 
> on this... :-)
>
> -- 
> Ciao...          //    Fon: 0381-2744150
> .     Ingo     \X/     http://blog.windfluechter.net
>
> gpg pubkey: http://www.juergensmann.de/ij_public_key.
> --
> To unsubscribe from this list: send the line "unsubscribe linux-m68k" 
> in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Zero Divide in Kernel 3.12-rc4

[Geert Uytterhoeven]

On Mon, Oct 21, 2013 at 9:34 AM, Michael Schmitz
<schmitz@biophys.uni-duesseldorf.de> wrote:
> this looks like it might be related to the ESP driver - scsi_finish_command
> called from the swapper process during apt-get dist-upgrade does seem
> plausible.
>
> Some of the Amiga SCSI drivers did fiddle with the chip interrupt enable on
> SCSI interrupt entry, but I'd have thought the ESP core is reasonably
> thread-safe these days.
>
> To pinpoint where in sd_completed_bytes this happens, I'd need the sd_mod
> module and the module symbol map.

                /* be careful ... don't want any overflows */
                u64 factor = scmd->device->sector_size / 512;
                do_div(start_lba, factor);
                do_div(end_lba, factor);

scmd->device->sector_size should be 512, so factor should be 1.

Let's try a bit harder with a fresher mind and a cup of coffee and
a mini-twix:

>> [77568.320000] PC: [<0484c33a>] sd_completed_bytes+0x90/0xe8 [sd_mod]
>> [77568.330000] SR: 2000  SP: 00277e58  a2: 0027e2e4
>> [77568.340000] d0: 00000000    d1: 007735a0    d2: 00000000    d3: 00000001
>> [77568.350000] d4: 00000000    d5: 007735a8    a0: 024dd000    a1: 024a0ea0

>> [77569.190000] Code: 4a80 6704 4c42 0001 2c01 2207 4c42 1406 <2c00> 2e01
>> 2004 2204 6704 4c42 0001 2801 2205 4c42 1404 2800 2a01 202e fff8 222e

"4c42" is a division. It's the second one of the four divisions:

   0: 4a80           tstl %d0

d0 is zero, so the first division is skipped.

   2: 6704           beqs 0x8
   4: 4c42 0001       divull %d2,%d1,%d0
   8: 2c01           movel %d1,%d6
   a: 2207           movel %d7,%d1
   c: 4c42 1406       divul %d2,%d6,%d1

It's dividing by d2, which is zero. So scmd->device->sector_size must be
smaller than 512 (probably zero).

  10: 2c00           movel %d0,%d6
  12: 2e01           movel %d1,%d7
  14: 2004           movel %d4,%d0
  16: 2204           movel %d4,%d1
  18: 6704           beqs 0x1e
  1a: 4c42 0001       divull %d2,%d1,%d0
  1e: 2801           movel %d1,%d4
  20: 2205           movel %d5,%d1
  22: 4c42 1404       divul %d2,%d4,%d1
  26: 2800           movel %d0,%d4
  28: 2a01           movel %d1,%d5
  2a: 202e fff8       movel %fp@(-8),%d0

The posted binary has slightly different code (different addresses, and the
division is "4c40"):

00168404 <sd_completed_bytes>:
  168404:       4e56 fff8       linkw %fp,#-8
  168408:       48e7 3f1c       moveml %d2-%d7/%a3-%a5,%sp@-
  16840c:       266e 0008       moveal %fp@(8),%a3
  168410:       206b 0054       moveal %a3@(84),%a0
  168414:       2828 0032       movel %a0@(50),%d4
  168418:       2a28 0036       movel %a0@(54),%d5
  16841c:       2c2b 0040       movel %a3@(64),%d6
  168420:       2e2b 0044       movel %a3@(68),%d7
  168424:       7001            moveq #1,%d0
  168426:       b0a8 0022       cmpl %a0@(34),%d0
  16842a:       6600 00b2       bnew 1684de <sd_completed_bytes+0xda>
  16842e:       486e fff8       pea %fp@(-8)
  168432:       4878 0060       pea 60 <PAGE_TABLE_SIZE+0x20>
  168436:       2f2b 0058       movel %a3@(88),%sp@-
  16843a:       4eb9 0015 4e86  jsr 154e86 <scsi_get_sense_info_fld>
  168440:       4fef 000c       lea %sp@(12),%sp
  168444:       4a80            tstl %d0
  168446:       6700 0096       beqw 1684de <sd_completed_bytes+0xda>
  16844a:       2053            moveal %a3@,%a0
  16844c:       2028 0054       movel %a0@(84),%d0
  168450:       b0ab 0040       cmpl %a3@(64),%d0
  168454:       6400 0088       bccw 1684de <sd_completed_bytes+0xda>
  168458:       2206            movel %d6,%d1
  16845a:       7409            moveq #9,%d2
  16845c:       e4a9            lsrl %d2,%d1
  16845e:       2601            movel %d1,%d3
  168460:       4202            clrb %d2
  168462:       d685            addl %d5,%d3
  168464:       d584            addxl %d4,%d2
  168466:       0c80 0000 01ff  cmpil #511,%d0
  16846c:       6212            bhis 168480 <sd_completed_bytes+0x7c>
  16846e:       da85            addl %d5,%d5
  168470:       d984            addxl %d4,%d4
  168472:       2002            movel %d2,%d0
  168474:       2203            movel %d3,%d1
  168476:       d281            addl %d1,%d1
  168478:       d180            addxl %d0,%d0
  16847a:       2840            moveal %d0,%a4
  16847c:       2a41            moveal %d1,%a5
  16847e:       602a            bras 1684aa <sd_completed_bytes+0xa6>
  168480:       7209            moveq #9,%d1
  168482:       e2a8            lsrl %d1,%d0
  168484:       2204            movel %d4,%d1
  168486:       2045            moveal %d5,%a0
  168488:       6704            beqs 16848e <sd_completed_bytes+0x8a>
  16848a:       4c40 1004       divull %d0,%d4,%d1
  16848e:       2a08            movel %a0,%d5
  168490:       4c40 5404       divul %d0,%d4,%d5
  168494:       2801            movel %d1,%d4
  168496:       2202            movel %d2,%d1
  168498:       2043            moveal %d3,%a0
  16849a:       6704            beqs 1684a0 <sd_completed_bytes+0x9c>
  16849c:       4c40 1002       divull %d0,%d2,%d1
  1684a0:       2608            movel %a0,%d3
  1684a2:       4c40 3402       divul %d0,%d2,%d3
  1684a6:       2841            moveal %d1,%a4
  1684a8:       2a43            moveal %d3,%a5
  1684aa:       202e fff8       movel %fp@(-8),%d0
  1684ae:       222e fffc       movel %fp@(-4),%d1
  1684b2:       2400            movel %d0,%d2
  1684b4:       2601            movel %d1,%d3
  1684b6:       9685            subl %d5,%d3
  1684b8:       9584            subxl %d4,%d2
  1684ba:       6522            bcss 1684de <sd_completed_bytes+0xda>
  1684bc:       240c            movel %a4,%d2
  1684be:       260d            movel %a5,%d3
  1684c0:       9681            subl %d1,%d3
  1684c2:       9580            subxl %d0,%d2
  1684c4:       6318            blss 1684de <sd_completed_bytes+0xda>
  1684c6:       9285            subl %d5,%d1
  1684c8:       9184            subxl %d4,%d0
  1684ca:       2053            moveal %a3@,%a0
  1684cc:       9c87            subl %d7,%d6
  1684ce:       2028 0054       movel %a0@(84),%d0
  1684d2:       4c01 0800       mulsl %d1,%d0
  1684d6:       bc80            cmpl %d0,%d6
  1684d8:       6406            bccs 1684e0 <sd_completed_bytes+0xdc>
  1684da:       2006            movel %d6,%d0
  1684dc:       6002            bras 1684e0 <sd_completed_bytes+0xdc>
  1684de:       4280            clrl %d0
  1684e0:       4cee 38fc ffd4  moveml %fp@(-44),%d2-%d7/%a3-%a5
  1684e6:       4e5e            unlk %fp
  1684e8:       4e75            rts

Gr{oetje,eeting}s,

                        Geert

--
Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org

In personal conversations with technical people, I call myself a hacker. But
when I'm talking to journalists I just say "programmer" or something like that.
                                -- Linus Torvalds

Re: Zero Divide in Kernel 3.12-rc4

[Michael Schmitz]

Geert,

>>
>> To pinpoint where in sd_completed_bytes this happens, I'd need the 
>> sd_mod
>> module and the module symbol map.
>
>                 /* be careful ... don't want any overflows */
>                 u64 factor = scmd->device->sector_size / 512;
>                 do_div(start_lba, factor);
>                 do_div(end_lba, factor);
>
> scmd->device->sector_size should be 512, so factor should be 1.
>
> Let's try a bit harder with a fresher mind and a cup of coffee and
> a mini-twix:
>
>>> [77568.320000] PC: [<0484c33a>] sd_completed_bytes+0x90/0xe8 [sd_mod]
>>> [77568.330000] SR: 2000  SP: 00277e58  a2: 0027e2e4
>>> [77568.340000] d0: 00000000    d1: 007735a0    d2: 00000000    d3: 
>>> 00000001
>>> [77568.350000] d4: 00000000    d5: 007735a8    a0: 024dd000    a1: 
>>> 024a0ea0
>
>>> [77569.190000] Code: 4a80 6704 4c42 0001 2c01 2207 4c42 1406 <2c00> 
>>> 2e01
>>> 2004 2204 6704 4c42 0001 2801 2205 4c42 1404 2800 2a01 202e fff8 222e
>
> "4c42" is a division. It's the second one of the four divisions:
>
>    0: 4a80           tstl %d0
>
> d0 is zero, so the first division is skipped.
>
>    2: 6704           beqs 0x8
>    4: 4c42 0001       divull %d2,%d1,%d0
>    8: 2c01           movel %d1,%d6
>    a: 2207           movel %d7,%d1
>    c: 4c42 1406       divul %d2,%d6,%d1
>
> It's dividing by d2, which is zero. So scmd->device->sector_size must 
> be
> smaller than 512 (probably zero).
>

Thanks for parsing the dump - now I'll have to find out how on earth 
sector_size got overwritten in the first place ... and whether anyrhing 
in scmd-> device still makes any sense at all.

Cheers,

	Michael

Re: Zero Divide in Kernel 3.12-rc4

[Michael Schmitz]

Hi Geert,

>>> To pinpoint where in sd_completed_bytes this happens, I'd need the 
>>> sd_mod
>>> module and the module symbol map.
>>
>>                 /* be careful ... don't want any overflows */
>>                 u64 factor = scmd->device->sector_size / 512;
>>                 do_div(start_lba, factor);
>>                 do_div(end_lba, factor);
>>
>> scmd->device->sector_size should be 512, so factor should be 1.

Looking at a bit of context right above what you quote here, we can be 
reasonably certain that scmd->device->sector_size is greater or equal 
512.

Ingo - could you add

if (scmd->device->sector_size > 2048)
	sdev_printk(KERN_ERR, scmd->device, "Whoa - large secor size %d\n", 
scmd->device->sector_size);

before the do_div calls, and see what that reports?

Cheers,

	Michael

>>
>> Let's try a bit harder with a fresher mind and a cup of coffee and
>> a mini-twix:
>>
>>>> [77568.320000] PC: [<0484c33a>] sd_completed_bytes+0x90/0xe8 
>>>> [sd_mod]
>>>> [77568.330000] SR: 2000  SP: 00277e58  a2: 0027e2e4
>>>> [77568.340000] d0: 00000000    d1: 007735a0    d2: 00000000    d3: 
>>>> 00000001
>>>> [77568.350000] d4: 00000000    d5: 007735a8    a0: 024dd000    a1: 
>>>> 024a0ea0
>>
>>>> [77569.190000] Code: 4a80 6704 4c42 0001 2c01 2207 4c42 1406 <2c00> 
>>>> 2e01
>>>> 2004 2204 6704 4c42 0001 2801 2205 4c42 1404 2800 2a01 202e fff8 
>>>> 222e
>>
>> "4c42" is a division. It's the second one of the four divisions:
>>
>>    0: 4a80           tstl %d0
>>
>> d0 is zero, so the first division is skipped.
>>
>>    2: 6704           beqs 0x8
>>    4: 4c42 0001       divull %d2,%d1,%d0
>>    8: 2c01           movel %d1,%d6
>>    a: 2207           movel %d7,%d1
>>    c: 4c42 1406       divul %d2,%d6,%d1
>>
>> It's dividing by d2, which is zero. So scmd->device->sector_size must 
>> be
>> smaller than 512 (probably zero).
>>
>
> Thanks for parsing the dump - now I'll have to find out how on earth 
> sector_size got overwritten in the first place ... and whether 
> anyrhing in scmd-> device still makes any sense at all.
>
> Cheers,
>
> 	Michael
>
> --
> To unsubscribe from this list: send the line "unsubscribe linux-m68k" 
> in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Zero Divide in Kernel 3.12-rc4

[Ingo Jürgensmann]

On 2013-10-22 22:38, Michael Schmitz wrote:

> Ingo - could you add
> if (scmd->device->sector_size > 2048)
> sdev_printk(KERN_ERR, scmd->device, "Whoa - large secor size %d\n",
> scmd->device->sector_size);
> before the do_div calls, and see what that reports?

Ok, so, drivers/scsi/sd.c looks now as this:


         if (scmd->device->sector_size < 512) {
                 /* only legitimate sector_size here is 256 */
                 start_lba <<= 1;
                 end_lba <<= 1;
         } else {
                 /* be careful ... don't want any overflows */
                 u64 factor = scmd->device->sector_size / 512;
                 if (scmd->device->sector_size > 2048)
                      sdev_printk(KERN_ERR, scmd->device, "Whoa - large 
sector size %d\n", scmd->device->sector_size);
                 do_div(start_lba, factor);
                 do_div(end_lba, factor);
         }

... will rebuilt and install it then...

-- 
Ciao...          //    Fon: 0381-2744150
.     Ingo     \X/     http://blog.windfluechter.net

gpg pubkey: http://www.juergensmann.de/ij_public_key.

Re: Zero Divide in Kernel 3.12-rc4

[Michael Schmitz]

Hi Ingo,

> On 2013-10-22 22:38, Michael Schmitz wrote:
>
>> Ingo - could you add
>> if (scmd->device->sector_size > 2048)
>> sdev_printk(KERN_ERR, scmd->device, "Whoa - large secor size %d\n",
>> scmd->device->sector_size);
>> before the do_div calls, and see what that reports?
>
> Ok, so, drivers/scsi/sd.c looks now as this:
>
>
>         if (scmd->device->sector_size < 512) {
>                 /* only legitimate sector_size here is 256 */
>                 start_lba <<= 1;
>                 end_lba <<= 1;
>         } else {
>                 /* be careful ... don't want any overflows */
>                 u64 factor = scmd->device->sector_size / 512;
>                 if (scmd->device->sector_size > 2048)
>                      sdev_printk(KERN_ERR, scmd->device, "Whoa - large  
> sector size %d\n", scmd->device->sector_size);
>                 do_div(start_lba, factor);
>                 do_div(end_lba, factor);
>         }
>
> ... will rebuilt and install it then...

Precisely what I meant, thanks.

Cheers,

	Michael


>
> --  
> Ciao...          //    Fon: 0381-2744150
> .     Ingo     \X/     http://blog.windfluechter.net
>
> gpg pubkey: http://www.juergensmann.de/ij_public_key.
>
>
> --  
> To UNSUBSCRIBE, email to debian-68k-REQUEST@lists.debian.org
> with a subject of "unsubscribe". Trouble? Contact  
> listmaster@lists.debian.org
> Archive:  
> http://lists.debian.org/ 
> 5cbf031e8c962394a34615d18977f609@muaddib.hro.localnet

Re: Zero Divide in Kernel 3.12-rc4

[Michael Schmitz]

Hello Ingo,

any further news on this one?

Cheers,

	Michael


> On 2013-10-22 22:38, Michael Schmitz wrote:
>
>> Ingo - could you add
>> if (scmd->device->sector_size > 2048)
>> sdev_printk(KERN_ERR, scmd->device, "Whoa - large secor size %d\n",
>> scmd->device->sector_size);
>> before the do_div calls, and see what that reports?
>
> Ok, so, drivers/scsi/sd.c looks now as this:
>
>
>         if (scmd->device->sector_size < 512) {
>                 /* only legitimate sector_size here is 256 */
>                 start_lba <<= 1;
>                 end_lba <<= 1;
>         } else {
>                 /* be careful ... don't want any overflows */
>                 u64 factor = scmd->device->sector_size / 512;
>                 if (scmd->device->sector_size > 2048)
>                      sdev_printk(KERN_ERR, scmd->device, "Whoa - large 
> sector size %d\n", scmd->device->sector_size);
>                 do_div(start_lba, factor);
>                 do_div(end_lba, factor);
>         }
>
> ... will rebuilt and install it then...
>
> -- 
> Ciao...          //    Fon: 0381-2744150
> .     Ingo     \X/     http://blog.windfluechter.net
>
> gpg pubkey: http://www.juergensmann.de/ij_public_key.

Re: Zero Divide in Kernel 3.12-rc4

[Ingo Jürgensmann]

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

Am 03.11.2013 um 07:55 schrieb Michael Schmitz <schmitz@biophys.uni-duesseldorf.de>:

> any further news on this one?

Well, not really, I think... but this might be good news. ;)

Yesterday there were two media sense errors on /dev/sda on Spice (A3000/040 with Warpengine, so no ESP), but I guess that's a real media error, especially because sda2 is an AFFS partition I had mounted. 

Nov  2 02:03:29 spice kernel: [629303.810000] sd 1:0:0:0: [sda] Unhandled sense code
Nov  2 02:03:29 spice kernel: [629303.820000] sd 1:0:0:0: [sda]  
Nov  2 02:03:29 spice kernel: [629303.830000] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
Nov  2 02:03:29 spice kernel: [629303.840000] sd 1:0:0:0: [sda]  
Nov  2 02:03:29 spice kernel: [629303.850000] Sense Key : Medium Error [current] 
Nov  2 02:03:29 spice kernel: [629303.880000] Info fld=0x7b1d0
Nov  2 02:03:29 spice kernel: [629303.890000] sd 1:0:0:0: [sda]  
Nov  2 02:03:29 spice kernel: [629303.900000] Add. Sense: Unrecovered read error
Nov  2 02:03:29 spice kernel: [629303.910000] sd 1:0:0:0: [sda] CDB: 
Nov  2 02:03:29 spice kernel: [629303.920000] Read(10): 28 00 00 07 b1 d0 00 00 01 00
Nov  2 02:03:29 spice kernel: [629303.970000] end_request: critical medium error, dev sda, sector 504272
Nov  2 02:03:30 spice kernel: [629303.980000] Buffer I/O error on device sda2, logical block 240944
Nov  2 02:03:30 spice kernel: [629306.740000] sd 1:0:0:0: [sda] Unhandled sense code
Nov  2 02:03:30 spice kernel: [629306.750000] sd 1:0:0:0: [sda]  
Nov  2 02:03:30 spice kernel: [629306.760000] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
Nov  2 02:03:30 spice kernel: [629306.770000] sd 1:0:0:0: [sda]  
Nov  2 02:03:30 spice kernel: [629306.780000] Sense Key : Medium Error [current] 
Nov  2 02:03:30 spice kernel: [629306.800000] Info fld=0x17c220
Nov  2 02:03:30 spice kernel: [629306.810000] sd 1:0:0:0: [sda]  
Nov  2 02:03:30 spice kernel: [629306.820000] Add. Sense: Unrecovered read error
Nov  2 02:03:30 spice kernel: [629306.830000] sd 1:0:0:0: [sda] CDB: 
Nov  2 02:03:30 spice kernel: [629306.840000] Read(10): 28 00 00 17 c2 20 00 00 01 00
Nov  2 02:03:30 spice kernel: [629306.890000] end_request: critical medium error, dev sda, sector 1557024
Nov  2 02:03:30 spice kernel: [629306.900000] Buffer I/O error on device sda2, logical block 1293696
Nov  2 02:03:30 spice kernel: [629309.590000] sd 1:0:0:0: [sda] Unhandled sense code
Nov  2 02:03:31 spice kernel: [629309.600000] sd 1:0:0:0: [sda]  
Nov  2 02:03:31 spice kernel: [629309.610000] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
Nov  2 02:03:31 spice kernel: [629309.620000] sd 1:0:0:0: [sda]  
Nov  2 02:03:31 spice kernel: [629309.630000] Sense Key : Medium Error [current] 
Nov  2 02:03:31 spice kernel: [629309.650000] Info fld=0x7b1d0
Nov  2 02:03:31 spice kernel: [629309.660000] sd 1:0:0:0: [sda]  
Nov  2 02:03:31 spice kernel: [629309.670000] Add. Sense: Unrecovered read error
Nov  2 02:03:31 spice kernel: [629309.680000] sd 1:0:0:0: [sda] CDB: 
Nov  2 02:03:31 spice kernel: [629309.690000] Read(10): 28 00 00 07 b1 d0 00 00 01 00
Nov  2 02:03:31 spice kernel: [629309.740000] end_request: critical medium error, dev sda, sector 504272
Nov  2 02:03:31 spice kernel: [629309.760000] Buffer I/O error on device sda2, logical block 240944
Nov  2 02:03:31 spice kernel: [629312.540000] sd 1:0:0:0: [sda] Unhandled sense code
Nov  2 02:03:31 spice kernel: [629312.550000] sd 1:0:0:0: [sda]  
Nov  2 02:03:31 spice kernel: [629312.560000] Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
Nov  2 02:03:31 spice kernel: [629312.570000] sd 1:0:0:0: [sda]  
Nov  2 02:03:31 spice kernel: [629312.580000] Sense Key : Medium Error [current] 
Nov  2 02:03:31 spice kernel: [629312.610000] Info fld=0x17c220
Nov  2 02:03:31 spice kernel: [629312.620000] sd 1:0:0:0: [sda]  
Nov  2 02:03:31 spice kernel: [629312.630000] Add. Sense: Unrecovered read error
Nov  2 02:03:31 spice kernel: [629312.640000] sd 1:0:0:0: [sda] CDB: 
Nov  2 02:03:32 spice kernel: [629312.650000] Read(10): 28 00 00 17 c2 20 00 00 01 00
Nov  2 02:03:32 spice kernel: [629312.700000] end_request: critical medium error, dev sda, sector 1557024
Nov  2 02:03:32 spice kernel: [629312.720000] Buffer I/O error on device sda2, logical block 1293696

Otherwise it looks good. No appearance of "Whoa" so far: 

spice:/home/ij# zgrep -i whoa /var/log/syslog* /var/log/messages* 
spice:/home/ij#

akire:~# zgrep -i whoa /var/log/syslog* /var/log/messages*
akire:~# 

I would like to stress akire a little more with a running buildd, but Aurelien didn't add Spice & Akire yet to w-b the last two weeks...

-- 
Ciao...            //      Fon: 0381-2744150
      Ingo       \X/       http://blog.windfluechter.net


gpg pubkey:  http://www.juergensmann.de/ij_public_key.asc


[-- Attachment #2: Message signed with OpenPGP using GPGMail --]
[-- Type: application/pgp-signature, Size: 801 bytes --]

Re: Zero Divide in Kernel 3.12-rc4

[Michael Schmitz]

Ingo,

>
>> any further news on this one?
>
> Well, not really, I think... but this might be good news. ;)

Indeed - at the very least it shows it is a rare error.

>
> Yesterday there were two media sense errors on /dev/sda on Spice 
> (A3000/040 with Warpengine, so no ESP), but I guess that's a real 
> media error, especially because sda2 is an AFFS partition I had 
> mounted.

That does look like a bad disk block, yes. Might be time for a backup.

Cheers,

	Michael


>
> Nov  2 02:03:29 spice kernel: [629303.810000] sd 1:0:0:0: [sda] 
> Unhandled sense code
> Nov  2 02:03:29 spice kernel: [629303.820000] sd 1:0:0:0: [sda]
> Nov  2 02:03:29 spice kernel: [629303.830000] Result: hostbyte=DID_OK 
> driverbyte=DRIVER_SENSE
> Nov  2 02:03:29 spice kernel: [629303.840000] sd 1:0:0:0: [sda]
> Nov  2 02:03:29 spice kernel: [629303.850000] Sense Key : Medium Error 
> [current]
> Nov  2 02:03:29 spice kernel: [629303.880000] Info fld=0x7b1d0
> Nov  2 02:03:29 spice kernel: [629303.890000] sd 1:0:0:0: [sda]
> Nov  2 02:03:29 spice kernel: [629303.900000] Add. Sense: Unrecovered 
> read error
> Nov  2 02:03:29 spice kernel: [629303.910000] sd 1:0:0:0: [sda] CDB:
> Nov  2 02:03:29 spice kernel: [629303.920000] Read(10): 28 00 00 07 b1 
> d0 00 00 01 00
> Nov  2 02:03:29 spice kernel: [629303.970000] end_request: critical 
> medium error, dev sda, sector 504272
> Nov  2 02:03:30 spice kernel: [629303.980000] Buffer I/O error on 
> device sda2, logical block 240944
> Nov  2 02:03:30 spice kernel: [629306.740000] sd 1:0:0:0: [sda] 
> Unhandled sense code
> Nov  2 02:03:30 spice kernel: [629306.750000] sd 1:0:0:0: [sda]
> Nov  2 02:03:30 spice kernel: [629306.760000] Result: hostbyte=DID_OK 
> driverbyte=DRIVER_SENSE
> Nov  2 02:03:30 spice kernel: [629306.770000] sd 1:0:0:0: [sda]
> Nov  2 02:03:30 spice kernel: [629306.780000] Sense Key : Medium Error 
> [current]
> Nov  2 02:03:30 spice kernel: [629306.800000] Info fld=0x17c220
> Nov  2 02:03:30 spice kernel: [629306.810000] sd 1:0:0:0: [sda]
> Nov  2 02:03:30 spice kernel: [629306.820000] Add. Sense: Unrecovered 
> read error
> Nov  2 02:03:30 spice kernel: [629306.830000] sd 1:0:0:0: [sda] CDB:
> Nov  2 02:03:30 spice kernel: [629306.840000] Read(10): 28 00 00 17 c2 
> 20 00 00 01 00
> Nov  2 02:03:30 spice kernel: [629306.890000] end_request: critical 
> medium error, dev sda, sector 1557024
> Nov  2 02:03:30 spice kernel: [629306.900000] Buffer I/O error on 
> device sda2, logical block 1293696
> Nov  2 02:03:30 spice kernel: [629309.590000] sd 1:0:0:0: [sda] 
> Unhandled sense code
> Nov  2 02:03:31 spice kernel: [629309.600000] sd 1:0:0:0: [sda]
> Nov  2 02:03:31 spice kernel: [629309.610000] Result: hostbyte=DID_OK 
> driverbyte=DRIVER_SENSE
> Nov  2 02:03:31 spice kernel: [629309.620000] sd 1:0:0:0: [sda]
> Nov  2 02:03:31 spice kernel: [629309.630000] Sense Key : Medium Error 
> [current]
> Nov  2 02:03:31 spice kernel: [629309.650000] Info fld=0x7b1d0
> Nov  2 02:03:31 spice kernel: [629309.660000] sd 1:0:0:0: [sda]
> Nov  2 02:03:31 spice kernel: [629309.670000] Add. Sense: Unrecovered 
> read error
> Nov  2 02:03:31 spice kernel: [629309.680000] sd 1:0:0:0: [sda] CDB:
> Nov  2 02:03:31 spice kernel: [629309.690000] Read(10): 28 00 00 07 b1 
> d0 00 00 01 00
> Nov  2 02:03:31 spice kernel: [629309.740000] end_request: critical 
> medium error, dev sda, sector 504272
> Nov  2 02:03:31 spice kernel: [629309.760000] Buffer I/O error on 
> device sda2, logical block 240944
> Nov  2 02:03:31 spice kernel: [629312.540000] sd 1:0:0:0: [sda] 
> Unhandled sense code
> Nov  2 02:03:31 spice kernel: [629312.550000] sd 1:0:0:0: [sda]
> Nov  2 02:03:31 spice kernel: [629312.560000] Result: hostbyte=DID_OK 
> driverbyte=DRIVER_SENSE
> Nov  2 02:03:31 spice kernel: [629312.570000] sd 1:0:0:0: [sda]
> Nov  2 02:03:31 spice kernel: [629312.580000] Sense Key : Medium Error 
> [current]
> Nov  2 02:03:31 spice kernel: [629312.610000] Info fld=0x17c220
> Nov  2 02:03:31 spice kernel: [629312.620000] sd 1:0:0:0: [sda]
> Nov  2 02:03:31 spice kernel: [629312.630000] Add. Sense: Unrecovered 
> read error
> Nov  2 02:03:31 spice kernel: [629312.640000] sd 1:0:0:0: [sda] CDB:
> Nov  2 02:03:32 spice kernel: [629312.650000] Read(10): 28 00 00 17 c2 
> 20 00 00 01 00
> Nov  2 02:03:32 spice kernel: [629312.700000] end_request: critical 
> medium error, dev sda, sector 1557024
> Nov  2 02:03:32 spice kernel: [629312.720000] Buffer I/O error on 
> device sda2, logical block 1293696
>
> Otherwise it looks good. No appearance of "Whoa" so far:
>
> spice:/home/ij# zgrep -i whoa /var/log/syslog* /var/log/messages*
> spice:/home/ij#
>
> akire:~# zgrep -i whoa /var/log/syslog* /var/log/messages*
> akire:~#
>
> I would like to stress akire a little more with a running buildd, but 
> Aurelien didn't add Spice & Akire yet to w-b the last two weeks...
>
> -- 
> Ciao...            //      Fon: 0381-2744150
>       Ingo       \X/       http://blog.windfluechter.net
>
>
> gpg pubkey:  http://www.juergensmann.de/ij_public_key.asc
>

Re: Zero Divide in Kernel 3.12-rc4

[Geert Uytterhoeven]

On Tue, Oct 22, 2013 at 10:38 PM, Michael Schmitz
<schmitz@biophys.uni-duesseldorf.de> wrote:
>>>> To pinpoint where in sd_completed_bytes this happens, I'd need the
>>>> sd_mod
>>>> module and the module symbol map.
>>>
>>>
>>>                 /* be careful ... don't want any overflows */
>>>                 u64 factor = scmd->device->sector_size / 512;
>>>                 do_div(start_lba, factor);
>>>                 do_div(end_lba, factor);
>>>
>>> scmd->device->sector_size should be 512, so factor should be 1.
>
>
> Looking at a bit of context right above what you quote here, we can be
> reasonably certain that scmd->device->sector_size is greater or equal 512.

Stupid me, I missed that check ;-)

Perhaps the "u64" is still an issue there, despite Andreas' fix for do_div()?

> Ingo - could you add
>
> if (scmd->device->sector_size > 2048)
>         sdev_printk(KERN_ERR, scmd->device, "Whoa - large secor size %d\n",
> scmd->device->sector_size);
>
> before the do_div calls, and see what that reports?

Anyway, if it triggers again, I'd like to see the real kernel binary
that matches
the crash log.

Gr{oetje,eeting}s,

                        Geert

--
Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org

In personal conversations with technical people, I call myself a hacker. But
when I'm talking to journalists I just say "programmer" or something like that.
                                -- Linus Torvalds