Hi, For the archives: we found out some traffic was VLAN tagged, hence defeating the aggregate_filter. Johannes to investigate and keep in touch if anything on the pmacctd side of the things is wrong.
Cheers, Paolo On Wed, Apr 09, 2014 at 12:01:47AM +0200, Johannes Formann wrote: > Hi Paolo, > > > The issue is persistent across reloads, correct? > > Correct. > And since the other aggregates seem to work normal I hope that this time the > hardware is not the reason ;) > > > Enable debug only for the plugin, ie. "debug[TMPflowSRC]: true", > > then check the log file to see if the problem is somehow with > > the database. > > Here are the results: > Apr 8 21:25:17 traffic pmacctd[15489]: INFO ( default/core ): Start logging > ... > Apr 8 21:25:17 traffic pmacctd[15489]: INFO ( inbound/mysql ): > plugin_pipe_size=40960000 bytes plugin_buffer_size=163840 bytes > Apr 8 21:25:17 traffic pmacctd[15489]: INFO ( inbound/mysql ): ctrl channel: > obtained=212992 bytes target=2000 bytes > Apr 8 21:25:17 traffic pmacctd[15489]: INFO ( outbound/mysql ): > plugin_pipe_size=40960000 bytes plugin_buffer_size=163840 bytes > Apr 8 21:25:17 traffic pmacctd[15489]: INFO ( outbound/mysql ): ctrl > channel: obtained=212992 bytes target=2000 bytes > Apr 8 21:25:17 traffic pmacctd[15489]: INFO ( TMPflowSRC/mysql ): > plugin_pipe_size=40960000 bytes plugin_buffer_size=163840 bytes > Apr 8 21:25:17 traffic pmacctd[15489]: INFO ( TMPflowSRC/mysql ): ctrl > channel: obtained=212992 bytes target=2000 bytes > Apr 8 21:25:17 traffic pmacctd[15489]: INFO ( TMPflowDST/mysql ): > plugin_pipe_size=40960000 bytes plugin_buffer_size=163840 bytes > Apr 8 21:25:17 traffic pmacctd[15489]: INFO ( TMPflowDST/mysql ): ctrl > channel: obtained=212992 bytes target=2000 bytes > Apr 8 21:25:17 traffic pmacctd[15492]: DEBUG ( /etc/pmacct/networks ): > [networks table IPv4] nh: peer asn: 0 asn: 0 net: xxx.yyy.64.0 mask: 20 > Apr 8 21:25:17 traffic pmacctd[15492]: DEBUG ( /etc/pmacct/networks ): > [networks table IPv4] nh: peer asn: 0 asn: 0 net: xxx.yyy.48.0 mask: 20 > Apr 8 21:25:17 traffic pmacctd[15492]: DEBUG ( /etc/pmacct/networks ): > [networks table IPv4] nh: peer asn: 0 asn: 0 net: xxx.yyy.164.0 mask: 24 > Apr 8 21:25:17 traffic pmacctd[15492]: DEBUG ( /etc/pmacct/networks ): > [networks table IPv4] nh: peer asn: 0 asn: 0 net: xxx.yyy.4.0 mask: 22 > Apr 8 21:25:17 traffic pmacctd[15492]: DEBUG ( /etc/pmacct/networks ): > [networks table IPv4] nh: peer asn: 0 asn: 0 net: xxx.yyy.104.0 mask: 22 > Apr 8 21:25:17 traffic pmacctd[15492]: DEBUG ( /etc/pmacct/networks ): > [networks table IPv4] nh: peer asn: 0 asn: 0 net: xxx.yyy.114.0 mask: 23 > Apr 8 21:25:17 traffic pmacctd[15492]: DEBUG ( /etc/pmacct/networks ): IPv4 > Networks Cache successfully created: 99991 entries. > Apr 8 21:25:17 traffic pmacctd[15492]: DEBUG ( /etc/pmacct/networks ): > [networks table IPv6] nh: peer_asn: 0 asn: 0 net: 2a00:xyza:: mask: 32 > Apr 8 21:25:17 traffic pmacctd[15492]: DEBUG ( /etc/pmacct/networks ): IPv6 > Networks Cache successfully created: 32771 entries. > Apr 8 21:25:17 traffic kernel: [22097.047614] device eth0 entered > promiscuous mode > Apr 8 21:25:17 traffic pmacctd[15489]: OK ( default/core ): link type is: 1 > Apr 8 21:26:01 traffic pmacctd[15494]: INFO ( TMPflowDST/mysql ): *** > Purging cache - START (PID: 15494) *** > Apr 8 21:26:01 traffic pmacctd[15495]: INFO ( TMPflowSRC/mysql ): *** > Purging cache - START (PID: 15495) *** > Apr 8 21:26:01 traffic pmacctd[15499]: INFO ( outbound/mysql ): *** Purging > cache - START (PID: 15499) *** > Apr 8 21:26:01 traffic pmacctd[15498]: INFO ( inbound/mysql ): *** Purging > cache - START (PID: 15498) *** > Apr 8 21:26:01 traffic pmacctd[15495]: DEBUG ( TMPflowSRC/mysql ): 36 VALUES > statements sent to the MySQL server. > Apr 8 21:26:01 traffic pmacctd[15495]: INFO ( TMPflowSRC/mysql ): *** > Purging cache - END (PID: 15495, QN: 36, ET: 0) *** > Apr 8 21:26:01 traffic pmacctd[15494]: INFO ( TMPflowDST/mysql ): *** > Purging cache - END (PID: 15494, QN: 556, ET: 0) *** > Apr 8 21:26:01 traffic pmacctd[15498]: INFO ( inbound/mysql ): *** Purging > cache - END (PID: 15498, QN: 1878, ET: 0) *** > Apr 8 21:26:01 traffic pmacctd[15499]: INFO ( outbound/mysql ): *** Purging > cache - END (PID: 15499, QN: 2333, ET: 0) *** > Apr 8 21:27:01 traffic pmacctd[15520]: INFO ( outbound/mysql ): *** Purging > cache - START (PID: 15520) *** > Apr 8 21:27:01 traffic pmacctd[15521]: INFO ( inbound/mysql ): *** Purging > cache - START (PID: 15521) *** > Apr 8 21:27:01 traffic pmacctd[15524]: INFO ( TMPflowSRC/mysql ): *** > Purging cache - START (PID: 15524) *** > Apr 8 21:27:01 traffic pmacctd[15526]: INFO ( TMPflowDST/mysql ): *** > Purging cache - START (PID: 15526) *** > Apr 8 21:27:01 traffic pmacctd[15524]: DEBUG ( TMPflowSRC/mysql ): 57 VALUES > statements sent to the MySQL server. > Apr 8 21:27:01 traffic pmacctd[15524]: INFO ( TMPflowSRC/mysql ): *** > Purging cache - END (PID: 15524, QN: 57, ET: 0) *** > Apr 8 21:27:01 traffic pmacctd[15526]: INFO ( TMPflowDST/mysql ): *** > Purging cache - END (PID: 15526, QN: 645, ET: 0) *** > Apr 8 21:27:01 traffic pmacctd[15521]: INFO ( inbound/mysql ): *** Purging > cache - END (PID: 15521, QN: 1665, ET: 0) *** > Apr 8 21:27:01 traffic pmacctd[15520]: INFO ( outbound/mysql ): *** Purging > cache - END (PID: 15520, QN: 2213, ET: 0) *** > > If I interpret the log correct some data is logged, but with 36 and 57 > entries far far away from the expectation. > > > If log is clear, meaning no entries are written > > out, i'd recommend to remove anything that can be potentially > > filtering so: aggregate_filter, networks_file and ports_file: > > see if this changes anything. Let's take it from there. > > After commenting the following lines out: > !aggregate_filter[TMPflowSRC]: udp > !networks_file[TMPflowSRC]: /etc/pmacct/networks > !ports_file[TMPflowSRC]: /etc/pmacct/portsudp > > The results looks same (expect capturing to much data) > Apr 8 21:38:01 traffic pmacctd[15800]: DEBUG ( TMPflowSRC/mysql ): 60329 > VALUES statements sent to the MySQL server. > Apr 8 21:38:01 traffic pmacctd[15800]: ERROR ( TMPflowSRC/mysql ): Duplicate > entry '2014-04-08 21:37:00-176.227.218.237-tcp-38820' for key 'PRIMARY'#012 > Apr 8 21:38:01 traffic pmacctd[15800]: INFO ( TMPflowSRC/mysql ): *** > Purging cache - END (PID: 15800, QN: 60329, ET: 0) *** > Apr 8 21:38:27 traffic pmacctd[15768]: WARN ( TMPflowSRC/mysql ): purging > process (CAUSE: safe action) > Apr 8 21:38:27 traffic pmacctd[15833]: INFO ( TMPflowSRC/mysql ): *** > Purging cache - START (PID: 15833) *** > Apr 8 21:38:32 traffic pmacctd[15833]: DEBUG ( TMPflowSRC/mysql ): 70000 > VALUES statements sent to the MySQL server. > Apr 8 21:38:32 traffic pmacctd[15833]: INFO ( TMPflowSRC/mysql ): *** > Purging cache - END (PID: 15833, QN: 70000, ET: 5) *** > Apr 8 21:38:49 traffic pmacctd[15768]: WARN ( TMPflowSRC/mysql ): purging > process (CAUSE: safe action) > Apr 8 21:38:49 traffic pmacctd[15835]: INFO ( TMPflowSRC/mysql ): *** > Purging cache - START (PID: 15835) *** > Apr 8 21:38:50 traffic pmacctd[15835]: DEBUG ( TMPflowSRC/mysql ): 70000 > VALUES statements sent to the MySQL server. > > After enabling the > networks_file[TMPflowSRC]: /etc/pmacct/networks > again still too much data but otherwise ok: > Apr 8 21:43:43 traffic pmacctd[16033]: WARN ( TMPflowSRC/mysql ): purging > process (CAUSE: safe action) > Apr 8 21:43:43 traffic pmacctd[16035]: INFO ( TMPflowSRC/mysql ): *** > Purging cache - START (PID: 16035) *** > Apr 8 21:43:47 traffic pmacctd[16035]: DEBUG ( TMPflowSRC/mysql ): 70000 > VALUES statements sent to the MySQL server. > Apr 8 21:43:47 traffic pmacctd[16035]: INFO ( TMPflowSRC/mysql ): *** > Purging cache - END (PID: 16035, QN: 70000, ET: 4) *** > Apr 8 21:44:01 traffic pmacctd[16041]: INFO ( TMPflowSRC/mysql ): *** > Purging cache - START (PID: 16041) *** > Apr 8 21:44:01 traffic pmacctd[16038]: INFO ( inbound/mysql ): *** Purging > cache - START (PID: 16038) *** > Apr 8 21:44:01 traffic pmacctd[16037]: INFO ( outbound/mysql ): *** Purging > cache - START (PID: 16037) *** > Apr 8 21:44:01 traffic pmacctd[16043]: INFO ( TMPflowDST/mysql ): *** > Purging cache - START (PID: 16043) *** > Apr 8 21:44:01 traffic pmacctd[16038]: INFO ( inbound/mysql ): *** Purging > cache - END (PID: 16038, QN: 1383, ET: 0) *** > Apr 8 21:44:01 traffic pmacctd[16043]: INFO ( TMPflowDST/mysql ): *** > Purging cache - END (PID: 16043, QN: 532, ET: 0) *** > Apr 8 21:44:01 traffic pmacctd[16037]: INFO ( outbound/mysql ): *** Purging > cache - END (PID: 16037, QN: 1783, ET: 0) *** > Apr 8 21:44:01 traffic pmacctd[16041]: DEBUG ( TMPflowSRC/mysql ): 53435 > VALUES statements sent to the MySQL server. > Apr 8 21:44:01 traffic pmacctd[16041]: ERROR ( TMPflowSRC/mysql ): Duplicate > entry '2014-04-08 21:43:00-xxx.yyy.75.20-tcp-20080' for key 'PRIMARY'#012 > Apr 8 21:44:01 traffic pmacctd[16041]: INFO ( TMPflowSRC/mysql ): *** > Purging cache - END (PID: 16041, QN: 53435, ET: 0) *** > Apr 8 21:44:32 traffic pmacctd[16033]: WARN ( TMPflowSRC/mysql ): purging > process (CAUSE: safe action) > Apr 8 21:44:32 traffic pmacctd[16066]: INFO ( TMPflowSRC/mysql ): *** > Purging cache - START (PID: 16066) *** > Apr 8 21:44:35 traffic pmacctd[16066]: DEBUG ( TMPflowSRC/mysql ): 70000 > VALUES statements sent to the MySQL server. > Apr 8 21:44:35 traffic pmacctd[16066]: INFO ( TMPflowSRC/mysql ): *** > Purging cache - END (PID: 16066, QN: 70000, ET: 3) *** > > Enabling > aggregate_filter[TMPflowSRC]: udp > networks_file[TMPflowSRC]: /etc/pmacct/networks > reduces the amount of data: > Apr 8 21:47:01 traffic pmacctd[16151]: DEBUG ( TMPflowSRC/mysql ): 13881 > VALUES statements sent to the MySQL server. > Apr 8 21:48:01 traffic pmacctd[16178]: DEBUG ( TMPflowSRC/mysql ): 29502 > VALUES statements sent to the MySQL server. > Apr 8 21:49:01 traffic pmacctd[16205]: DEBUG ( TMPflowSRC/mysql ): 29167 > VALUES statements sent to the MySQL server. > > BUT the error occurred, only IPv6 with a very small amount of the traffic > show up. > > Enabling > networks_file[TMPflowSRC]: /etc/pmacct/networks > ports_file[TMPflowSRC]: /etc/pmacct/portsudp > works without problems (only generating too much data since tcp is not > needed.) > > So the problem seem to result in the use of the > „aggregate_filter[TMPflowSRC]: udp“ which is kind of strange since the > aggregate TMPflowDST uses the same without problems. > > Ideas? Running without the aggregate_filter is a good quick workaround but > seems a strange error to me. > > regards > > Johannes > > > On Tue, Apr 08, 2014 at 05:50:50PM +0200, Johannes Formann wrote: > >> Hi, > >> > >> I have a strange problem again. I already tested the newest CVS version > >> but it persists: > >> > >> I use four aggregates: > >> - inbound: incoming traffic for local IPs > >> - outbound: outgoing traffic for local ips > >> - TMPflowSRC: short time local outgoing udp traffic (with a short port > >> list) > >> - TMPflowDST: short time udp traffic (after destination address) to be > >> able to identify potential outgoing ddos > >> > >> Everything worked fine for some time but today I found that TMPflowSRC > >> accounts almost no traffic anymore and if its accounts mostly IPv6 > >> addresses. Sadly in this network IPv6 traffic is less than 4% so there > >> must be some fault in my configuration. > >> > >> With debug enabled the initialization of the three aggregates with a > >> network filter looks identical, so there shouldn’t be the problem. > >> commenting out the port-List didn’t help either. > >> > >> My configuration: > >> > >> ! pmacctd configuration > >> ! > >> ! > >> ! > >> daemonize: true > >> pidfile: /var/run/pmacctd.pid > >> syslog: daemon > >> ! > >> aggregate[inbound]: dst_host > >> aggregate[outbound]: src_host,proto > >> aggregate[TMPflowSRC]: src_host,src_port,proto > >> aggregate[TMPflowDST]: dst_host,proto > >> aggregate_filter[TMPflowSRC]: udp > >> aggregate_filter[TMPflowDST]: udp > >> plugins: mysql[inbound], mysql[outbound], mysql[TMPflowSRC], > >> mysql[TMPflowDST] > >> sql_table[inbound]: acct_%Y_%m_in > >> sql_table[outbound]: acct_%Y_%m_out > >> sql_table[TMPflowSRC]: acct_TMPflowSRC > >> sql_table[TMPflowDST]: acct_TMPflowDST > >> sql_table_schema[inbound]: /etc/pmacct/inbound.schema > >> sql_table_schema[outbound]: /etc/pmacct/outbound.schema > >> networks_file[inbound]: /etc/pmacct/networks > >> networks_file[outbound]: /etc/pmacct/networks > >> networks_file[TMPflowSRC]: /etc/pmacct/networks > >> ports_file[TMPflowSRC]: /etc/pmacct/portsudp > >> > >> networks_file_filter: true > >> > >> interface: eth0 > >> > >> ! storage methods > >> sql_db: pmacct > >> sql_table_version: 4 > >> sql_passwd: <secret> > >> sql_user: pmacct > >> sql_refresh_time: 60 > >> sql_optimize_clauses: true > >> sql_history: 1m > >> sql_history_roundoff: m > >> sql_multi_values: 12000000 > >> sql_cache_entries: 64000 > >> > >> pmacctd_flow_buffer_buckets: 4096 > >> > >> sql_dont_try_update: true > >> > >> plugin_buffer_size: 163840 > >> plugin_pipe_size: 40960000 > >> > >> Any ideas where to look? > >> > >> greetings > >> > >> Johannes > >> _______________________________________________ > >> pmacct-discussion mailing list > >> http://www.pmacct.net/#mailinglists > > > > _______________________________________________ > > pmacct-discussion mailing list > > http://www.pmacct.net/#mailinglists > _______________________________________________ pmacct-discussion mailing list http://www.pmacct.net/#mailinglists
