Project

General

Profile

Bug #9363

Cannot read multiple events from file produced by aggregating several files in art v1_14_03, nu release v1_13_00

Added by Brian Rebel about 4 years ago. Updated about 4 years ago.

Status:
Closed
Priority:
High
Assignee:
Category:
Event Loop
Target version:
Start date:
07/02/2015
Due date:
% Done:

100%

Estimated time:
Spent time:
Occurs In:
Scope:
Internal
Experiment:
LArSoft
SSI Package:
art
Duration:

Description

The LArIAT raw data files produced by artdaq each contain a single event. The files from the same run have a common run number and the subrun number is the same as the event number.

A file created from a job that reads the artdaq fragments from multiple files and then creates a single file containing LArSoft data products can be found at

/afs/fnal.gov/files/home/room1/brebel/lar/lariat/develop/standard_reco.root

When the file is viewed with the larsoft event display the following error is produced when attempting to advance past the first event in the file:

evd [0] lar: /scratch/workspace/nu-release-build/v1_13_00/s12-e7/debug/build/art/v1_14_03/src/art/Framework/Core/DecrepitRelicInputSourceImplementation.cc:304: std::vector<std::shared_ptr<art::SubRunPrincipal> > art::DecrepitRelicInputSourceImplementation::readSubRunFromSecondaryFiles(std::shared_ptr<art::RunPrincipal>): Assertion `state_ == input::IsSubRun' failed.

Instructions for checking out and building the LArIAT code (which depends on larsoft) can be found at

https://cdcvs.fnal.gov/redmine/projects/lardbt/wiki/Setting_up_the_Offline_Software

The develop branch of the repository builds version v01_05_02 of lariatsoft. The following command runs the event display

lar -c evd_lariat.fcl standard_reco.root

Running

lar -c eventdump.fcl standard_reco.root

does not trigger the problem, but I am not sure it would/should.

standard_fragmenttodigit.fcl (1.46 KB) standard_fragmenttodigit.fcl Brian Rebel, 07/06/2015 10:39 AM
evd_lariat.fcl (1.08 KB) evd_lariat.fcl Brian Rebel, 07/06/2015 10:40 AM

Associated revisions

Revision eda75132
Added by Christopher Green almost 4 years ago

Merge tag 'v1_15_01'

Tag for release with fix for issue #9363.

History

#1 Updated by Christopher Green about 4 years ago

  • Status changed from New to Feedback

Are you able run Tracer so we can see event IDs of each event as they are being dumped? Ditto for the files from which this file was made? A preliminary check of the file structure suggests that the event ID's are all identical: 6099 / 0 / 0. The latter 0 makes no sense, as that is the invalid ID, so I'm hoping I did something wrong with the diagnostics.

Please also attach the .fcl files (original or via one of art's command-line options to dump the post-processed configuration) used to generate the files at every stage of the process.

#2 Updated by Brian Rebel about 4 years ago

Here is the output when running the event dump with the Tracer:

-bash-4.1$ lar -c eventdump.fcl --trace standard_reco.root 
%MSG-i MF_INIT_OK:  lar 06-Jul-2015 10:27:52 CDT JobSetup
Messagelogger initialization complete.
%MSG
06-Jul-2015 10:27:54 CDT  Initiating request to open file standard_reco.root
06-Jul-2015 10:27:55 CDT  Successfully opened file standard_reco.root
++ constructing module:out1
++ construction finished:out1
++ beginJob module:out1
++ beginJob finished:out1
++ Job started
++++open input file
++++finished: open input file standard_reco.root
++++opened output file from out1
++++source run
++++finished: source run
++++ processing begin run:run: 6099 time:1434052338
++++++ processing path for begin run:end_path
++++++++ module for begin run:out1
++++++++ finished for begin run:out1
++++++ finished path for begin run:
++++ finished begin run:
++++source subRun
++++finished: source subRun
++++ processing begin subRun:run: 6099 subRun: 606 time:1434088847
++++++ processing path for begin subRun:end_path
++++++++ module for begin subRun:out1
++++++++ finished for begin subRun:out1
++++++ finished path for begin subRun:
++++ finished begin subRun:
++++source event
++++finished: source event
Begin processing the 1st record. run: 6099 subRun: 606 event: 606 at 06-Jul-2015 10:27:55 CDT
++++ processing event:run: 6099 subRun: 606 event: 606 time:1434088847
++++++ processing path for event:end_path
++++++++ module for event:out1
PROCESS NAME.. | MODULE LABEL... | PRODUCT INSTANCE NAME | DATA PRODUCT TYPE............................. | SIZE
LariatProducer | FragmentToDigit | ..................... | art::Assns<raw::Trigger,raw::OpDetPulse,void>. | ...8
LariatProducer | FragmentToDigit | ..................... | art::Assns<raw::Trigger,raw::RawDigit,void>... | 1920
LariatProducer | FragmentToDigit | ..................... | art::Assns<raw::Trigger,raw::AuxDetDigit,void> | .204
LariatProducer | FragmentToDigit | ..................... | std::vector<raw::OpDetPulse>.................. | ...8
LariatProducer | FragmentToDigit | ..................... | std::vector<raw::Trigger>..................... | ...5
DAQ........... | daq............ | unidentified......... | std::vector<artdaq::Fragment>................. | ...?
LariatProducer | TriggerResults. | ..................... | art::TriggerResults........................... | ...-
DAQ........... | daq............ | SPILL................ | std::vector<artdaq::Fragment>................. | ...1
DAQAG......... | TriggerResults. | ..................... | art::TriggerResults........................... | ...-
LariatProducer | FragmentToDigit | ..................... | std::vector<raw::AuxDetDigit>................. | .204
LariatProducer | FragmentToDigit | ..................... | std::vector<raw::RawDigit>.................... | 1920

Total products (present, not present): 11 (10, 1).

++++++++ finished for event:out1
++++++ finished path for event:
++++ finished event:
++++ processing end subRun:run: 6099 subRun: 606 time:1434088847
++++++ processing path for end subRun:end_path
++++++++ module for end subRun:out1
++++++++ finished for end subRun:out1
++++++ finished path for end subRun:
++++ finished end subRun:
++++source subRun
++++finished: source subRun
++++ processing begin subRun:run: 6099 subRun: 607 time:1434088907
++++++ processing path for begin subRun:end_path
++++++++ module for begin subRun:out1
++++++++ finished for begin subRun:out1
++++++ finished path for begin subRun:
++++ finished begin subRun:
++++source event
Begin processing the 2nd record. run: 6099 subRun: 607 event: 607 at 06-Jul-2015 10:27:55 CDT
++++finished: source event
++++ processing event:run: 6099 subRun: 607 event: 607 time:1434088907
++++++ processing path for event:end_path
++++++++ module for event:out1
PROCESS NAME.. | MODULE LABEL... | PRODUCT INSTANCE NAME | DATA PRODUCT TYPE............................. | SIZE
LariatProducer | FragmentToDigit | ..................... | art::Assns<raw::Trigger,raw::OpDetPulse,void>. | ...8
LariatProducer | FragmentToDigit | ..................... | art::Assns<raw::Trigger,raw::RawDigit,void>... | 1920
LariatProducer | FragmentToDigit | ..................... | art::Assns<raw::Trigger,raw::AuxDetDigit,void> | .542
LariatProducer | FragmentToDigit | ..................... | std::vector<raw::OpDetPulse>.................. | ...8
LariatProducer | FragmentToDigit | ..................... | std::vector<raw::Trigger>..................... | ...5
DAQ........... | daq............ | unidentified......... | std::vector<artdaq::Fragment>................. | ...?
LariatProducer | TriggerResults. | ..................... | art::TriggerResults........................... | ...-
DAQ........... | daq............ | SPILL................ | std::vector<artdaq::Fragment>................. | ...1
DAQAG......... | TriggerResults. | ..................... | art::TriggerResults........................... | ...-
LariatProducer | FragmentToDigit | ..................... | std::vector<raw::AuxDetDigit>................. | .542
LariatProducer | FragmentToDigit | ..................... | std::vector<raw::RawDigit>.................... | 1920

Total products (present, not present): 11 (10, 1).

++++++++ finished for event:out1
++++++ finished path for event:
++++ finished event:
++++ processing end subRun:run: 6099 subRun: 607 time:1434088907
++++++ processing path for end subRun:end_path
++++++++ module for end subRun:out1
++++++++ finished for end subRun:out1
++++++ finished path for end subRun:
++++ finished end subRun:
++++source subRun
++++finished: source subRun
++++ processing begin subRun:run: 6099 subRun: 608 time:1434088967
++++++ processing path for begin subRun:end_path
++++++++ module for begin subRun:out1
++++++++ finished for begin subRun:out1
++++++ finished path for begin subRun:
++++ finished begin subRun:
++++source event
Begin processing the 3rd record. run: 6099 subRun: 608 event: 608 at 06-Jul-2015 10:27:56 CDT
++++finished: source event
++++ processing event:run: 6099 subRun: 608 event: 608 time:1434088967
++++++ processing path for event:end_path
++++++++ module for event:out1
PROCESS NAME.. | MODULE LABEL... | PRODUCT INSTANCE NAME | DATA PRODUCT TYPE............................. | SIZE
LariatProducer | FragmentToDigit | ..................... | art::Assns<raw::Trigger,raw::OpDetPulse,void>. | ...6
LariatProducer | FragmentToDigit | ..................... | art::Assns<raw::Trigger,raw::RawDigit,void>... | .960
LariatProducer | FragmentToDigit | ..................... | art::Assns<raw::Trigger,raw::AuxDetDigit,void> | .103
LariatProducer | FragmentToDigit | ..................... | std::vector<raw::OpDetPulse>.................. | ...6
LariatProducer | FragmentToDigit | ..................... | std::vector<raw::Trigger>..................... | ...6
DAQ........... | daq............ | unidentified......... | std::vector<artdaq::Fragment>................. | ...?
LariatProducer | TriggerResults. | ..................... | art::TriggerResults........................... | ...-
DAQ........... | daq............ | SPILL................ | std::vector<artdaq::Fragment>................. | ...1
DAQAG......... | TriggerResults. | ..................... | art::TriggerResults........................... | ...-
LariatProducer | FragmentToDigit | ..................... | std::vector<raw::AuxDetDigit>................. | .103
LariatProducer | FragmentToDigit | ..................... | std::vector<raw::RawDigit>.................... | .960

Total products (present, not present): 11 (10, 1).

++++++++ finished for event:out1
++++++ finished path for event:
++++ finished event:
++++ processing end subRun:run: 6099 subRun: 608 time:1434088967
++++++ processing path for end subRun:end_path
++++++++ module for end subRun:out1
++++++++ finished for end subRun:out1
++++++ finished path for end subRun:
++++ finished end subRun:
++++source subRun
++++finished: source subRun
++++ processing begin subRun:run: 6099 subRun: 609 time:1434089028
++++++ processing path for begin subRun:end_path
++++++++ module for begin subRun:out1
++++++++ finished for begin subRun:out1
++++++ finished path for begin subRun:
++++ finished begin subRun:
++++source event
Begin processing the 4th record. run: 6099 subRun: 609 event: 609 at 06-Jul-2015 10:27:56 CDT
++++finished: source event
++++ processing event:run: 6099 subRun: 609 event: 609 time:1434089028
++++++ processing path for event:end_path
++++++++ module for event:out1
PROCESS NAME.. | MODULE LABEL... | PRODUCT INSTANCE NAME | DATA PRODUCT TYPE............................. | SIZE
LariatProducer | FragmentToDigit | ..................... | art::Assns<raw::Trigger,raw::OpDetPulse,void>. | ...4
LariatProducer | FragmentToDigit | ..................... | art::Assns<raw::Trigger,raw::RawDigit,void>... | .960
LariatProducer | FragmentToDigit | ..................... | art::Assns<raw::Trigger,raw::AuxDetDigit,void> | ..84
LariatProducer | FragmentToDigit | ..................... | std::vector<raw::OpDetPulse>.................. | ...4
LariatProducer | FragmentToDigit | ..................... | std::vector<raw::Trigger>..................... | ...4
DAQ........... | daq............ | unidentified......... | std::vector<artdaq::Fragment>................. | ...?
LariatProducer | TriggerResults. | ..................... | art::TriggerResults........................... | ...-
DAQ........... | daq............ | SPILL................ | std::vector<artdaq::Fragment>................. | ...1
DAQAG......... | TriggerResults. | ..................... | art::TriggerResults........................... | ...-
LariatProducer | FragmentToDigit | ..................... | std::vector<raw::AuxDetDigit>................. | ..84
LariatProducer | FragmentToDigit | ..................... | std::vector<raw::RawDigit>.................... | .960

Total products (present, not present): 11 (10, 1).

++++++++ finished for event:out1
++++++ finished path for event:
++++ finished event:
++++ processing end subRun:run: 6099 subRun: 609 time:1434089028
++++++ processing path for end subRun:end_path
++++++++ module for end subRun:out1
++++++++ finished for end subRun:out1
++++++ finished path for end subRun:
++++ finished end subRun:
++++source subRun
++++finished: source subRun
++++ processing begin subRun:run: 6099 subRun: 625 time:1434089991
++++++ processing path for begin subRun:end_path
++++++++ module for begin subRun:out1
++++++++ finished for begin subRun:out1
++++++ finished path for begin subRun:
++++ finished begin subRun:
++++source event
Begin processing the 5th record. run: 6099 subRun: 625 event: 625 at 06-Jul-2015 10:27:56 CDT
++++finished: source event
++++ processing event:run: 6099 subRun: 625 event: 625 time:1434089991
++++++ processing path for event:end_path
++++++++ module for event:out1
PROCESS NAME.. | MODULE LABEL... | PRODUCT INSTANCE NAME | DATA PRODUCT TYPE............................. | SIZE
LariatProducer | FragmentToDigit | ..................... | art::Assns<raw::Trigger,raw::OpDetPulse,void>. | ..18
LariatProducer | FragmentToDigit | ..................... | art::Assns<raw::Trigger,raw::RawDigit,void>... | 3840
LariatProducer | FragmentToDigit | ..................... | art::Assns<raw::Trigger,raw::AuxDetDigit,void> | .408
LariatProducer | FragmentToDigit | ..................... | std::vector<raw::OpDetPulse>.................. | ..18
LariatProducer | FragmentToDigit | ..................... | std::vector<raw::Trigger>..................... | ..11
DAQ........... | daq............ | unidentified......... | std::vector<artdaq::Fragment>................. | ...?
LariatProducer | TriggerResults. | ..................... | art::TriggerResults........................... | ...-
DAQ........... | daq............ | SPILL................ | std::vector<artdaq::Fragment>................. | ...1
DAQAG......... | TriggerResults. | ..................... | art::TriggerResults........................... | ...-
LariatProducer | FragmentToDigit | ..................... | std::vector<raw::AuxDetDigit>................. | .408
LariatProducer | FragmentToDigit | ..................... | std::vector<raw::RawDigit>.................... | 3840

Total products (present, not present): 11 (10, 1).

++++++++ finished for event:out1
++++++ finished path for event:
++++ finished event:
++++ processing end subRun:run: 6099 subRun: 625 time:1434089991
++++++ processing path for end subRun:end_path
++++++++ module for end subRun:out1
++++++++ finished for end subRun:out1
++++++ finished path for end subRun:
++++ finished end subRun:
++++source subRun
++++finished: source subRun
++++ processing begin subRun:run: 6099 subRun: 626 time:1434090051
++++++ processing path for begin subRun:end_path
++++++++ module for begin subRun:out1
++++++++ finished for begin subRun:out1
++++++ finished path for begin subRun:
++++ finished begin subRun:
++++source event
Begin processing the 6th record. run: 6099 subRun: 626 event: 626 at 06-Jul-2015 10:27:58 CDT
++++finished: source event
++++ processing event:run: 6099 subRun: 626 event: 626 time:1434090051
++++++ processing path for event:end_path
++++++++ module for event:out1
PROCESS NAME.. | MODULE LABEL... | PRODUCT INSTANCE NAME | DATA PRODUCT TYPE............................. | SIZE
LariatProducer | FragmentToDigit | ..................... | art::Assns<raw::Trigger,raw::OpDetPulse,void>. | ...4
LariatProducer | FragmentToDigit | ..................... | art::Assns<raw::Trigger,raw::RawDigit,void>... | .960
LariatProducer | FragmentToDigit | ..................... | art::Assns<raw::Trigger,raw::AuxDetDigit,void> | ..84
LariatProducer | FragmentToDigit | ..................... | std::vector<raw::OpDetPulse>.................. | ...4
LariatProducer | FragmentToDigit | ..................... | std::vector<raw::Trigger>..................... | ...3
DAQ........... | daq............ | unidentified......... | std::vector<artdaq::Fragment>................. | ...?
LariatProducer | TriggerResults. | ..................... | art::TriggerResults........................... | ...-
DAQ........... | daq............ | SPILL................ | std::vector<artdaq::Fragment>................. | ...1
DAQAG......... | TriggerResults. | ..................... | art::TriggerResults........................... | ...-
LariatProducer | FragmentToDigit | ..................... | std::vector<raw::AuxDetDigit>................. | ..84
LariatProducer | FragmentToDigit | ..................... | std::vector<raw::RawDigit>.................... | .960

Total products (present, not present): 11 (10, 1).

++++++++ finished for event:out1
++++++ finished path for event:
++++ finished event:
++++ processing end subRun:run: 6099 subRun: 626 time:1434090051
++++++ processing path for end subRun:end_path
++++++++ module for end subRun:out1
++++++++ finished for end subRun:out1
++++++ finished path for end subRun:
++++ finished end subRun:
++++source subRun
++++finished: source subRun
++++ processing begin subRun:run: 6099 subRun: 627 time:1434090111
++++++ processing path for begin subRun:end_path
++++++++ module for begin subRun:out1
++++++++ finished for begin subRun:out1
++++++ finished path for begin subRun:
++++ finished begin subRun:
++++source event
Begin processing the 7th record. run: 6099 subRun: 627 event: 627 at 06-Jul-2015 10:27:58 CDT
++++finished: source event
++++ processing event:run: 6099 subRun: 627 event: 627 time:1434090111
++++++ processing path for event:end_path
++++++++ module for event:out1
PROCESS NAME.. | MODULE LABEL... | PRODUCT INSTANCE NAME | DATA PRODUCT TYPE............................. | SIZE
LariatProducer | FragmentToDigit | ..................... | art::Assns<raw::Trigger,raw::OpDetPulse,void>. | ...2
LariatProducer | FragmentToDigit | ..................... | art::Assns<raw::Trigger,raw::RawDigit,void>... | .480
LariatProducer | FragmentToDigit | ..................... | art::Assns<raw::Trigger,raw::AuxDetDigit,void> | ..42
LariatProducer | FragmentToDigit | ..................... | std::vector<raw::OpDetPulse>.................. | ...2
LariatProducer | FragmentToDigit | ..................... | std::vector<raw::Trigger>..................... | ...4
DAQ........... | daq............ | unidentified......... | std::vector<artdaq::Fragment>................. | ...?
LariatProducer | TriggerResults. | ..................... | art::TriggerResults........................... | ...-
DAQ........... | daq............ | SPILL................ | std::vector<artdaq::Fragment>................. | ...1
DAQAG......... | TriggerResults. | ..................... | art::TriggerResults........................... | ...-
LariatProducer | FragmentToDigit | ..................... | std::vector<raw::AuxDetDigit>................. | ..42
LariatProducer | FragmentToDigit | ..................... | std::vector<raw::RawDigit>.................... | .480

Total products (present, not present): 11 (10, 1).

++++++++ finished for event:out1
++++++ finished path for event:
++++ finished event:
++++ processing end subRun:run: 6099 subRun: 627 time:1434090111
++++++ processing path for end subRun:end_path
++++++++ module for end subRun:out1
++++++++ finished for end subRun:out1
++++++ finished path for end subRun:
++++ finished end subRun:
++++source subRun
++++finished: source subRun
++++ processing begin subRun:run: 6099 subRun: 628 time:1434090171
++++++ processing path for begin subRun:end_path
++++++++ module for begin subRun:out1
++++++++ finished for begin subRun:out1
++++++ finished path for begin subRun:
++++ finished begin subRun:
++++source event
Begin processing the 8th record. run: 6099 subRun: 628 event: 628 at 06-Jul-2015 10:27:58 CDT
++++finished: source event
++++ processing event:run: 6099 subRun: 628 event: 628 time:1434090171
++++++ processing path for event:end_path
++++++++ module for event:out1
PROCESS NAME.. | MODULE LABEL... | PRODUCT INSTANCE NAME | DATA PRODUCT TYPE............................. | SIZE
LariatProducer | FragmentToDigit | ..................... | art::Assns<raw::Trigger,raw::OpDetPulse,void>. | ...0
LariatProducer | FragmentToDigit | ..................... | art::Assns<raw::Trigger,raw::RawDigit,void>... | ...0
LariatProducer | FragmentToDigit | ..................... | art::Assns<raw::Trigger,raw::AuxDetDigit,void> | ...0
LariatProducer | FragmentToDigit | ..................... | std::vector<raw::OpDetPulse>.................. | ...0
LariatProducer | FragmentToDigit | ..................... | std::vector<raw::Trigger>..................... | ...2
DAQ........... | daq............ | unidentified......... | std::vector<artdaq::Fragment>................. | ...?
LariatProducer | TriggerResults. | ..................... | art::TriggerResults........................... | ...-
DAQ........... | daq............ | SPILL................ | std::vector<artdaq::Fragment>................. | ...1
DAQAG......... | TriggerResults. | ..................... | art::TriggerResults........................... | ...-
LariatProducer | FragmentToDigit | ..................... | std::vector<raw::AuxDetDigit>................. | ...0
LariatProducer | FragmentToDigit | ..................... | std::vector<raw::RawDigit>.................... | ...0

Total products (present, not present): 11 (10, 1).

++++++++ finished for event:out1
++++++ finished path for event:
++++ finished event:
++++ processing end subRun:run: 6099 subRun: 628 time:1434090171
++++++ processing path for end subRun:end_path
++++++++ module for end subRun:out1
++++++++ finished for end subRun:out1
++++++ finished path for end subRun:
++++ finished end subRun:
++++source subRun
++++finished: source subRun
++++ processing begin subRun:run: 6099 subRun: 629 time:1434090232
++++++ processing path for begin subRun:end_path
++++++++ module for begin subRun:out1
++++++++ finished for begin subRun:out1
++++++ finished path for begin subRun:
++++ finished begin subRun:
++++source event
Begin processing the 9th record. run: 6099 subRun: 629 event: 629 at 06-Jul-2015 10:27:58 CDT
++++finished: source event
++++ processing event:run: 6099 subRun: 629 event: 629 time:1434090232
++++++ processing path for event:end_path
++++++++ module for event:out1
PROCESS NAME.. | MODULE LABEL... | PRODUCT INSTANCE NAME | DATA PRODUCT TYPE............................. | SIZE
LariatProducer | FragmentToDigit | ..................... | art::Assns<raw::Trigger,raw::OpDetPulse,void>. | ..12
LariatProducer | FragmentToDigit | ..................... | art::Assns<raw::Trigger,raw::RawDigit,void>... | 2400
LariatProducer | FragmentToDigit | ..................... | art::Assns<raw::Trigger,raw::AuxDetDigit,void> | .307
LariatProducer | FragmentToDigit | ..................... | std::vector<raw::OpDetPulse>.................. | ..12
LariatProducer | FragmentToDigit | ..................... | std::vector<raw::Trigger>..................... | ...7
DAQ........... | daq............ | unidentified......... | std::vector<artdaq::Fragment>................. | ...?
LariatProducer | TriggerResults. | ..................... | art::TriggerResults........................... | ...-
DAQ........... | daq............ | SPILL................ | std::vector<artdaq::Fragment>................. | ...1
DAQAG......... | TriggerResults. | ..................... | art::TriggerResults........................... | ...-
LariatProducer | FragmentToDigit | ..................... | std::vector<raw::AuxDetDigit>................. | .307
LariatProducer | FragmentToDigit | ..................... | std::vector<raw::RawDigit>.................... | 2400

Total products (present, not present): 11 (10, 1).

++++++++ finished for event:out1
++++++ finished path for event:
++++ finished event:
++++ processing end subRun:run: 6099 subRun: 629 time:1434090232
++++++ processing path for end subRun:end_path
++++++++ module for end subRun:out1
++++++++ finished for end subRun:out1
++++++ finished path for end subRun:
++++ finished end subRun:
++++source subRun
++++finished: source subRun
++++ processing begin subRun:run: 6099 subRun: 630 time:1434090292
++++++ processing path for begin subRun:end_path
++++++++ module for begin subRun:out1
++++++++ finished for begin subRun:out1
++++++ finished path for begin subRun:
++++ finished begin subRun:
++++source event
Begin processing the 10th record. run: 6099 subRun: 630 event: 630 at 06-Jul-2015 10:27:59 CDT
++++finished: source event
++++ processing event:run: 6099 subRun: 630 event: 630 time:1434090292
++++++ processing path for event:end_path
++++++++ module for event:out1
PROCESS NAME.. | MODULE LABEL... | PRODUCT INSTANCE NAME | DATA PRODUCT TYPE............................. | SIZE
LariatProducer | FragmentToDigit | ..................... | art::Assns<raw::Trigger,raw::OpDetPulse,void>. | ...2
LariatProducer | FragmentToDigit | ..................... | art::Assns<raw::Trigger,raw::RawDigit,void>... | .480
LariatProducer | FragmentToDigit | ..................... | art::Assns<raw::Trigger,raw::AuxDetDigit,void> | ..42
LariatProducer | FragmentToDigit | ..................... | std::vector<raw::OpDetPulse>.................. | ...2
LariatProducer | FragmentToDigit | ..................... | std::vector<raw::Trigger>..................... | ...4
DAQ........... | daq............ | unidentified......... | std::vector<artdaq::Fragment>................. | ...?
LariatProducer | TriggerResults. | ..................... | art::TriggerResults........................... | ...-
DAQ........... | daq............ | SPILL................ | std::vector<artdaq::Fragment>................. | ...1
DAQAG......... | TriggerResults. | ..................... | art::TriggerResults........................... | ...-
LariatProducer | FragmentToDigit | ..................... | std::vector<raw::AuxDetDigit>................. | ..42
LariatProducer | FragmentToDigit | ..................... | std::vector<raw::RawDigit>.................... | .480

Total products (present, not present): 11 (10, 1).

++++++++ finished for event:out1
++++++ finished path for event:
++++ finished event:
++++ processing end subRun:run: 6099 subRun: 630 time:1434090292
++++++ processing path for end subRun:end_path
++++++++ module for end subRun:out1
++++++++ finished for end subRun:out1
++++++ finished path for end subRun:
++++ finished end subRun:
++++ processing end run:run: 6099 time:1434090292
++++++ processing path for end run:end_path
++++++++ module for end run:out1
++++++++ finished for end run:out1
++++++ finished path for end run:
++++ finished end run:
PROCESS NAME.. | MODULE LABEL......... | PRODUCT INSTANCE NAME | DATA PRODUCT TYPE.................... | SIZE
DAQAG......... | lariatOnlineBuildInfo | LariatOnlineBuildInfo | std::vector<artdaq::PackageBuildInfo> | ...3
LariatProducer | FragmentToDigit...... | ..................... | sumdata::RunData..................... | ...-

Total products (present, not present): 2 (2, 0).

++++close output file from out1
++++finished close output file <none> from out1
++++close input file
06-Jul-2015 10:27:59 CDT  Closed file standard_reco.root
++++finished: close input file
++ endJob module:out1
++ endJob finished:out1

TrigReport ---------- Event  Summary ------------
TrigReport Events total = 10 passed = 10 failed = 0

TrigReport ------ Modules in End-Path: end_path ------------
TrigReport  Trig Bit#    Visited     Passed     Failed      Error Name
TrigReport     0    0         10         10          0          0 out1

TimeReport ---------- Time  Summary ---[sec]----
TimeReport CPU = 4.058186 Real = 4.054382

++ Job ended
Art has completed and will exit with status 0.

The process used to create the file was

lar -c standard_fragmenttodigit.fcl /pnfs/lariat/pnfs/fnal.gov/usr/lariat/raw/000/541/lariat_r006099_sr0* -n 10

I run the event dump.fcl along with --trace on the input files, I see

-bash-4.1$ lar -c eventdump.fcl --trace /pnfs/lariat/pnfs/fnal.gov/usr/lariat/raw/000/541/lariat_r006099_sr0* -n 10
%MSG-i MF_INIT_OK:  lar 06-Jul-2015 10:33:39 CDT JobSetup
Messagelogger initialization complete.
%MSG
06-Jul-2015 10:33:41 CDT  Initiating request to open file /pnfs/lariat/pnfs/fnal.gov/usr/lariat/raw/000/541/lariat_r006099_sr0606.root
06-Jul-2015 10:33:41 CDT  Successfully opened file /pnfs/lariat/pnfs/fnal.gov/usr/lariat/raw/000/541/lariat_r006099_sr0606.root
++ constructing module:out1
++ construction finished:out1
++ beginJob module:out1
++ beginJob finished:out1
++ Job started
++++open input file
++++finished: open input file /pnfs/lariat/pnfs/fnal.gov/usr/lariat/raw/000/541/lariat_r006099_sr0606.root
++++opened output file from out1
++++source run
++++finished: source run
++++ processing begin run:run: 6099 time:1434052338
++++++ processing path for begin run:end_path
++++++++ module for begin run:out1
++++++++ finished for begin run:out1
++++++ finished path for begin run:
++++ finished begin run:
++++source subRun
++++finished: source subRun
++++ processing begin subRun:run: 6099 subRun: 606 time:1434088847
++++++ processing path for begin subRun:end_path
++++++++ module for begin subRun:out1
++++++++ finished for begin subRun:out1
++++++ finished path for begin subRun:
++++ finished begin subRun:
++++source event
++++finished: source event
Begin processing the 1st record. run: 6099 subRun: 606 event: 606 at 06-Jul-2015 10:33:42 CDT
++++ processing event:run: 6099 subRun: 606 event: 606 time:1434088847
++++++ processing path for event:end_path
++++++++ module for event:out1
PROCESS NAME | MODULE LABEL.. | PRODUCT INSTANCE NAME | DATA PRODUCT TYPE............ | SIZE
DAQ......... | daq........... | unidentified......... | std::vector<artdaq::Fragment> | ...?
DAQ......... | daq........... | SPILL................ | std::vector<artdaq::Fragment> | ...1
DAQAG....... | TriggerResults | ..................... | art::TriggerResults.......... | ...-

Total products (present, not present): 3 (2, 1).

++++++++ finished for event:out1
++++++ finished path for event:
++++ finished event:
++++close input file
06-Jul-2015 10:33:42 CDT  Closed file /pnfs/lariat/pnfs/fnal.gov/usr/lariat/raw/000/541/lariat_r006099_sr0606.root
++++finished: close input file
++++open input file
06-Jul-2015 10:33:42 CDT  Initiating request to open file /pnfs/lariat/pnfs/fnal.gov/usr/lariat/raw/000/541/lariat_r006099_sr0607.root
06-Jul-2015 10:33:42 CDT  Successfully opened file /pnfs/lariat/pnfs/fnal.gov/usr/lariat/raw/000/541/lariat_r006099_sr0607.root
++++finished: open input file /pnfs/lariat/pnfs/fnal.gov/usr/lariat/raw/000/541/lariat_r006099_sr0607.root
++++source run
%MSG-w RunMerging:  SourceRun 06-Jul-2015 10:33:42 CDT PostProcessEvent
Problem found while adding product provenance, product already exists for (artdaq::PackageBuildInfos,lariatOnlineBuildInfo,LariatOnlineBuildInfo,DAQAG)

%MSG
++++finished: source run
++++ processing end subRun:run: 6099 subRun: 606 time:1434088847
++++++ processing path for end subRun:end_path
++++++++ module for end subRun:out1
++++++++ finished for end subRun:out1
++++++ finished path for end subRun:
++++ finished end subRun:
++++source subRun
++++finished: source subRun
++++ processing begin subRun:run: 6099 subRun: 607 time:1434088907
++++++ processing path for begin subRun:end_path
++++++++ module for begin subRun:out1
++++++++ finished for begin subRun:out1
++++++ finished path for begin subRun:
++++ finished begin subRun:
++++source event
Begin processing the 2nd record. run: 6099 subRun: 607 event: 607 at 06-Jul-2015 10:33:42 CDT
++++finished: source event
++++ processing event:run: 6099 subRun: 607 event: 607 time:1434088907
++++++ processing path for event:end_path
++++++++ module for event:out1
PROCESS NAME | MODULE LABEL.. | PRODUCT INSTANCE NAME | DATA PRODUCT TYPE............ | SIZE
DAQ......... | daq........... | unidentified......... | std::vector<artdaq::Fragment> | ...?
DAQ......... | daq........... | SPILL................ | std::vector<artdaq::Fragment> | ...1
DAQAG....... | TriggerResults | ..................... | art::TriggerResults.......... | ...-

Total products (present, not present): 3 (2, 1).

++++++++ finished for event:out1
++++++ finished path for event:
++++ finished event:
++++close input file
06-Jul-2015 10:33:42 CDT  Closed file /pnfs/lariat/pnfs/fnal.gov/usr/lariat/raw/000/541/lariat_r006099_sr0607.root
++++finished: close input file
++++open input file
06-Jul-2015 10:33:42 CDT  Initiating request to open file /pnfs/lariat/pnfs/fnal.gov/usr/lariat/raw/000/541/lariat_r006099_sr0608.root
06-Jul-2015 10:33:42 CDT  Successfully opened file /pnfs/lariat/pnfs/fnal.gov/usr/lariat/raw/000/541/lariat_r006099_sr0608.root
++++finished: open input file /pnfs/lariat/pnfs/fnal.gov/usr/lariat/raw/000/541/lariat_r006099_sr0608.root
++++source run
++++finished: source run
%MSG-w RunMerging:  SourceRun 06-Jul-2015 10:33:42 CDT PostProcessEvent
Problem found while adding product provenance, product already exists for (artdaq::PackageBuildInfos,lariatOnlineBuildInfo,LariatOnlineBuildInfo,DAQAG)

%MSG
++++ processing end subRun:run: 6099 subRun: 607 time:1434088907
++++++ processing path for end subRun:end_path
++++++++ module for end subRun:out1
++++++++ finished for end subRun:out1
++++++ finished path for end subRun:
++++ finished end subRun:
++++source subRun
++++finished: source subRun
++++ processing begin subRun:run: 6099 subRun: 608 time:1434088967
++++++ processing path for begin subRun:end_path
++++++++ module for begin subRun:out1
++++++++ finished for begin subRun:out1
++++++ finished path for begin subRun:
++++ finished begin subRun:
++++source event
Begin processing the 3rd record. run: 6099 subRun: 608 event: 608 at 06-Jul-2015 10:33:42 CDT
++++finished: source event
++++ processing event:run: 6099 subRun: 608 event: 608 time:1434088967
++++++ processing path for event:end_path
++++++++ module for event:out1
PROCESS NAME | MODULE LABEL.. | PRODUCT INSTANCE NAME | DATA PRODUCT TYPE............ | SIZE
DAQ......... | daq........... | unidentified......... | std::vector<artdaq::Fragment> | ...?
DAQ......... | daq........... | SPILL................ | std::vector<artdaq::Fragment> | ...1
DAQAG....... | TriggerResults | ..................... | art::TriggerResults.......... | ...-

Total products (present, not present): 3 (2, 1).

++++++++ finished for event:out1
++++++ finished path for event:
++++ finished event:
++++close input file
06-Jul-2015 10:33:42 CDT  Closed file /pnfs/lariat/pnfs/fnal.gov/usr/lariat/raw/000/541/lariat_r006099_sr0608.root
++++finished: close input file
++++open input file
06-Jul-2015 10:33:42 CDT  Initiating request to open file /pnfs/lariat/pnfs/fnal.gov/usr/lariat/raw/000/541/lariat_r006099_sr0609.root
06-Jul-2015 10:33:42 CDT  Successfully opened file /pnfs/lariat/pnfs/fnal.gov/usr/lariat/raw/000/541/lariat_r006099_sr0609.root
++++finished: open input file /pnfs/lariat/pnfs/fnal.gov/usr/lariat/raw/000/541/lariat_r006099_sr0609.root
++++source run
++++finished: source run
%MSG-w RunMerging:  SourceRun 06-Jul-2015 10:33:42 CDT PostProcessEvent
Problem found while adding product provenance, product already exists for (artdaq::PackageBuildInfos,lariatOnlineBuildInfo,LariatOnlineBuildInfo,DAQAG)

%MSG
++++ processing end subRun:run: 6099 subRun: 608 time:1434088967
++++++ processing path for end subRun:end_path
++++++++ module for end subRun:out1
++++++++ finished for end subRun:out1
++++++ finished path for end subRun:
++++ finished end subRun:
++++source subRun
++++finished: source subRun
++++ processing begin subRun:run: 6099 subRun: 609 time:1434089028
++++++ processing path for begin subRun:end_path
++++++++ module for begin subRun:out1
++++++++ finished for begin subRun:out1
++++++ finished path for begin subRun:
++++ finished begin subRun:
++++source event
++++finished: source event
Begin processing the 4th record. run: 6099 subRun: 609 event: 609 at 06-Jul-2015 10:33:42 CDT
++++ processing event:run: 6099 subRun: 609 event: 609 time:1434089028
++++++ processing path for event:end_path
++++++++ module for event:out1
PROCESS NAME | MODULE LABEL.. | PRODUCT INSTANCE NAME | DATA PRODUCT TYPE............ | SIZE
DAQ......... | daq........... | unidentified......... | std::vector<artdaq::Fragment> | ...?
DAQ......... | daq........... | SPILL................ | std::vector<artdaq::Fragment> | ...1
DAQAG....... | TriggerResults | ..................... | art::TriggerResults.......... | ...-

Total products (present, not present): 3 (2, 1).

++++++++ finished for event:out1
++++++ finished path for event:
++++ finished event:
++++close input file
06-Jul-2015 10:33:42 CDT  Closed file /pnfs/lariat/pnfs/fnal.gov/usr/lariat/raw/000/541/lariat_r006099_sr0609.root
++++finished: close input file
++++open input file
06-Jul-2015 10:33:42 CDT  Initiating request to open file /pnfs/lariat/pnfs/fnal.gov/usr/lariat/raw/000/541/lariat_r006099_sr0625.root
06-Jul-2015 10:33:43 CDT  Successfully opened file /pnfs/lariat/pnfs/fnal.gov/usr/lariat/raw/000/541/lariat_r006099_sr0625.root
++++finished: open input file /pnfs/lariat/pnfs/fnal.gov/usr/lariat/raw/000/541/lariat_r006099_sr0625.root
++++source run
++++finished: source run
%MSG-w RunMerging:  SourceRun 06-Jul-2015 10:33:43 CDT PostProcessEvent
Problem found while adding product provenance, product already exists for (artdaq::PackageBuildInfos,lariatOnlineBuildInfo,LariatOnlineBuildInfo,DAQAG)

%MSG
++++ processing end subRun:run: 6099 subRun: 609 time:1434089028
++++++ processing path for end subRun:end_path
++++++++ module for end subRun:out1
++++++++ finished for end subRun:out1
++++++ finished path for end subRun:
++++ finished end subRun:
++++source subRun
++++finished: source subRun
++++ processing begin subRun:run: 6099 subRun: 625 time:1434089991
++++++ processing path for begin subRun:end_path
++++++++ module for begin subRun:out1
++++++++ finished for begin subRun:out1
++++++ finished path for begin subRun:
++++ finished begin subRun:
++++source event
Begin processing the 5th record. run: 6099 subRun: 625 event: 625 at 06-Jul-2015 10:33:43 CDT
++++finished: source event
++++ processing event:run: 6099 subRun: 625 event: 625 time:1434089991
++++++ processing path for event:end_path
++++++++ module for event:out1
PROCESS NAME | MODULE LABEL.. | PRODUCT INSTANCE NAME | DATA PRODUCT TYPE............ | SIZE
DAQ......... | daq........... | unidentified......... | std::vector<artdaq::Fragment> | ...?
DAQ......... | daq........... | SPILL................ | std::vector<artdaq::Fragment> | ...1
DAQAG....... | TriggerResults | ..................... | art::TriggerResults.......... | ...-

Total products (present, not present): 3 (2, 1).

++++++++ finished for event:out1
++++++ finished path for event:
++++ finished event:
++++close input file
06-Jul-2015 10:33:43 CDT  Closed file /pnfs/lariat/pnfs/fnal.gov/usr/lariat/raw/000/541/lariat_r006099_sr0625.root
++++finished: close input file
++++open input file
06-Jul-2015 10:33:43 CDT  Initiating request to open file /pnfs/lariat/pnfs/fnal.gov/usr/lariat/raw/000/541/lariat_r006099_sr0626.root
06-Jul-2015 10:33:43 CDT  Successfully opened file /pnfs/lariat/pnfs/fnal.gov/usr/lariat/raw/000/541/lariat_r006099_sr0626.root
++++finished: open input file /pnfs/lariat/pnfs/fnal.gov/usr/lariat/raw/000/541/lariat_r006099_sr0626.root
++++source run
++++finished: source run
++++ processing end subRun:run: 6099 subRun: 625 time:1434089991
++++++ processing path for end subRun:end_path
++++++++ module for end subRun:out1
++++++++ finished for end subRun:out1
++++++ finished path for end subRun:
++++ finished end subRun:
++++source subRun
%MSG-w RunMerging:  SourceRun 06-Jul-2015 10:33:43 CDT PostProcessEvent
Problem found while adding product provenance, product already exists for (artdaq::PackageBuildInfos,lariatOnlineBuildInfo,LariatOnlineBuildInfo,DAQAG)

%MSG
++++finished: source subRun
++++ processing begin subRun:run: 6099 subRun: 626 time:1434090051
++++++ processing path for begin subRun:end_path
++++++++ module for begin subRun:out1
++++++++ finished for begin subRun:out1
++++++ finished path for begin subRun:
++++ finished begin subRun:
++++source event
Begin processing the 6th record. run: 6099 subRun: 626 event: 626 at 06-Jul-2015 10:33:43 CDT
++++finished: source event
++++ processing event:run: 6099 subRun: 626 event: 626 time:1434090051
++++++ processing path for event:end_path
++++++++ module for event:out1
PROCESS NAME | MODULE LABEL.. | PRODUCT INSTANCE NAME | DATA PRODUCT TYPE............ | SIZE
DAQ......... | daq........... | unidentified......... | std::vector<artdaq::Fragment> | ...?
DAQ......... | daq........... | SPILL................ | std::vector<artdaq::Fragment> | ...1
DAQAG....... | TriggerResults | ..................... | art::TriggerResults.......... | ...-

Total products (present, not present): 3 (2, 1).

++++++++ finished for event:out1
++++++ finished path for event:
++++ finished event:
++++close input file
06-Jul-2015 10:33:43 CDT  Closed file /pnfs/lariat/pnfs/fnal.gov/usr/lariat/raw/000/541/lariat_r006099_sr0626.root
++++finished: close input file
++++open input file
06-Jul-2015 10:33:43 CDT  Initiating request to open file /pnfs/lariat/pnfs/fnal.gov/usr/lariat/raw/000/541/lariat_r006099_sr0627.root
06-Jul-2015 10:33:43 CDT  Successfully opened file /pnfs/lariat/pnfs/fnal.gov/usr/lariat/raw/000/541/lariat_r006099_sr0627.root
++++finished: open input file /pnfs/lariat/pnfs/fnal.gov/usr/lariat/raw/000/541/lariat_r006099_sr0627.root
++++source run
++++finished: source run
%MSG-w RunMerging:  SourceRun 06-Jul-2015 10:33:43 CDT PostProcessEvent
Problem found while adding product provenance, product already exists for (artdaq::PackageBuildInfos,lariatOnlineBuildInfo,LariatOnlineBuildInfo,DAQAG)

%MSG
++++ processing end subRun:run: 6099 subRun: 626 time:1434090051
++++++ processing path for end subRun:end_path
++++++++ module for end subRun:out1
++++++++ finished for end subRun:out1
++++++ finished path for end subRun:
++++ finished end subRun:
++++source subRun
++++finished: source subRun
++++ processing begin subRun:run: 6099 subRun: 627 time:1434090111
++++++ processing path for begin subRun:end_path
++++++++ module for begin subRun:out1
++++++++ finished for begin subRun:out1
++++++ finished path for begin subRun:
++++ finished begin subRun:
++++source event
Begin processing the 7th record. run: 6099 subRun: 627 event: 627 at 06-Jul-2015 10:33:43 CDT
++++finished: source event
++++ processing event:run: 6099 subRun: 627 event: 627 time:1434090111
++++++ processing path for event:end_path
++++++++ module for event:out1
PROCESS NAME | MODULE LABEL.. | PRODUCT INSTANCE NAME | DATA PRODUCT TYPE............ | SIZE
DAQ......... | daq........... | unidentified......... | std::vector<artdaq::Fragment> | ...?
DAQ......... | daq........... | SPILL................ | std::vector<artdaq::Fragment> | ...1
DAQAG....... | TriggerResults | ..................... | art::TriggerResults.......... | ...-

Total products (present, not present): 3 (2, 1).

++++++++ finished for event:out1
++++++ finished path for event:
++++ finished event:
++++close input file
06-Jul-2015 10:33:43 CDT  Closed file /pnfs/lariat/pnfs/fnal.gov/usr/lariat/raw/000/541/lariat_r006099_sr0627.root
++++finished: close input file
++++open input file
06-Jul-2015 10:33:43 CDT  Initiating request to open file /pnfs/lariat/pnfs/fnal.gov/usr/lariat/raw/000/541/lariat_r006099_sr0628.root
06-Jul-2015 10:33:43 CDT  Successfully opened file /pnfs/lariat/pnfs/fnal.gov/usr/lariat/raw/000/541/lariat_r006099_sr0628.root
++++finished: open input file /pnfs/lariat/pnfs/fnal.gov/usr/lariat/raw/000/541/lariat_r006099_sr0628.root
++++source run
++++finished: source run
%MSG-w RunMerging:  SourceRun 06-Jul-2015 10:33:43 CDT PostProcessEvent
Problem found while adding product provenance, product already exists for (artdaq::PackageBuildInfos,lariatOnlineBuildInfo,LariatOnlineBuildInfo,DAQAG)

%MSG
++++ processing end subRun:run: 6099 subRun: 627 time:1434090111
++++++ processing path for end subRun:end_path
++++++++ module for end subRun:out1
++++++++ finished for end subRun:out1
++++++ finished path for end subRun:
++++ finished end subRun:
++++source subRun
++++finished: source subRun
++++ processing begin subRun:run: 6099 subRun: 628 time:1434090171
++++++ processing path for begin subRun:end_path
++++++++ module for begin subRun:out1
++++++++ finished for begin subRun:out1
++++++ finished path for begin subRun:
++++ finished begin subRun:
++++source event
Begin processing the 8th record. run: 6099 subRun: 628 event: 628 at 06-Jul-2015 10:33:43 CDT
++++finished: source event
++++ processing event:run: 6099 subRun: 628 event: 628 time:1434090171
++++++ processing path for event:end_path
++++++++ module for event:out1
PROCESS NAME | MODULE LABEL.. | PRODUCT INSTANCE NAME | DATA PRODUCT TYPE............ | SIZE
DAQ......... | daq........... | unidentified......... | std::vector<artdaq::Fragment> | ...?
DAQ......... | daq........... | SPILL................ | std::vector<artdaq::Fragment> | ...1
DAQAG....... | TriggerResults | ..................... | art::TriggerResults.......... | ...-

Total products (present, not present): 3 (2, 1).

++++++++ finished for event:out1
++++++ finished path for event:
++++ finished event:
++++close input file
06-Jul-2015 10:33:43 CDT  Closed file /pnfs/lariat/pnfs/fnal.gov/usr/lariat/raw/000/541/lariat_r006099_sr0628.root
++++finished: close input file
++++open input file
06-Jul-2015 10:33:43 CDT  Initiating request to open file /pnfs/lariat/pnfs/fnal.gov/usr/lariat/raw/000/541/lariat_r006099_sr0629.root
06-Jul-2015 10:33:43 CDT  Successfully opened file /pnfs/lariat/pnfs/fnal.gov/usr/lariat/raw/000/541/lariat_r006099_sr0629.root
++++finished: open input file /pnfs/lariat/pnfs/fnal.gov/usr/lariat/raw/000/541/lariat_r006099_sr0629.root
++++source run
++++finished: source run
%MSG-w RunMerging:  SourceRun 06-Jul-2015 10:33:43 CDT PostProcessEvent
Problem found while adding product provenance, product already exists for (artdaq::PackageBuildInfos,lariatOnlineBuildInfo,LariatOnlineBuildInfo,DAQAG)

%MSG
++++ processing end subRun:run: 6099 subRun: 628 time:1434090171
++++++ processing path for end subRun:end_path
++++++++ module for end subRun:out1
++++++++ finished for end subRun:out1
++++++ finished path for end subRun:
++++ finished end subRun:
++++source subRun
++++finished: source subRun
++++ processing begin subRun:run: 6099 subRun: 629 time:1434090232
++++++ processing path for begin subRun:end_path
++++++++ module for begin subRun:out1
++++++++ finished for begin subRun:out1
++++++ finished path for begin subRun:
++++ finished begin subRun:
++++source event
++++finished: source event
Begin processing the 9th record. run: 6099 subRun: 629 event: 629 at 06-Jul-2015 10:33:43 CDT
++++ processing event:run: 6099 subRun: 629 event: 629 time:1434090232
++++++ processing path for event:end_path
++++++++ module for event:out1
PROCESS NAME | MODULE LABEL.. | PRODUCT INSTANCE NAME | DATA PRODUCT TYPE............ | SIZE
DAQ......... | daq........... | unidentified......... | std::vector<artdaq::Fragment> | ...?
DAQ......... | daq........... | SPILL................ | std::vector<artdaq::Fragment> | ...1
DAQAG....... | TriggerResults | ..................... | art::TriggerResults.......... | ...-

Total products (present, not present): 3 (2, 1).

++++++++ finished for event:out1
++++++ finished path for event:
++++ finished event:
++++close input file
06-Jul-2015 10:33:44 CDT  Closed file /pnfs/lariat/pnfs/fnal.gov/usr/lariat/raw/000/541/lariat_r006099_sr0629.root
++++finished: close input file
++++open input file
06-Jul-2015 10:33:44 CDT  Initiating request to open file /pnfs/lariat/pnfs/fnal.gov/usr/lariat/raw/000/541/lariat_r006099_sr0630.root
06-Jul-2015 10:33:44 CDT  Successfully opened file /pnfs/lariat/pnfs/fnal.gov/usr/lariat/raw/000/541/lariat_r006099_sr0630.root
++++finished: open input file /pnfs/lariat/pnfs/fnal.gov/usr/lariat/raw/000/541/lariat_r006099_sr0630.root
++++source run
++++finished: source run
%MSG-w RunMerging:  SourceRun 06-Jul-2015 10:33:44 CDT PostProcessEvent
Problem found while adding product provenance, product already exists for (artdaq::PackageBuildInfos,lariatOnlineBuildInfo,LariatOnlineBuildInfo,DAQAG)

%MSG
++++ processing end subRun:run: 6099 subRun: 629 time:1434090232
++++++ processing path for end subRun:end_path
++++++++ module for end subRun:out1
++++++++ finished for end subRun:out1
++++++ finished path for end subRun:
++++ finished end subRun:
++++source subRun
++++finished: source subRun
++++ processing begin subRun:run: 6099 subRun: 630 time:1434090292
++++++ processing path for begin subRun:end_path
++++++++ module for begin subRun:out1
++++++++ finished for begin subRun:out1
++++++ finished path for begin subRun:
++++ finished begin subRun:
++++source event
Begin processing the 10th record. run: 6099 subRun: 630 event: 630 at 06-Jul-2015 10:33:44 CDT
++++finished: source event
++++ processing event:run: 6099 subRun: 630 event: 630 time:1434090292
++++++ processing path for event:end_path
++++++++ module for event:out1
PROCESS NAME | MODULE LABEL.. | PRODUCT INSTANCE NAME | DATA PRODUCT TYPE............ | SIZE
DAQ......... | daq........... | unidentified......... | std::vector<artdaq::Fragment> | ...?
DAQ......... | daq........... | SPILL................ | std::vector<artdaq::Fragment> | ...1
DAQAG....... | TriggerResults | ..................... | art::TriggerResults.......... | ...-

Total products (present, not present): 3 (2, 1).

++++++++ finished for event:out1
++++++ finished path for event:
++++ finished event:
++++ processing end subRun:run: 6099 subRun: 630 time:1434090292
++++++ processing path for end subRun:end_path
++++++++ module for end subRun:out1
++++++++ finished for end subRun:out1
++++++ finished path for end subRun:
++++ finished end subRun:
++++ processing end run:run: 6099 time:1434090292
++++++ processing path for end run:end_path
++++++++ module for end run:out1
++++++++ finished for end run:out1
++++++ finished path for end run:
++++ finished end run:
PROCESS NAME | MODULE LABEL......... | PRODUCT INSTANCE NAME | DATA PRODUCT TYPE.................... | SIZE
DAQAG....... | lariatOnlineBuildInfo | LariatOnlineBuildInfo | std::vector<artdaq::PackageBuildInfo> | ...3

Total products (present, not present): 1 (1, 0).

++++close output file from out1
++++finished close output file <none> from out1
++++close input file
06-Jul-2015 10:33:44 CDT  Closed file /pnfs/lariat/pnfs/fnal.gov/usr/lariat/raw/000/541/lariat_r006099_sr0630.root
++++finished: close input file
++ endJob module:out1
++ endJob finished:out1

TrigReport ---------- Event  Summary ------------
TrigReport Events total = 10 passed = 10 failed = 0

TrigReport ------ Modules in End-Path: end_path ------------
TrigReport  Trig Bit#    Visited     Passed     Failed      Error Name
TrigReport     0    0         10         10          0          0 out1

TimeReport ---------- Time  Summary ---[sec]----
++ Job ended
TimeReport CPU = 1.760061 Real = 1.757732

Art has completed and will exit with status 0.

The relevant .fcl files are attached.

#3 Updated by Christopher Green about 4 years ago

  • Status changed from Feedback to Assigned
  • Assignee set to Kyle Knoepfel
  • SSI Package art added
  • SSI Package deleted ()

Thanks for providing this information.

We will need to study this issue to analyze the behavior further.

#4 Updated by Kyle Knoepfel about 4 years ago

Upon investigation, the art::EventID objects of each of the input files have invalid member values. In other words, if one of the files is opened in a TBrowser, and one looks at the values of the FileIndex branch of the MetaData tree, the following numbers are obtained (in C++ish syntax):

RunNumber_t    run_; // ... run_ actually isn't used so no worries here
SubRunNumber_t subRun_ = { 6099, INVALID }; // where 6099 is the run number, but the subrun number is invalid
EventNumber_t  event_  = INVALID;

where INVALID is a constant literal of value -1.

To debug further we would need to know how the EventID was assigned in the source. Can you point us to the relevant code and FHiCL files?

#5 Updated by Brian Rebel about 4 years ago

The EventID was assigned by artdaq. Perhaps we have a problem there? The code is somewhere in lariatonline, but I don't know where. Perhaps John Freeman can help you?

#6 Updated by Kyle Knoepfel about 4 years ago

Our first analysis of the problem was incorrect -- after debugging with gdb, it appears the FileIndex elements for the individual input files have well-formed values. The confusion stemmed from the ROOT TBrowser printing incorrect values for the subrun and event numbers of the FileIndex branch. The next step is to verify that the aggregated file is well-formed.

Thanks for your patience.

#7 Updated by Kyle Knoepfel about 4 years ago

I have been able to reproduce the behavior described above: namely an assertion failure when attempting to access the next event through the event display, and no problems when running the eventdump.fcl job.

The aggregated file standard_reco.root has well-formed art::FileIndex::Element values, so I confirm that that is not the problem. Will now run the event-display process through gdb.

#8 Updated by Kyle Knoepfel about 4 years ago

  • % Done changed from 0 to 100

The problem is now understood. The details of the observed behavior are somewhat esoteric, but briefly speaking, since the EventDisplay::postProcessEvent callback calls RootInput::seekToEvent, the state of the event processor and the state as determined by RootInput get out-of-sync. This asynchrony is not a problem since the state machine is designed to handle it. However, an extra function that unnecessarily tests for this mismatch was added in art 1.14 to support secondary file reading. We will remove the assert call, which is not necessary here, and release a new version of art, 1.14.04, that does not have this problem.

In the meantime, since the problem is triggered by an assert, you can sidestep it entirely by using the prof build of art 1.14.03.

#9 Updated by Brian Rebel about 4 years ago

Thanks for the answer, Kyle.

We'll use a prof build for now, and update when the new art version is ready.

#10 Updated by Christopher Green about 4 years ago

  • Target version set to 1.15.01

#11 Updated by Christopher Green about 4 years ago

  • Status changed from Assigned to Resolved

Fix applied with 406626b.

#12 Updated by Kyle Knoepfel about 4 years ago

  • Status changed from Resolved to Closed


Also available in: Atom PDF