Daily Usenet report for csiph.com: Jan 31 04:15:00

Unknown entries from news log file:

First 1 / 1 lines (100.0%)

Jan 31 16:30:04 csiph controlchan[19063]: Multiple control headers in article <t5JtF-2Tw-45@gated-at.bofh.it>

Log entries by program:

Program name	Lines	%Lines	Size	%Size
inn	77910	54.8%	12.3 MB	62.3%
innd	57716	40.6%	6.6 MB	33.3%
innfeed	3262	2.3%	532.1 KB	2.6%
nnrpd	3115	2.2%	346.1 KB	1.7%
nocem	38	0.0%	3.7 KB	0.0%
controlchan	6	0.0%	1.0 KB	0.0%
TOTAL: 6	142047	100.0%	19.7 MB	100.0%

History cache:

Reason	Count	%Count
Positive hits	412532	49.9%
Negative hits	337312	40.8%
Do not exist	77004	9.3%
Cache misses	669	0.1%
TOTAL: 4	827517	100.0%

INND timer:

Code region	Time	Pct	Invoked	Min(ms)	Avg(ms)	Max(ms)
article cancel	00:00:00.426	0.0%	129	0.000	3.302	36.000
article cleanup	00:00:00.410	0.0%	76841	0.000	0.005	0.030
article logging	00:00:02.921	0.0%	77535	0.000	0.038	0.666
article parse	00:00:02.683	0.0%	177318	0.002	0.015	0.350
article write	00:02:10.262	0.2%	24549	0.190	5.306	13.678
artlog/artcncl	00:00:00.002	0.0%	111	0.000	0.018	0.500
artlog/artparse	00:00:00.015	0.0%	267	0.000	0.056	5.000
data move	00:00:00.294	0.0%	716008	0.000	0.000	0.006
hisgrep/artcncl	00:00:00.080	0.0%	128	0.000	0.625	28.000
hishave/artcncl	00:00:00.001	0.0%	129	0.000	0.008	0.200
hishave/artparse	00:00:00.000	0.0%	265	0.000	0.000	0.000
history grep	00:00:00.000	0.0%	0	0.000	0.000	0.000
history lookup	00:00:33.088	0.0%	827898	0.001	0.040	0.337
history sync	00:00:05.606	0.0%	361	0.000	15.529	123.000
history write	00:03:01.110	0.2%	76703	0.069	2.361	12.521
hiswrite/artcncl	00:00:00.000	0.0%	1	0.000	0.000	0.000
hiswrite/artparse	00:00:00.941	0.0%	265	0.000	3.551	87.000
idle	23:48:41.118	99.1%	719466	21.622	119.145	404.395
nntp read	00:00:03.429	0.0%	739955	0.002	0.005	0.014
overview write	00:03:26.114	0.2%	24549	0.625	8.396	60.345
perl filter	00:01:28.070	0.1%	76701	0.240	1.148	5.358
python filter	00:00:00.000	0.0%	0	0.000	0.000	0.000
site send	00:00:00.450	0.0%	49132	0.000	0.009	0.031
TOTAL: 24:00:57.239	23:59:37.020	99.9%	-	-	-	-

INNfeed timer:

Code region	Time	Pct	Invoked	Min(ms)	Avg(ms)	Max(ms)
article new	00:00:00.060	0.0%	24631	0.000	0.002	0.024
article prepare	00:00:00.004	0.0%	39200	0.000	0.000	0.005
article read	00:00:01.292	0.0%	7589	0.000	0.170	2.224
backlog stats	00:00:00.289	0.0%	436127	0.000	0.001	0.003
callbacks	00:00:00.000	0.0%	0	0.000	0.000	0.000
data read	00:00:02.279	0.0%	342253	0.002	0.007	0.011
data write	00:00:02.002	0.0%	326188	0.002	0.006	0.010
idle	23:53:35.966	100.0%	436127	86.443	197.227	535.391
status file	00:00:00.249	0.0%	304	0.000	0.819	16.000
TOTAL: 23:53:50.794	23:53:42.141	100.0%	-	-	-	-

