From a8defca048fd11eb2d1a17ab61a60a856292dd4e Mon Sep 17 00:00:00 2001 From: Eric Dumazet Date: Mon, 4 Oct 2010 20:56:05 +0200 Subject: 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 Signed-off-by: Patrick McHardy --- net/ipv4/netfilter/ipt_LOG.c | 145 ++++++++++++++++++++++--------------------- 1 file changed, 73 insertions(+), 72 deletions(-) (limited to 'net/ipv4/netfilter') 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 #include #include +#include MODULE_LICENSE("GPL"); MODULE_AUTHOR("Netfilter Core Team "); 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 -- cgit v1.2.1