netfilter: ipt_LOG: add bufferisation to call printk() once

ipt_LOG & ip6t_LOG use lot of calls to printk() and use a lock in a hope
several cpus wont mix their output in syslog.

printk() being very expensive [1], its better to call it once, on a
prebuilt and complete line. Also, with mixed IPv4 and IPv6 trafic,
separate IPv4/IPv6 locks dont avoid garbage.

I used an allocation of a 1024 bytes structure, sort of seq_printf() but
with a fixed size limit.
Use a static buffer if dynamic allocation failed.

Emit a once time alert if buffer size happens to be too short.

[1]: printk() has various features like printk_delay()...

Signed-off-by: Eric Dumazet <eric.dumazet@gmail.com>
Signed-off-by: Patrick McHardy <kaber@trash.net>

1 files changed, 73 insertions, 72 deletions

diff --git a/net/ipv4/netfilter/ipt_LOG.c b/net/ipv4/netfilter/ipt_LOG.c
index 915fc17d7ce2..72ffc8fda2e9 100644
--- a/net/ipv4/netfilter/ipt_LOG.c
+++ b/net/ipv4/netfilter/ipt_LOG.c
@@ -24,16 +24,15 @@
 #include <linux/netfilter/x_tables.h>
 #include <linux/netfilter_ipv4/ipt_LOG.h>
 #include <net/netfilter/nf_log.h>
+#include <net/netfilter/xt_log.h>
 
 MODULE_LICENSE("GPL");
 MODULE_AUTHOR("Netfilter Core Team <coreteam@netfilter.org>");
 MODULE_DESCRIPTION("Xtables: IPv4 packet logging to syslog");
 
-/* Use lock to serialize, so printks don't overlap */
-static DEFINE_SPINLOCK(log_lock);
-
 /* One level of recursion won't kill us */
