Discussion:
Message "in_cksum_skip: out of data by ...."
(too old to reply)
David Wolfskill
2012-10-07 15:12:21 UTC
Permalink
I started seeing these messages spewed (to both console &
/var/log/messages) following an update from:

FreeBSD g1-227.catwhisker.org 10.0-CURRENT FreeBSD 10.0-CURRENT #697 241222M: Fri Oct 5 05:32:19 PDT 2012 ***@g1-227.catwhisker.org:/usr/obj/usr/src/sys/CANARY i386

to

FreeBSD g1-227.catwhisker.org 10.0-CURRENT FreeBSD 10.0-CURRENT #698 241245M: Sat Oct 6 08:01:23 PDT 2012 ***@g1-227.catwhisker.org:/usr/obj/usr/src/sys/CANARY i386

and I'm still seeing them as of

FreeBSD g1-227.catwhisker.org 10.0-CURRENT FreeBSD 10.0-CURRENT #699 241309M: Sun Oct 7 07:35:41 PDT 2012 ***@g1-227.catwhisker.org:/usr/obj/usr/src/sys/CANARY i386

E.g.:
Oct 6 08:24:10 g1-227 kernel: wlan0: Ethernet address: 00:21:6a:26:34:c0
Oct 6 08:24:10 g1-227 kernel: Expensive timeout(9) function: 0xc0c27520(0) 0.010540166 s
Oct 6 08:24:10 g1-227 kernel: in_cksum_skip: out of data by 10200
Oct 6 08:24:10 g1-227 kernel: in_cksum_skip: out of data by 10200
Oct 6 08:24:10 g1-227 kernel: in_cksum_skip: out of data by 18105
Oct 6 08:24:10 g1-227 kernel: in_cksum_skip: out of data by 18105
Oct 6 08:24:10 g1-227 kernel: in_cksum_skip: out of data by 17340
Oct 6 08:24:10 g1-227 last message repeated 3 times
Oct 6 08:24:10 g1-227 kernel: in_cksum_skip: out of data by 19380
Oct 6 08:24:10 g1-227 kernel: in_cksum_skip: out of data by 10200
Oct 6 08:24:10 g1-227 kernel: in_cksum_skip: out of data by 19380
Oct 6 08:24:10 g1-227 last message repeated 4 times
..

or (more recently):
Oct 7 07:58:53 g1-227 kernel: wlan0: Ethernet address: 00:21:6a:26:34:c0
Oct 7 07:58:53 g1-227 kernel: Expensive timeout(9) function: 0xc0c27550(0) 0.011038204 s
Oct 7 07:58:53 g1-227 kernel: in_cksum_skip: out of data by 18105
Oct 7 07:58:53 g1-227 kernel: in_cksum_skip: out of data by 18105
Oct 7 07:58:53 g1-227 kernel: in_cksum_skip: out of data by 17340
Oct 7 07:58:53 g1-227 last message repeated 3 times
Oct 7 07:58:53 g1-227 kernel: in_cksum_skip: out of data by 10200
Oct 7 07:58:53 g1-227 kernel: in_cksum_skip: out of data by 19380
Oct 7 07:58:54 g1-227 last message repeated 4 times
..

As far as I have been able to tell so far, the machine (my laptop) is
not exhibiting any (aother) indications of problems.

I confess that I am not entirely clear on what information the
message is apparently trying to convey (let alone what I can or
should do about it -- if anything).

Peace,
david
--
David H. Wolfskill ***@catwhisker.org
Depriving a girl or boy of an opportunity for education is evil.