nnrpd timer:

Code region	Time	Pct	Invoked	Min(ms)	Avg(ms)	Max(ms)
hisgrep	00:00:00.104	0.0%	97	0.000	1.072	26.000
idle	77:41:12.383	99.8%	10284	81.083	27194.903	900277.000
newnews	00:00:00.000	0.0%	0	0.000	0.000	0.000
nntpwrite	00:00:00.109	0.0%	20716	0.000	0.005	0.250
readart	00:00:04.468	0.0%	691	0.000	6.466	48.000
TOTAL: 77:50:34.035	77:41:17.064	99.8%	-	-	-	-

Control commands to INND:

Command	Number
L	1
flush	5
flushlogs	2
go	2
logmode	2
mode	144
pause	2
paused	2
reload	2
reserve	2
TOTAL: 10	164

Control Channel:

Sender	newgroup	rmgroup	Other	Bad PGP	DoIt	OK
usenet@film.rlss.okayama-u.ac.jp	0	0	1	0	1	1
TOTAL	0	0	1	0	1	1

Incoming Feeds (INN):

Server		Connects	Offered	Taken	Refused	Reject	%Accpt	Elapsed
1	csiph-out.feeder.erje.net	1153	120035	6500	105596	7939	5%	95:03:21
2	csiph-out.news.weretis.net	3	51325	6205	44443	677	12%	48:05:05
3	feeder.eternal-september.org	8	29974	3722	25443	809	12%	24:39:39
4	news-out.aioe.org	4	23809	1688	22095	26	7%	24:09:37
5	newsfeed.neva.ru	139	40869	1464	37669	1736	3%	71:38:12
6	news-out.mixmin.net	3	26050	1221	24608	221	4%	24:08:51
7	newsfeed.fu-berlin.de	52	65666	1182	22049	42435	1%	32:37:26
8	news.redatomik.org	2	24631	1022	23563	46	4%	24:53:54
9	newsfeeds.xmission.com	2	25215	890	24292	33	3%	27:04:49
10	news.freedyn.net	3	26389	307	25910	172	1%	24:09:50
11	news.fcku.it	2	10202	254	9850	98	2%	23:59:53
12	nntp.pasdenom.info	6	23736	176	23540	20	0%	24:12:00
13	news.swapon.de	2	1919	77	1838	4	4%	21:02:43
14	xanadu-bbs.net	14	945	54	887	4	5%	22:58:56
15	news.bbs.geek.nz	1	18929	31	18896	2	0%	23:59:48
16	localhost	42	10	10	0	0	100%	00:00:00
TOTAL: 16		1436	489704	24803	410679	54222	5%	512:44:04

Incoming Volume (INN):

