Article delegate-en/4042 of [1-5169] on the server localhost:119
  upper oldest olders older1 this newer1 newers latest
search
[Top/Up] [oldest] - [Older+chunk] - [Newer+chunk] - [newest + Check]
[Reference:<_A4039@delegate-en.ML_>]
Newsgroups: mail-lists.delegate-en

[DeleGate-En] Re: NNTP-Delegate will not cache in Linux
04 Aug 2008 19:36:00 GMT Jeff <pyqhqbdyi-mnvdjl4kcrfr.ml@ml.delegate.org>


Hi Yutaka,

Ok I have tried what you said I should try. Testing using the "simple
method" does indeed write the article to the cache on the drive. However,
testing with a typical NNTP client seems to not have the same result. I
can't confirm in the simple test if it is serving from the cache (there are
CACHE lines in the log, but I can't make out if they are cache in or cache
out).

I'm finding different results for using a typical NNTP download client
versus the telnet approach. I'm not sure if that is relevant - BUT I want it
to work with all clients.

It is not a local server as you will see in the logs below (though I am
using a private IP address range on the local network).

Config used:
DGOPTS="-S;-P2299"
DGROOT=/var/delegate/dgtesting
OWNER=news/news
SERVER=nntp
CACHE=do
CACHEDIR=/var/delegate/dgtesting/cache
MOUNT="= nntp://serverIP:1219/ rw,nonlocal"
TMPDIR=/var/delegate/dgtesting/tmp
CONNECT=cache,direct
PERMIT=*:*:.localnet,*

Here are some log extracts that I think might help:

serverIP denotes the content source (remote NNTP server)
serverFQDN = FQDN of serverIP
client IP replaced with kac-002054 (client IP = 172.17.2.133)
proxy IP (NNTP proxy) = 172.17.2.132

