2006-09-07 23:56:43

by Stefan Richter

[permalink] [raw]
Subject: [PATCH 0/2] ieee1394: ohci1394: endianess bug in verbose debug log

This fixes a debug macro on some big endian machines. Related code is
touched up too to make it harder to introduce such bugs in the future.

- ieee1394: ohci1394: fix endianess bug in debug message
- ieee1394: ohci1394: more obvious endianess handling

Wolfgang, could you test and send an ACK? The tlabel in each "Packet
received from node" message should match that of the previous "Packet
sent to node" line. Example of a wrong log:
http://www.wolfgangpfeiffer.com/disable-irm.kern.log.when.fw.disk.is.switched.on.txt
The received tlabel was always 48 on this Apple AluBook 5,8.
--
Stefan Richter
-=====-=-==- =--= -=---
http://arcgraph.de/sr/


2006-09-07 23:58:16

by Stefan Richter

[permalink] [raw]
Subject: [PATCH 1/2] ieee1394: ohci1394: fix endianess bug in debug message

The transaction labels were misprinted int the debug printk "Packet
received from node..." due two byte-swapping once too often. Affected
were big endian machines, except UniNorth based ones.

Signed-off-by: Stefan Richter <[email protected]>
---
Index: linux/drivers/ieee1394/ohci1394.c
===================================================================
--- linux.orig/drivers/ieee1394/ohci1394.c 2006-09-06 23:50:53.000000000 +0200
+++ linux/drivers/ieee1394/ohci1394.c 2006-09-07 15:48:15.000000000 +0200
@@ -2743,7 +2743,7 @@ static void dma_rcv_tasklet (unsigned lo
(cond_le32_to_cpu(d->spb[length/4-1], ohci->no_swap_incoming)>>16)&0x1f,
(cond_le32_to_cpu(d->spb[length/4-1], ohci->no_swap_incoming)>>21)&0x3,
tcode, length, d->ctx,
- (cond_le32_to_cpu(d->spb[0], ohci->no_swap_incoming)>>10)&0x3f);
+ (d->spb[0]>>10)&0x3f);

ack = (((cond_le32_to_cpu(d->spb[length/4-1], ohci->no_swap_incoming)>>16)&0x1f)
== 0x11) ? 1 : 0;


2006-09-08 00:00:12

by Stefan Richter

[permalink] [raw]
Subject: [PATCH 2/2] ieee1394: ohci1394: more obvious endianess handling

Rename ohci1394's packet_swab to header_le32_to_cpu to better reflect
what it actually does. Also, define a constant array as 'const' and
check the array index properly.