Server		AcceptVol	DupVol	RejVol	TotalVol	%Acc	Vol/Art
1	csiph-out.feeder.erje.net	23.2 MB	493.1 KB	27.7 MB	51.4 MB	45%	3.6 KB
2	csiph-out.news.weretis.net	18.0 MB	86.7 KB	12.2 MB	30.3 MB	59%	4.5 KB
3	feeder.eternal-september.org	10.5 MB	446.4 KB	11.3 MB	22.2 MB	47%	5.0 KB
4	news-out.mixmin.net	5.6 MB	44.6 KB	1.2 MB	6.8 MB	82%	4.8 KB
5	newsfeed.neva.ru	4.8 MB	257.3 KB	11.6 MB	16.7 MB	29%	5.3 KB
6	news-out.aioe.org	4.7 MB	29.6 KB	143.5 KB	4.9 MB	96%	2.9 KB
7	news.redatomik.org	2.7 MB	31.7 KB	323.8 KB	3.1 MB	88%	3.0 KB
8	newsfeed.fu-berlin.de	2.5 MB	0.0 KB	81.0 MB	83.5 MB	2%	2.0 KB
9	newsfeeds.xmission.com	2.4 MB	5.0 KB	305.6 KB	2.7 MB	88%	3.0 KB
10	news.freedyn.net	1.2 MB	0.0 KB	4.8 MB	6.0 MB	20%	12.8 KB
11	news.fcku.it	504.1 KB	24.0 KB	441.2 KB	969.2 KB	52%	2.8 KB
12	nntp.pasdenom.info	483.2 KB	4.8 KB	49.8 KB	537.8 KB	89%	2.7 KB
13	news.swapon.de	206.1 KB	0.0 KB	12.5 KB	218.6 KB	94%	2.7 KB
14	xanadu-bbs.net	148.1 KB	0.0 KB	13.2 KB	161.2 KB	91%	2.8 KB
15	news.bbs.geek.nz	65.3 KB	0.0 KB	12.0 KB	77.3 KB	84%	2.3 KB
16	localhost	11.2 KB	0.0 KB	0.0 KB	11.2 KB	100%	1.1 KB
TOTAL: 16		77.0 MB	1.4 MB	151.0 MB	229.4 MB	33%	3.0 KB

Incoming articles:

Date	Articles	%Arts	Art/sec	Size	%Size	KB/sec
Jan 31 04:15:00 - 04:59:59	372	1.5%	0.14	1.2 MB	1.6%	0.45
Jan 31 05:00:00 - 05:59:59	599	2.4%	0.17	2.2 MB	2.8%	0.61
Jan 31 06:00:00 - 06:59:59	604	2.5%	0.17	3.0 MB	3.9%	0.84
Jan 31 07:00:00 - 07:59:59	717	2.9%	0.20	2.1 MB	2.7%	0.59
Jan 31 08:00:00 - 08:59:59	883	3.6%	0.25	2.7 MB	3.5%	0.77
Jan 31 09:00:00 - 09:59:59	1120	4.6%	0.31	3.7 MB	4.8%	1.04
Jan 31 10:00:00 - 10:59:59	1178	4.8%	0.33	3.0 MB	3.9%	0.86
Jan 31 11:00:00 - 11:59:59	1031	4.2%	0.29	2.8 MB	3.7%	0.80
Jan 31 12:00:00 - 12:59:59	1110	4.5%	0.31	3.3 MB	4.3%	0.93
Jan 31 13:00:00 - 13:59:59	1445	5.9%	0.40	3.2 MB	4.2%	0.92
Jan 31 14:00:00 - 14:59:59	1200	4.9%	0.33	3.5 MB	4.6%	1.00
Jan 31 15:00:00 - 15:59:59	1409	5.7%	0.39	3.6 MB	4.6%	1.01
Jan 31 16:00:00 - 16:59:59	1456	5.9%	0.40	4.3 MB	5.6%	1.22
Jan 31 17:00:00 - 17:59:59	1448	5.9%	0.40	4.5 MB	5.9%	1.29
Jan 31 18:00:00 - 18:59:59	1406	5.7%	0.39	4.3 MB	5.6%	1.22
Jan 31 19:00:00 - 19:59:59	1335	5.4%	0.37	4.2 MB	5.4%	1.18
Jan 31 20:00:00 - 20:59:59	1360	5.5%	0.38	3.8 MB	5.0%	1.09
Jan 31 21:00:00 - 21:59:59	1248	5.1%	0.35	3.6 MB	4.8%	1.04
Jan 31 22:00:00 - 22:59:59	1131	4.6%	0.31	3.3 MB	4.3%	0.93
Jan 31 23:00:00 - 23:59:59	953	3.9%	0.26	2.8 MB	3.7%	0.81
Feb 1 00:00:00 - 00:59:59	721	2.9%	0.20	2.2 MB	2.9%	0.62
Feb 1 01:00:00 - 01:59:59	539	2.2%	0.15	1.5 MB	2.0%	0.43
Feb 1 02:00:00 - 02:59:59	694	2.8%	0.19	5.5 MB	7.3%	1.58
Feb 1 03:00:00 - 03:59:59	479	2.0%	0.13	1.9 MB	2.5%	0.54
Feb 1 04:00:00 - 04:15:00	109	0.4%	0.12	330.5 KB	0.4%	0.37
TOTAL: 24:00:00	24547	100.0%	0.28	76.4 MB	100.0%	0.91