See http://www.catwhisker.org/~david/publickey.gpg for my public key.
Michael Butler
2012-10-07 16:18:20 UTC
Permalink
Post by David Wolfskill
I started seeing these messages spewed (to both console &
to
and I'm still seeing them as of
Oct 6 08:24:10 g1-227 kernel: wlan0: Ethernet address: 00:21:6a:26:34:c0
Oct 6 08:24:10 g1-227 kernel: Expensive timeout(9) function: 0xc0c27520(0) 0.010540166 s
Oct 6 08:24:10 g1-227 kernel: in_cksum_skip: out of data by 10200
+1 on a laptop running with:

re0: <RealTek 8168/8111 B/C/CP/D/DP/E/F PCIe Gigabit Ethernet> port
0x2000-0x20ff mem 0xf0700000-0xf0700fff,0xf0200000-0xf0203fff irq 17 at
device 0.0 on pci3
re0: Using 1 MSI-X message
re0: ASPM disabled
re0: Chip rev. 0x28000000
re0: MAC rev. 0x00000000
miibus0: <MII bus> on re0
rgephy0: <RTL8169S/8110S/8211 1000BASE-T media interface> PHY 1 on miibus0
rgephy0: none, 10baseT, 10baseT-FDX, 10baseT-FDX-flow, 100baseTX,
100baseTX-FDX, 100baseTX-FDX-flow, 1000baseT, 1000baseT-master,
1000baseT-FDX, 1000baseT-FDX-master, 1000baseT-FDX-flow,
1000baseT-FDX-flow-master, auto, auto-flow
re0: Ethernet address: 00:0a:cd:1d:30:a2

I thought it may have had something to do with a VirtualBox module, so I
recompiled that too .. no joy :-(

imb
Garrett Cooper
2012-10-07 17:04:15 UTC
Permalink
On Sun, Oct 7, 2012 at 9:16 AM, Michael Butler
-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1
Post by David Wolfskill
I started seeing these messages spewed (to both console &
to
and I'm still seeing them as of
Oct 6 08:24:10 g1-227 kernel: wlan0: Ethernet address: 00:21:6a:26:34:c0
Oct 6 08:24:10 g1-227 kernel: Expensive timeout(9) function: 0xc0c27520(0) 0.010540166 s
Oct 6 08:24:10 g1-227 kernel: in_cksum_skip: out of data by 10200
re0: <RealTek 8168/8111 B/C/CP/D/DP/E/F PCIe Gigabit Ethernet> port
0x2000-0x20ff mem 0xf0700000-0xf0700fff,0xf0200000-0xf0203fff irq 17 at
device 0.0 on pci3
re0: Using 1 MSI-X message
re0: ASPM disabled
re0: Chip rev. 0x28000000
re0: MAC rev. 0x00000000
miibus0: <MII bus> on re0
rgephy0: <RTL8169S/8110S/8211 1000BASE-T media interface> PHY 1 on miibus0
rgephy0: none, 10baseT, 10baseT-FDX, 10baseT-FDX-flow, 100baseTX,
100baseTX-FDX, 100baseTX-FDX-flow, 1000baseT, 1000baseT-master,
1000baseT-FDX, 1000baseT-FDX-master, 1000baseT-FDX-flow,
1000baseT-FDX-flow-master, auto, auto-flow
re0: Ethernet address: 00:0a:cd:1d:30:a2
I thought it may have had something to do with a VirtualBox module, so I
recompiled that too .. no joy :-(
Maybe these revisions had something to do with it... (r241245 is
more likely)?

------------------------------------------------------------------------
r241245 | glebius | 2012-10-06 03:02:11 -0700 (Sat, 06 Oct 2012) | 19 lines

A step in resolving mess with byte ordering for AF_INET. After this change:

- All packets in NETISR_IP queue are in net byte order.
- ip_input() is entered in net byte order and converts packet
to host byte order right _after_ processing pfil(9) hooks.
- ip_output() is entered in host byte order and converts packet
to net byte order right _before_ processing pfil(9) hooks.
- ip_fragment() accepts and emits packet in net byte order.
- ip_forward(), ip_mloopback() use host byte order (untouched actually).
- ip_fastforward() no longer modifies packet at all (except ip_ttl).
- Swapping of byte order there and back removed from the following modules:
pf(4), ipfw(4), enc(4), if_bridge(4).
- Swapping of byte order added to ipfilter(4), based on __FreeBSD_version
- __FreeBSD_version bumped.
- pfil(9) manual page updated.

Reviewed by: ray, luigi, eri, melifaro
Tested by: glebius (LE), ray (BE)

------------------------------------------------------------------------
r241244 | glebius | 2012-10-06 00:06:57 -0700 (Sat, 06 Oct 2012) | 5 lines

The pfil(9) layer guarantees us presence of the protocol header,
so remove extra check, that is always false.

P.S. Also, goto there lead to unlocking a not locked rwlock.

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

Did you rebuild all of your modules, and (for David) are you
running any firmware blobs with your wireless NIC?
Cheers,
-Garrett
David Wolfskill
2012-10-07 17:45:13 UTC
Permalink
Post by Garrett Cooper
...
Maybe these revisions had something to do with it... (r241245 is
more likely)?
------------------------------------------------------------------------
r241245 | glebius | 2012-10-06 03:02:11 -0700 (Sat, 06 Oct 2012) | 19 lines
...
------------------------------------------------------------------------
r241244 | glebius | 2012-10-06 00:06:57 -0700 (Sat, 06 Oct 2012) | 5 lines
The pfil(9) layer guarantees us presence of the protocol header,
so remove extra check, that is always false.
...
Did you rebuild all of your modules, and (for David) are you
running any firmware blobs with your wireless NIC?
Yes; when I update, my changes from the process in src/UPDATING
generally augment what's there (e.g., to clear /usr/include &
/usr/share/man before the make installworld).

And the NIC that's in use (at home -- and most other places) on the
laptop is iwn(4), so yes, there is a firmware blob:

4 1 0xc138a000 54e38 iwn5000fw.ko

(Well, that particular line is from kldstat when it's running stable/9;
I just checked the head slice, and the blob had been rebuilt (based on
mtime), and has contents different from the contents in stable/9:

g1-227(9.1-P)[3] md5 /{,S4/}boot/kernel/iwn5000fw.ko
MD5 (/boot/kernel/iwn5000fw.ko) = 8f98e8f28c70fe801c73aec4f717973f
MD5 (/S4/boot/kernel/iwn5000fw.ko) = a0150e03bfd307595ab37b0924252844
g1-227(9.1-P)[4] ls -lT !$
ls -lT /{,S4/}boot/kernel/iwn5000fw.ko
-r-xr-xr-x 1 root wheel 345868 Oct 7 07:48:46 2012 /S4/boot/kernel/iwn5000fw.ko
-r-xr-xr-x 1 root wheel 344416 Oct 7 04:51:11 2012 /boot/kernel/iwn5000fw.ko
g1-227(9.1-P)[5]

FWIW.)

As noted, the message does not appear to be associated with (other)
unwanted behavior, so I wouldn't consider this of earth-shattering
importance. It just seemed rather odd, and I got to wondering if
the developer who committed the change had intended this result.
And if said result was actually of use to anyone. :-}

Peace,
david
--
David H. Wolfskill ***@catwhisker.org
Depriving a girl or boy of an opportunity for education is evil.

See http://www.catwhisker.org/~david/publickey.gpg for my public key.
Garrett Cooper
2012-10-07 17:54:37 UTC
Permalink
Post by David Wolfskill
Post by Garrett Cooper
...
Maybe these revisions had something to do with it... (r241245 is
more likely)?
------------------------------------------------------------------------
r241245 | glebius | 2012-10-06 03:02:11 -0700 (Sat, 06 Oct 2012) | 19 lines
...
------------------------------------------------------------------------
r241244 | glebius | 2012-10-06 00:06:57 -0700 (Sat, 06 Oct 2012) | 5 lines
The pfil(9) layer guarantees us presence of the protocol header,
so remove extra check, that is always false.
...
Did you rebuild all of your modules, and (for David) are you
running any firmware blobs with your wireless NIC?
Yes; when I update, my changes from the process in src/UPDATING
generally augment what's there (e.g., to clear /usr/include &
/usr/share/man before the make installworld).
And the NIC that's in use (at home -- and most other places) on the
4 1 0xc138a000 54e38 iwn5000fw.ko
(Well, that particular line is from kldstat when it's running stable/9;
I just checked the head slice, and the blob had been rebuilt (based on
g1-227(9.1-P)[3] md5 /{,S4/}boot/kernel/iwn5000fw.ko
MD5 (/boot/kernel/iwn5000fw.ko) = 8f98e8f28c70fe801c73aec4f717973f
MD5 (/S4/boot/kernel/iwn5000fw.ko) = a0150e03bfd307595ab37b0924252844
g1-227(9.1-P)[4] ls -lT !$
ls -lT /{,S4/}boot/kernel/iwn5000fw.ko
-r-xr-xr-x 1 root wheel 345868 Oct 7 07:48:46 2012 /S4/boot/kernel/iwn5000fw.ko
-r-xr-xr-x 1 root wheel 344416 Oct 7 04:51:11 2012 /boot/kernel/iwn5000fw.ko
g1-227(9.1-P)[5]
FWIW.)
As noted, the message does not appear to be associated with (other)
unwanted behavior, so I wouldn't consider this of earth-shattering
importance. It just seemed rather odd, and I got to wondering if
the developer who committed the change had intended this result.
And if said result was actually of use to anyone. :-}
Given that the issue is present on both your machine and
Michael's, it's unlikely that it's firmware related (unless re(4) is
doing something hacktacularly awesome!), but I just wanted to gather
all the facts before something's brought up to glebius@, if the issue
is indeed one of the two commits (or both) mentioned above.
Could you guys please try reverting one or both of the commits to
see if the issue goes away?
Thanks!
-Garrett
Michael Butler
2012-10-07 17:53:56 UTC
Permalink
Post by Garrett Cooper
Maybe these revisions had something to do with it... (r241245 is
more likely)?
I reverted r241245 and the messages went away,
Post by Garrett Cooper
Did you rebuild all of your modules, and (for David) are you
running any firmware blobs with your wireless NIC?
I always rebuild modules (system and ports) along with a new kernel,