-static void dump_packet(const struct nf_loginfo *info,
+static void dump_packet(struct sbuff *m,
+                        const struct nf_loginfo *info,
                         const struct sk_buff *skb,
                         unsigned int iphoff)
 {
@@ -48,32 +47,32 @@ static void dump_packet(const struct nf_loginfo *info,
 
         ih = skb_header_pointer(skb, iphoff, sizeof(_iph), &_iph);
         if (ih == NULL) {
-                printk("TRUNCATED");
+                sb_add(m, "TRUNCATED");
                 return;
         }
 
         /* Important fields:
          * TOS, len, DF/MF, fragment offset, TTL, src, dst, options. */
         /* Max length: 40 "SRC=255.255.255.255 DST=255.255.255.255 " */
-        printk("SRC=%pI4 DST=%pI4 ",
+        sb_add(m, "SRC=%pI4 DST=%pI4 ",
                &ih->saddr, &ih->daddr);
 
         /* Max length: 46 "LEN=65535 TOS=0xFF PREC=0xFF TTL=255 ID=65535 " */
-        printk("LEN=%u TOS=0x%02X PREC=0x%02X TTL=%u ID=%u ",
+        sb_add(m, "LEN=%u TOS=0x%02X PREC=0x%02X TTL=%u ID=%u ",
                ntohs(ih->tot_len), ih->tos & IPTOS_TOS_MASK,
                ih->tos & IPTOS_PREC_MASK, ih->ttl, ntohs(ih->id));
 
         /* Max length: 6 "CE DF MF " */
         if (ntohs(ih->frag_off) & IP_CE)
-                printk("CE ");
+                sb_add(m, "CE ");
         if (ntohs(ih->frag_off) & IP_DF)
-                printk("DF ");
+                sb_add(m, "DF ");
         if (ntohs(ih->frag_off) & IP_MF)
-                printk("MF ");
+                sb_add(m, "MF ");
 
         /* Max length: 11 "FRAG:65535 " */
         if (ntohs(ih->frag_off) & IP_OFFSET)
-                printk("FRAG:%u ", ntohs(ih->frag_off) & IP_OFFSET);
+                sb_add(m, "FRAG:%u ", ntohs(ih->frag_off) & IP_OFFSET);
 
         if ((logflags & IPT_LOG_IPOPT) &&
             ih->ihl * 4 > sizeof(struct iphdr)) {
@@ -85,15 +84,15 @@ static void dump_packet(const struct nf_loginfo *info,
                 op = skb_header_pointer(skb, iphoff+sizeof(_iph),
                                         optsize, _opt);
                 if (op == NULL) {
-                        printk("TRUNCATED");
+                        sb_add(m, "TRUNCATED");
                         return;
                 }
 
                 /* Max length: 127 "OPT (" 15*4*2chars ") " */
-                printk("OPT (");
+                sb_add(m, "OPT (");
                 for (i = 0; i < optsize; i++)
-                        printk("%02X", op[i]);
-                printk(") ");
+                        sb_add(m, "%02X", op[i]);
+                sb_add(m, ") ");
         }
 
         switch (ih->protocol) {
@@ -102,7 +101,7 @@ static void dump_packet(const struct nf_loginfo *info,
                 const struct tcphdr *th;
 
                 /* Max length: 10 "PROTO=TCP " */
-                printk("PROTO=TCP ");
+                sb_add(m, "PROTO=TCP ");
 
                 if (ntohs(ih->frag_off) & IP_OFFSET)
                         break;
@@ -111,41 +110,41 @@ static void dump_packet(const struct nf_loginfo *info,
                 th = skb_header_pointer(skb, iphoff + ih->ihl * 4,
                                         sizeof(_tcph), &_tcph);
                 if (th == NULL) {
-                        printk("INCOMPLETE [%u bytes] ",
+                        sb_add(m, "INCOMPLETE [%u bytes] ",
                                skb->len - iphoff - ih->ihl*4);
                         break;
                 }
 
                 /* Max length: 20 "SPT=65535 DPT=65535 " */
-                printk("SPT=%u DPT=%u ",
+                sb_add(m, "SPT=%u DPT=%u ",
                        ntohs(th->source), ntohs(th->dest));
                 /* Max length: 30 "SEQ=4294967295 ACK=4294967295 " */
                 if (logflags & IPT_LOG_TCPSEQ)
-                        printk("SEQ=%u ACK=%u ",
+                        sb_add(m, "SEQ=%u ACK=%u ",
                                ntohl(th->seq), ntohl(th->ack_seq));
                 /* Max length: 13 "WINDOW=65535 " */
-                printk("WINDOW=%u ", ntohs(th->window));
+                sb_add(m, "WINDOW=%u ", ntohs(th->window));
                 /* Max length: 9 "RES=0x3F " */
-                printk("RES=0x%02x ", (u8)(ntohl(tcp_flag_word(th) & TCP_RESERVED_BITS) >> 22));
+                sb_add(m, "RES=0x%02x ", (u8)(ntohl(tcp_flag_word(th) & TCP_RESERVED_BITS) >> 22));
                 /* Max length: 32 "CWR ECE URG ACK PSH RST SYN FIN " */
                 if (th->cwr)
-                        printk("CWR ");
+                        sb_add(m, "CWR ");
                 if (th->ece)
-                        printk("ECE ");
+                        sb_add(m, "ECE ");
                 if (th->urg)
-                        printk("URG ");
+                        sb_add(m, "URG ");
                 if (th->ack)
-                        printk("ACK ");
+                        sb_add(m, "ACK ");
                 if (th->psh)
-                        printk("PSH ");
+                        sb_add(m, "PSH ");
                 if (th->rst)
-                        printk("RST ");
+                        sb_add(m, "RST ");
                 if (th->syn)
-                        printk("SYN ");
+                        sb_add(m, "SYN ");
                 if (th->fin)
-                        printk("FIN ");
+                        sb_add(m, "FIN ");
                 /* Max length: 11 "URGP=65535 " */
-                printk("URGP=%u ", ntohs(th->urg_ptr));
+                sb_add(m, "URGP=%u ", ntohs(th->urg_ptr));
 
                 if ((logflags & IPT_LOG_TCPOPT) &&
                     th->doff * 4 > sizeof(struct tcphdr)) {
@@ -158,15 +157,15 @@ static void dump_packet(const struct nf_loginfo *info,
                                                 iphoff+ih->ihl*4+sizeof(_tcph),
                                                 optsize, _opt);
                         if (op == NULL) {
-                                printk("TRUNCATED");
+                                sb_add(m, "TRUNCATED");
                                 return;
                         }
 
                         /* Max length: 127 "OPT (" 15*4*2chars ") " */
-                        printk("OPT (");
+                        sb_add(m, "OPT (");
                         for (i = 0; i < optsize; i++)
-                                printk("%02X", op[i]);
-                        printk(") ");
+                                sb_add(m, "%02X", op[i]);
+                        sb_add(m, ") ");
                 }
                 break;
         }
@@ -177,9 +176,9 @@ static void dump_packet(const struct nf_loginfo *info,
 
                 if (ih->protocol == IPPROTO_UDP)
                         /* Max length: 10 "PROTO=UDP "     */
-                        printk("PROTO=UDP " );
+                        sb_add(m, "PROTO=UDP " );
                 else    /* Max length: 14 "PROTO=UDPLITE " */
-                        printk("PROTO=UDPLITE ");
+                        sb_add(m, "PROTO=UDPLITE ");
 
                 if (ntohs(ih->frag_off) & IP_OFFSET)
                         break;
@@ -188,13 +187,13 @@ static void dump_packet(const struct nf_loginfo *info,
                 uh = skb_header_pointer(skb, iphoff+ih->ihl*4,
                                         sizeof(_udph), &_udph);
                 if (uh == NULL) {
-                        printk("INCOMPLETE [%u bytes] ",
+                        sb_add(m, "INCOMPLETE [%u bytes] ",
                                skb->len - iphoff - ih->ihl*4);
                         break;
                 }
 
                 /* Max length: 20 "SPT=65535 DPT=65535 " */
-                printk("SPT=%u DPT=%u LEN=%u ",
+                sb_add(m, "SPT=%u DPT=%u LEN=%u ",
                        ntohs(uh->source), ntohs(uh->dest),
                        ntohs(uh->len));
                 break;
@@ -221,7 +220,7 @@ static void dump_packet(const struct nf_loginfo *info,
                             [ICMP_ADDRESSREPLY] = 12 };
 
                 /* Max length: 11 "PROTO=ICMP " */
-                printk("PROTO=ICMP ");
+                sb_add(m, "PROTO=ICMP ");
 
                 if (ntohs(ih->frag_off) & IP_OFFSET)
                         break;
@@ -230,19 +229,19 @@ static void dump_packet(const struct nf_loginfo *info,
                 ich = skb_header_pointer(skb, iphoff + ih->ihl * 4,
                                          sizeof(_icmph), &_icmph);
                 if (ich == NULL) {
-                        printk("INCOMPLETE [%u bytes] ",
+                        sb_add(m, "INCOMPLETE [%u bytes] ",
                                skb->len - iphoff - ih->ihl*4);
                         break;
                 }
 
                 /* Max length: 18 "TYPE=255 CODE=255 " */
-                printk("TYPE=%u CODE=%u ", ich->type, ich->code);
+                sb_add(m, "TYPE=%u CODE=%u ", ich->type, ich->code);
 
                 /* Max length: 25 "INCOMPLETE [65535 bytes] " */
                 if (ich->type <= NR_ICMP_TYPES &&
                     required_len[ich->type] &&
                     skb->len-iphoff-ih->ihl*4 < required_len[ich->type]) {
-                        printk("INCOMPLETE [%u bytes] ",
+                        sb_add(m, "INCOMPLETE [%u bytes] ",
                                skb->len - iphoff - ih->ihl*4);
                         break;
                 }
@@ -251,35 +250,35 @@ static void dump_packet(const struct nf_loginfo *info,
                 case ICMP_ECHOREPLY:
                 case ICMP_ECHO:
                         /* Max length: 19 "ID=65535 SEQ=65535 " */
-                        printk("ID=%u SEQ=%u ",
+                        sb_add(m, "ID=%u SEQ=%u ",
                                ntohs(ich->un.echo.id),
                                ntohs(ich->un.echo.sequence));
                         break;
 
                 case ICMP_PARAMETERPROB:
                         /* Max length: 14 "PARAMETER=255 " */
-                        printk("PARAMETER=%u ",
+                        sb_add(m, "PARAMETER=%u ",
                                ntohl(ich->un.gateway) >> 24);
                         break;
                 case ICMP_REDIRECT:
                         /* Max length: 24 "GATEWAY=255.255.255.255 " */
-                        printk("GATEWAY=%pI4 ", &ich->un.gateway);
+                        sb_add(m, "GATEWAY=%pI4 ", &ich->un.gateway);
                         /* Fall through */
                 case ICMP_DEST_UNREACH:
                 case ICMP_SOURCE_QUENCH:
                 case ICMP_TIME_EXCEEDED:
                         /* Max length: 3+maxlen */
                         if (!iphoff) { /* Only recurse once. */
-                                printk("[");
-                                dump_packet(info, skb,
+                                sb_add(m, "[");
+                                dump_packet(m, info, skb,
                                             iphoff + ih->ihl*4+sizeof(_icmph));
-                                printk("] ");
+                                sb_add(m, "] ");
                         }
 
                         /* Max length: 10 "MTU=65535 " */
                         if (ich->type == ICMP_DEST_UNREACH &&
                             ich->code == ICMP_FRAG_NEEDED)
-                                printk("MTU=%u ", ntohs(ich->un.frag.mtu));
+                                sb_add(m, "MTU=%u ", ntohs(ich->un.frag.mtu));
                 }
                 break;
         }
@@ -292,19 +291,19 @@ static void dump_packet(const struct nf_loginfo *info,
                         break;
 
                 /* Max length: 9 "PROTO=AH " */
-                printk("PROTO=AH ");
+                sb_add(m, "PROTO=AH ");
 
                 /* Max length: 25 "INCOMPLETE [65535 bytes] " */
                 ah = skb_header_pointer(skb, iphoff+ih->ihl*4,
                                         sizeof(_ahdr), &_ahdr);
                 if (ah == NULL) {
-                        printk("INCOMPLETE [%u bytes] ",
+                        sb_add(m, "INCOMPLETE [%u bytes] ",
                                skb->len - iphoff - ih->ihl*4);
                         break;
                 }
 
                 /* Length: 15 "SPI=0xF1234567 " */
-                printk("SPI=0x%x ", ntohl(ah->spi));
+                sb_add(m, "SPI=0x%x ", ntohl(ah->spi));
                 break;
         }
         case IPPROTO_ESP: {
@@ -312,7 +311,7 @@ static void dump_packet(const struct nf_loginfo *info,
                 const struct ip_esp_hdr *eh;
 
                 /* Max length: 10 "PROTO=ESP " */
-                printk("PROTO=ESP ");
+                sb_add(m, "PROTO=ESP ");
 
                 if (ntohs(ih->frag_off) & IP_OFFSET)
                         break;
@@ -321,25 +320,25 @@ static void dump_packet(const struct nf_loginfo *info,
                 eh = skb_header_pointer(skb, iphoff+ih->ihl*4,
                                         sizeof(_esph), &_esph);
                 if (eh == NULL) {
-                        printk("INCOMPLETE [%u bytes] ",
+                        sb_add(m, "INCOMPLETE [%u bytes] ",
                                skb->len - iphoff - ih->ihl*4);
                         break;
                 }
 
                 /* Length: 15 "SPI=0xF1234567 " */
-                printk("SPI=0x%x ", ntohl(eh->spi));
+                sb_add(m, "SPI=0x%x ", ntohl(eh->spi));
                 break;
         }
         /* Max length: 10 "PROTO 255 " */
         default:
-                printk("PROTO=%u ", ih->protocol);
+                sb_add(m, "PROTO=%u ", ih->protocol);
         }
 
         /* Max length: 15 "UID=4294967295 " */
         if ((logflags & IPT_LOG_UID) && !iphoff && skb->sk) {
                 read_lock_bh(&skb->sk->sk_callback_lock);
                 if (skb->sk->sk_socket && skb->sk->sk_socket->file)
-                        printk("UID=%u GID=%u ",
+                        sb_add(m, "UID=%u GID=%u ",
                                 skb->sk->sk_socket->file->f_cred->fsuid,
                                 skb->sk->sk_socket->file->f_cred->fsgid);
                 read_unlock_bh(&skb->sk->sk_callback_lock);
@@ -347,7 +346,7 @@ static void dump_packet(const struct nf_loginfo *info,
 
         /* Max length: 16 "MARK=0xFFFFFFFF " */
         if (!iphoff && skb->mark)
-                printk("MARK=0x%x ", skb->mark);
+                sb_add(m, "MARK=0x%x ", skb->mark);
 
         /* Proto    Max log string length */
         /* IP:      40+46+6+11+127 = 230 */
@@ -364,7 +363,8 @@ static void dump_packet(const struct nf_loginfo *info,
         /* maxlen = 230+   91  + 230 + 252 = 803 */
 }
 
-static void dump_mac_header(const struct nf_loginfo *info,
+static void dump_mac_header(struct sbuff *m,
+                            const struct nf_loginfo *info,
                             const struct sk_buff *skb)
 {
         struct net_device *dev = skb->dev;
@@ -378,7 +378,7 @@ static void dump_mac_header(const struct nf_loginfo *info,
 
         switch (dev->type) {
         case ARPHRD_ETHER:
-                printk("MACSRC=%pM MACDST=%pM MACPROTO=%04x ",
+                sb_add(m, "MACSRC=%pM MACDST=%pM MACPROTO=%04x ",
                        eth_hdr(skb)->h_source, eth_hdr(skb)->h_dest,
                        ntohs(eth_hdr(skb)->h_proto));
                 return;
@@ -387,17 +387,17 @@ static void dump_mac_header(const struct nf_loginfo *info,
         }
 
 fallback:
-        printk("MAC=");
+        sb_add(m, "MAC=");
         if (dev->hard_header_len &&
             skb->mac_header != skb->network_header) {
                 const unsigned char *p = skb_mac_header(skb);
                 unsigned int i;
 
-                printk("%02x", *p++);
+                sb_add(m, "%02x", *p++);
                 for (i = 1; i < dev->hard_header_len; i++, p++)
-                        printk(":%02x", *p);
+                        sb_add(m, ":%02x", *p);
         }
-        printk(" ");
+        sb_add(m, " ");
 }
 
 static struct nf_loginfo default_loginfo = {
@@ -419,11 +419,12 @@ ipt_log_packet(u_int8_t pf,
                const struct nf_loginfo *loginfo,
                const char *prefix)
 {
+        struct sbuff *m = sb_open();
+
         if (!loginfo)
                 loginfo = &default_loginfo;
 
-        spin_lock_bh(&log_lock);
-        printk("<%d>%sIN=%s OUT=%s ", loginfo->u.log.level,
+        sb_add(m, "<%d>%sIN=%s OUT=%s ", loginfo->u.log.level,
                prefix,
                in ? in->name : "",
                out ? out->name : "");
@@ -434,20 +435,20 @@ ipt_log_packet(u_int8_t pf,
 
                 physindev = skb->nf_bridge->physindev;
                 if (physindev && in != physindev)
-                        printk("PHYSIN=%s ", physindev->name);
+                        sb_add(m, "PHYSIN=%s ", physindev->name);
                 physoutdev = skb->nf_bridge->physoutdev;
                 if (physoutdev && out != physoutdev)
-                        printk("PHYSOUT=%s ", physoutdev->name);
+                        sb_add(m, "PHYSOUT=%s ", physoutdev->name);
         }
 #endif
 
         /* MAC logging for input path only. */
         if (in && !out)
-                dump_mac_header(loginfo, skb);
+                dump_mac_header(m, loginfo, skb);
+
+        dump_packet(m, loginfo, skb, 0);
 
-        dump_packet(loginfo, skb, 0);
-        printk("\n");
-        spin_unlock_bh(&log_lock);
+        sb_close(m);
 }
 
 static unsigned int