Sites sending bad articles:

Server		Total	Group	Duplic	Other
1	newsfeed.fu-berlin.de	42843	36	0	42807
2	csiph-out.feeder.erje.net	6150	523	38	5589
3	newsfeed.neva.ru	1845	372	24	1449
4	feeder.eternal-september.org	907	56	38	813
5	csiph-out.news.weretis.net	790	164	12	614
6	news-out.mixmin.net	244	7	12	225
7	news.freedyn.net	181	15	0	166
8	news.fcku.it	98	2	2	94
9	news.redatomik.org	76	0	5	71
10	newsfeeds.xmission.com	40	25	3	12
11	news-out.aioe.org	34	17	4	13
12	nntp.pasdenom.info	21	9	2	10
13	news.swapon.de	14	0	0	14
14	news.bbs.geek.nz	5	2	0	3
15	xanadu-bbs.net	4	0	0	4
TOTAL: 15		53252	1228	140	51884

Unwanted newsgroups [Top 20]:

Newsgroup	Count
lada.auto	173
it.annunci.varie	117
ut.test	93
lada.talk	88
it.annunci.immobiliari	85
gmane.linux.alsa.devel	78
it-alt.sport.calcio.juventus	40
it.annunci.commerciali	28
gmane.comp.gis.openstreetmap	27
mozilla.support.seamonkey	26
lada.commerce	26
alt.binaries.solar-xl	24
alt.2600	19
mozilla.general	16
oesterreich.tratsch	15
alt.computer.workshop	14
alt.windows7.general	14
cakewalk.audio	14
mozilla.dev.developer-tools	13
alt.politics.scorched-earth	13
TOTAL: 132	1228

INND Perl filter [Top 20]:

Reason	Count
EMP (md5)	5515
Binary: misplaced 19	4002
Binary: misplaced 17	3376
Binary: misplaced 20	3204
Binary: misplaced 14	3118
Binary: misplaced 16	2842
Binary: misplaced 01	2691
Binary: misplaced 18	2133
Binary: misplaced 02	2041
Binary: misplaced 13	1861
Binary: misplaced 15	1779
EMP (phn path)	1676
Binary: misplaced 03	1664
Binary: misplaced 11	1637
Binary: misplaced 07	1599
Binary: misplaced 04	1528
Binary: misplaced 12	1521
Binary: misplaced 08	1504
Binary: misplaced 05	1408
Binary: misplaced 06	1396
TOTAL: 44	50925

NoCeM on Spool:

Id	Good	Bad	Unique	Total
bleachbot@httrack.com	32	0	32	32
TOTAL: 1	32	0	32	32

Miscellaneous innd statistics [Top 10]:

Event	Server	Number
Huge articles
	newsfeed.fu-berlin.de	84
	news.freedyn.net	77
	csiph-out.news.weretis.net	72
	news-out.mixmin.net	13
	feeder.eternal-september.org	12
	newsfeeds.xmission.com	4
	news.fcku.it	2
	news.redatomik.org	1
	TOTAL: 8	265
Including strange strings
	newsfeed.fu-berlin.de	409
	csiph-out.feeder.erje.net	143
	feeder.eternal-september.org	37
	csiph-out.news.weretis.net	33
	news.redatomik.org	16
	news-out.mixmin.net	14
	newsfeed.neva.ru	11
	news.swapon.de	10
	newsfeeds.xmission.com	8
	news-out.aioe.org	8
	TOTAL: 12	692