Signed-off-by: Stefan Richter <[email protected]>
---
Index: linux/drivers/ieee1394/ohci1394.c
===================================================================
--- linux.orig/drivers/ieee1394/ohci1394.c 2006-09-07 15:48:15.000000000 +0200
+++ linux/drivers/ieee1394/ohci1394.c 2006-09-07 20:33:29.000000000 +0200
@@ -181,36 +181,35 @@ static int alloc_dma_trm_ctx(struct ti_o
static void ohci1394_pci_remove(struct pci_dev *pdev);

#ifndef __LITTLE_ENDIAN
-static unsigned hdr_sizes[] =
-{
+const static size_t hdr_sizes[] = {
3, /* TCODE_WRITEQ */
4, /* TCODE_WRITEB */
3, /* TCODE_WRITE_RESPONSE */
- 0, /* ??? */
+ 0, /* reserved */
3, /* TCODE_READQ */
4, /* TCODE_READB */
3, /* TCODE_READQ_RESPONSE */
4, /* TCODE_READB_RESPONSE */
- 1, /* TCODE_CYCLE_START (???) */
+ 1, /* TCODE_CYCLE_START */
4, /* TCODE_LOCK_REQUEST */
2, /* TCODE_ISO_DATA */
4, /* TCODE_LOCK_RESPONSE */
+ /* rest is reserved or link-internal */
};

-/* Swap headers */
-static inline void packet_swab(quadlet_t *data, int tcode)
+static inline void header_le32_to_cpu(quadlet_t *data, unsigned char tcode)
{
- size_t size = hdr_sizes[tcode];
+ size_t size;

- if (tcode > TCODE_LOCK_RESPONSE || hdr_sizes[tcode] == 0)
+ if (unlikely(tcode >= ARRAY_SIZE(hdr_sizes)))
return;

+ size = hdr_sizes[tcode];
while (size--)
- data[size] = swab32(data[size]);
+ data[size] = le32_to_cpu(data[size]);
}
#else
-/* Don't waste cycles on same sex byte swaps */
-#define packet_swab(w,x) do {} while (0)
+#define header_le32_to_cpu(w,x) do {} while (0)
#endif /* !LITTLE_ENDIAN */

/***********************************
@@ -705,7 +704,7 @@ static void insert_packet(struct ti_ohci
d->prg_cpu[idx]->data[2] = packet->header[2];
d->prg_cpu[idx]->data[3] = packet->header[3];
}
- packet_swab(d->prg_cpu[idx]->data, packet->tcode);
+ header_le32_to_cpu(d->prg_cpu[idx]->data, packet->tcode);
}

if (packet->data_size) { /* block transmit */
@@ -781,7 +780,7 @@ static void insert_packet(struct ti_ohci
d->prg_cpu[idx]->data[0] = packet->speed_code<<16 |
(packet->header[0] & 0xFFFF);
d->prg_cpu[idx]->data[1] = packet->header[0] & 0xFFFF0000;
- packet_swab(d->prg_cpu[idx]->data, packet->tcode);
+ header_le32_to_cpu(d->prg_cpu[idx]->data, packet->tcode);

d->prg_cpu[idx]->begin.control =
cpu_to_le32(DMA_CTL_OUTPUT_MORE |
@@ -2735,7 +2734,7 @@ static void dma_rcv_tasklet (unsigned lo
* bus reset. We always ignore it. */
if (tcode != OHCI1394_TCODE_PHY) {
if (!ohci->no_swap_incoming)
- packet_swab(d->spb, tcode);
+ header_le32_to_cpu(d->spb, tcode);
DBGMSG("Packet received from node"
" %d ack=0x%02X spd=%d tcode=0x%X"
" length=%d ctx=%d tlabel=%d",


2006-09-10 13:00:27

by Wolfgang Pfeiffer

[permalink] [raw]
Subject: Re: [PATCH 0/2] ieee1394: ohci1394: endianess bug in verbose debug log

Hi Stefan, Hi All

Success, on the PowerBook5,8, Stefan. ... :) At least it looks so to me ...

And this:
Sorry for the delay: I had to leave the house yesterday for work --
with no access to computers in that time. And yes, I had a few fights
with 'make' that also took some time ... :)


On Fri, Sep 08, 2006 at 01:55:24AM +0200, Stefan Richter wrote:
> This fixes a debug macro on some big endian machines. Related code is
> touched up too to make it harder to introduce such bugs in the future.
>
> - ieee1394: ohci1394: fix endianess bug in debug message
> - ieee1394: ohci1394: more obvious endianess handling
>
> Wolfgang, could you test and send an ACK? The tlabel in each "Packet
> received from node" message should match that of the previous "Packet
> sent to node" line. Example of a wrong log:
> http://www.wolfgangpfeiffer.com/disable-irm.kern.log.when.fw.disk.is.switched.on.txt

Seems with your patched ohci1394.ko tlabels from sent/received don't
differ anymore. Here's a fresh log with the patched and recompiled
ohci1394:
http://wolfgangpfeiffer.com/kern.log.06-09-10.when.fw.disk.is.switched.on.txt

I repeated the test a few times. And I always saw the same results as
to the identical tlabels. So log above is just one of a few I did the
last minutes.

Ugly notes, for later reference:
-----------------------------
$ cat /proc/cpuinfo
processor : 0
cpu : 7447A, altivec supported
clock : 833.333000MHz
revision : 0.5 (pvr 8003 0105)
bogomips : 16.57
timebase : 8320000
platform : PowerMac
machine : PowerBook5,8
motherboard : PowerBook5,8 MacRISC3 Power Macintosh
detected as : 287 (PowerBook G4 15")
pmac flags : 00000019
L2 cache : 512K unified
pmac-generation : NewWorld
-----------------------


The script I used (IIRC with the syntax shamelessly lifted from various
files in my local /etc/ :)

------------------------------------
#!/bin/sh -x
/bin/sh -nv /home/shorty/scripts/ieee.test.060910.sh; \
/home/shorty/scripts/scsi.stop.sh; \
/home/shorty/scripts/scsi.start.sh; \

sleep 2; \
/home/shorty/kernel-factory/git.make.test/git.060822/linux-2.6/scripts/ver_linux; \

cat /dev/null > /var/log/kern.log; \
echo "===> NOW SWITCH ON THE FW DISK <===="; \
sleep 70; \
ls /dev/sda*; \

if [ -f /home/shorty/kern.log.06-09-10.when.fw.disk.is.switched.on.txt ]; then
rm -f /home/shorty/kern.log.06-09-10.when.fw.disk.is.switched.on.txt
cp /var/log/kern.log /home/shorty/kern.log.06-09-10.when.fw.disk.is.switched.on.txt
chown shorty.shorty /home/shorty/kern.log.06-09-10.when.fw.disk.is.switched.on.txt
else
cp /var/log/kern.log /home/shorty/kern.log.06-09-10.when.fw.disk.is.switched.on.txt
chown shorty.shorty /home/shorty/kern.log.06-09-10.when.fw.disk.is.switched.on.txt
fi


--------------------------------------




And this should be the latest output from the script above, slightly
reformatted (line wrappings, etc.) for better readability:

--------------------------------------------------------
# /home/shorty/scripts/ieee.test.060910.sh
+ /bin/sh -nv /home/shorty/scripts/ieee.test.060910.sh
#!/bin/sh -x
/bin/sh -nv /home/shorty/scripts/ieee.test.060910.sh; \
/home/shorty/scripts/scsi.stop.sh; \
/home/shorty/scripts/scsi.start.sh; \

sleep 2; \
/home/shorty/kernel-factory/git.make.test/git.060822/linux-2.6/scripts/ver_linux; \

cat /dev/null > /var/log/kern.log; \
echo "===> NOW SWITCH ON THE FW DISK <===="; \
sleep 70; \
ls /dev/sda*; \

if [ -f /home/shorty/kern.log.06-09-10.when.fw.disk.is.switched.on.txt ]; then
rm -f /home/shorty/kern.log.06-09-10.when.fw.disk.is.switched.on.txt
cp /var/log/kern.log /home/shorty/kern.log.06-09-10.when.fw.disk.is.switched.on.txt
chown shorty.shorty /home/shorty/kern.log.06-09-10.when.fw.disk.is.switched.on.txt
else
cp /var/log/kern.log /home/shorty/kern.log.06-09-10.when.fw.disk.is.switched.on.txt
chown shorty.shorty /home/shorty/kern.log.06-09-10.when.fw.disk.is.switched.on.txt
fi

+ /home/shorty/scripts/scsi.stop.sh
+ /bin/sh -n /home/shorty/scripts/scsi.stop.sh
+ rmmod raw1394
+ rmmod eth1394
+ rmmod ohci1394
+ rmmod sbp2
+ rmmod ieee1394
+ /home/shorty/scripts/scsi.start.sh
+ /bin/sh -n /home/shorty/scripts/scsi.start.sh
+ modprobe ieee1394 disable_irm=0
+ sleep 2
+ modprobe ohci1394
+ sleep 2
+ modprobe sbp2
+ sleep 2
+ modprobe raw1394
+ sleep 2
+ chown root.shorty /dev/raw1394
+ sleep 2
+ /home/shorty/kernel-factory/git.make.test/git.060822/linux-2.6/scripts/ver_linux
If some fields are empty or look unusual you may have an old version.
Compare to the current minimal requirements in Documentation/Changes.

Linux debby1-6 2.6.18-rc4-ieeeverbose-gef7d1b24-dirty #1 Tue Aug 22
22:18:50 CEST 2006 ppc GNU/Linux



Gnu C 4.1.2
Gnu make 3.81
binutils 2.17
util-linux 2.12r
mount 2.12r
module-init-tools 3.2.2
e2fsprogs 1.39
pcmcia-cs 3.2.8
PPP 2.4.4
Linux C Library 2.3.6
Dynamic linker (ldd) 2.3.6
Procps 3.2.7
Net-tools 1.60
Console-tools 0.2.3
Sh-utils 5.97
udev 100


Modules Loaded raw1394 sbp2 eth1394 ohci1394 ieee1394 bluetooth radeon
drm ipv6 xt_multiport iptable_nat ip_nat xt_state ip_conntrack
xt_tcpudp iptable_filter ip_tables x_tables therm_adt746x sr_m od
cpufreq_powersave cpufreq_performance scsi_mod apm_emu joydev
appletouch snd_aoa_codec_onyx snd_aoa_fabric_layout snd_aoa usbhid
pcmcia firmware_class snd_aoa_i2sbus snd_pcm_oss snd_pcm
snd_page_alloc snd_mixer_oss snd_seq_dummy snd_seq_oss snd_seq_midi
snd_rawmidi snd_seq_midi_event ide_cd cdrom snd_seq snd_timer
snd_seq_device yenta_socket rsrc_nonstatic pcmcia_core snd ohci_hcd
sungem sungem_phy evd ev ehci_hcd soundcore snd_aoa_soundbus
i2c_powermac uninorth_agp agpgart pmac_zilog serial_core usbcore


+ cat /dev/null
+ echo '===> NOW SWITCH ON THE FW DISK <===='
===> NOW SWITCH ON THE FW DISK <====
+ sleep 70
+ ls '/dev/sda*'
ls: /dev/sda*: No such file or directory
+ '[' -f /home/shorty/kern.log.06-09-10.when.fw.disk.is.switched.on.txt ']'
+ rm -f /home/shorty/kern.log.06-09-10.when.fw.disk.is.switched.on.txt
+ cp /var/log/kern.log /home/shorty/kern.log.06-09-10.when.fw.disk.is.switched.on.txt
+ chown shorty.shorty /home/shorty/kern.log.06-09-10.when.fw.disk.is.switched.on.txt
------------------------------------------------



> The received tlabel was always 48 on this Apple AluBook 5,8.

Thanks Stefan for your work. Please let me know if I can help any more
with tests.

Best Regards
Wolfgang

--
Wolfgang Pfeiffer: /ICQ: 286585973/ + + + /AIM: crashinglinux/
http://profiles.yahoo.com/wolfgangpfeiffer

Key ID: E3037113
http://keyserver.mine.nu/pks/lookup?search=0xE3037113&fingerprint=on