imb
Garrett Cooper
2012-10-07 17:56:28 UTC
Permalink
On Sun, Oct 7, 2012 at 10:51 AM, Michael Butler
-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1
Post by Garrett Cooper
Maybe these revisions had something to do with it... (r241245 is
more likely)?
I reverted r241245 and the messages went away,
Post by Garrett Cooper
Did you rebuild all of your modules, and (for David) are you
running any firmware blobs with your wireless NIC?
I always rebuild modules (system and ports) along with a new kernel,
Gleb CCed then.
Thanks!
-Garrett
Gleb Smirnoff
2012-10-08 08:05:58 UTC
Permalink
David and Michael,

On Sun, Oct 07, 2012 at 10:52:13AM -0700, Garrett Cooper wrote:
G> > On 10/07/12 13:03, Garrett Cooper wrote:
G> >> Maybe these revisions had something to do with it... (r241245 is
G> >> more likely)?
G> >
G> > I reverted r241245 and the messages went away,

Can you please try r241344?
--
Totus tuus, Glebius.
David Wolfskill
2012-10-08 13:52:36 UTC
Permalink
Post by Gleb Smirnoff
David and Michael,
G> >> Maybe these revisions had something to do with it... (r241245 is
G> >> more likely)?
G> >
G> > I reverted r241245 and the messages went away,
Can you please try r241344?
Done; seems to work:

FreeBSD g1-227.catwhisker.org 10.0-CURRENT FreeBSD 10.0-CURRENT #700 241344M: Mon Oct 8 06:20:59 PDT 2012 ***@g1-227.catwhisker.org:/usr/obj/usr/src/sys/CANARY i386

No whines in /var/log/messages or console (about "in_cksum_skip:
out of data by ....", at least).

Thanks!

Peace,
david
--
David H. Wolfskill ***@catwhisker.org
Depriving a girl or boy of an opportunity for education is evil.

See http://www.catwhisker.org/~david/publickey.gpg for my public key.
Michael Butler
2012-10-14 18:21:44 UTC
Permalink
Post by Gleb Smirnoff
David and Michael,
G> >> Maybe these revisions had something to do with it... (r241245 is
G> >> more likely)?
G> >
G> > I reverted r241245 and the messages went away,
Can you please try r241344?
Sorry for the delay; it seems that the last remaining cause was resolved
with SVN r241547. Thanks,

imb

Gleb Smirnoff
2012-10-07 19:12:52 UTC
Permalink
On Sun, Oct 07, 2012 at 01:51:20PM -0400, Michael Butler wrote:
M> On 10/07/12 13:03, Garrett Cooper wrote:
M> > Maybe these revisions had something to do with it... (r241245 is
M> > more likely)?
M>
M> I reverted r241245 and the messages went away,

I'll handle that. Sorry for breakage.
--
Totus tuus, Glebius.
Gleb Smirnoff
2012-10-07 19:40:30 UTC
Permalink
David and Michael,

can you please build a kernel with attached patch and options KDB,
and report what's the trace is.

Unfortunately my iwn(4) is running on amd64, so I can reproduce
exactly your case.
--
Totus tuus, Glebius.
Loading...