No colon-space in header
	csiph-out.feeder.erje.net	2
	TOTAL: 1	2
TOTAL: 3		959

Outgoing Feeds (innfeed) by Articles:

Server		Offered	Taken	Refused	Reject	Spool	%Took	Elapsed
1	news.bbs.geek.nz	41078	6074	17756	127	0	14%	23:59:38
2	xanadu-bbs	26428	756	23712	4	2	2%	23:59:56
3	news.freedyn.net	25066	675	23543	16	1	2%	23:59:53
4	fu-berlin.de	23045	562	22483	0	0	2%	23:59:56
5	xmission	26800	122	22809	5	0	0%	23:59:56
6	usenet.pasdenom.info	26286	88	23089	1189	62	0%	23:59:56
7	news.redatomik.org	23760	46	22906	10	58	0%	23:59:56
8	aioe	21295	39	20154	5	0	0%	23:59:55
9	eternal-september	21324	28	19865	0	1	0%	23:59:34
10	weretis.net	16707	14	16405	2	0	0%	23:59:50
11	news.swapon.de	2048	11	2012	0	0	0%	23:59:06
12	news.mixmin.net	22392	11	21861	0	0	0%	23:59:56
13	neva.ru	22956	10	22176	10	0	0%	23:59:56
14	news.fcku.it	2677	3	2634	0	0	0%	22:18:07
15	erje	18016	2	17835	20	2	0%	23:59:56
16	au2pb	0	0	0	0	23988	0%	23:58:42
17	bwh	0	0	0	0	23724	0%	23:59:33
TOTAL: 17		319878	8441	279240	1388	47838	2%	406:13:46

Outgoing Feeds (innfeed) by Volume:

Server		AcceptVol	RejectVol	TotalVol	Volume/sec	Vol/Art	Elapsed
1	news.bbs.geek.nz	16.4 MB	679.2 KB	17.0 MB	0.2 KB/s	2.8 KB	23:59:38
2	news.freedyn.net	6.3 MB	187.8 KB	6.5 MB	0.1 KB/s	9.6 KB	23:59:53
3	xanadu-bbs	5.9 MB	6.8 KB	5.9 MB	0.1 KB/s	8.0 KB	23:59:56
4	fu-berlin.de	5.3 MB	0.0 KB	5.3 MB	0.1 KB/s	9.7 KB	23:59:56
5	usenet.pasdenom.info	305.9 KB	7.4 MB	7.7 MB	0.1 KB/s	6.2 KB	23:59:56
6	xmission	274.4 KB	27.8 KB	302.2 KB	0.0 KB/s	2.4 KB	23:59:56
7	news.redatomik.org	257.2 KB	136.1 KB	393.3 KB	0.0 KB/s	7.0 KB	23:59:56
8	aioe	101.6 KB	24.6 KB	126.2 KB	0.0 KB/s	2.9 KB	23:59:55
9	eternal-september	98.7 KB	0.0 KB	98.7 KB	0.0 KB/s	3.5 KB	23:59:34
10	weretis.net	22.4 KB	40.3 KB	62.7 KB	0.0 KB/s	3.9 KB	23:59:50
11	neva.ru	13.8 KB	22.6 KB	36.4 KB	0.0 KB/s	1.8 KB	23:59:56
12	news.mixmin.net	13.0 KB	0.0 KB	13.0 KB	0.0 KB/s	1.2 KB	23:59:56
13	news.swapon.de	13.0 KB	0.0 KB	13.0 KB	0.0 KB/s	1.2 KB	23:59:06
14	news.fcku.it	8.3 KB	0.0 KB	8.3 KB	0.0 KB/s	2.8 KB	22:18:07
15	erje	2.4 KB	96.5 KB	98.9 KB	0.0 KB/s	4.5 KB	23:59:56
16	au2pb	0.0 KB	0.0 KB	0.0 KB	0.0 KB/s	0	23:58:42
17	bwh	0.0 KB	0.0 KB	0.0 KB	0.0 KB/s	0	23:59:33
TOTAL: 17		35.0 MB	8.6 MB	43.6 MB	0.0 KB/s	4.5 KB	406:13:46

