Timestamps, NFLOG, and ULOG

Timestamps, NFLOG, and ULOG

[Korodev]

Hi all,

This is my first time posting on this list so please let me know if
this it not the appropriate list, but I figured I should start here.
We've been using traditional IP tables LOG targets for some time now
and in an effort to clean up our kernel logs and boost performance, we
began looking at NFLOG to ulogd. However, it appears that the packet
timestamps being shown in the ulogd logs are the timestamps at which
the packet is processed by a ulogd stack instead of the actual packet
timestamp.

My platform (Ubuntu 16.04 4.15.0-58-generic), provides 2.0.5 and I
have since compiled and tested 2.0.7, since I saw the JSON output
plugin had been updated to pull the timestamp from the packets. Here's
what I'm seeing with the following stacks and IPTables rules.

stack=firewall9:NFLOG,base1:BASE,ifi1:IFINDEX,ip2str1:IP2STR,mac2str1:HWHDR,json9:JSON
stack=firewall10:NFLOG,base1:BASE,ifi1:IFINDEX,ip2str1:IP2STR,print1:PRINTPKT,emu10:LOGEMU
stack=firewall11:NFLOG,base1:BASE,ifi1:IFINDEX,ip2str1:IP2STR,print1:PRINTPKT,emu11:LOGEMU
stack=firewall12:NFLOG,base1:BASE,ifi1:IFINDEX,ip2str1:IP2STR,mac2str1:HWHDR,json12:JSON

Chain LOG_DROP (4 references)
 pkts bytes target     prot opt in     out     source               destination
 6625  440K NFLOG      all  --  *      *       0.0.0.0/0
0.0.0.0/0            nflog-group 9
31653 2709K LOG        all  --  *      *       0.0.0.0/0
0.0.0.0/0             LOG flags 0 level 6
 6612  438K NFLOG      all  --  *      *       0.0.0.0/0
0.0.0.0/0            nflog-group 10
 6611  437K NFLOG      all  --  *      *       0.0.0.0/0
0.0.0.0/0            nflog-group 11
 6611  437K NFLOG      all  --  *      *       0.0.0.0/0
0.0.0.0/0            nflog-group 12
33437 3119K DROP       all  --  *      *       0.0.0.0/0            0.0.0.0/0


group 9 (json) - 2020-05-21T14:20:18.663625
iptables log - 2020-05-21T14:20:17.643629+00:00
group 10 - May 21 14:20:18
group 11 - May 21 14:20:18
group 12 - 2020-05-21T14:20:18.664217:D

Additionally if I implement any sort of queuing or thresholding, which
I'd like to eventually, the timestamps are affected. This seems to
indicate I'm not getting the actual packet timestamps. Any ideas on
what could be causing this or is this expected behaviour?



\\korodev

Re: Timestamps, NFLOG, and ULOG

[Florian Westphal]

Korodev <korodev@gmail.com> wrote:
> Additionally if I implement any sort of queuing or thresholding, which
> I'd like to eventually, the timestamps are affected. This seems to
> indicate I'm not getting the actual packet timestamps. Any ideas on
> what could be causing this or is this expected behaviour?

Its expected.  If you want rx timestamps you should set
SO_TIMESTAMP(NS) socket option,

Re: Timestamps, NFLOG, and ULOG

[Korodev]

On Thu, May 21, 2020 at 6:26 PM Florian Westphal <fw@strlen.de> wrote:
> Its expected.  If you want rx timestamps you should set
> SO_TIMESTAMP(NS) socket option,

Thank you for your reply. My understanding is that SO_TIMESTAMP is a
socket option I could set for an application that I control, but how
would I go about enabling that such that IPTables, Netlink, and ULOGd
are aware? I assumed I would at least get the software timestamp at
which the kernel received the packet. Am I correct in assuming that
the IPTables LOG action has simply been providing me the timestamp at
the time printk is called all this time?

\\korodev

Re: Timestamps, NFLOG, and ULOG

[Florian Westphal]

Korodev <korodev@gmail.com> wrote:
> On Thu, May 21, 2020 at 6:26 PM Florian Westphal <fw@strlen.de> wrote:
> > Its expected.  If you want rx timestamps you should set
> > SO_TIMESTAMP(NS) socket option,
> 
> Thank you for your reply. My understanding is that SO_TIMESTAMP is a
> socket option I could set for an application that I control, but how
> would I go about enabling that such that IPTables, Netlink, and ULOGd
> are aware?

Setting this option makes the kernel record a timestamp at reception
time for all packets it receives (it won't know the socket the packet
will be delivered to yet, so it can't do this in a fine-grained way).

This is off by default for performance reasons.
Ideally ulogd should have an option to enable this (it doesn't have
one).

> I assumed I would at least get the software timestamp at
> which the kernel received the packet.

No, the kernel does not record a timestamp by default.