System randomly not logging complete bi-directional traffic.

Sun Oct 9 17:28:20 UTC 2011

freebsd-questions at freebsd.org
#
#
# FreeBSD_7-4 RELEASE
# Our hardware is pristine
#
# What is described herein are regular, yet random occurrences; we need help.

We have already performed a reinstall of FreeBSD_7-4 RELEASE (and the
daemons in question); the issue remains. Below, is part of a conversation
with an httpd whereby the packets (entire conversations) are randomly
'not' being logged and/or seen by either the httpd nor ipfw (logging
enabled), yet both tshark and tcpdump are capturing everything.

To be perfectly clear, httpd and ipfw (randomly) will not see/log anything
of an 'entire conversation'.  It is not like it drops certain packets of a
conversation; they (httpd/ipfw) either see and log everything during a
conversation, or, 'do not see' and 'do not log' any packet associated with
a given conversation; all the while tshark and tcpdump are capturing
everything (bidirectional); hence the connection is real.

The capture below was witnessed by both tshark and tcpdump, but not logged
via the httpd or the following ipfw rule:

$cmd 00029 deny log logamount 0 ip from "table(1)" to me 80

The above ipfw rule functions properly from "table(1)" which contains --
ip.ip.ip.ip/32 -- one (1) ip per line.

The names (below) were changed to protect the innocent; yeah right.

Internet Protocol Version 4, Src: ex.ter.nal.ip (ex.ter.nal.ip), Dst:
in.ter.nal.ip (in.ter.nal.ip)
    Version: 4
    Header length: 20 bytes
    Differentiated Services Field: 0x00 (DSCP 0x00: Default; ECN: 0x00:
Not-ECT (Not ECN-Capable Transport))
        0000 00.. = Differentiated Services Codepoint: Default (0x00) ....
