ROOT files with duplicated GUIDs observed on production T0 replay workflows

[khurtado]

This is related to a WMCore issue:

dmwm/WMCore#10870

Bug description
When deploying T0 replays with a significant amount of jobs, one of the WMCore components fail complaining about duplicated LFNs. Our LFN patterns look like this:

/store/unmerged/HG2202_Val/RelValProdMinBias/GEN-SIM/HG2202_Val_OLD_Alanv4-v22/00000/2AE85F14-94A1-EC11-BBF5-FA163EC7AA59.root

where: 2AE85F14-94A1-EC11-BBF5-FA163EC7AA59 is the GUID extracted from the ROOT file through the framework XML job report.

So we are basically observing 2 different jobs generating files with the same GUID.
We get the GUID from the framework XML job report here:

And since the GUID from the FW report seems to be generated here:
https://github.com/cms-sw/cmssw/blob/master/FWCore/Utilities/src/Guid.cc#L18-L28

I'm reporting the issue here.

How to reproduce
Deploy a Tier0 replay with a significant amount of jobs. I think @germanfgv can help with this if needed. At least one incident has been reported per week lately this year.

[cmsbuild]

A new Issue was created by @khurtado Kenyi Hurtado.

@Dr15Jones, @perrotta, @dpiparo, @makortel, @smuzaffar, @qliphy can you please review it and eventually sign/assign? Thanks.

cms-bot commands are listed here

[makortel]

assign core

[cmsbuild]

New categories assigned: core

@Dr15Jones,@smuzaffar,@makortel you have been requested to review this Pull request/Issue and eventually sign? Thanks

[makortel]

@khurtado What CMSSW version was used in these tests? Was there only one GUID collision in the replay or many? Do you have any information about the hosts that produced the files whose GUIDs collided?

[makortel]

The process-level GUID is created here

cmssw/FWCore/Utilities/src/processGUID.cc

Lines 4 to 7 in 62d26a2

	Guid const& processGUID() {
	static Guid const guid;
	return guid;
	}

Notably this calls the edm::Guid() constructor with usetime == false leading to

cmssw/FWCore/Utilities/src/Guid.cc

Lines 21 to 27 in 62d26a2

	} else {
	// uuid_generate() defaults to uuid_generate_random() if /dev/urandom
	// is available; if /dev/urandom is not available, then it is better
	// to let uuid_generate() choose the best fallback rather than forcing
	// use of an inferior source of randomness
	::uuid_generate(data_);
	}

branch being taken.

[khurtado]

@makortel
They were using:
CMSSW_12_0_2_patch1 with scram arch: slc7_amd64_gcc900

You can find logs of different set of jobs generating files with the same guid here:
/afs/cern.ch/user/c/cmst0/public/JobAccountant/jobs

Logs seem to have 2 replays, one with many incidents, involving 2 files/jobs but one of them (in g5 directory) involves 3 files/jobs:

[khurtado@lxplus708 /afs/cern.ch/user/c/cmst0/public/JobAccountant/jobs]$ find . -name "dupPickles.json" -exec head -n 2 {} \;
{
  "/data/tier0/srv/wmagent/3.0.1/install/tier0/JobCreator/JobCache/Express_Run343082_StreamCalibration_Tier0_REPLAY_2021_v2110131547_211013_1547/Express/JobCollection_1_1/job_1058/Report.0.pkl": {
{
  "/data/tier0/srv/wmagent/3.0.1/install/tier0/JobCreator/JobCache/Express_Run343082_StreamCalibration_Tier0_REPLAY_2021_v2110131547_211013_1547/Express/JobCollection_1_1/job_1064/Report.0.pkl": {
{
  "/data/tier0/srv/wmagent/3.0.1/install/tier0/JobCreator/JobCache/Express_Run343082_StreamCalibration_Tier0_REPLAY_2021_v2110131547_211013_1547/Express/JobCollection_1_1/job_1038/Report.0.pkl": {
{
  "/data/tier0/srv/wmagent/3.0.1/install/tier0/JobCreator/JobCache/Express_Run343082_StreamCalibration_Tier0_REPLAY_2021_v2110131547_211013_1547/Express/JobCollection_1_0/job_527/Report.0.pkl": {
{
  "/data/tier0/srv/wmagent/3.0.1/install/tier0/JobCreator/JobCache/Express_Run344063_StreamCalibration_Tier0_REPLAY_2021_v2110131547_211013_1548/Express/JobCollection_5_1/job_4623/Report.0.pkl": {

The condor logfiles have information about the hosts runninig these jobs. The collisions involve different condor jobs, but runnnig in the same host for each collision incident:

[khurtado@lxplus708 /afs/cern.ch/user/c/cmst0/public/JobAccountant/jobs]$ find . -name "condor*out" -exec grep -H Hostname {} \; | sort
./g1/job_1038/condor.41731.37.out:Hostname:   b7g18p9798.cern.ch
./g1/job_1048/condor.41731.47.out:Hostname:   b7g18p9798.cern.ch
./g2/job_98/condor.41726.97.out:Hostname:   b7g18p7310.cern.ch
./g2/job_99/condor.41726.98.out:Hostname:   b7g18p7310.cern.ch
./g3/job_1137/condor.41731.136.out:Hostname:   b7g17p4406.cern.ch
./g3/job_1138/condor.41731.137.out:Hostname:   b7g17p4406.cern.ch
./g4/job_1169/condor.41731.168.out:Hostname:   b7g18p3673.cern.ch
./g4/job_1170/condor.41731.169.out:Hostname:   b7g18p3673.cern.ch
./g5/job_527/condor.41729.133.out:Hostname:   b7g10p4995.cern.ch
./g5/job_530/condor.41729.136.out:Hostname:   b7g10p4995.cern.ch
./g5/job_531/condor.41729.137.out:Hostname:   b7g10p4995.cern.ch
./g6/job_4623/condor.41780.47.out:Hostname:   b7g17p1733.cern.ch
./g6/job_4635/condor.41780.59.out:Hostname:   b7g17p1733.cern.ch

And they involve the same or almost the same runtime date:

[khurtado@lxplus708 /afs/cern.ch/user/c/cmst0/public/JobAccountant/jobs]$ find . -name "condor*out" -exec grep -H "Local time" {} \; | sort
./g1/job_1038/condor.41731.37.out:Local time: Wed Oct 13 16:25:29 CEST 2021
./g1/job_1048/condor.41731.47.out:Local time: Wed Oct 13 16:25:29 CEST 2021
./g2/job_98/condor.41726.97.out:Local time: Wed Oct 13 15:58:51 CEST 2021
./g2/job_99/condor.41726.98.out:Local time: Wed Oct 13 15:58:53 CEST 2021
./g3/job_1137/condor.41731.136.out:Local time: Wed Oct 13 16:26:53 CEST 2021
./g3/job_1138/condor.41731.137.out:Local time: Wed Oct 13 16:26:53 CEST 2021
./g4/job_1169/condor.41731.168.out:Local time: Wed Oct 13 16:27:32 CEST 2021
./g4/job_1170/condor.41731.169.out:Local time: Wed Oct 13 16:27:31 CEST 2021
./g5/job_527/condor.41729.133.out:Local time: Wed Oct 13 16:18:54 CEST 2021
./g5/job_530/condor.41729.136.out:Local time: Wed Oct 13 16:18:54 CEST 2021
./g5/job_531/condor.41729.137.out:Local time: Wed Oct 13 16:18:54 CEST 2021
./g6/job_4623/condor.41780.47.out:Local time: Wed Oct 13 17:34:21 CEST 2021
./g6/job_4635/condor.41780.59.out:Local time: Wed Oct 13 17:34:21 CEST 2021

[makortel]

Thanks @khurtado. Can you tell if the affected hosts have /dev/urandom? Or check contents of /proc/sys/kernel/random/entropy_avail on them?

[khurtado]

I unfortunately don't have direct ssh access to these machines. I can probably submit some condor jobs matching to these hosts, but I don't know how long they would take to match and run. I will check if there is anybody with direct access to them for a quick check or submit those jobs otherwise.

Do you know if /dev/urandom and /proc/sys/kernel/random/entropy_avail can vary depending on whether they run inside a singularity container or not by the way? We run these jobs inside containers in production.

[dan131riley]

Am I reading the logs correctly, that the duplicates are all in the DQMIO output? DQMIO does not use the code Matti pointed to, it calls TFile::GetUUID() instead:

cmssw/DQMServices/FwkIO/plugins/DQMRootOutputModule.cc

Lines 327 to 338 in ce4f5b2

	void DQMRootOutputModule::openFile(edm::FileBlock const&) {
	//NOTE: I need to also set the I/O performance settings
	m_file = std::make_unique<TFile>(m_fileName.c_str(),
	"RECREATE",
	"1" //This is the file format version number
	);
	edm::Service<edm::JobReport> jr;
	cms::Digest branchHash;
	std::string guid{m_file->GetUUID().AsString()};
	std::transform(guid.begin(), guid.end(), guid.begin(), (int (*)(int))std::toupper);

That UUID comes from TUUID(), see comments here: https://github.com/root-project/root/blob/bd7c94375627ae10a401543ac84f296f5386c874/core/base/src/TUUID.cxx#L24-L30 TUUID() only implements the older UUID generation algorithm that uses the system time and ethernet address. We actually had to switch away from that algorithm to the one that uses /dev/urandom because we were getting duplicates in docker containers, as apparently containers don't guarantee clock monotonicity across different containers on the same system.

So, if it is just the DQMIO getting duplicates, that's not unexpected and the issue is with the DQM use of the ROOT UUID.

[makortel]

DQMIO does not use the code Matti pointed to,

On a closer look my reference to edm::processGUID() was incorrect anyway, RootOutputFile doesn't use it either but calls edm::createGlobalIdentifier()

cmssw/IOPool/Output/src/RootOutputFile.cc

Line 199 in ce4f5b2

fid_ = FileID(createGlobalIdentifier());

cmssw/IOPool/Output/src/RootOutputFile.cc

Lines 230 to 239 in ce4f5b2

	Service<JobReport> reportSvc;
	reportToken_ = reportSvc->outputFileOpened(file_,
	logicalFile_, // PFN and LFN
	om_->catalog(), // catalog
	moduleName, // module class name
	om_->moduleLabel(), // module label
	fid_.fid(), // file id (guid)
	std::string(), // data type (not yet known, so string is empty).
	md5alg.digest().toString(), // branch hash
	branchNames); // branch names being written

edm::createGlobalIdentifier() itself is just

cmssw/FWCore/Utilities/src/GlobalIdentifier.cc

Lines 5 to 8 in ce4f5b2

	std::string createGlobalIdentifier(bool binary) {
	Guid guid;
	return binary ? guid.toBinary() : guid.toString();
	}

I see I changed the DQMIO output behavior from edm::createGlobalIdentifier() to TFile::GetUUID() in #28551 to fix inconsistency between DQMIO input and output that was reported in #28534.

Then I see #28622 removed the whole call to edm::JobReport::inputFileOpened() from DQMRootSource (?!) that used the TFile::GetUUID().

So on one hand, we could easily change the DQMRootOutputModule to use edm::createGlobalIdentifier() without worrying the consistency raised in #28534, but on the other hand, should DQMRootSource report inputFileOpened()?