Initialisation ->
08/04 21:02:02.06 [11172] 0+0: PORT= 2299/8 (8,251)
08/04 21:02:02.06 [11172] 0+0: OWNER=news/news => OWNER=news/news(news/news)
08/04 21:02:02.06 [11172] 0+0: SPECIALIST: nntp
08/04 21:02:02.06 [11172] 0+0: ##DeleGate/6.X: MIMECONV=thru is set by
default. MIMECONV="" will make it compatible with former versions.
08/04 21:02:02.06 [11172] 0+0:
dirfopen(/var/delegate/dgtesting/log/errors.log.1,a): 83fe2b0 [9]
08/04 21:02:02.06 [11172] 0+0: #### newRoute[NOTIFYPLTFM] 0/16
08/04 21:02:02.06 [11172] 0+0: [0] NOTIFYPLTFM=://:0-_-{}:{}
08/04 21:02:02.06 [11172] 0+0: default netmask 127.0.1.1/. = FFFFFF00
08/04 21:02:02.06 [11172] 0+0: #### newRoute[REMITTABLE] 0/16
08/04 21:02:02.06 [11172] 0+0: [0] REMITTABLE={}{nntp,nntps,news}:{*}:{*}
08/04 21:02:02.06 [11172] 0+0: REMITTABLE = nntp,nntps,news
08/04 21:02:02.06 [11172] 0+0: #### newRoute[PERMIT] 0/16
08/04 21:02:02.06 [11172] 0+0: [0]
PERMIT={}{nntp,nntps,news}:{*}:{.localnet,*}
08/04 21:02:02.06 [11172] 0+0: #### newRoute[CMAP] 0/16
08/04 21:02:02.06 [11172] 0+0: [0]
CMAP={delegate,vhost,nojava}relay{*}:{*}:{.localnet}
08/04 21:02:02.06 [11172] 0+0: #### newRoute[CMAP] 1/16
08/04 21:02:02.06 [11172] 0+0: [1] CMAP={proxy}relay{*}:{*}:{*}
08/04 21:02:02.06 [11172] 0+0: ### [0] /var/delegate/dgtesting/etc/dglibz.so
0
08/04 21:02:02.06 [11172] 0+0: ### [1] /var/delegate/dgtesting/lib/dglibz.so
0
08/04 21:02:02.06 [11172] 0+0: ### [2] /var/delegate/./dglibz.so 0
08/04 21:02:02.06 [11172] 0+0: ### [3] /var/delegate/dglibz.so 0
08/04 21:02:02.13 [11172] 0+0: ### [4] /root/lib/dglibz.so 0
08/04 21:02:02.13 [11172] 0+0: ### [5] /usr/local/lib/dglibz.so 0
08/04 21:02:02.13 [11172] 0+0: ### [6] /usr/lib/dglibz.so 0
08/04 21:02:02.13 [11172] 0+0: ### [7] /lib/dglibz.so 0
08/04 21:02:02.13 [11172] 0+0: --- [z] 0 dglibz.so
08/04 21:02:02.13 [11172] 0+0: ### [0]
/var/delegate/dgtesting/etc/libz.so.0.9.8 0
08/04 21:02:02.13 [11172] 0+0: ### [1]
/var/delegate/dgtesting/lib/libz.so.0.9.8 0
08/04 21:02:02.13 [11172] 0+0: ### [2] /var/delegate/./libz.so.0.9.8 0
08/04 21:02:02.13 [11172] 0+0: ### [3] /var/delegate/libz.so.0.9.8 0
08/04 21:02:02.13 [11172] 0+0: ### [4] /root/lib/libz.so.0.9.8 0
08/04 21:02:02.14 [11172] 0+0: ### [5] /usr/local/lib/libz.so.0.9.8 0
08/04 21:02:02.14 [11172] 0+0: ### [6] /usr/lib/libz.so.0.9.8 0
08/04 21:02:02.14 [11172] 0+0: ### [7] /lib/libz.so.0.9.8 0
08/04 21:02:02.14 [11172] 0+0: --- [z] 0 libz.so.0.9.8
08/04 21:02:02.14 [11172] 0+0: ### [0] /var/delegate/dgtesting/etc/libz.so 0
08/04 21:02:02.14 [11172] 0+0: ### [1] /var/delegate/dgtesting/lib/libz.so 0
08/04 21:02:02.14 [11172] 0+0: ### [2] /var/delegate/./libz.so 0
08/04 21:02:02.14 [11172] 0+0: ### [3] /var/delegate/libz.so 0
08/04 21:02:02.14 [11172] 0+0: ### [4] /root/lib/libz.so 0
08/04 21:02:02.14 [11172] 0+0: ### [5] /usr/local/lib/libz.so 0
08/04 21:02:02.14 [11172] 0+0: ### [6] /usr/lib/libz.so 0
08/04 21:02:02.14 [11172] 0+0: ### [7] /lib/libz.so 0
08/04 21:02:02.14 [11172] 0+0: --- [z] 0 libz.so
08/04 21:02:02.14 [11172] 0+0: ### [0] /var/delegate/dgtesting/etc/libz.so.1
0
08/04 21:02:02.14 [11172] 0+0: ### [1] /var/delegate/dgtesting/lib/libz.so.1
0
08/04 21:02:02.14 [11172] 0+0: ### [2] /var/delegate/./libz.so.1 0
08/04 21:02:02.14 [11172] 0+0: ### [3] /var/delegate/libz.so.1 0
08/04 21:02:02.14 [11172] 0+0: ### [4] /root/lib/libz.so.1 0
08/04 21:02:02.14 [11172] 0+0: ### [5] /usr/local/lib/libz.so.1 0
08/04 21:02:02.14 [11172] 0+0: ### [6] /usr/lib/libz.so.1 8419db8
08/04 21:02:02.14 [11172] 0+0: --- [/usr/lib/libz.so.1]
08/04 21:02:02.14 [11172] 0+0: --- [z] 83FA798 /usr/lib/libz.so.1
08/04 21:02:02.14 [11172] 0+0: --- [z] optional: gziocallback
08/04 21:02:02.14 [11172] 0+0: ---- [z] loaded 17 syms, unknown=0+1,
already=0
08/04 21:02:02.14 [11172] 0+0: +++ loaded Zlib 1.2.3.3
08/04 21:02:02.14 [11172] 0+0: #### gzip/gunzip = dynamically linked
08/04 21:02:02.14 [11172] 0+0: ADMIN=nntp@server protocol=nntp(specialist)
08/04 21:02:02.14 [11172] 0+0: #### newRoute[CMAP] 2/16
08/04 21:02:02.14 [11172] 0+0: [2] CMAP={30d}expire{*}:{*}:{*}
08/04 21:02:02.14 [11172] 0+0: = nntp://server:1219/ rw,nonlocal
08/04 21:02:02.14 [11172] 0+0: MOUNT[0]X[3] /-/builtin/icons/* = default
08/04 21:02:02.14 [11172] 0+0: MOUNT[1]X[4] /-/* =
forbidden,from=!.RELIABLE,default
08/04 21:02:02.14 [11172] 0+0: MOUNT[2]X[0] /-* = default
08/04 21:02:02.14 [11172] 0+0: MOUNT[3]X[1] /=* = default
08/04 21:02:02.14 [11172] 0+0: MOUNT[4]X[2] =
nntp://196.25.44.66:1219/rw,nonlocal
08/04 21:02:02.14 [11172] 0+0: MOUNT[5]=[5] = nntp://-/* default
08/04 21:02:02.14 [11172] 0+0: S[server:1219] = UP[]U[]P[] +
HP[196.25.44.66:1219]H[196.25.44.66]P[1219]
08/04 21:02:02.14 [11172] 0+0: MOUNT HOST serverIP=serverIP
08/04 21:02:02.15 [11172] 0+0: *** gethostbyaddr(serverIP): serverFQDN /
0.01 secs. has_alias:0
08/04 21:02:02.15 [11172] 0+0: HOSTS[4]=
08/04 21:02:02.15 [11172] 0+0: [4] MOUNT== nntp://serverIP[serverIP]:1219/
rw,nonlocal
08/04 21:02:02.15 [11172] 0+0: S[-] = UP[]U[]P[] + HP[-]H[-]P[]
08/04 21:02:02.15 [11172] 0+0: MOUNT HOST -=
08/04 21:02:02.15 [11172] 0+0: [5] MOUNT== nntp://-[]:119/ default
08/04 21:02:02.15 [11172] 0+0: #### newRoute[CMAP] 3/16
08/04 21:02:02.15 [11172] 0+0: [3] CMAP={30d}expire{*}:{*}:{*}
08/04 21:02:02.15 [11172] 0+0:
dirfopen(/var/delegate/dgtesting/act/pid/2299,w+): 843cf90 [10]
08/04 21:02:02.15 [11172] 0+0: #{TR}# START accepting SIGCHLD
08/04 21:02:02.15 [11172] 0+0: StickyReport[10,11]127.0.0.127:65535><
127.0.0.127:65535 110592/110592 110592/110592
08/04 21:02:02.15 [11172] 0+0: env[35]
LIBPATH=.;/var/delegate;/var/spool/delegate-nobody/lib;/var/delegate/.;/var/spool/delegate-nobody/etc
08/04 21:02:02.15 [11172] 0+0: env[39] RESOLV=cache,file,dns,sys
08/04 21:02:02.15 [11172] 0+0: ext[0] DGOPTS=-S;-P2299
08/04 21:02:02.15 [11172] 0+0: ext[1] DGROOT=/var/delegate/dgtesting
08/04 21:02:02.15 [11172] 0+0: ext[2] ADMIN=
08/04 21:02:02.15 [11172] 0+0: ext[3] OWNER=news/news
08/04 21:02:02.15 [11172] 0+0: ext[4] SERVER=nntp
08/04 21:02:02.15 [11172] 0+0: ext[5] CACHE=do
08/04 21:02:02.15 [11172] 0+0: ext[6] CACHEDIR=/var/delegate/dgtesting/cache
08/04 21:02:02.15 [11172] 0+0: ext[7] MOUNT== nntp://serverIP:1219/
rw,nonlocal
08/04 21:02:02.15 [11172] 0+0: ext[8] TMPDIR=/var/delegate/dgtesting/tmp
08/04 21:02:02.15 [11172] 0+0: ext[9] NNTPCONF=xover:2000
08/04 21:02:02.15 [11172] 0+0: ext[10] LOGFILE=${PORT}[date+.%H]
08/04 21:02:02.15 [11172] 0+0: ext[11] PROTOLOG=${PORT}.${PROTO}[date+.%H]
08/04 21:02:02.15 [11172] 0+0: ext[12] ERRORLOG=errors.log[date+.%w]
08/04 21:02:02.15 [11172] 0+0: ext[13] MAXIMA=nntpcc:50,delegated:100
08/04 21:02:02.15 [11172] 0+0: ext[14] CONNECT=cache,direct
08/04 21:02:02.15 [11172] 0+0: ext[15] TIMEOUT=nntpcc:10,io:30,shutout:10
08/04 21:02:02.15 [11172] 0+0: ext[16] EXPIRE=30d
08/04 21:02:02.15 [11172] 0+0: ext[17] PERMIT=*:*:.localnet,*
08/04 21:02:02.15 [11172] 0+0: TMPFILE(setLastModified) = (12)
/var/delegate/dgtesting/tmp/dg11172.000003.1217876522
08/04 21:02:02.15 [11172] 0+0: >>>TMPFILE(setLastModified)>>>843cf90[12]
08/04 21:02:02.15 [11172] 0+0:
dirfopen(/var/delegate/dgtesting/etc/params/2299,r): 843d158 [13]
08/04 21:02:02.15 [11172] 0+0: DELEGATE_Modified[0]: 489748ef 1217874159
08/04 21:02:02.15 [11172] 0+0: Accept-LOCK: 0
08/04 21:02:02.15 [11172] 0+0: --INITIALIZATION DONE-08080421+0200:
9.8.4-pre3 on Linux/2.6.24-19-generic--

First download ->

08/04 21:05:19.90 [11172] 1+0:
dirfopen(/var/spool/delegate-nobody/act/restart/_2299_,r): 0 [-1]
08/04 21:05:19.90 [11279] 1+0: SPECIALIST: nntp
08/04 21:05:19.90 [11279] 1+0: CONNECT={cd}:{*}:{*}:{*}
08/04 21:05:19.90 [11279] 1+0: #### newRoute[CONNECT] 0/16
08/04 21:05:19.90 [11279] 1+0: [0] CONNECT={}{*}:{*}:{*}
08/04 21:05:19.90 [11279] 1+0: #### newRoute[CMAP] 4/16
08/04 21:05:19.90 [11279] 1+0: [4] CMAP={30d}expire{*}:{*}:{*}
08/04 21:05:19.90 [11279] 1+0: #### newRoute[USERIDENT] 0/16
08/04 21:05:19.90 [11279] 1+0: [0] USERIDENT=://:0-_-{}:{}
08/04 21:05:19.90 [11279] 1+0:
dirfopen(/var/spool/delegate-nobody/act/clients/11/172.17.2.133:kac-002054,w+):
0 [-1]
08/04 21:05:19.90 [11279] 1+0: #### countUp can't open w+
[/var/spool/delegate-nobody/act/clients/11/172.17.2.133:kac-002054]
08/04 21:05:19.90 [11279] 1+0: (0) accepted [49]
-@[172.17.2.133]kac-002054:2397
(1210000000.00Xs)(-1)
08/04 21:05:19.90 [11279] 1+0:
dirfopen(/var/spool/delegate-nobody/adm/shutout/172.17.2.133,r): 0 [-1]
08/04 21:05:19.90 [11279] 1+0:
dirfopen(/var/spool/delegate-nobody/adm/shutout/172.17.2.133,r): 0 [-1]
08/04 21:05:19.90 [11279] 1+0: KeepAlive[49] = 1
08/04 21:05:19.91 [11279] 1+0: execGeneralist->execSpecialist
08/04 21:05:19.91 [11279] 1+0: PATH:
nntp://-:119!falcon:2299!kac-002054:2397!anonymous@kac-002054;1217876719
08/04 21:05:19.92 [11279] 1+0: setsockbuf[49] in:0->0 out:16384->32768
08/04 21:05:19.92 [11279] 1+0: #### newRoute[RELIABLE] 0/16
08/04 21:05:19.92 [11279] 1+0: [0] RELIABLE=://:0-_-{}:{}
08/04 21:05:19.92 [11279] 1+0: #### newRoute[REACHABLE] 0/16
08/04 21:05:19.92 [11279] 1+0: [0] REACHABLE=://:0-_-{}:{}
08/04 21:05:19.92 [11279] 1+0: PERMITTED: nntp://serverIP
08/04 21:05:19.92 [11279] 1+0:
dirfopen(/var/delegate/dgtesting/act/servers/cc/nntp-anonymous-serverIP-1219-0,r+):
0 [-1]
08/04 21:05:19.92 [11279] 1+0: -[0,0]- TRY CACHE ...
08/04 21:05:19.92 [11279] 1+0: -[0,1]- TRY DIRECT ...
08/04 21:05:19.92 [11279] 1+0: ConnectToServer connect nntp://serverIP:1219
08/04 21:05:19.92 [11172] 1+0: AcceptByMain: start polling(15000)[10]...
08/04 21:05:20.01 [11279] 1+0: connect[8] ready=1, err=0
08/04 21:05:20.01 [11279] 1+0: ConnectToServer connected [8] {serverIP:1219
<- 172.17.2.132:45718} [0.097s]
08/04 21:05:20.01 [11279] 1+0: KeepAlive[8] = 1
08/04 21:05:20.01 [11279] 1+0: willSTLS_SV: ServerFlags=0
08/04 21:05:20.01 [11279] 1+0: NNTP-LOGIN; from=kac-002054;
to=serverIP:1219; ACCEPTED
08/04 21:05:20.01 [11279] 1+0: FQDN:
08/04 21:05:20.01 [11279] 1+0: [0] newServer = nntp://serverIP:1219
08/04 21:05:20.01 [11279] 1+0: islocal = 0
08/04 21:05:20.01 [11279] 1+0: CACHE hostname: serverIP -> (removed)
08/04 21:05:20.01 [11279] 1+0: CACHE:
`/var/delegate/dgtesting/cache/$[server:%P/%L/%p]'
08/04 21:05:20.01 [11279] 1+0: CACHE:
`/var/delegate/dgtesting/cache/nntp/serverFQDN:1219/LIST/active'
08/04 21:05:20.01 [11279] 1+0: setLISTcache: private=0 created=0 TIMEOFF=0
/var/delegate/dgtesting/cache/nntp/serverFQDN:1219/LIST/active
08/04 21:05:20.02 [11279] 1+0: [0][0] = <=> nntp://:@serverIP:1219/
08/04 21:05:20.02 [11279] 1+0: MOUNT[0] serverIP[1]
08/04 21:05:20.02 [11279] 1+0: MOUNT[0] serverIP[1] rw
08/04 21:05:20.02 [11279] 1+0: TMPFILE(NNTP-AUTHORIZER) = (18)
/var/delegate/dgtesting/tmp/dg11279.000004.1217876720
08/04 21:05:20.02 [11279] 1+0: >>>TMPFILE(NNTP-AUTHORIZER)>>>845b7a8[18]
08/04 21:05:20.02 [11279] 1+0: #### no authorization required
08/04 21:05:20.02 [11279] 1+0: ## DGAuth: No such user [creysalt] in
-dgauth@admin auth.
08/04 21:05:20.02 [11279] 1+0: Will not retry DigestPass: No creysalt
08/04 21:05:20.77 [11279] 1+0: ## S-C 200 News.GigaNews.Com [][]
08/04 21:05:20.77 [11279] 1+0: NNTP[0]+0  [] > 200 News.GigaNews.Com^M
08/04 21:05:20.77 [11279] 1+0: ## S-C 200 News.GigaNews.Com^M
08/04 21:05:20.77 [11279] 1+0: CACHE hostname: serverIP -> serverFQDN
08/04 21:05:20.77 [11279] 1+0: CACHE:
`/var/delegate/dgtesting/cache/$[server:%P/%L/%p]'
08/04 21:05:20.77 [11279] 1+0: CACHE:
`/var/delegate/dgtesting/cache/nntp/serverFQDN:1219/lib/opening'
08/04 21:05:20.77 [11279] 1+0:
dirfopen(/var/delegate/dgtesting/cache/nntp/serverFQDN:1219/lib/opening,r):
845b9c0 [18]
08/04 21:05:20.77 [11279] 1+0: age=798 timeoff=0
/var/delegate/dgtesting/cache/nntp/serverFQDN:1219/lib/opening
08/04 21:05:20.77 [11279] 1+0:
dirfopen(/var/delegate/dgtesting/cache/nntp/serverFQDN:1219/lib/opening,w):
845b9c0 [18]
08/04 21:05:20.77 [11279] 1+0: CACHE:
`/var/delegate/dgtesting/adm/attrs/$[server:%P/%L/%p]'
08/04 21:05:20.77 [11279] 1+0: CACHE:
`/var/delegate/dgtesting/adm/attrs/nntp/serverIP:1219/'
08/04 21:05:20.77 [11279] 1+0:
dirfopen(/var/delegate/dgtesting/adm/attrs/nntp/serverIP:1219/#attr,r): 0
[-1]
08/04 21:05:20.77 [11279] 1+0: CACHE:
`/var/delegate/dgtesting/adm/attrs/$[server:%P/%L/%p]'
08/04 21:05:20.77 [11279] 1+0: CACHE:
`/var/delegate/dgtesting/adm/attrs/nntp/serverIP:0000//000/0X'
08/04 21:05:20.77 [11279] 1+0:
dirfopen(/var/delegate/dgtesting/adm/attrs/nntp/serverIP:0000//000/0X#attr,r):
0 [-1]
08/04 21:05:20.77 [11279] 1+0: 200 response done (decode=-1).
20080804-210520 11279 -x7wwdbtdz6dw kac-002054 - 200 :0 ""
08/04 21:05:20.77 [11279] 1+0: DO_INIT
08/04 21:05:20.77 [11279] 1+0: getting HELP from serverIP...
08/04 21:05:21.38 [11279] 1+0: ## S-C 100 help (GC 3.1.55) [][]
08/04 21:05:21.38 [11279] 1+0: ## got HELP:
100 help (GC 3.1.55)^M
  ARTICLE [<msgid>|number]^M
  AUTHINFO type value^M
  BODY [<msgid>|number]^M
  DATE^M
  GROUP newsgroup^M
  HEAD [<msgid>|number]^M
  HELP^M
  LAST^M
  LIST^M
  LISTGROUP newsgroup^M
  MODE READER^M
  NEWGROUPS yyyymmdd hhmmss [GMT]^M
  NEWNEWS newsgroups yyyymmdd hhmmss [GMT]^M
  NEXT^M
  POST^M
  STAT^M
  XHDR field range^M
  XOVER range^M
  XPAT field range pattern^M
  QUIT^M
##### NNTP proxy information #### BEGIN^M
NNTP-DeleGate/9.8.4-pre3 (July 31, 2008)^M
XLIST [difference]  -- LIST ACTIVE by delta.^M
XCACHE FETCH|EXPIRE [range|yymmdd hhmmss|message-id]^M
Report problems to <testing@za..>^M
AIST-Product-ID: 2000-ETL-198715-01, H14PRO-049, H15PRO-165, H18PRO-443^M
Copyright (c) 1994-2000 Yutaka Sato and ETL,AIST,MITI^M
Copyright (c) 2001-2008 National Institute of Advanced Industrial Science
and Technology (AIST)^M
WWW: http://www.delegate.org/delegate/^M
##### NNTP proxy information #### END^M
08/04 21:05:21.38 [11279] 1+0: CACHE hostname:
08/04 21:05:21.38 [11279] 1+0: CACHE:
`/var/delegate/dgtesting/cache/$[server:%P/%L/%p]'
08/04 21:05:21.38 [11279] 1+0: CACHE:
`/var/delegate/dgtesting/cache/nntp/serverFQDNserverFQDN:1219/lib/HELP'
08/04 21:05:21.38 [11279] 1+0:
dirfopen(/var/delegate/dgtesting/cache/nntp/serverFQDN:1219/lib/HELP,r):
846bd88 [18]
08/04 21:05:21.38 [11279] 1+0: age=796 timeoff=0
/var/delegate/dgtesting/cache/nntp/serverFQDN:1219/lib/HELP
08/04 21:05:21.38 [11279] 1+0:
dirfopen(/var/delegate/dgtesting/cache/nntp/serverFQDN:1219/lib/HELP,w):
846bd88 [18]
08/04 21:05:21.38 [11279] 1+0: CACHE:
`/var/delegate/dgtesting/cache/$[server:%P/%L/%p]'
08/04 21:05:21.38 [11279] 1+0: CACHE:
`/var/delegate/dgtesting/cache/nntp/serverFQDN:1219/lib/wildmat'
08/04 21:05:21.38 [11279] 1+0: age=2522 timeoff=0
/var/delegate/dgtesting/cache/nntp/serverFQDN:1219/lib/wildmat
08/04 21:05:22.30 [11279] 1+0: ## S-C 215 List follows. [][]
08/04 21:05:22.30 [11279] 1+0:
dirfopen(/var/delegate/dgtesting/cache/nntp/serverFQDN:1219/lib/wildmat,w):
846bd88 [18]
08/04 21:05:22.30 [11279] 1+0: CACHE:
`/var/delegate/dgtesting/cache/$[server:%P/%L/%p]'
08/04 21:05:22.30 [11279] 1+0: CACHE:
`/var/delegate/dgtesting/cache/nntp/serverFQDN:1219/LIST/active'
08/04 21:05:22.30 [11279] 1+0: CLOSE previous cache: private=0 TIMEOFF=0
/var/delegate/dgtesting/cache/nntp/serverFQDN:1219/LIST/active
08/04 21:05:22.30 [11279] 1+0: setLISTcache: private=0 created=0 TIMEOFF=0
/var/delegate/dgtesting/cache/nntp/serverFQDN:1219/LIST/active
08/04 21:05:22.30 [11279] 1+0: with LIST ACTIVE [wildmat] =
/var/delegate/dgtesting/cache/nntp/serverFQDN:1219/LIST/active
08/04 21:05:22.30 [11279] 1+0: CACHE hostname: serverIP -> serverFQDN
08/04 21:05:22.30 [11279] 1+0: CACHE:
`/var/delegate/dgtesting/cache/$[server:%P/%L/%p]'
08/04 21:05:22.30 [11279] 1+0: CACHE:
`/var/delegate/dgtesting/cache/nntp/serverFQDN:1219/lib/pathhost'
08/04 21:05:22.30 [11279] 1+0: age=2521 timeoff=0
/var/delegate/dgtesting/cache/nntp/serverFQDN:1219/lib/pathhost
08/04 21:05:22.30 [11279] 1+0: checking pathhost of serverIP in junk...
08/04 21:05:22.51 [11279] 1+0: ## S-C 211 581265 423812 1005076 junk [][]
08/04 21:05:22.83 [11279] 1+0: ## S-C 000 00000X <0.1056783287@funet..fi>
[][]
08/04 21:05:24.31 [11279] 1+0: ## S-C 000 00000X <0.1056783287@funet..fi>
[][]
08/04 21:05:24.31 [11279] 1+0:
dirfopen(/var/delegate/dgtesting/cache/nntp/serverFQDN:1219/lib/pathhost,w):
846bdc0 [18]
08/04 21:05:24.31 [11279] 1+0: automatic NNTPCONF=pathhost:serverIP/
news5.aus1.giganews.com
08/04 21:05:24.31 [11279] 1+0: ## C-S body <65211$4895b8f2$5b79aabb$
9255@news.usenext.de>^M
08/04 21:05:24.32 [11279] 1+0: CACHE:
`/var/delegate/dgtesting/cache/$[server:%P/%L/%p]'
08/04 21:05:24.32 [11279] 1+0: CACHE:
`/var/delegate/dgtesting/cache/nntp/all/de/usenext/news/65211$4895b8f2$5b79aabb$9255'
08/04 21:05:24.32 [11279] 1+0: put[0] body <65211$4895b8f2$5b79aabb$
9255@news.usenext.de>^M
08/04 21:05:25.38 [11279] 1+0/1: ## S-C 222 0 <65211$4895b8f2$5b79aabb$
9255@news.usenext.de> [][body <65211$4895b8f2$5b79aabb$9255@news.usenext.de
>]
08/04 21:05:25.38 [11279] 1+0/1: NNTP[0]+0  [] > 222 0
<65211$4895b8f2$5b79aabb$9255@news.usenext.de>^M
08/04 21:05:25.38 [11279] 1+0/1: CACHE:
`/var/delegate/dgtesting/adm/attrs/$[server:%P/%L/%p]'
08/04 21:05:25.38 [11279] 1+0/1: CACHE:
`/var/delegate/dgtesting/adm/attrs/nntp/serverIP:1219/'
08/04 21:05:25.38 [11279] 1+0/1:
dirfopen(/var/delegate/dgtesting/adm/attrs/nntp/serverIP:1219/#attr,r): 0
[-1]
08/04 21:05:25.38 [11279] 1+0/1: CACHE:
`/var/delegate/dgtesting/adm/attrs/$[server:%P/%L/%p]'
08/04 21:05:25.38 [11279] 1+0/1: CACHE:
`/var/delegate/dgtesting/adm/attrs/nntp/serverIP:0000//000/0X'
08/04 21:05:25.38 [11279] 1+0/1:
dirfopen(/var/delegate/dgtesting/adm/attrs/nntp/serverIP:0000//000/0X#attr,r):
0 [-1]
08/04 21:05:26.21 [11279] 1+0/1: TMPFILE(readPart) = (18)
/var/delegate/dgtesting/tmp/dg11279.000005.1217876726
08/04 21:05:26.21 [11279] 1+0/1: >>>TMPFILE(readPart)>>>846bdf8[18]
08/04 21:05:34.92 [11172] 1+0: AcceptByMain: TIMEOUT(children=1, timeout=15)
08/04 21:05:34.92 [11172] 1+0: MAX_DELEGATEP 100 (1)32 64 >>> 100
08/04 21:05:34.92 [11172] 1+0: MAX_DELEGATEP 100 (1)32 64 >>> 100
08/04 21:05:34.92 [11172] 1+0:
dirfopen(/var/spool/delegate-nobody/act/restart/_2299_,r): 0 [-1]
08/04 21:05:34.92 [11172] 1+0: AcceptByMain: start polling(15000)[10]...
08/04 21:05:37.31 [11279] 1+0/1: ### readPart: got large message (396209)
08/04 21:05:37.32 [11279] 1+0/1: 222 response done (decode=2).
20080804-210537 11279 -x7wwdbtdz6dw kac-002054 - 222 :0 "body
<65211$4895b8f2$5b79aabb$9255@news.usenext.de>"
08/04 21:05:37.33 [11279] 1+0/1: ## C-S body <bae4c$4895b8f2$5b79aabb$
9255@news.usenext.de>^M
08/04 21:05:37.33 [11279] 1+0/1: CACHE:
`/var/delegate/dgtesting/cache/$[server:%P/%L/%p]'
08/04 21:05:37.33 [11279] 1+0/1: CACHE:
`/var/delegate/dgtesting/cache/nntp/all/de/usenext/news/bae4c$4895b8f2$5b79aabb$9255'
08/04 21:05:37.33 [11279] 1+0/1: put[0] body <bae4c$4895b8f2$5b79aabb$
9255@news.usenext.de>^M
08/04 21:05:39.12 [11279] 1+0/2: ## S-C 222 0 <bae4c$4895b8f2$5b79aabb$
9255@news.usenext.de> [][body <bae4c$4895b8f2$5b79aabb$9255@news.usenext.de
>]
08/04 21:05:39.13 [11279] 1+0/2: NNTP[0]+0  [] > 222 0
<bae4c$4895b8f2$5b79aabb$9255@news.usenext.de>^M
08/04 21:05:39.13 [11279] 1+0/2: CACHE:
`/var/delegate/dgtesting/adm/attrs/$[server:%P/%L/%p]'
08/04 21:05:39.13 [11279] 1+0/2: CACHE:
`/var/delegate/dgtesting/adm/attrs/nntp/serverIP:1219/'
08/04 21:05:39.13 [11279] 1+0/2:
dirfopen(/var/delegate/dgtesting/adm/attrs/nntp/serverIP:1219/#attr,r): 0
[-1]
08/04 21:05:39.13 [11279] 1+0/2: CACHE:
`/var/delegate/dgtesting/adm/attrs/$[server:%P/%L/%p]'
08/04 21:05:39.13 [11279] 1+0/2: CACHE:
`/var/delegate/dgtesting/adm/attrs/nntp/serverIP:0000//000/0X'
08/04 21:05:39.13 [11279] 1+0/2:
dirfopen(/var/delegate/dgtesting/adm/attrs/nntp/serverIP:0000//000/0X#attr,r):
0 [-1]
08/04 21:05:41.40 [11279] 1+0/2: TMPFILE(readPart) = (18)
/var/delegate/dgtesting/tmp/dg11279.000006.1217876741
08/04 21:05:41.40 [11279] 1+0/2: >>>TMPFILE(readPart)>>>846bdf8[18]
08/04 21:05:46.37 [11279] 1+0/2: ### readPart: got large message (396180)
08/04 21:05:46.38 [11279] 1+0/2: 222 response done (decode=2).
20080804-210546 11279 -x7wwdbtdz6dw kac-002054 - 222 :0 "body
<bae4c$4895b8f2$5b79aabb$9255@news.usenext.de>"
08/04 21:05:46.40 [11279] 1+0/2: ## C-S body <e935$4895b8f3$5b79aabb$
9255@news.usenext.de>^M
08/04 21:05:46.40 [11279] 1+0/2: CACHE:
`/var/delegate/dgtesting/cache/$[server:%P/%L/%p]'
08/04 21:05:46.40 [11279] 1+0/2: CACHE:
`/var/delegate/dgtesting/cache/nntp/all/de/usenext/news/e935$4895b8f3$5b79aabb$9255'
08/04 21:05:46.40 [11279] 1+0/2: put[0] body <e935$4895b8f3$5b79aabb$
9255@news.usenext.de>^M
08/04 21:05:47.01 [11279] 1+0/3: ## S-C 222 0 <e935$4895b8f3$5b79aabb$
9255@news.usenext.de> [][body <e935$4895b8f3$5b79aabb$9255@news.usenext.de>]
08/04 21:05:47.01 [11279] 1+0/3: NNTP[0]+0  [] > 222 0
<e935$4895b8f3$5b79aabb$9255@news.usenext.de>^M
08/04 21:05:47.01 [11279] 1+0/3: CACHE:
`/var/delegate/dgtesting/adm/attrs/$[server:%P/%L/%p]'
08/04 21:05:47.01 [11279] 1+0/3: CACHE:
`/var/delegate/dgtesting/adm/attrs/nntp/serverIP:1219/'
08/04 21:05:47.01 [11279] 1+0/3:
dirfopen(/var/delegate/dgtesting/adm/attrs/nntp/serverIP:1219/#attr,r): 0
[-1]
08/04 21:05:47.01 [11279] 1+0/3: CACHE:
`/var/delegate/dgtesting/adm/attrs/$[server:%P/%L/%p]'
08/04 21:05:47.01 [11279] 1+0/3: CACHE:
`/var/delegate/dgtesting/adm/attrs/nntp/serverIP:0000//000/0X'
08/04 21:05:47.01 [11279] 1+0/3:
dirfopen(/var/delegate/dgtesting/adm/attrs/nntp/serverIP:0000//000/0X#attr,r):
0 [-1]
08/04 21:05:47.77 [11279] 1+0/3: TMPFILE(readPart) = (18)
/var/delegate/dgtesting/tmp/dg11279.000007.1217876747
08/04 21:05:47.77 [11279] 1+0/3: >>>TMPFILE(readPart)>>>846bdf8[18]
08/04 21:05:49.25 [11279] 1+0/3: abort: caught SIGPIPE
08/04 21:05:49.26 [11172] 1+0: (0) process [11279] dead
08/04 21:05:49.26 [11172] 1+0: MAX_DELEGATEP 100 (1)32 64 >>> 100
08/04 21:05:49.26 [11172] 1+0: MAX_DELEGATEP 100 (1)32 64 >>> 100
08/04 21:05:49.26 [11172] 1+0: AcceptByMain: start polling(664)[10]...
08/04 21:05:49.92 [11172] 1+0: MAX_DELEGATEP 100 (1)32 64 >>> 100
08/04 21:05:49.92 [11172] 1+0: MAX_DELEGATEP 100 (1)32 64 >>> 100
08/04 21:05:49.93 [11172] 1+0:
dirfopen(/var/spool/delegate-nobody/act/restart/_2299_,r): 0 [-1]
08/04 21:05:49.93 [11172] 1+0: AcceptByMain: start polling(15000)[10]...
08/04 21:06:04.93 [11172] 1+0: MAX_DELEGATEP 100 (1)32 64 >>> 100
08/04 21:06:04.93 [11172] 1+0: MAX_DELEGATEP 100 (1)32 64 >>> 100
08/04 21:06:04.93 [11172] 1+0:
dirfopen(/var/spool/delegate-nobody/act/restart/_2299_,r): 0 [-1]
08/04 21:06:04.93 [11172] 1+0: AcceptByMain: start polling(15000)[10]...
08/04 21:06:19.93 [11172] 1+0: MAX_DELEGATEP 100 (1)32 64 >>> 100
08/04 21:06:19.93 [11172] 1+0: MAX_DELEGATEP 100 (1)32 64 >>> 100
08/04 21:06:19.93 [11172] 1+0:
dirfopen(/var/spool/delegate-nobody/act/restart/_2299_,r): 0 [-1]
08/04 21:06:19.93 [11172] 1+0: AcceptByMain: start polling(15000)[10]...

Please accept my apologies for the extensive post.

It seems for some reason that it is still trying to write to
/var/spool/delegate-nobody/
Even though I have specified DGROOT, CACHEDIR and the user account under
which delegate should run. Is this intended or a bug?

Is there anything else that stands out from the logs?

When I download an article using the telnet method, I get the following in
the logs. Why do I not see this when downloading using a client?

20080804-212349 11870 -x7wwdbsqf6dw kac-002054.gripen.pwp.za.net - 211
alt.binaries.hdtv:0 "GROUP alt.binaries.hdtv"
08/04 21:23:56.06 [11172] 3+0:
dirfopen(/var/spool/delegate-nobody/act/restart/_2299_,r): 0 [-1]
08/04 21:23:56.06 [11172] 3+0: AcceptByMain: start polling(15000)[10]...
08/04 21:24:01.67 [11870] 3+0/1: ## C-S ARTICLE 300000000^M

08/04 21:24:01.67 [11870] 3+0/1: CACHE:
`/var/delegate/dgtesting/cache/$[server:%P/%L/%p]'
08/04 21:24:01.67 [11870] 3+0/1: CACHE:
`/var/delegate/dgtesting/cache/nntp/serverFQDN:1219/spool/alt/binaries/hdtv/300000000'
08/04 21:24:01.67 [11870] 3+0/1: put[0] ARTICLE 300000000^M
08/04 21:24:02.21 [11870] 3+0/2: ## S-C 220 00000000X <0336a571$0$14514$
c3e8da3@news.astraweb.com> ARTICLE [alt.binaries.hdtv][ARTICLE 300000000]
08/04 21:24:02.21 [11870] 3+0/2: NNTP[0]+0  [alt.binaries.hdtv] > 220
300000000 <0336a571$0$14514$c3e8da3@news.astraweb.com> ARTICLE^M
08/04 21:24:02.21 [11870] 3+0/2: TMPFILE(-NNTP_relay_reaponse) = (18)
/var/delegate/dgtesting/tmp/dg11870.000005.1217877842
08/04 21:24:02.21 [11870] 3+0/2: CACHE:
`/var/delegate/dgtesting/adm/attrs/$[server:%P/%L/%p]'
08/04 21:24:02.21 [11870] 3+0/2: CACHE:
`/var/delegate/dgtesting/adm/attrs/nntp/196.25.44.66:1219/'
08/04 21:24:02.21 [11870] 3+0/2:
dirfopen(/var/delegate/dgtesting/adm/attrs/nntp/196.25.44.66:1219/#attr,r):
0 [-1]
08/04 21:24:02.21 [11870] 3+0/2: CACHE:
`/var/delegate/dgtesting/adm/attrs/$[server:%P/%L/%p]'
08/04 21:24:02.21 [11870] 3+0/2: CACHE:
`/var/delegate/dgtesting/adm/attrs/nntp/
196.25.44.66:1219/alt/binaries/hdtv/0000000/0X'
08/04 21:24:02.21 [11870] 3+0/2:
dirfopen(/var/delegate/dgtesting/adm/attrs/nntp/
196.25.44.66:1219/alt/binaries/hdtv/0000000/0X#attr,r): 0 [-1]
08/04 21:24:02.21 [11870] 3+0/2: INSERTED-1: Xref: serverFQDN
alt.binaries.hdtv:300000000
08/04 21:24:03.11 [11870] 3+0/2: TMPFILE(readPart) = (20)
/var/delegate/dgtesting/tmp/dg11870.000006.1217877843
08/04 21:24:03.11 [11870] 3+0/2: >>>TMPFILE(readPart)>>>845c018[20]
08/04 21:24:11.05 [11172] 3+0: MAX_DELEGATEP 100 (1)32 64 >>> 100
08/04 21:24:11.05 [11172] 3+0: MAX_DELEGATEP 100 (1)32 64 >>> 100
08/04 21:24:11.06 [11172] 3+0:
dirfopen(/var/spool/delegate-nobody/act/restart/_2299_,r): 0 [-1]
08/04 21:24:11.06 [11172] 3+0: AcceptByMain: start polling(15000)[10]...
08/04 21:24:19.85 [11870] 3+0/2: ### readPart: got large message (395593)
08/04 21:24:19.86 [11870] 3+0/2: 220 response done (decode=3).
08/04 21:24:19.86 [11870] 3+0/2: CACHE hostname:
08/04 21:24:19.86 [11870] 3+0/2: CACHE:
`/var/delegate/dgtesting/cache/$[server:%P/%L/%p]'
08/04 21:24:19.86 [11870] 3+0/2: CACHE:
`/var/delegate/dgtesting/cache/nntp/serverFQDN:1219/spool/alt/binaries/hdtv/300000000'
08/04 21:24:19.86 [11870] 3+0/2: CACHE:
`/var/delegate/dgtesting/cache/$[server:%P/%L/%p]'
08/04 21:24:19.86 [11870] 3+0/2: CACHE:
`/var/delegate/dgtesting/cache/nntp/serverFQDN:1219/spool/alt/binaries/hdtv/300000000'
08/04 21:24:19.86 [11870] 3+0/2:
dirfopen(/var/delegate/dgtesting/cache/nntp/serverFQDN:1219/spool/alt/binaries/hdtv/300000000,w+):
845c018 [20]
08/04 21:24:19.86 [11870] 3+0/2: openCACHE: create
/var/delegate/dgtesting/cache/nntp/serverFQDN:1219/spool/alt/binaries/hdtv/300000000
08/04 21:24:19.93 [11870] 3+0/2: #### article spool wrote [396454 bytes]
/var/delegate/dgtesting/cache/nntp/serverFQDN:1219/spool/alt/binaries/hdtv/300000000
08/04 21:24:19.95 [11870] 3+0/2: CACHE:
`/var/delegate/dgtesting/cache/$[server:%P/%L/%p]'
08/04 21:24:19.95 [11870] 3+0/2: CACHE:
`/var/delegate/dgtesting/cache/nntp/all/com/astraweb/news/0336a571$0$14514$c3e8da3'
08/04 21:24:19.95 [11870] 3+0/2: LINKED-2
[/var/delegate/dgtesting/cache/nntp/serverFQDN:1219/spool/alt/binaries/hdtv/300000000]
from
[/var/delegate/dgtesting/cache/nntp/all/com/astraweb/news/0336a571$0$14514$c3e8da3]
20080804-212419 11870 -x7wwdbsqf6dw kac-002054.gripen.pwp.za.net - 220
alt.binaries.hdtv:300000000 "ARTICLE 300000000"

When downloading a second time using the same method, I see this line in the
log:
08/04 21:29:16.79 [12000] 4+0/5: reuse [396454 bytes][age=297]
/var/delegate/dgtesting/cache/nntp/serverFQDN:1219/spool/alt/binaries/hdtv/300000000

I assume this means it was used from the cache?

Thanks again,
Jeff

On Sun, Aug 3, 2008 at 11:26 PM, Yutaka Sato <feedback@delegate.org> wrote:

> Hi,
>
> In message <_A4038@delegate-en.ML_>
> on 08/04/08(04:28:56)
> you Jeff <pyqhqbdyi-mnvdjl4kcrfr.ml@ml.delegate.org> wrote:
>  |Can you confirm that when you made the change it did indeed cache
> properly?
>  |I'm still getting the situation where my CACHEDIR is only 32.0KB after
>  |having downloaded > 10MB through the NNTP-Delegate proxy. It just does
> not
>  |seem to write anything at all.
>  |
>  |Is there anything else I can try? I'm quite reliant on the caching
> function
>  |to work :-)
>
> If you see "islocal = 1" after "newServer = nntp://server" in your
> LOGFILE, it is the reason why the cache is disabled.
> DeleGate suppresses caching of articles from a local newsserver
> (a server running on the same host on which DeleGate is running),
> or if you specify a filter with the server like FSV.
> The enclosed patch introduces "nonlocal" option to be used as
> follows to enable caching even with local server.
>
>  MOUNT="= nntp://server nonlocal"
>
> If it is not the case, testing with the simplest configuration
> like follows will give us hints.  (Running DeleGate under super-user
> is never recommended in any case.)
>
>  % delegated \
>  -P9999 \
>  SERVER=nntp \
>  MOUNT="= nntp://news.delegate.org/" \
>  DGROOT=/tmp/nndg \
>  CACHE=do \
>  -vd
>
>  % telnet localhost 9999
>  GROUP mail-lists.delegate-en
>  ARTICLE 1
>  QUIT
>
> Cheers,
> Yutaka
> --
>  9 9   Yutaka Sato <y.sato@delegate.org> http://delegate.org/y.sato/
>  ( ~ )  National Institute of Advanced Industrial Science and Technology
> _<   >_ 1-1-4 Umezono, Tsukuba, Ibaraki, 305-8568 Japan
> Do the more with the less -- B. Fuller
>
>
> *** delegate9.8.4-pre4/src/nntp.c       2007-11-05 17:11:16.000000000 +0900
> --- src/nntp.c  2008-08-04 05:58:43.000000000 +0900
> ***************
> *** 5499,5504 ****
> --- 5499,5510 ----
>        if( strstr(opt1,"ro") == opt1 && (opt1[2]==0 || opt1[2]=='=') ){
>                nm->nm_flags |= MF_RO;
>        }else
> +       if( strstr(opt1,"nonlocal") ){
> +               if( ns->ns_islocal ){
> +                       sv1log("## nonlocal: %s\n",ns->ns_host);
> +                       ns->ns_islocal = 0;
> +               }
> +       }else
>        if( strstr(opt1,"rewaddr=") ){
>                nm->nm_rewaddr = stralloc(opt1+8);
>                ns->ns_rewaddr = nm->nm_rewaddr;
>


  admin search upper oldest olders older1 this newer1 newers latest
[Top/Up] [oldest] - [Older+chunk] - [Newer+chunk] - [newest + Check]
@_@V