NNRP readership statistics:

System		Conn	Arts	Size	Groups	Post	Rej	Elapsed
1	68-185-181-64.dhcp.mdsn.wi.charter.com	29	15	19.5 KB	12	10	8	07:21:03
2	dhcp-089-099-203-254.chello.nl	52	15	19.4 KB	6	0	0	15:16:15
3	tempe0.bbox.io	18	6	8.2 KB	1	0	0	04:31:12
4	mtrlpq2314w-lp130-01-70-49-68-214.dsl.bell.ca	40	5	24.1 KB	5	0	0	01:14:54
5	194-73-239-109.cust.centrio.cz	9	1	1.7 KB	1	0	0	01:41:01
TOTAL: 5		148	42	72.9 KB	25	10	8	77:50:31

NNRP readership statistics (by domain):

System		Conn	Arts	Size	Groups	Post	Rej	Elapsed
1	*.dhcp.mdsn.wi.charter.com	29	15	19.5 KB	12	10	8	07:21:03
2	*.chello.nl	52	15	19.4 KB	6	0	0	15:16:15
3	*.bbox.io	18	6	8.2 KB	1	0	0	04:31:12
4	*.dsl.bell.ca	40	5	24.1 KB	5	0	0	01:14:54
5	*.cust.centrio.cz	9	1	1.7 KB	1	0	0	01:41:01
6	unresolved	97	0	0.0 KB	0	0	0	47:46:03
TOTAL: 6		245	42	72.9 KB	25	10	8	77:50:31

NNRP auth users [Top 20]:

User	Conn
ohlandl	8
ctomczyk	5
TOTAL: 2	13

NNRP total resource statistics [Top 20]:

System	User(ms)	System(ms)	Idle(ms)	Elapsed
216.239.174.218	7.183	1.914	0.000	47:46:03
dhcp-089-099-203-254.chello.nl	4.173	1.216	0.000	15:16:15
68-185-181-64.dhcp.mdsn.wi.charter.com	2.783	0.793	0.026	07:21:03
tempe0.bbox.io	1.540	0.306	0.000	04:31:12
194-73-239-109.cust.centrio.cz	0.740	0.180	0.019	01:41:01
mtrlpq2314w-lp130-01-70-49-68-214.dsl.bell.ca	3.953	0.845	0.000	01:14:54
TOTAL: 6	20.372	5.254	0.045	77:50:31

Curious NNRP server explorers [Top 20]:

System	Conn
216.239.174.218	97
TOTAL: 1	97

NNRP client timeouts [Top 20]:

System	Conn	Peer
216.239.174.218	94	0
68-185-181-64.dhcp.mdsn.wi.charter.com	8	0
tempe0.bbox.io	8	0
194-73-239-109.cust.centrio.cz	3	0
mtrlpq2314w-lp130-01-70-49-68-214.dsl.bell.ca	2	0
TOTAL: 5	115	0

Newsgroup request counts (by category):

Category		Count	Pct
1	comp	37	88.1%
2	alt	3	7.1%
3	linux	1	2.4%
4	talk	1	2.4%
TOTAL: 4		42	100.0%

Newsgroup request counts (by newsgroup) [Top 100]:

Newsgroup		Count
1	comp.sys.ibm.ps2.hardware	36
2	alt.comp.freeware	1
3	alt.life.sucks	1
4	talk.politics.misc	1
5	comp.lang.javascript	1
6	alt.christnet.christianlife	1
7	linux.kernel	1
TOTAL: 7		42

Daily Usenet report for csiph.com

Jan 31 04:15:00 -- Feb 1 04:15:00