`nodupe_fileAgeMin` doesn't ignore files correctly in a cpost

[andreleblanc11]

nodupe_fileAgeMin doesn't seem to work with a cpost

Here is my config

post_baseUrl            ftp://ca-ops@${HOSTNAME}
post_baseDir            /apps/users/ca-ops/

logReject               on
#debug True
loglevel                debug
# critical error warning
#loglevel warning

fileEvents              modify,create

sleep                   31

# Nodupe options
fileSizeMin 1

nodupe_basis            name
nodupe_fileAgeMin               25s
retry_refilter          True
nodupe_fileAgeMax               1d
nodupe_ttl              2d

# Other options
header                  sundew_extension=pull-ca-ops-hourly-pxpaz1:CWAO:CA:5:Direct

batch                   500
#permCopy               off

# DIRECTORIES
path                    /apps/users/ca-ops/hourly

accept                  .*

# nothing else in that directory
acceptUnmatched         False

The cpost looks to be posting the file and then ignoring it, after already posting it.

grep -B1 USR:JBH_702_787928.da cpost_hourly_rawca_01.log | head -n20
2025-03-17 16:04:15,667 [DEBUG] entries_done hit! ignoring:/apps/users/ca-ops/hourly/USR:XZQ_215_769115.dat
2025-03-17 16:04:15,667 [DEBUG] bytes read: 1440, sz ev: 48, event: 0100 create: len=32, fn=/apps/users/ca-ops/hourly/USR:JBH_702_787928.dat
2025-03-17 16:04:15,667 [DEBUG] looking in entries_done, for /apps/users/ca-ops/hourly/USR:JBH_702_787928.dat, result=(nil)
2025-03-17 16:04:15,667 [DEBUG] e->mask=0100 from:  0040  to: 0080
2025-03-17 16:04:15,667 [DEBUG] do one file: /apps/users/ca-ops/hourly/USR:JBH_702_787928.dat
--
2025-03-17 16:04:15,667 [DEBUG] sr_post cache_check: not found
2025-03-17 16:04:15,669 [INFO] cpost published: { "pubTime":"20250317160415.66771174", "baseUrl":"ftp://ca-ops@my-host", "relPath":"hourly/USR:JBH_702_787928.dat", "topic":"v02.post.hourly", "identity":{  "method" : "sha512", "value" : "wyxaS40YyZiWhN7lLi7cHs5egHHJUKm6nnLQNyPplJoa2LgcTJNr4pQAX3ovBj6LTMKtMA1tuG3gOi\no1PE1Ahg=="  } , "mtime":"20250317160347.29521911", "atime":"20250317160347.26621657", "mode":"0644", "size":"9901", "sundew_extension":"pull-ca-ops-hourly-pxpaz1:CWAO:CA:5:Direct"}
2025-03-17 16:04:15,669 [DEBUG] bytes read: 1440, sz ev: 48, event: 0008 dunno: 0008!: len=32, fn=/apps/users/ca-ops/hourly/USR:JBH_702_787928.dat
2025-03-17 16:04:15,669 [DEBUG] looking in entries_done, for /apps/users/ca-ops/hourly/USR:JBH_702_787928.dat, result=0x652423d0dc90
2025-03-17 16:04:15,669 [DEBUG] entries_done hit! ignoring:/apps/users/ca-ops/hourly/USR:JBH_702_787928.dat
--
2025-03-17 16:04:15,669 [DEBUG] do one file: /apps/users/ca-ops/hourly/USR:UBI_15_337084.dat
2025-03-17 16:04:15,669 [INFO] rejecting newer than 25: ignoring /apps/users/ca-ops/hourly/USR:JBH_702_787928.dat
--
2025-03-17 16:04:15,669 [DEBUG] do one file: /apps/users/ca-ops/hourly/USR:PDR_17_890366.dat
2025-03-17 16:04:15,669 [INFO] rejecting newer than 25: ignoring /apps/users/ca-ops/hourly/USR:JBH_702_787928.dat
--
2025-03-17 16:04:15,669 [DEBUG] do one file: /apps/users/ca-ops/hourly/USR:SPQ_19_703758.dat
2025-03-17 16:04:15,669 [INFO] rejecting newer than 25: ignoring /apps/users/ca-ops/hourly/USR:JBH_702_787928.dat

The file got uploaded at 16:03:47Z

grep USR:JBH_702_787928.da /apps/log/vsftpd.log
Mar 17 16:03:47.267 my-host vsftpd[2345439]: [ca-ops] FTP command: Client "174.114.146.51", "STOR USR:JBH_702_787928.dat"

We think this be happening because of the separate events being registered (0100 vs. 0008).

[reidsunderland]

We've been talking about this on Teams, so I'm adding a bit of additional information.

I'm pretty sure there's a bug here. fn is used before being set in the fileAge log messages, so it's producing misleading logs. I think fn should be replaced with pathspec in those messages (fn is set later, by realpath_adjust):

sarrac/sr_post.c

Lines 658 to 689 in 9ed0fc5

	int sr_file2message_start(struct sr_context *sr_c, const char *pathspec,
	struct stat *sb, struct sr_message_s *m, const int rmflags)
	/*
	reading a file, initialize the message that corresponds to it. Return the number of messages to post entire file.
	*/
	{
	bool absolute_path; /* true if path given is absolute */
	int i;
	char *drfound;
	char fn[PATH_MAXNUL];
	char *c, *d;
	int lasti;
	int linklen;
	int pbdlen = 0;
	char linkstr[PATH_MAXNUL];
	char tmprk[PATH_MAXNUL + 100];
	if ((sb) && (sr_c->cfg) && (sr_c->cfg->nodupe_ttl > 0)) {
	time_t age = time(NULL)-sb->st_mtime ;
	if ((sr_c->cfg->nodupe_fileAgeMax>0) && (age > sr_c->cfg->nodupe_fileAgeMax )) {
	if (sr_c->cfg->logReject) {
	sr_log_msg(sr_c->cfg->logctx,LOG_INFO, "rejecting older than %g: ignoring %s\n", sr_c->cfg->nodupe_fileAgeMax, fn );
	}
	return(0);
	}
	if ((sr_c->cfg->nodupe_fileAgeMin>0) && (age < sr_c->cfg->nodupe_fileAgeMin )) {
	if (sr_c->cfg->logReject) {
	sr_log_msg(sr_c->cfg->logctx,LOG_INFO, "rejecting newer than %g: ignoring %s\n", sr_c->cfg->nodupe_fileAgeMin, fn );
	}
	return(0);
	}
	}

Another issue is that fileAgeMin in C behaves like it used to in sr3, where files that are too young are just ignored. It would be nice if we could wait until they become old enough.