..00 = Explicit Congestion Notification: Not-ECT (Not
ECN-Capable Transport) (0x00)
    Total Length: 60
    Identification: 0x8ce5 (36069)
    Flags: 0x02 (Don't Fragment)
        0... .... = Reserved bit: Not set
        .1.. .... = Don't fragment: Set
        ..0. .... = More fragments: Not set
    Fragment offset: 0
    Time to live: 251
    Protocol: TCP (6)
    Header checksum: 0x9102 [correct]
        [Good: True]
        [Bad: False]
    Source: ex.ter.nal.ip (ex.ter.nal.ip)
    Destination: in.ter.nal.ip (in.ter.nal.ip)
Transmission Control Protocol, Src Port: 46463 (46463), Dst Port: http
(80), Seq: 0, Len: 0
    Source port: 46463 (46463)
    Destination port: http (80)
    [Stream index: 19]
    Sequence number: 0    (relative sequence number)
    Header length: 40 bytes
    Flags: 0x02 (SYN)
        000. .... .... = Reserved: Not set
        ...0 .... .... = Nonce: Not set
        .... 0... .... = Congestion Window Reduced (CWR): Not set
        .... .0.. .... = ECN-Echo: Not set
        .... ..0. .... = Urgent: Not set
        .... ...0 .... = Acknowledgement: Not set
        .... .... 0... = Push: Not set
        .... .... .0.. = Reset: Not set
        .... .... ..1. = Syn: Set
            [Expert Info (Chat/Sequence): Connection establish request
(SYN): server port http]
                [Message: Connection establish request (SYN): server port
http]
                [Severity level: Chat]
                [Group: Sequence]
        .... .... ...0 = Fin: Not set
    Window size value: 5840
    [Calculated window size: 5840]
    Checksum: 0xe7f8 [validation disabled]
        [Good Checksum: False]
        [Bad Checksum: False]
    Options: (20 bytes)
        Maximum segment size: 1460 bytes
        TCP SACK Permitted Option: True
        Timestamps: TSval 309029146, TSecr 0
            Kind: Timestamp (8)
            Length: 10
            Timestamp value: 309029146
            Timestamp echo reply: 0
        No-Operation (NOP)
        Window scale: 7 (multiply by 128)
            Kind: Window Scale (3)
            Length: 3
            Shift count: 7
            [Multiplier: 128]
    Frame Number: 51
    Frame Length: 74 bytes (592 bits)
    Capture Length: 74 bytes (592 bits)
    [Frame is marked: False]
    [Frame is ignored: False]
    [Protocols in frame: eth:ip:tcp]
Ethernet II, Src: Router_cf:gr:f0 (11:52:c3:fd:dd:f0), Dst: Goe_40:84:21
(00:15:18:40:28:41)
    Destination: Goe_40:84:21 (00:15:18:40:28:41)
        Address: Goe_40:84:21 (00:15:18:40:28:41)
        .... ...0 .... .... .... .... = IG bit: Individual address
(unicast)
        .... ..0. .... .... .... .... = LG bit: Globally unique address
(factory default)
    Source: Router_cf:gr:f0 (11:52:c3:fd:dd:f0)
        Address: Router_cf:gr:f0 (11:52:c3:fd:dd:f0)
        .... ...0 .... .... .... .... = IG bit: Individual address
(unicast)
        .... ..0. .... .... .... .... = LG bit: Globally unique address
(factory default)
    Type: IP (0x0800)
Internet Protocol Version 4, Src: ex.ter.nal.ip (ex.ter.nal.ip), Dst:
in.ter.nal.ip (in.ter.nal.ip)
    Version: 4
    Header length: 20 bytes
    Differentiated Services Field: 0x00 (DSCP 0x00: Default; ECN: 0x00:
Not-ECT (Not ECN-Capable Transport))
        0000 00.. = Differentiated Services Codepoint: Default (0x00) ....
..00 = Explicit Congestion Notification: Not-ECT (Not
ECN-Capable Transport) (0x00)
    Total Length: 60
    Identification: 0x8ce5 (36069)
    Flags: 0x02 (Don't Fragment)
        0... .... = Reserved bit: Not set
        .1.. .... = Don't fragment: Set
        ..0. .... = More fragments: Not set
    Fragment offset: 0
    Time to live: 251
    Protocol: TCP (6)
    Header checksum: 0x9102 [correct]
        [Good: True]
        [Bad: False]
    Source: ex.ter.nal.ip (ex.ter.nal.ip)
    Destination: in.ter.nal.ip (in.ter.nal.ip)
Transmission Control Protocol, Src Port: 46463 (46463), Dst Port: http
(80), Seq: 0, Len: 0
    Source port: 46463 (46463)
    Destination port: http (80)
    [Stream index: 19]
    Sequence number: 0    (relative sequence number)
    Header length: 40 bytes
    Flags: 0x02 (SYN)
        000. .... .... = Reserved: Not set
        ...0 .... .... = Nonce: Not set
        .... 0... .... = Congestion Window Reduced (CWR): Not set
        .... .0.. .... = ECN-Echo: Not set
        .... ..0. .... = Urgent: Not set
        .... ...0 .... = Acknowledgement: Not set
        .... .... 0... = Push: Not set
        .... .... .0.. = Reset: Not set
        .... .... ..1. = Syn: Set
            [Expert Info (Chat/Sequence): Connection establish request
(SYN): server port http]
                [Message: Connection establish request (SYN): server port
http]
                [Severity level: Chat]
                [Group: Sequence]
        .... .... ...0 = Fin: Not set
    Window size value: 5840
    [Calculated window size: 5840]
    Checksum: 0xe7f8 [validation disabled]
        [Good Checksum: False]
        [Bad Checksum: False]
    Options: (20 bytes)
        Maximum segment size: 1460 bytes
        TCP SACK Permitted Option: True
        Timestamps: TSval 309029146, TSecr 0
            Kind: Timestamp (8)
            Length: 10
            Timestamp value: 309029146
            Timestamp echo reply: 0
        No-Operation (NOP)
        Window scale: 7 (multiply by 128)
            Kind: Window Scale (3)
            Length: 3
            Shift count: 7
            [Multiplier: 128]
================================

We first noticed this logging issue with Apache22 and thought httpd was
the culprit; we installed another httpd and the problem remained.  At that
point, with two (2) httpds' seemingly offering the same results we decided
to enable ipfw and its logging feature. Shortly thereafter we notice ipfw
was also randomly 'not seeing' the exact same traffic, destined for port
80, that neither httpd's were also 'not seeing', yet Tshark and tcpdump
are in fact, capturing these packets.

We would like help to troubleshoot this concern rather than blindly
replacing things such as syslogd.