ganga
ganga copied to clipboard
Published
20 hours ago •
ganga-devs
ganga-devs
WIP: Create initial async monitoring service
This PR contains a very basic initial implementation of the new asyncio based monitoring service. It currently only works for the local backend.
Also every file that I change is formatted using autopep8 so that we can hopefully format most of the files as we go on.
You can run ganga as PYTHONASYNCIODEBUG=1 ganga. This enables asyncio's debug mode which logs issues such as non thread safe calls and slow coroutines (>100ms) on the event loop.
@mesmith75 @alexanderrichards I pushed some changes to handle graceful shutdown. Basically I added a method that cancels all remaining tasks except for the one currently running. I do that in the thread's stop method which is called here by GangaThreadPool since I am subclassing GangaThread.
My question is, do you think that is enough? In your experience are there any termination signals that are not handled by GangaTheadPool in which case I should add some signal handlers?
My question is, do you think that is enough? In your experience are there any termination signals that are not handled by GangaTheadPool in which case I should add some signal handlers?
From memory GangThreadPool should handle most cases. Although I can't remember where we register the signal handler for things like SIGINT/SIGTERM and it doesn't appear to be in the GangaThreadPool itself
I left it running to monitor and finalise some Dirac jobs - it is producing a stream of errors:
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/afs/cern.ch/user/m/masmith/ganga_testing/lib/python3.9/site-packages/ganga/GangaCore/Core/MonitoringComponent/MonitoringService.py", line 21, in log_exceptions
return await awaitable
File "/afs/cern.ch/user/m/masmith/ganga_testing/lib/python3.9/site-packages/ganga/GangaDirac/Lib/Backends/DiracBase.py", line 1607, in updateMonitoringInformation
await DiracBase.monitor_dirac_running_jobs(monitor_jobs_group, finalised_statuses)
File "/afs/cern.ch/user/m/masmith/ganga_testing/lib/python3.9/site-packages/ganga/GangaDirac/Lib/Backends/DiracBase.py", line 1483, in monitor_dirac_running_jobs
result = await dm.execute(dirac_status, args_dict={'job_ids': dirac_job_ids, 'statusmapping': statusmapping})
File "/afs/cern.ch/user/m/masmith/ganga_testing/lib/python3.9/site-packages/ganga/GangaDirac/Lib/Server/DiracProcessManager.py", line 86, in execute
if not self.is_dirac_process_active(env_hash):
File "/afs/cern.ch/user/m/masmith/ganga_testing/lib/python3.9/site-packages/ganga/GangaDirac/Lib/Server/DiracProcessManager.py", line 78, in is_dirac_process_active
if not psutil.pid_exists(pid):
File "/afs/cern.ch/user/m/masmith/ganga_testing/lib/python3.9/site-packages/psutil/__init__.py", line 1389, in pid_exists
File "/afs/cern.ch/user/m/masmith/ganga_testing/lib/python3.9/site-packages/psutil/_pslinux.py", line 1610, in pid_exists
File "/afs/cern.ch/user/m/masmith/ganga_testing/lib/python3.9/site-packages/psutil/_pslinux.py", line 1578, in pids
OSError: [Errno 24] Too many open files: b'/proc'
Unfortunately the original error has disappeared off the screen
When I try to quit I get some different errors:
Traceback (most recent call last):
File "/afs/cern.ch/user/m/masmith/ganga_testing/lib/python3.9/site-packages/ganga/GangaCore/Core/MonitoringComponent/MonitoringService.py", line 21, in log_exceptions
return await awaitable
File "/afs/cern.ch/user/m/masmith/ganga_testing/lib/python3.9/site-packages/ganga/GangaDirac/Lib/Backends/DiracBase.py", line 1607, in updateMonitoringInformation
await DiracBase.monitor_dirac_running_jobs(monitor_jobs_group, finalised_statuses)
File "/afs/cern.ch/user/m/masmith/ganga_testing/lib/python3.9/site-packages/ganga/GangaDirac/Lib/Backends/DiracBase.py", line 1483, in monitor_dirac_running_jobs
result = await dm.execute(dirac_status, args_dict={'job_ids': dirac_job_ids, 'statusmapping': statusmapping})
File "/afs/cern.ch/user/m/masmith/ganga_testing/lib/python3.9/site-packages/ganga/GangaDirac/Lib/Server/DiracProcessManager.py", line 91, in execute
await self.task_queues[env_hash].coro_put((task_done, task_id, cmd, args_dict))
File "/afs/cern.ch/user/m/masmith/ganga_testing/lib/python3.9/site-packages/aioprocessing/executor.py", line 192, in coro_func
return self.run_in_executor(
File "/afs/cern.ch/user/m/masmith/ganga_testing/lib/python3.9/site-packages/aioprocessing/executor.py", line 13, in wrapper
return func(self, *args, **kwargs)
File "/afs/cern.ch/user/m/masmith/ganga_testing/lib/python3.9/site-packages/aioprocessing/executor.py", line 39, in run_in_executor
return util.run_in_executor(
File "/afs/cern.ch/user/m/masmith/ganga_testing/lib/python3.9/site-packages/aioprocessing/util.py", line 12, in run_in_executor
return loop.run_in_executor(executor, callback, *args)
File "/cvmfs/lhcb.cern.ch/lib/var/lib/LbEnv/2541/stable/linux-64/lib/python3.9/asyncio/base_events.py", line 819, in run_in_executor
executor.submit(func, *args), loop=self)
File "/cvmfs/lhcb.cern.ch/lib/var/lib/LbEnv/2541/stable/linux-64/lib/python3.9/concurrent/futures/thread.py", line 167, in submit
raise RuntimeError('cannot schedule new futures after shutdown')
RuntimeError: cannot schedule new futures after shutdown
This is eventually followed by:
ERROR A severe error occurred in the Repository 'jobs': IOError on AFS global lock: [Errno 24] Too many open files: '/afs/cern.ch/work/m/masmith/gangadir_kstmumu_data/repository/masmith/LocalXML/6.0/sessions/global_lock.afs/lock_file'
ERROR If you believe the problem has been solved, type "reactivate()" to re-enable
ERROR Cannot disable monitoring loop. It has already been stopped
ERROR Shutting Down Repository_runtime
@mesmith75 Could you give a brief overview of what your workflow looks like? Judging by the error OSError: [Errno 24] Too many open files: b'/proc' my first guess is that your environment somehow enforces a minimum amount of resources that can be open. Could you run ulimit -n?
For this I just started it with an existing repository to monitor and finalise some jobs submitted to Dirac. Maybe a few hundred subjobs in total. From ulimit -n I find 1024 .
@mesmith75 The second error is something I am working on right now, it happens when we try to quit Ganga while a long asyncio task is still running. It is not relevant to the first error unless the first error causes the app to hang.
Right, so I am pretty sure that the issue is that we are exceeding the maximum amount of allowed resource usage. Could you also please give me the output of ulimit -a?
core file size (blocks, -c) 0
data seg size (kbytes, -d) unlimited
scheduling priority (-e) 0
file size (blocks, -f) unlimited
pending signals (-i) 116901
max locked memory (kbytes, -l) 64
max memory size (kbytes, -m) unlimited
open files (-n) 1024
pipe size (512 bytes, -p) 8
POSIX message queues (bytes, -q) 819200
real-time priority (-r) 0
stack size (kbytes, -s) 8192
cpu time (seconds, -t) unlimited
max user processes (-u) 4096
virtual memory (kbytes, -v) unlimited
file locks (-x) unlimited
Alright thanks, I will get to memory profiling the app so that I can see which of these resources we are exceeding the limit of and get back to you. It would also help if you could give me a more specific sense of the DIRAC jobs you tested it with so that I can replicate it. I.e. number of subjobs, and output sandbox size.
It was about 20 jobs in total, with a varying number of subjobs (from 15 - 277) although most subjobs had already completed. I think in total there were about 100 still to finalise. Each sandbox is ~475K
I see, thank you. A last piece of relevant info, could you also give me the max number of subjobs that can be monitored at once within your Ganga config? You can check it by using config['PollThread']['numParallelJobs'] within ganga.
So it seems like the sessionLocks are only two files for each repository, so they should not be involved in the 1024 issue. I think the /afs file system might still be the issue though. When using /afs, we sometimes see leftover files that prevent us from deleting directories (as in that you can't delete a directory that contains a file that is open). It makes me wonder if we somehow "hang on" to files long after they have been opened. Opening and closing many files in a short time could then cause the problem.
I tried on one of the Imperial computers. There are no errors but it doesn't seem to be monitoring Dirac jobs. It did for a local one but nothing on Dirac (ignore the first that is a very old job):
Ganga In [15]: jobs
Ganga Out [15]:
Registry Slice: jobs (4 objects)
--------------
fqid | status | name | subjobs | application | backend |backend.actualCE | comment | subjob status
--------------------------------------------------------------------------------------------------------------------------------------------------------------------
44 | submitted | | | Executable | Dirac |LCG.NCBJ.p | | 0/0/0/0
45 | submitted | | | Executable | Dirac | None | | 0/0/0/0
46 | completed | | | Executable | Localhost |lx03.hep.p | | 0/0/0/0
47 | submitted | | | Executable | Dirac | None | | 0/0/0/0
I also left it running on the Imperial machine and it came up with this error:
Traceback (most recent call last):
File "/cvmfs/lhcb.cern.ch/lib/var/lib/LbEnv/2541/stable/linux-64/lib/python3.9/multiprocessing/managers.py", line 802, in _callmethod
conn = self._tls.connection
AttributeError: 'ForkAwareLocal' object has no attribute 'connection'
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/home/hep/mesmith/ganga_async_test/lib/python3.9/site-packages/ganga/GangaCore/Core/MonitoringComponent/MonitoringService.py", line 21, in log_exceptions
return await awaitable
File "/home/hep/mesmith/ganga_async_test/lib/python3.9/site-packages/ganga/GangaDirac/Lib/Backends/DiracBase.py", line 1607, in updateMonitoringInformation
await DiracBase.monitor_dirac_running_jobs(monitor_jobs_group, finalised_statuses)
File "/home/hep/mesmith/ganga_async_test/lib/python3.9/site-packages/ganga/GangaDirac/Lib/Backends/DiracBase.py", line 1483, in monitor_dirac_running_jobs
result = await dm.execute(dirac_status, args_dict={'job_ids': dirac_job_ids, 'statusmapping': statusmapping})
File "/home/hep/mesmith/ganga_async_test/lib/python3.9/site-packages/ganga/GangaDirac/Lib/Server/DiracProcessManager.py", line 93, in execute
await task_done.coro_wait()
File "/cvmfs/lhcb.cern.ch/lib/var/lib/LbEnv/2541/stable/linux-64/lib/python3.9/concurrent/futures/thread.py", line 58, in run
result = self.fn(*self.args, **self.kwargs)
File "/cvmfs/lhcb.cern.ch/lib/var/lib/LbEnv/2541/stable/linux-64/lib/python3.9/multiprocessing/managers.py", line 806, in _callmethod
self._connect()
File "/cvmfs/lhcb.cern.ch/lib/var/lib/LbEnv/2541/stable/linux-64/lib/python3.9/multiprocessing/managers.py", line 793, in _connect
conn = self._Client(self._token.address, authkey=self._authkey)
File "/cvmfs/lhcb.cern.ch/lib/var/lib/LbEnv/2541/stable/linux-64/lib/python3.9/multiprocessing/connection.py", line 513, in Client
answer_challenge(c, authkey)
File "/cvmfs/lhcb.cern.ch/lib/var/lib/LbEnv/2541/stable/linux-64/lib/python3.9/multiprocessing/connection.py", line 757, in answer_challenge
message = connection.recv_bytes(256) # reject large message
File "/cvmfs/lhcb.cern.ch/lib/var/lib/LbEnv/2541/stable/linux-64/lib/python3.9/multiprocessing/connection.py", line 221, in recv_bytes
buf = self._recv_bytes(maxlength)
File "/cvmfs/lhcb.cern.ch/lib/var/lib/LbEnv/2541/stable/linux-64/lib/python3.9/multiprocessing/connection.py", line 419, in _recv_bytes
buf = self._recv(4)
File "/cvmfs/lhcb.cern.ch/lib/var/lib/LbEnv/2541/stable/linux-64/lib/python3.9/multiprocessing/connection.py", line 388, in _recv
raise EOFError
EOFError
[12:11:41]
Interestingly I was unable to log in to that machine again until I had closed ganga - ssh was giving me:
shell request failed on channel 0
So I tried this out as well in yet another different environment. Just gtried to submit a single job to the Dirac backend. What I observe is
- No monitoring of job
- An error on shutdown (see below).
Ganga In [2]:
Do you really want to exit ([y]/n)?
Traceback (most recent call last):
File "/centos/ganga/ganga/ganga/GangaCore/Core/MonitoringComponent/MonitoringService.py", line 21, in log_exceptions
return await awaitable
File "/centos/ganga/ganga/ganga/GangaDirac/Lib/Backends/DiracBase.py", line 1607, in updateMonitoringInformation
await DiracBase.monitor_dirac_running_jobs(monitor_jobs_group, finalised_statuses)
File "/centos/ganga/ganga/ganga/GangaDirac/Lib/Backends/DiracBase.py", line 1483, in monitor_dirac_running_jobs
result = await dm.execute(dirac_status, args_dict={'job_ids': dirac_job_ids, 'statusmapping': statusmapping})
File "/centos/ganga/ganga/ganga/GangaDirac/Lib/Server/DiracProcessManager.py", line 91, in execute
await self.task_queues[env_hash].coro_put((task_done, task_id, cmd, args_dict))
File "/centos/ganga/lib/python3.9/site-packages/aioprocessing/executor.py", line 192, in coro_func
return self.run_in_executor(
File "/centos/ganga/lib/python3.9/site-packages/aioprocessing/executor.py", line 13, in wrapper
return func(self, *args, **kwargs)
File "/centos/ganga/lib/python3.9/site-packages/aioprocessing/executor.py", line 39, in run_in_executor
return util.run_in_executor(
File "/centos/ganga/lib/python3.9/site-packages/aioprocessing/util.py", line 12, in run_in_executor
return loop.run_in_executor(executor, callback, *args)
File "/cvmfs/lhcb.cern.ch/lib/var/lib/LbEnv/2541/stable/linux-64/lib/python3.9/asyncio/base_events.py", line 819, in run_in_executor
executor.submit(func, *args), loop=self)
File "/cvmfs/lhcb.cern.ch/lib/var/lib/LbEnv/2541/stable/linux-64/lib/python3.9/concurrent/futures/thread.py", line 167, in submit
raise RuntimeError('cannot schedule new futures after shutdown')
RuntimeError: cannot schedule new futures after shutdown
A few thoughts as to why this doesn't work for @egede and @mesmith75 but does for @joj0s
- Different
Diracserver is used - CERN (LHCb) vs Imperial - Backend is not quite the same ( GangaLHCb/Lib/Backends/Dirac.py vs GangaDirac/Lib/Backends/Dirac.py. Both depend on the same
DiracBase. - Different python version (3.9 vs 3.8)
Running ganga --debug, I see the following (job number 2 is the one submitted to Dirac. It has finished but Ganga never registered this, so it is in the submitted state). In notice Monitoring jobs: ['Job#2'] and Finished Monitoring request, so it seems to register that it should monitor the job.
2022-10-19 01:30:37,879 GANGA_Update_Thread_AsyncMonitoringService Registry ::keys :380 DEBUG : keys
2022-10-19 01:30:37,881 MainThread bootstrap ::bootstrap :953 DEBUG : Post-Bootstrap hooks
2022-10-19 01:30:37,881 GANGA_Update_Thread_AsyncMonitoringService Registry ::ids :362 DEBUG : ids
2022-10-19 01:30:37,882 GANGA_Update_Thread_AsyncMonitoringService MonitoringService ::_check_active_backends:78 DEBUG : Adding Dirac to list of backends to monitor.
2022-10-19 01:30:37,883 MainThread ICredentialInfo ::__init__ :128 DEBUG : Trying to wrap /tmp/x509up_u1000
2022-10-19 01:30:37,883 GANGA_Update_Thread_AsyncMonitoringService MonitoringService ::_check_backend :111 DEBUG : Checking backend Dirac
2022-10-19 01:30:37,883 MainThread ICredentialInfo ::exists :254 DEBUG : Checking for Credential at: '/tmp/x509up_u1000'
2022-10-19 01:30:37,883 GANGA_Update_Thread_AsyncMonitoringService IBackend ::master_updateMonitoringInformation:421 DEBUG : Running Monitoring for Jobs: ['2']
2022-10-19 01:30:37,883 MainThread ICredentialInfo ::__init__ :131 DEBUG : Wrapping existing file /tmp/x509up_u1000
2022-10-19 01:30:37,883 GANGA_Update_Thread_AsyncMonitoringService Registry ::_locked_load :554 DEBUG : _locked_load
2022-10-19 01:30:37,883 MainThread ICredentialInfo ::exists :254 DEBUG : Checking for Credential at: '/tmp/x509up_u1000'
2022-10-19 01:30:37,884 GANGA_Update_Thread_AsyncMonitoringService GangaRepositoryXML ::load :1032 DEBUG : Loading Repo object(s): [2]
2022-10-19 01:30:37,884 MainThread ICredentialInfo ::check_requirements :227 DEBUG : Credential exists, checking it
2022-10-19 01:30:37,884 MainThread DiracUtilities ::get_env :92 DEBUG : Running DIRAC source command nonsense
2022-10-19 01:30:37,887 GANGA_Update_Thread_AsyncMonitoringService GangaRepositoryXML ::_load_xml_from_obj :941 DEBUG : Loading XML file for ID: 2 took 0.002440214157104492 sec
2022-10-19 01:30:37,887 GANGA_Update_Thread_AsyncMonitoringService GangaRepositoryXML ::_load_xml_from_obj :949 DEBUG : Checking children: 2
2022-10-19 01:30:37,889 GANGA_Update_Thread_AsyncMonitoringService SubJobXMLList ::countSubJobDirs :633 DEBUG : count: 0 len: 0
2022-10-19 01:30:37,889 GANGA_Update_Thread_AsyncMonitoringService GangaRepositoryXML ::_load_xml_from_obj :955 DEBUG : Found children: False
2022-10-19 01:30:37,891 GANGA_Update_Thread_AsyncMonitoringService GangaRepositoryXML ::_load_xml_from_obj :966 DEBUG : Finished Loading XML
2022-10-19 01:30:37,892 GANGA_Update_Thread_AsyncMonitoringService GangaRepositoryXML ::load :1091 DEBUG : Finished 'load'-ing of: [2]
2022-10-19 01:30:37,892 MainThread execute ::execute :228 DEBUG : Executing Command:
'source nonsense;python -c "import base64;exec(base64.b64decode(b'CmltcG9ydCBvcwppbXBvcnQgcGlja2xlIGFzIHBpY2tsZQp3aXRoIG9zLmZkb3BlbigxMiwnd2InKSBhcyBlbnZwaXBlOgogICAgcGlja2xlLmR1bXAoZGljdChvcy5lbnZpcm9uKSwgZW52cGlwZSwgMikK'))"'
2022-10-19 01:30:37,892 GANGA_Update_Thread_AsyncMonitoringService IBackend ::master_updateMonitoringInformation:504 DEBUG : Monitoring jobs: ['Job#2']
2022-10-19 01:30:37,892 GANGA_Update_Thread_AsyncMonitoringService IBackend ::master_updateMonitoringInformation:508 DEBUG : Finished Monitoring request
2022-10-19 01:30:37,893 GANGA_Update_Thread_AsyncMonitoringService MonitoringService ::_log_backend_summary:93 DEBUG : Active backends: {"Dirac" : [2, ], }
2022-10-19 01:30:37,893 GANGA_Update_Thread_AsyncMonitoringService ICredentialInfo ::__init__ :128 DEBUG : Trying to wrap /tmp/x509up_u1000
2022-10-19 01:30:37,893 GANGA_Update_Thread_AsyncMonitoringService ICredentialInfo ::exists :254 DEBUG : Checking for Credential at: '/tmp/x509up_u1000'
2022-10-19 01:30:37,894 GANGA_Update_Thread_AsyncMonitoringService ICredentialInfo ::__init__ :131 DEBUG : Wrapping existing file /tmp/x509up_u1000
2022-10-19 01:30:37,894 GANGA_Update_Thread_AsyncMonitoringService ICredentialInfo ::exists :254 DEBUG : Checking for Credential at: '/tmp/x509up_u1000'
2022-10-19 01:30:37,894 GANGA_Update_Thread_AsyncMonitoringService ICredentialInfo ::check_requirements :227 DEBUG : Credential exists, checking it
@egede I am pushing a commit that adds more logging, specifically to see what happens within the DIRAC subprocess. If you could please repeat the above process and provide a similar log to the one you did it would be really helpful to get to the bottom of this.
All of your assumptions as to why all the tests are passing and this works for me but not for you seem plausible. I also have another one in mind. The subprocess module that we previously used to start DIRAC processes accepts an env argument which sets the process environment. The multiprocessing module that we now use however does not, and what I am doing is I am accepting an environment dictionary and setting each env variable manually as you can see here. So maybe the created CERN environments aren't what we would expect and it causes something to break? I have no way to test this however. The only way to do that would be to switch to the develop branch and take a snapshot of the environment created within a DIRAC subprocess and compare it to a snapshot of this branch.
But let's first see what the new logging output produces.
Also this error Mark provided is interesting:
AttributeError: 'ForkAwareLocal' object has no attribute 'connection'
Searching for it, I found that it occurs when we use a shared space data structure (in our case the queue that we use to communicate between the main Ganga process and the DIRAC subprocess) and the main process (in our case Ganga) exits ungracefully. So @mesmith75 did you see somethiing happen to crash the Ganga process? If not, I believe PR #2075 might solve this, because we handle SIGTERM and exit everything gracefully.
Here is the full debug from starting Ganga to quitting again. I updated to the latest commit on this branch.
(ganga) [centos7] ~/ganga/ganga new_monitoring_service % ganga --debug
*** Welcome to Ganga ***
Version: 8.6.0 - DEV
Documentation: https://ganga.readthedocs.io/en/latest/
Report issues: https://github.com/ganga-devs/ganga
Type help() or help('index') for online help.
This is free software (GPL), and you are welcome to redistribute it
under certain conditions; type license() for details.
2022-10-19 11:10:59,564 MainThread Config ::setSessionValue :608 DEBUG : trying to set session option [System]GANGA_CONFIG_PATH = /centos/ganga/ganga/ganga/GangaLHCb/LHCb.ini
2022-10-19 11:10:59,564 MainThread Config ::convert_type :427 DEBUG : checking value type: <class 'str'> (while setting option [.]GANGA_CONFIG_PATH = /centos/ganga/ganga/ganga/GangaLHCb/LHCb.ini )
2022-10-19 11:10:59,565 MainThread Config ::setSessionValue :621 DEBUG : sucessfully set session option [System]GANGA_CONFIG_PATH = /centos/ganga/ganga/ganga/GangaLHCb/LHCb.ini
2022-10-19 11:10:59,565 MainThread Config ::transform_PATH_option:824 DEBUG : PATH-like variable: GANGA_CONFIG_PATH /centos/ganga/ganga/ganga/GangaLHCb/LHCb.ini /centos/ganga/ganga/ganga/
2022-10-19 11:10:59,565 MainThread Config ::transform_PATH_option:828 DEBUG : Prepended /centos/ganga/ganga/ganga/GangaLHCb/LHCb.ini to PATH-like variable GANGA_CONFIG_PATH
2022-10-19 11:10:59,565 MainThread Config ::read_ini_files :852 DEBUG : reading ini files: ['/centos/.gangarc']
2022-10-19 11:10:59,565 MainThread Config ::read_ini_files :866 INFO : reading config file /centos/.gangarc
2022-10-19 11:10:59,570 MainThread Config ::read_ini_files :852 DEBUG : reading ini files: ['/centos/ganga/ganga/ganga/GangaLHCb/LHCb.ini']
2022-10-19 11:10:59,570 MainThread Config ::read_ini_files :866 INFO : reading config file /centos/ganga/ganga/ganga/GangaLHCb/LHCb.ini
2022-10-19 11:10:59,570 MainThread Config ::transform_PATH_option:824 DEBUG : PATH-like variable: RUNTIME_PATH GangaDirac:GangaGaudi:GangaLHCb None
2022-10-19 11:10:59,571 MainThread Config ::setSessionValue :608 DEBUG : trying to set session option [Configuration]RUNTIME_PATH = GangaDirac:GangaGaudi:GangaLHCb
2022-10-19 11:10:59,571 MainThread Config ::convert_type :427 DEBUG : checking value type: <class 'str'> (while setting option [.]RUNTIME_PATH = GangaDirac:GangaGaudi:GangaLHCb )
2022-10-19 11:10:59,571 MainThread Config ::setSessionValue :621 DEBUG : sucessfully set session option [Configuration]RUNTIME_PATH = GangaDirac:GangaGaudi:GangaLHCb
2022-10-19 11:10:59,571 MainThread Config ::setSessionValue :608 DEBUG : trying to set session option [Configuration]SMTPHost = cernmx.cern.ch
2022-10-19 11:10:59,571 MainThread Config ::convert_type :427 DEBUG : checking value type: <class 'str'> (while setting option [.]SMTPHost = cernmx.cern.ch )
2022-10-19 11:10:59,572 MainThread Config ::setSessionValue :621 DEBUG : sucessfully set session option [Configuration]SMTPHost = cernmx.cern.ch
2022-10-19 11:10:59,572 MainThread Config ::setSessionValue :608 DEBUG : trying to set session option [Configuration]ReleaseNotes = True
2022-10-19 11:10:59,572 MainThread Config ::convert_type :422 DEBUG : applied eval(True) -> True (while setting option [.]ReleaseNotes = True )
2022-10-19 11:10:59,572 MainThread Config ::convert_type :427 DEBUG : checking value type: <class 'bool'> (while setting option [.]ReleaseNotes = True )
2022-10-19 11:10:59,572 MainThread Config ::setSessionValue :621 DEBUG : sucessfully set session option [Configuration]ReleaseNotes = True
2022-10-19 11:10:59,572 MainThread Config ::setSessionValue :608 DEBUG : trying to set session option [Output]ForbidLegacyInput = True
2022-10-19 11:10:59,572 MainThread Config ::convert_type :422 DEBUG : applied eval(True) -> True (while setting option [.]ForbidLegacyInput = True )
2022-10-19 11:10:59,572 MainThread Config ::convert_type :427 DEBUG : checking value type: <class 'bool'> (while setting option [.]ForbidLegacyInput = True )
2022-10-19 11:10:59,572 MainThread Config ::setSessionValue :621 DEBUG : sucessfully set session option [Output]ForbidLegacyInput = True
2022-10-19 11:10:59,572 MainThread Config ::setSessionValue :608 DEBUG : trying to set session option [Output]ForbidLegacyOutput = True
2022-10-19 11:10:59,572 MainThread Config ::convert_type :422 DEBUG : applied eval(True) -> True (while setting option [.]ForbidLegacyOutput = True )
2022-10-19 11:10:59,572 MainThread Config ::convert_type :427 DEBUG : checking value type: <class 'bool'> (while setting option [.]ForbidLegacyOutput = True )
2022-10-19 11:10:59,572 MainThread Config ::setSessionValue :621 DEBUG : sucessfully set session option [Output]ForbidLegacyOutput = True
2022-10-19 11:10:59,572 MainThread Config ::setSessionValue :608 DEBUG : trying to set session option [Output]LCGSEFile = {'fileExtensions': [''], 'uploadOptions': {'dest_SRM': 'srm-public.cern.ch', 'LFC_HOST': 'lfc-dteam.cern.ch'}, 'backendPostprocess': {'LSF': 'client', 'LCG': 'WN', 'Interactive': 'WN', 'Localhost': 'WN', 'CREAM': 'WN'}}
2022-10-19 11:10:59,572 MainThread Config ::convert_type :422 DEBUG : applied eval({'fileExtensions': [''], 'uploadOptions': {'dest_SRM': 'srm-public.cern.ch', 'LFC_HOST': 'lfc-dteam.cern.ch'}, 'backendPostprocess': {'LSF': 'client', 'LCG': 'WN', 'Interactive': 'WN', 'Localhost': 'WN', 'CREAM': 'WN'}}) -> {'fileExtensions': [''], 'uploadOptions': {'dest_SRM': 'srm-public.cern.ch', 'LFC_HOST': 'lfc-dteam.cern.ch'}, 'backendPostprocess': {'LSF': 'client', 'LCG': 'WN', 'Interactive': 'WN', 'Localhost': 'WN', 'CREAM': 'WN'}} (while setting option [.]LCGSEFile = {'fileExtensions': [''], 'uploadOptions': {'dest_SRM': 'srm-public.cern.ch', 'LFC_HOST': 'lfc-dteam.cern.ch'}, 'backendPostprocess': {'LSF': 'client', 'LCG': 'WN', 'Interactive': 'WN', 'Localhost': 'WN', 'CREAM': 'WN'}} )
2022-10-19 11:10:59,572 MainThread Config ::convert_type :427 DEBUG : checking value type: <class 'dict'> (while setting option [.]LCGSEFile = {'fileExtensions': [''], 'uploadOptions': {'dest_SRM': 'srm-public.cern.ch', 'LFC_HOST': 'lfc-dteam.cern.ch'}, 'backendPostprocess': {'LSF': 'client', 'LCG': 'WN', 'Interactive': 'WN', 'Localhost': 'WN', 'CREAM': 'WN'}} )
2022-10-19 11:10:59,573 MainThread Config ::setSessionValue :621 DEBUG : sucessfully set session option [Output]LCGSEFile = {'fileExtensions': [''], 'uploadOptions': {'dest_SRM': 'srm-public.cern.ch', 'LFC_HOST': 'lfc-dteam.cern.ch'}, 'backendPostprocess': {'LSF': 'client', 'LCG': 'WN', 'Interactive': 'WN', 'Localhost': 'WN', 'CREAM': 'WN'}}
2022-10-19 11:10:59,573 MainThread Config ::setSessionValue :608 DEBUG : trying to set session option [LCG]VirtualOrganisation = lhcb
2022-10-19 11:10:59,573 MainThread Config ::convert_type :427 DEBUG : checking value type: <class 'str'> (while setting option [.]VirtualOrganisation = lhcb )
2022-10-19 11:10:59,573 MainThread Config ::setSessionValue :621 DEBUG : sucessfully set session option [LCG]VirtualOrganisation = lhcb
2022-10-19 11:10:59,573 MainThread Config ::setSessionValue :608 DEBUG : trying to set session option [Mergers]associate = {'log':'TextMerger','root':'RootMerger','text':'TextMerger','txt':'TextMerger','dst':'LHCbFileMerger','mdst':'LHCbFileMerger','sim':'LHCbFileMerger','digi':'LHCbFileMerger'}
2022-10-19 11:10:59,573 MainThread Config ::convert_type :422 DEBUG : applied eval({'log':'TextMerger','root':'RootMerger','text':'TextMerger','txt':'TextMerger','dst':'LHCbFileMerger','mdst':'LHCbFileMerger','sim':'LHCbFileMerger','digi':'LHCbFileMerger'}) -> {'log': 'TextMerger', 'root': 'RootMerger', 'text': 'TextMerger', 'txt': 'TextMerger', 'dst': 'LHCbFileMerger', 'mdst': 'LHCbFileMerger', 'sim': 'LHCbFileMerger', 'digi': 'LHCbFileMerger'} (while setting option [.]associate = {'log':'TextMerger','root':'RootMerger','text':'TextMerger','txt':'TextMerger','dst':'LHCbFileMerger','mdst':'LHCbFileMerger','sim':'LHCbFileMerger','digi':'LHCbFileMerger'} )
2022-10-19 11:10:59,573 MainThread Config ::convert_type :427 DEBUG : checking value type: <class 'dict'> (while setting option [.]associate = {'log':'TextMerger','root':'RootMerger','text':'TextMerger','txt':'TextMerger','dst':'LHCbFileMerger','mdst':'LHCbFileMerger','sim':'LHCbFileMerger','digi':'LHCbFileMerger'} )
2022-10-19 11:10:59,573 MainThread Config ::setSessionValue :621 DEBUG : sucessfully set session option [Mergers]associate = {'log':'TextMerger','root':'RootMerger','text':'TextMerger','txt':'TextMerger','dst':'LHCbFileMerger','mdst':'LHCbFileMerger','sim':'LHCbFileMerger','digi':'LHCbFileMerger'}
2022-10-19 11:10:59,573 MainThread Config ::setSessionValue :608 DEBUG : trying to set session option [PollThread]creds_poll_rate = 24*3600
2022-10-19 11:10:59,573 MainThread Config ::convert_type :422 DEBUG : applied eval(24*3600) -> 86400 (while setting option [.]creds_poll_rate = 24*3600 )
2022-10-19 11:10:59,573 MainThread Config ::convert_type :427 DEBUG : checking value type: <class 'int'> (while setting option [.]creds_poll_rate = 24*3600 )
2022-10-19 11:10:59,573 MainThread Config ::setSessionValue :621 DEBUG : sucessfully set session option [PollThread]creds_poll_rate = 24*3600
2022-10-19 11:10:59,573 MainThread Config ::setSessionValue :608 DEBUG : trying to set session option [Logging]GangaLHCb = INFO
2022-10-19 11:10:59,573 MainThread Config ::convert_type :427 DEBUG : checking value type: <class 'str'> (while setting option [.]GangaLHCb = INFO )
2022-10-19 11:10:59,573 MainThread Config ::setSessionValue :621 DEBUG : sucessfully set session option [Logging]GangaLHCb = INFO
2022-10-19 11:10:59,574 MainThread __init__ ::post_config_handler :271 INFO : setting loglevel: GangaLHCb INFO
2022-10-19 11:10:59,574 MainThread __init__ ::bootstrap :483 DEBUG : bootstrap
2022-10-19 11:10:59,574 MainThread __init__ ::bootstrap :514 INFO : logging Ganga in INFO mode
2022-10-19 11:10:59,574 MainThread __init__ ::bootstrap :514 INFO : logging GangaCore.Runtime.bootstrap in INFO mode
2022-10-19 11:10:59,574 MainThread __init__ ::bootstrap :514 INFO : logging GangaCore.GPIDev in INFO mode
2022-10-19 11:10:59,574 MainThread __init__ ::bootstrap :514 INFO : logging GangaCore.Utility.logging in WARNING mode
2022-10-19 11:10:59,574 MainThread bootstrap ::configure :823 DEBUG : user specified cmdline_options: []
2022-10-19 11:10:59,574 MainThread bootstrap ::initEnvironment :888 DEBUG : Installing Shutdown Manager
2022-10-19 11:10:59,578 MainThread GangaPlugin ::add :101 DEBUG : adding plugin GangaList (category "internal")
2022-10-19 11:10:59,581 MainThread GangaPlugin ::add :101 DEBUG : adding plugin AfsToken (category "CredentialRequirement")
2022-10-19 11:10:59,595 MainThread GangaPlugin ::add :101 DEBUG : adding plugin MultiPostProcessor (category "postprocessor")
2022-10-19 11:10:59,596 MainThread Proxy ::raw_eval :184 DEBUG : Proxy Cannot evaluate v=: ''
2022-10-19 11:10:59,597 MainThread Proxy ::raw_eval :185 DEBUG : Using raw value instead
2022-10-19 11:10:59,597 MainThread Proxy ::raw_eval :184 DEBUG : Proxy Cannot evaluate v=: '.'
2022-10-19 11:10:59,597 MainThread Proxy ::raw_eval :185 DEBUG : Using raw value instead
2022-10-19 11:10:59,598 MainThread GangaPlugin ::add :101 DEBUG : adding plugin File (category "files")
2022-10-19 11:10:59,598 MainThread GangaPlugin ::add :101 DEBUG : adding plugin ShareDir (category "shareddirs")
2022-10-19 11:10:59,599 MainThread GangaPlugin ::add :101 DEBUG : adding plugin LocalFile (category "gangafiles")
2022-10-19 11:10:59,599 MainThread GangaPlugin ::add :101 DEBUG : adding plugin MassStorageFile (category "gangafiles")
2022-10-19 11:10:59,600 MainThread GangaPlugin ::add :101 DEBUG : adding plugin SharedFile (category "gangafiles")
2022-10-19 11:10:59,601 MainThread GangaPlugin ::add :101 DEBUG : adding plugin VomsProxy (category "CredentialRequirement")
2022-10-19 11:10:59,601 MainThread Proxy ::raw_eval :184 DEBUG : Proxy Cannot evaluate v=: 'srm-public.cern.ch'
2022-10-19 11:10:59,602 MainThread Proxy ::raw_eval :185 DEBUG : Using raw value instead
2022-10-19 11:10:59,602 MainThread Proxy ::raw_eval :184 DEBUG : Proxy Cannot evaluate v=: 'lfc-dteam.cern.ch'
2022-10-19 11:10:59,602 MainThread Proxy ::raw_eval :185 DEBUG : Using raw value instead
2022-10-19 11:10:59,602 MainThread GangaPlugin ::add :101 DEBUG : adding plugin LCGSEFile (category "gangafiles")
2022-10-19 11:10:59,603 MainThread GangaPlugin ::add :101 DEBUG : adding plugin GoogleFile (category "gangafiles")
2022-10-19 11:10:59,604 MainThread Schema ::_check_type :578 DEBUG : valType: <class 'dict'> defValueType: <class 'dict'> name: MetadataDict.data
2022-10-19 11:10:59,604 MainThread GangaPlugin ::add :101 DEBUG : adding plugin MetadataDict (category "metadata")
2022-10-19 11:10:59,604 MainThread Schema ::_check_type :578 DEBUG : valType: <class 'dict'> defValueType: <class 'dict'> name: JobTime.timestamps
2022-10-19 11:10:59,604 MainThread GangaPlugin ::add :101 DEBUG : adding plugin JobTime (category "jobtime")
2022-10-19 11:10:59,639 MainThread GangaPlugin ::add :101 DEBUG : adding plugin Local (category "backends")
2022-10-19 11:10:59,642 MainThread Proxy ::raw_eval :184 DEBUG : Proxy Cannot evaluate v=: 'echo'
2022-10-19 11:10:59,643 MainThread Proxy ::raw_eval :185 DEBUG : Using raw value instead
2022-10-19 11:10:59,643 MainThread Proxy ::raw_eval :184 DEBUG : Proxy Cannot evaluate v=: 'Hello World'
2022-10-19 11:10:59,643 MainThread Proxy ::raw_eval :185 DEBUG : Using raw value instead
2022-10-19 11:10:59,643 MainThread Proxy ::raw_eval :184 DEBUG : Proxy Cannot evaluate v=: 'ANY'
2022-10-19 11:10:59,643 MainThread Proxy ::raw_eval :185 DEBUG : Using raw value instead
2022-10-19 11:10:59,644 MainThread GangaPlugin ::add :101 DEBUG : adding plugin Executable (category "applications")
2022-10-19 11:10:59,645 MainThread GangaPlugin ::add :101 DEBUG : adding plugin JobInfo (category "jobinfos")
2022-10-19 11:10:59,648 MainThread Proxy ::raw_eval :184 DEBUG : Proxy Cannot evaluate v=: 'new'
2022-10-19 11:10:59,648 MainThread Proxy ::raw_eval :185 DEBUG : Using raw value instead
2022-10-19 11:10:59,648 MainThread GangaPlugin ::add :101 DEBUG : adding plugin Job (category "jobs")
2022-10-19 11:10:59,651 MainThread Proxy ::raw_eval :184 DEBUG : Proxy Cannot evaluate v=: 'template'
2022-10-19 11:10:59,651 MainThread Proxy ::raw_eval :185 DEBUG : Using raw value instead
2022-10-19 11:10:59,651 MainThread GangaPlugin ::add :101 DEBUG : adding plugin JobTemplate (category "jobs")
2022-10-19 11:10:59,653 GANGA_Update_Thread_MonitoringWorker_0_1666170659652 Local_GangaMC_Service::_execUpdateAction :121 DEBUG : <MonitoringWorkerThread(GANGA_Update_Thread_MonitoringWorker_0_1666170659652, started daemon 140290050488064)> waiting...
2022-10-19 11:10:59,653 GANGA_Update_Thread_MonitoringWorker_1_1666170659653 Local_GangaMC_Service::_execUpdateAction :121 DEBUG : <MonitoringWorkerThread(GANGA_Update_Thread_MonitoringWorker_1_1666170659653, started daemon 140290042095360)> waiting...
2022-10-19 11:10:59,654 GANGA_Update_Thread_MonitoringWorker_2_1666170659653 Local_GangaMC_Service::_execUpdateAction :121 DEBUG : <MonitoringWorkerThread(GANGA_Update_Thread_MonitoringWorker_2_1666170659653, started daemon 140290033702656)> waiting...
2022-10-19 11:10:59,654 GANGA_Update_Thread_MonitoringWorker_3_1666170659654 Local_GangaMC_Service::_execUpdateAction :121 DEBUG : <MonitoringWorkerThread(GANGA_Update_Thread_MonitoringWorker_3_1666170659654, started daemon 140290025309952)> waiting...
2022-10-19 11:10:59,654 GANGA_Update_Thread_MonitoringWorker_4_1666170659654 Local_GangaMC_Service::_execUpdateAction :121 DEBUG : <MonitoringWorkerThread(GANGA_Update_Thread_MonitoringWorker_4_1666170659654, started daemon 140290016917248)> waiting...
2022-10-19 11:10:59,657 MainThread GangaPlugin ::add :101 DEBUG : adding plugin BoxMetadataObject (category "internal")
2022-10-19 11:10:59,658 MainThread Schema ::_check_type :578 DEBUG : valType: <class 'dict'> defValueType: <class 'dict'> name: ShareRef.name
2022-10-19 11:10:59,659 MainThread GangaPlugin ::add :101 DEBUG : adding plugin ShareRef (category "sharerefs")
2022-10-19 11:10:59,660 MainThread Proxy ::raw_eval :184 DEBUG : Proxy Cannot evaluate v=: 'NewTask'
2022-10-19 11:10:59,660 MainThread Proxy ::raw_eval :185 DEBUG : Using raw value instead
2022-10-19 11:10:59,661 MainThread GangaPlugin ::add :101 DEBUG : adding plugin ITask (category "tasks")
2022-10-19 11:10:59,662 MainThread Proxy ::raw_eval :184 DEBUG : Proxy Cannot evaluate v=: 'Simple Unit'
2022-10-19 11:10:59,662 MainThread Proxy ::raw_eval :185 DEBUG : Using raw value instead
2022-10-19 11:10:59,663 MainThread Proxy ::raw_eval :184 DEBUG : Proxy Cannot evaluate v=: 'Simple Transform'
2022-10-19 11:10:59,663 MainThread Proxy ::raw_eval :185 DEBUG : Using raw value instead
2022-10-19 11:10:59,664 MainThread GangaPlugin ::add :101 DEBUG : adding plugin EmptyDataset (category "datasets")
2022-10-19 11:10:59,664 MainThread GangaPlugin ::add :101 DEBUG : adding plugin GangaDataset (category "datasets")
2022-10-19 11:10:59,665 MainThread GangaPlugin ::add :101 DEBUG : adding plugin TaskChainInput (category "datasets")
2022-10-19 11:10:59,665 MainThread GangaPlugin ::add :101 DEBUG : adding plugin TaskLocalCopy (category "datasets")
2022-10-19 11:10:59,666 MainThread GangaPlugin ::add :101 DEBUG : adding plugin CoreTask (category "tasks")
2022-10-19 11:10:59,666 MainThread GangaPlugin ::add :101 DEBUG : adding plugin CoreUnit (category "units")
2022-10-19 11:10:59,667 MainThread GangaPlugin ::add :101 DEBUG : adding plugin ArgSplitter (category "splitters")
2022-10-19 11:10:59,667 MainThread GangaPlugin ::add :101 DEBUG : adding plugin GangaDatasetSplitter (category "splitters")
2022-10-19 11:10:59,668 MainThread Schema ::_check_type :578 DEBUG : valType: <class 'dict'> defValueType: <class 'dict'> name: GenericSplitter.multi_attrs
2022-10-19 11:10:59,668 MainThread GangaPlugin ::add :101 DEBUG : adding plugin GenericSplitter (category "splitters")
2022-10-19 11:10:59,669 MainThread GangaPlugin ::add :101 DEBUG : adding plugin CoreTransform (category "transforms")
2022-10-19 11:10:59,669 MainThread Config ::convert_type :424 DEBUG : ignored failed eval(nonsense): name 'nonsense' is not defined (while setting option [.]DiracEnvSource = nonsense )
2022-10-19 11:10:59,669 MainThread Config ::convert_type :427 DEBUG : checking value type: <class 'NoneType'> (while setting option [.]DiracEnvSource = nonsense )
2022-10-19 11:10:59,670 MainThread Config ::convert_type :422 DEBUG : applied eval(["/centos/ganga/ganga/ganga/GangaLHCb/Lib/Server/DiracLHCbDefinition.py",
"/centos/ganga/ganga/ganga/GangaDirac/Lib/Server/DiracCommands.py",
"/centos/ganga/ganga/ganga/GangaLHCb/Lib/Server/DiracLHCbCommands.py"]) -> ['/centos/ganga/ganga/ganga/GangaLHCb/Lib/Server/DiracLHCbDefinition.py', '/centos/ganga/ganga/ganga/GangaDirac/Lib/Server/DiracCommands.py', '/centos/ganga/ganga/ganga/GangaLHCb/Lib/Server/DiracLHCbCommands.py'] (while setting option [.]DiracCommandFiles = ["/centos/ganga/ganga/ganga/GangaLHCb/Lib/Server/DiracLHCbDefinition.py",
"/centos/ganga/ganga/ganga/GangaDirac/Lib/Server/DiracCommands.py",
"/centos/ganga/ganga/ganga/GangaLHCb/Lib/Server/DiracLHCbCommands.py"] )
2022-10-19 11:10:59,670 MainThread Config ::convert_type :427 DEBUG : checking value type: <class 'list'> (while setting option [.]DiracCommandFiles = ["/centos/ganga/ganga/ganga/GangaLHCb/Lib/Server/DiracLHCbDefinition.py",
"/centos/ganga/ganga/ganga/GangaDirac/Lib/Server/DiracCommands.py",
"/centos/ganga/ganga/ganga/GangaLHCb/Lib/Server/DiracLHCbCommands.py"] )
2022-10-19 11:10:59,670 MainThread Config ::convert_type :422 DEBUG : applied eval(False) -> False (while setting option [.]load_default_Dirac_backend = False )
2022-10-19 11:10:59,670 MainThread Config ::convert_type :427 DEBUG : checking value type: <class 'bool'> (while setting option [.]load_default_Dirac_backend = False )
2022-10-19 11:10:59,671 MainThread bootstrap ::initEnvironment :895 DEBUG : Import plugins
2022-10-19 11:10:59,672 MainThread plugins ::<module> :5 DEBUG : Loading IApplication
2022-10-19 11:10:59,672 MainThread plugins ::<module> :8 DEBUG : Loading IBackend
2022-10-19 11:10:59,672 MainThread plugins ::<module> :11 DEBUG : Loading ISplitter
2022-10-19 11:10:59,672 MainThread plugins ::<module> :14 DEBUG : Loading IMerger
2022-10-19 11:10:59,672 MainThread plugins ::<module> :17 DEBUG : Loading GangaList
2022-10-19 11:10:59,672 MainThread plugins ::<module> :20 DEBUG : Loading File
2022-10-19 11:10:59,672 MainThread plugins ::<module> :23 DEBUG : Loading Job
2022-10-19 11:10:59,672 MainThread plugins ::<module> :26 DEBUG : Loading Mergers
2022-10-19 11:10:59,673 MainThread GangaPlugin ::add :101 DEBUG : adding plugin TextMerger (category "postprocessor")
2022-10-19 11:10:59,673 MainThread GangaPlugin ::add :101 DEBUG : adding plugin RootMerger (category "postprocessor")
2022-10-19 11:10:59,674 MainThread GangaPlugin ::add :101 DEBUG : adding plugin CustomMerger (category "postprocessor")
2022-10-19 11:10:59,674 MainThread GangaPlugin ::add :101 DEBUG : adding plugin SmartMerger (category "postprocessor")
2022-10-19 11:10:59,674 MainThread plugins ::<module> :29 DEBUG : Loading Splitters
2022-10-19 11:10:59,674 MainThread plugins ::<module> :32 DEBUG : Loading Executable
2022-10-19 11:10:59,674 MainThread plugins ::<module> :35 DEBUG : Loading Notebook
2022-10-19 11:10:59,675 MainThread Proxy ::raw_eval :184 DEBUG : Proxy Cannot evaluate v=: 'python2'
2022-10-19 11:10:59,675 MainThread Proxy ::raw_eval :185 DEBUG : Using raw value instead
2022-10-19 11:10:59,675 MainThread Proxy ::raw_eval :184 DEBUG : Proxy Cannot evaluate v=: '.+\.ipynb$'
2022-10-19 11:10:59,675 MainThread Proxy ::raw_eval :185 DEBUG : Using raw value instead
2022-10-19 11:10:59,675 MainThread GangaPlugin ::add :101 DEBUG : adding plugin Notebook (category "applications")
2022-10-19 11:10:59,675 MainThread plugins ::<module> :38 DEBUG : Loading LocalHost
2022-10-19 11:10:59,675 MainThread plugins ::<module> :41 DEBUG : Loading LCG
2022-10-19 11:10:59,678 MainThread Schema ::_check_type :578 DEBUG : valType: <class 'dict'> defValueType: <class 'dict'> name: GridFileIndex.attributes
2022-10-19 11:10:59,678 MainThread GangaPlugin ::add :101 DEBUG : adding plugin GridFileIndex (category "GridFileIndex")
2022-10-19 11:10:59,678 MainThread GangaPlugin ::add :101 DEBUG : adding plugin GridSandboxCache (category "GridSandboxCache")
2022-10-19 11:10:59,679 MainThread Schema ::_check_type :578 DEBUG : valType: <class 'dict'> defValueType: <class 'dict'> name: GridftpFileIndex.attributes
2022-10-19 11:10:59,679 MainThread GangaPlugin ::add :101 DEBUG : adding plugin GridftpFileIndex (category "GridFileIndex")
2022-10-19 11:10:59,679 MainThread Proxy ::raw_eval :184 DEBUG : Proxy Cannot evaluate v=: 'globus-copy-url'
2022-10-19 11:10:59,679 MainThread Proxy ::raw_eval :185 DEBUG : Using raw value instead
2022-10-19 11:10:59,679 MainThread GangaPlugin ::add :101 DEBUG : adding plugin GridftpSandboxCache (category "GridSandboxCache")
2022-10-19 11:10:59,680 MainThread Proxy ::raw_eval :184 DEBUG : Proxy Cannot evaluate v=: 'Normal'
2022-10-19 11:10:59,680 MainThread Proxy ::raw_eval :185 DEBUG : Using raw value instead
2022-10-19 11:10:59,680 MainThread GangaPlugin ::add :101 DEBUG : adding plugin ARC (category "backends")
2022-10-19 11:10:59,681 MainThread GangaPlugin ::add :101 DEBUG : adding plugin CREAM (category "backends")
2022-10-19 11:10:59,683 MainThread Proxy ::raw_eval :184 DEBUG : Proxy Cannot evaluate v=: 'GLITE'
2022-10-19 11:10:59,683 MainThread Proxy ::raw_eval :185 DEBUG : Using raw value instead
2022-10-19 11:10:59,683 MainThread Schema ::_check_type :578 DEBUG : valType: <class 'dict'> defValueType: <class 'dict'> name: LCG.monInfo
2022-10-19 11:10:59,683 MainThread GangaPlugin ::add :101 DEBUG : adding plugin LCG (category "backends")
2022-10-19 11:10:59,684 MainThread Proxy ::raw_eval :184 DEBUG : Proxy Cannot evaluate v=: 'gsiftp'
2022-10-19 11:10:59,684 MainThread Proxy ::raw_eval :185 DEBUG : Using raw value instead
2022-10-19 11:10:59,684 MainThread GangaPlugin ::add :101 DEBUG : adding plugin LCGRequirements (category "LCGRequirements")
2022-10-19 11:10:59,685 MainThread Schema ::_check_type :578 DEBUG : valType: <class 'dict'> defValueType: <class 'dict'> name: LCGFileIndex.attributes
2022-10-19 11:10:59,685 MainThread GangaPlugin ::add :101 DEBUG : adding plugin LCGFileIndex (category "GridFileIndex")
2022-10-19 11:10:59,685 MainThread Proxy ::raw_eval :184 DEBUG : Proxy Cannot evaluate v=: 'srmv2'
2022-10-19 11:10:59,685 MainThread Proxy ::raw_eval :185 DEBUG : Using raw value instead
2022-10-19 11:10:59,685 MainThread Proxy ::raw_eval :184 DEBUG : Proxy Cannot evaluate v=: 'generated'
2022-10-19 11:10:59,685 MainThread Proxy ::raw_eval :185 DEBUG : Using raw value instead
2022-10-19 11:10:59,686 MainThread GangaPlugin ::add :101 DEBUG : adding plugin LCGSandboxCache (category "GridSandboxCache")
2022-10-19 11:10:59,686 MainThread plugins ::<module> :44 DEBUG : Loading Condor
2022-10-19 11:10:59,708 MainThread Schema ::_check_type :578 DEBUG : valType: <class 'dict'> defValueType: <class 'dict'> name: Condor.env
2022-10-19 11:10:59,708 MainThread Proxy ::raw_eval :184 DEBUG : Proxy Cannot evaluate v=: 'Memory'
2022-10-19 11:10:59,708 MainThread Proxy ::raw_eval :185 DEBUG : Using raw value instead
2022-10-19 11:10:59,708 MainThread Proxy ::raw_eval :184 DEBUG : Proxy Cannot evaluate v=: 'vanilla'
2022-10-19 11:10:59,709 MainThread Proxy ::raw_eval :185 DEBUG : Using raw value instead
2022-10-19 11:10:59,709 MainThread Schema ::_check_type :578 DEBUG : valType: <class 'dict'> defValueType: <class 'dict'> name: Condor.cdf_options
2022-10-19 11:10:59,709 MainThread GangaPlugin ::add :101 DEBUG : adding plugin Condor (category "backends")
2022-10-19 11:10:59,710 MainThread GangaPlugin ::add :101 DEBUG : adding plugin CondorRequirements (category "condor_requirements")
2022-10-19 11:10:59,710 MainThread plugins ::<module> :47 DEBUG : Loading Interactive
2022-10-19 11:10:59,711 MainThread GangaPlugin ::add :101 DEBUG : adding plugin Interactive (category "backends")
2022-10-19 11:10:59,711 MainThread plugins ::<module> :50 DEBUG : Loading Batch
2022-10-19 11:10:59,712 MainThread GangaPlugin ::add :101 DEBUG : adding plugin LSF (category "backends")
2022-10-19 11:10:59,712 MainThread GangaPlugin ::add :101 DEBUG : adding plugin PBS (category "backends")
2022-10-19 11:10:59,713 MainThread GangaPlugin ::add :101 DEBUG : adding plugin SGE (category "backends")
2022-10-19 11:10:59,713 MainThread GangaPlugin ::add :101 DEBUG : adding plugin Slurm (category "backends")
2022-10-19 11:10:59,713 MainThread plugins ::<module> :53 DEBUG : Loading Remote
2022-10-19 11:10:59,714 MainThread Proxy ::raw_eval :184 DEBUG : Proxy Cannot evaluate v=: 'RSA'
2022-10-19 11:10:59,714 MainThread Proxy ::raw_eval :185 DEBUG : Using raw value instead
2022-10-19 11:10:59,714 MainThread Schema ::_check_type :578 DEBUG : valType: <class 'dict'> defValueType: <class 'dict'> name: Remote.environment
2022-10-19 11:10:59,714 MainThread GangaPlugin ::add :101 DEBUG : adding plugin Remote (category "backends")
2022-10-19 11:10:59,715 MainThread Config ::convert_type :422 DEBUG : applied eval(['source /afs/cern.ch/lhcb/software/releases/LBSCRIPTS/prod/InstallArea/scripts/LbLogin.sh', 'source `runpy LbConfiguration.SetupProject --shell=sh --mktemp Ganga`']) -> ['source /afs/cern.ch/lhcb/software/releases/LBSCRIPTS/prod/InstallArea/scripts/LbLogin.sh', 'source `runpy LbConfiguration.SetupProject --shell=sh --mktemp Ganga`'] (while setting option [.]pre_script = ['source /afs/cern.ch/lhcb/software/releases/LBSCRIPTS/prod/InstallArea/scripts/LbLogin.sh', 'source `runpy LbConfiguration.SetupProject --shell=sh --mktemp Ganga`'] )
2022-10-19 11:10:59,715 MainThread Config ::convert_type :427 DEBUG : checking value type: [<class 'list'>] (while setting option [.]pre_script = ['source /afs/cern.ch/lhcb/software/releases/LBSCRIPTS/prod/InstallArea/scripts/LbLogin.sh', 'source `runpy LbConfiguration.SetupProject --shell=sh --mktemp Ganga`'] )
2022-10-19 11:10:59,715 MainThread plugins ::<module> :56 DEBUG : Loading Tasks
2022-10-19 11:10:59,715 MainThread plugins ::<module> :59 DEBUG : Loading Checkers
2022-10-19 11:10:59,716 MainThread GangaPlugin ::add :101 DEBUG : adding plugin CustomChecker (category "postprocessor")
2022-10-19 11:10:59,716 MainThread GangaPlugin ::add :101 DEBUG : adding plugin FileChecker (category "postprocessor")
2022-10-19 11:10:59,717 MainThread GangaPlugin ::add :101 DEBUG : adding plugin RootFileChecker (category "postprocessor")
2022-10-19 11:10:59,717 MainThread plugins ::<module> :62 DEBUG : Loading Notifier
2022-10-19 11:10:59,725 MainThread GangaPlugin ::add :101 DEBUG : adding plugin Notifier (category "postprocessor")
2022-10-19 11:10:59,725 MainThread plugins ::<module> :65 DEBUG : Loading virtualization classes
2022-10-19 11:10:59,726 MainThread Schema ::_check_type :578 DEBUG : valType: <class 'dict'> defValueType: <class 'dict'> name: IVirtualization.mounts
2022-10-19 11:10:59,726 MainThread Schema ::_check_type :578 DEBUG : valType: <class 'dict'> defValueType: <class 'dict'> name: Docker.mounts
2022-10-19 11:10:59,727 MainThread Proxy ::raw_eval :184 DEBUG : Proxy Cannot evaluate v=: 'P1'
2022-10-19 11:10:59,727 MainThread Proxy ::raw_eval :185 DEBUG : Using raw value instead
2022-10-19 11:10:59,727 MainThread GangaPlugin ::add :101 DEBUG : adding plugin Docker (category "virtualization")
2022-10-19 11:10:59,727 MainThread Schema ::_check_type :578 DEBUG : valType: <class 'dict'> defValueType: <class 'dict'> name: Singularity.mounts
2022-10-19 11:10:59,728 MainThread Proxy ::raw_eval :184 DEBUG : Proxy Cannot evaluate v=: 'singularity'
2022-10-19 11:10:59,728 MainThread Proxy ::raw_eval :185 DEBUG : Using raw value instead
2022-10-19 11:10:59,728 MainThread GangaPlugin ::add :101 DEBUG : adding plugin Singularity (category "virtualization")
2022-10-19 11:10:59,728 MainThread plugins ::<module> :68 DEBUG : Finished Runtime.plugins
2022-10-19 11:10:59,728 MainThread Config ::transform_PATH_option:824 DEBUG : PATH-like variable: RUNTIME_PATH GangaDirac:GangaGaudi:GangaLHCb
2022-10-19 11:10:59,728 MainThread Config ::transform_PATH_option:828 DEBUG : Prepended GangaDirac:GangaGaudi:GangaLHCb to PATH-like variable RUNTIME_PATH
2022-10-19 11:10:59,728 MainThread Runtime ::__init__ :121 DEBUG : initializing runtime: 'GangaDirac' '/centos/ganga/ganga/ganga'
2022-10-19 11:10:59,728 MainThread Runtime ::__init__ :121 DEBUG : initializing runtime: 'GangaGaudi' '/centos/ganga/ganga/ganga'
2022-10-19 11:10:59,729 MainThread Runtime ::__init__ :121 DEBUG : initializing runtime: 'GangaLHCb' '/centos/ganga/ganga/ganga'
2022-10-19 11:10:59,730 MainThread GangaPlugin ::add :101 DEBUG : adding plugin DiracProxy (category "CredentialRequirement")
2022-10-19 11:10:59,730 MainThread Config ::convert_type :424 DEBUG : ignored failed eval(lhcb_user): name 'lhcb_user' is not defined (while setting option [.]group = lhcb_user )
2022-10-19 11:10:59,730 MainThread Config ::convert_type :427 DEBUG : checking value type: [<class 'str'>, None] (while setting option [.]group = lhcb_user )
2022-10-19 11:10:59,730 MainThread Proxy ::raw_eval :184 DEBUG : Proxy Cannot evaluate v=: 'lhcb_user'
2022-10-19 11:10:59,730 MainThread Proxy ::raw_eval :185 DEBUG : Using raw value instead
2022-10-19 11:10:59,730 MainThread Config ::convert_type :422 DEBUG : applied eval(False) -> False (while setting option [.]encodeDefaultProxyFileName = False )
2022-10-19 11:10:59,730 MainThread Config ::convert_type :427 DEBUG : checking value type: [<class 'bool'>] (while setting option [.]encodeDefaultProxyFileName = False )
2022-10-19 11:10:59,734 MainThread execute ::execute :228 DEBUG : Executing Command:
'. /cvmfs/lhcb.cern.ch/lib/LbEnv &> /dev/null && python3 -c "import json, os; print(json.dumps(dict(os.environ.copy())))"'
2022-10-19 11:10:59,772 MainThread execute ::execute :232 DEBUG : stdout: {"LBENV_FLAVOUR": "stable", "SSH_AGENT_PID": "136", "HOSTNAME": "centos7", "PIP_REQUIRE_VIRTUALENV": "true", "TERM": "xterm", "UNISONLOCALHOSTNAME": "mylaptop", "QSYS_ROOTDIR": "/home/data/intelFPGA_lite/19.1/quartus/sopc_builder/bin", "LHCBRELEASES": "/cvmfs/lhcb.cern.ch/lib/lhcb", "LBENV_ALIASES": "/cvmfs/lhcb.cern.ch/lib/var/lib/LbEnv/2541/stable/linux-64/lib/python3.9/site-packages/LbEnv/data/aliases.sh", "LS_COLORS": "rs=0:di=01;34:ln=01;36:mh=00:pi=40;33:so=01;35:do=01;35:bd=40;33;01:cd=40;33;01:or=40;31;01:mi=01;05;37;41:su=37;41:sg=30;43:ca=30;41:tw=30;42:ow=34;42:st=37;44:ex=01;32:*.tar=01;31:*.tgz=01;31:*.arc=01;31:*.arj=01;31:*.taz=01;31:*.lha=01;31:*.lz4=01;31:*.lzh=01;31:*.lzma=01;31:*.tlz=01;31:*.txz=01;31:*.tzo=01;31:*.t7z=01;31:*.zip=01;31:*.z=01;31:*.Z=01;31:*.dz=01;31:*.gz=01;31:*.lrz=01;31:*.lz=01;31:*.lzo=01;31:*.xz=01;31:*.bz2=01;31:*.bz=01;31:*.tbz=01;31:*.tbz2=01;31:*.tz=01;31:*.deb=01;31:*.rpm=01;31:*.jar=01;31:*.war=01;31:*.ear=01;31:*.sar=01;31:*.rar=01;31:*.alz=01;31:*.ace=01;31:*.zoo=01;31:*.cpio=01;31:*.7z=01;31:*.rz=01;31:*.cab=01;31:*.jpg=01;35:*.jpeg=01;35:*.gif=01;35:*.bmp=01;35:*.pbm=01;35:*.pgm=01;35:*.ppm=01;35:*.tga=01;35:*.xbm=01;35:*.xpm=01;35:*.tif=01;35:*.tiff=01;35:*.png=01;35:*.svg=01;35:*.svgz=01;35:*.mng=01;35:*.pcx=01;35:*.mov=01;35:*.mpg=01;35:*.mpeg=01;35:*.m2v=01;35:*.mkv=01;35:*.webm=01;35:*.ogm=01;35:*.mp4=01;35:*.m4v=01;35:*.mp4v=01;35:*.vob=01;35:*.qt=01;35:*.nuv=01;35:*.wmv=01;35:*.asf=01;35:*.rm=01;35:*.rmvb=01;35:*.flc=01;35:*.avi=01;35:*.fli=01;35:*.flv=01;35:*.gl=01;35:*.dl=01;35:*.xcf=01;35:*.xwd=01;35:*.yuv=01;35:*.cgm=01;35:*.emf=01;35:*.axv=01;35:*.anx=01;35:*.ogv=01;35:*.ogx=01;35:*.aac=01;36:*.au=01;36:*.flac=01;36:*.mid=01;36:*.midi=01;36:*.mka=01;36:*.mp3=01;36:*.mpc=01;36:*.ogg=01;36:*.ra=01;36:*.wav=01;36:*.axa=01;36:*.oga=01;36:*.spx=01;36:*.xspf=01;36:", "SSH_AUTH_SOCK": "/tmp/ssh-cL0fDxTTCWm9/agent.135", "LBENV_SOURCED": "2.1.11", "CASTOR_HOME": "/castor/cern.ch/user//", "VIRTUAL_ENV": "/centos/ganga", "LCG_RELEASES": "/cvmfs/lhcb.cern.ch/lib/lcg/releases", "MYSITEROOT": "/cvmfs/lhcb.cern.ch/lib", "PATH": "/centos/ganga/bin:/home/egede/scripts:/centos/scripts:/usr/sue/bin:/usr/lib64/ccache:/cvmfs/lhcb.cern.ch/lib/bin/x86_64-centos7:/cvmfs/lhcb.cern.ch/lib/bin/Linux-x86_64:/cvmfs/lhcb.cern.ch/lib/bin:/cvmfs/lhcb.cern.ch/lib/var/lib/LbEnv/2541/stable/linux-64/bin:/usr/sbin:/usr/bin:/sbin:/bin", "CONDOR_CONFIG": "/dev/null", "PWD": "/centos/ganga/ganga", "EDITOR": "/bin/nano -w", "LBENV_PREFIX": "/cvmfs/lhcb.cern.ch/lib/var/lib/LbEnv/2541/stable/linux-64", "LBENV_ENTRYPOINT": "/cvmfs/lhcb.cern.ch/lib/LbEnv-stable.sh", "GANGA_CONFIG_PATH": "GangaLHCb/LHCb.ini", "HOME": "/centos", "SHLVL": "4", "LCG_hostos": "x86_64-centos7", "PYTHONPATH": "/centos/ganga/ganga/ganga:/centos/external/google-api-python-client/1.1/noarch/python:/centos/external/python-gflags/2.0/noarch/python:/centos/external/httplib2/0.8/noarch/python:/centos/external/ipython/1.2.1/noarch/lib/python", "LESSOPEN": "||/usr/bin/lesspipe.sh %s", "PROMPT_COMMAND": "prompt_command", "DISPLAY": "localhost:10.0", "CMAKE_PREFIX_PATH": "/cvmfs/lhcb.cern.ch/lib/lhcb:/cvmfs/lhcb.cern.ch/lib/lcg/releases:/cvmfs/lhcb.cern.ch/lib/lcg/app/releases:/cvmfs/lhcb.cern.ch/lib/lcg/external:/cvmfs/lhcb.cern.ch/lib/contrib:/cvmfs/lhcb.cern.ch/lib/var/lib/LbEnv/2541/stable/linux-64/lib/python3.9/site-packages/LbDevTools/data/cmake", "LCG_external_area": "/cvmfs/lhcb.cern.ch/lib/lcg/external", "container": "podman", "_": "/centos/ganga/bin/python3"}
2022-10-19 11:10:59,772 MainThread execute ::execute :233 DEBUG : stderr:
2022-10-19 11:10:59,773 MainThread execute ::execute :282 DEBUG : Command Failed to Execute:
. /cvmfs/lhcb.cern.ch/lib/LbEnv &> /dev/null && python3 -c "import json, os; print(json.dumps(dict(os.environ.copy())))"
2022-10-19 11:10:59,773 MainThread execute ::execute :283 DEBUG : Command Output is:
{"LBENV_FLAVOUR": "stable", "SSH_AGENT_PID": "136", "HOSTNAME": "centos7", "PIP_REQUIRE_VIRTUALENV": "true", "TERM": "xterm", "UNISONLOCALHOSTNAME": "mylaptop", "QSYS_ROOTDIR": "/home/data/intelFPGA_lite/19.1/quartus/sopc_builder/bin", "LHCBRELEASES": "/cvmfs/lhcb.cern.ch/lib/lhcb", "LBENV_ALIASES": "/cvmfs/lhcb.cern.ch/lib/var/lib/LbEnv/2541/stable/linux-64/lib/python3.9/site-packages/LbEnv/data/aliases.sh", "LS_COLORS": "rs=0:di=01;34:ln=01;36:mh=00:pi=40;33:so=01;35:do=01;35:bd=40;33;01:cd=40;33;01:or=40;31;01:mi=01;05;37;41:su=37;41:sg=30;43:ca=30;41:tw=30;42:ow=34;42:st=37;44:ex=01;32:*.tar=01;31:*.tgz=01;31:*.arc=01;31:*.arj=01;31:*.taz=01;31:*.lha=01;31:*.lz4=01;31:*.lzh=01;31:*.lzma=01;31:*.tlz=01;31:*.txz=01;31:*.tzo=01;31:*.t7z=01;31:*.zip=01;31:*.z=01;31:*.Z=01;31:*.dz=01;31:*.gz=01;31:*.lrz=01;31:*.lz=01;31:*.lzo=01;31:*.xz=01;31:*.bz2=01;31:*.bz=01;31:*.tbz=01;31:*.tbz2=01;31:*.tz=01;31:*.deb=01;31:*.rpm=01;31:*.jar=01;31:*.war=01;31:*.ear=01;31:*.sar=01;31:*.rar=01;31:*.alz=01;31:*.ace=01;31:*.zoo=01;31:*.cpio=01;31:*.7z=01;31:*.rz=01;31:*.cab=01;31:*.jpg=01;35:*.jpeg=01;35:*.gif=01;35:*.bmp=01;35:*.pbm=01;35:*.pgm=01;35:*.ppm=01;35:*.tga=01;35:*.xbm=01;35:*.xpm=01;35:*.tif=01;35:*.tiff=01;35:*.png=01;35:*.svg=01;35:*.svgz=01;35:*.mng=01;35:*.pcx=01;35:*.mov=01;35:*.mpg=01;35:*.mpeg=01;35:*.m2v=01;35:*.mkv=01;35:*.webm=01;35:*.ogm=01;35:*.mp4=01;35:*.m4v=01;35:*.mp4v=01;35:*.vob=01;35:*.qt=01;35:*.nuv=01;35:*.wmv=01;35:*.asf=01;35:*.rm=01;35:*.rmvb=01;35:*.flc=01;35:*.avi=01;35:*.fli=01;35:*.flv=01;35:*.gl=01;35:*.dl=01;35:*.xcf=01;35:*.xwd=01;35:*.yuv=01;35:*.cgm=01;35:*.emf=01;35:*.axv=01;35:*.anx=01;35:*.ogv=01;35:*.ogx=01;35:*.aac=01;36:*.au=01;36:*.flac=01;36:*.mid=01;36:*.midi=01;36:*.mka=01;36:*.mp3=01;36:*.mpc=01;36:*.ogg=01;36:*.ra=01;36:*.wav=01;36:*.axa=01;36:*.oga=01;36:*.spx=01;36:*.xspf=01;36:", "SSH_AUTH_SOCK": "/tmp/ssh-cL0fDxTTCWm9/agent.135", "LBENV_SOURCED": "2.1.11", "CASTOR_HOME": "/castor/cern.ch/user//", "VIRTUAL_ENV": "/centos/ganga", "LCG_RELEASES": "/cvmfs/lhcb.cern.ch/lib/lcg/releases", "MYSITEROOT": "/cvmfs/lhcb.cern.ch/lib", "PATH": "/centos/ganga/bin:/home/egede/scripts:/centos/scripts:/usr/sue/bin:/usr/lib64/ccache:/cvmfs/lhcb.cern.ch/lib/bin/x86_64-centos7:/cvmfs/lhcb.cern.ch/lib/bin/Linux-x86_64:/cvmfs/lhcb.cern.ch/lib/bin:/cvmfs/lhcb.cern.ch/lib/var/lib/LbEnv/2541/stable/linux-64/bin:/usr/sbin:/usr/bin:/sbin:/bin", "CONDOR_CONFIG": "/dev/null", "PWD": "/centos/ganga/ganga", "EDITOR": "/bin/nano -w", "LBENV_PREFIX": "/cvmfs/lhcb.cern.ch/lib/var/lib/LbEnv/2541/stable/linux-64", "LBENV_ENTRYPOINT": "/cvmfs/lhcb.cern.ch/lib/LbEnv-stable.sh", "GANGA_CONFIG_PATH": "GangaLHCb/LHCb.ini", "HOME": "/centos", "SHLVL": "4", "LCG_hostos": "x86_64-centos7", "PYTHONPATH": "/centos/ganga/ganga/ganga:/centos/external/google-api-python-client/1.1/noarch/python:/centos/external/python-gflags/2.0/noarch/python:/centos/external/httplib2/0.8/noarch/python:/centos/external/ipython/1.2.1/noarch/lib/python", "LESSOPEN": "||/usr/bin/lesspipe.sh %s", "PROMPT_COMMAND": "prompt_command", "DISPLAY": "localhost:10.0", "CMAKE_PREFIX_PATH": "/cvmfs/lhcb.cern.ch/lib/lhcb:/cvmfs/lhcb.cern.ch/lib/lcg/releases:/cvmfs/lhcb.cern.ch/lib/lcg/app/releases:/cvmfs/lhcb.cern.ch/lib/lcg/external:/cvmfs/lhcb.cern.ch/lib/contrib:/cvmfs/lhcb.cern.ch/lib/var/lib/LbEnv/2541/stable/linux-64/lib/python3.9/site-packages/LbDevTools/data/cmake", "LCG_external_area": "/cvmfs/lhcb.cern.ch/lib/lcg/external", "container": "podman", "_": "/centos/ganga/bin/python3"}
2022-10-19 11:10:59,773 MainThread execute ::execute :284 DEBUG : Error received:
invalid load key, '{'.
2022-10-19 11:10:59,777 MainThread execute ::execute :228 DEBUG : Executing Command:
'. /cvmfs/lhcb.cern.ch/lib/LbEnv &>/dev/null && lb-dirac prod python -c "import json, os; print(json.dumps(dict(os.environ)))"'
2022-10-19 11:11:00,221 MainThread execute ::execute :232 DEBUG : stdout: {"DIRAC": "/cvmfs/lhcb.cern.ch/lhcbdirac/prod/Linux-x86_64", "DIRACOS": "/cvmfs/lhcb.cern.ch/lhcbdirac/versions/v10.4.20-1664186607/Linux-x86_64", "VOMS_USERCONF": "/cvmfs/lhcb.cern.ch/etc/grid-security/vomses", "CONDA_SHLVL": "1", "CONDA_PROMPT_MODIFIER": "(base) ", "GSETTINGS_SCHEMA_DIR_CONDA_BACKUP": "", "X509_CERT_DIR": "/cvmfs/lhcb.cern.ch/etc/grid-security/certificates", "X509_VOMSES": "/cvmfs/lhcb.cern.ch/etc/grid-security/vomses", "XRD_RUNFORKHANDLER": "0", "PYTHONWARNINGS": "ignore", "GLOBUS_IO_IPV6": "TRUE", "MYSITEROOT": "/cvmfs/lhcb.cern.ch/lib", "PATH": "/cvmfs/lhcb.cern.ch/lhcbdirac/versions/v10.4.20-1664186607/Linux-x86_64/bin:/cvmfs/lhcb.cern.ch/lhcbdirac/versions/v10.4.20-1664186607/Linux-x86_64/condabin:/usr/local/bin:/usr/bin", "GSETTINGS_SCHEMA_DIR": "/cvmfs/lhcb.cern.ch/lhcbdirac/versions/v10.4.20-1664186607/Linux-x86_64/share/glib-2.0/schemas", "CONDOR_CONFIG": "/cvmfs/lhcb.cern.ch/lhcbdirac/versions/v10.4.20-1664186607/Linux-x86_64/etc/condor/condor_config", "CONDA_PREFIX": "/cvmfs/lhcb.cern.ch/lhcbdirac/versions/v10.4.20-1664186607/Linux-x86_64", "PWD": "/centos/ganga/ganga", "MAMBA_ROOT_PREFIX": "/cvmfs/lhcb.cern.ch/lhcbdirac/versions/v10.4.20-1664186607/Linux-x86_64", "DAVIX_USE_LIBCURL": "1", "X509_VOMS_DIR": "/cvmfs/lhcb.cern.ch/etc/grid-security/vomsdir", "SSL_CERT_DIR": "/cvmfs/lhcb.cern.ch/etc/grid-security/certificates", "SHLVL": "1", "HOME": "/centos", "CONDA_BACKUP_CONDOR_CONFIG": "empty", "BASH_ENV": "/cvmfs/lhcb.cern.ch/lhcbdirac/bashrc.py3", "CONDA_DEFAULT_ENV": "base", "GLOBUS_FTP_CLIENT_IPV6": "TRUE", "_": "/cvmfs/lhcb.cern.ch/lhcbdirac/versions/v10.4.20-1664186607/Linux-x86_64/bin/python"}
2022-10-19 11:11:00,221 MainThread execute ::execute :233 DEBUG : stderr:
2022-10-19 11:11:00,221 MainThread execute ::execute :282 DEBUG : Command Failed to Execute:
. /cvmfs/lhcb.cern.ch/lib/LbEnv &>/dev/null && lb-dirac prod python -c "import json, os; print(json.dumps(dict(os.environ)))"
2022-10-19 11:11:00,222 MainThread execute ::execute :283 DEBUG : Command Output is:
{"DIRAC": "/cvmfs/lhcb.cern.ch/lhcbdirac/prod/Linux-x86_64", "DIRACOS": "/cvmfs/lhcb.cern.ch/lhcbdirac/versions/v10.4.20-1664186607/Linux-x86_64", "VOMS_USERCONF": "/cvmfs/lhcb.cern.ch/etc/grid-security/vomses", "CONDA_SHLVL": "1", "CONDA_PROMPT_MODIFIER": "(base) ", "GSETTINGS_SCHEMA_DIR_CONDA_BACKUP": "", "X509_CERT_DIR": "/cvmfs/lhcb.cern.ch/etc/grid-security/certificates", "X509_VOMSES": "/cvmfs/lhcb.cern.ch/etc/grid-security/vomses", "XRD_RUNFORKHANDLER": "0", "PYTHONWARNINGS": "ignore", "GLOBUS_IO_IPV6": "TRUE", "MYSITEROOT": "/cvmfs/lhcb.cern.ch/lib", "PATH": "/cvmfs/lhcb.cern.ch/lhcbdirac/versions/v10.4.20-1664186607/Linux-x86_64/bin:/cvmfs/lhcb.cern.ch/lhcbdirac/versions/v10.4.20-1664186607/Linux-x86_64/condabin:/usr/local/bin:/usr/bin", "GSETTINGS_SCHEMA_DIR": "/cvmfs/lhcb.cern.ch/lhcbdirac/versions/v10.4.20-1664186607/Linux-x86_64/share/glib-2.0/schemas", "CONDOR_CONFIG": "/cvmfs/lhcb.cern.ch/lhcbdirac/versions/v10.4.20-1664186607/Linux-x86_64/etc/condor/condor_config", "CONDA_PREFIX": "/cvmfs/lhcb.cern.ch/lhcbdirac/versions/v10.4.20-1664186607/Linux-x86_64", "PWD": "/centos/ganga/ganga", "MAMBA_ROOT_PREFIX": "/cvmfs/lhcb.cern.ch/lhcbdirac/versions/v10.4.20-1664186607/Linux-x86_64", "DAVIX_USE_LIBCURL": "1", "X509_VOMS_DIR": "/cvmfs/lhcb.cern.ch/etc/grid-security/vomsdir", "SSL_CERT_DIR": "/cvmfs/lhcb.cern.ch/etc/grid-security/certificates", "SHLVL": "1", "HOME": "/centos", "CONDA_BACKUP_CONDOR_CONFIG": "empty", "BASH_ENV": "/cvmfs/lhcb.cern.ch/lhcbdirac/bashrc.py3", "CONDA_DEFAULT_ENV": "base", "GLOBUS_FTP_CLIENT_IPV6": "TRUE", "_": "/cvmfs/lhcb.cern.ch/lhcbdirac/versions/v10.4.20-1664186607/Linux-x86_64/bin/python"}
2022-10-19 11:11:00,222 MainThread execute ::execute :284 DEBUG : Error received:
invalid load key, '{'.
2022-10-19 11:11:00,222 MainThread LHCbDIRACenv ::store_dirac_environment:53 DEBUG : Storing new LHCbDirac environment (prod:x86_64-slc6-gcc49-opt)
2022-10-19 11:11:00,222 MainThread LHCbDIRACenv ::store_dirac_environment:57 INFO : Using LHCbDirac version prod
2022-10-19 11:11:00,224 MainThread Runtime ::initSetupRuntimePackages:247 DEBUG : Setting up Runtime Packages
2022-10-19 11:11:00,224 MainThread __init__ ::startUpQueues :20 DEBUG : Starting Queues
2022-10-19 11:11:00,227 MainThread Runtime ::loadPlugins :289 DEBUG : Loading: ['/centos/ganga/ganga/ganga/GangaDirac', '/centos/ganga/ganga/ganga/GangaGaudi', '/centos/ganga/ganga/ganga/GangaLHCb'] PLUGINS
2022-10-19 11:11:00,227 MainThread Runtime ::loadPlugins :291 DEBUG : Bootstrapping: /centos/ganga/ganga/ganga/GangaDirac
2022-10-19 11:11:00,228 MainThread Runtime ::loadPlugins :291 DEBUG : Bootstrapping: /centos/ganga/ganga/ganga/GangaGaudi
2022-10-19 11:11:00,228 MainThread Runtime ::bootstrap :188 DEBUG : problems with bootstrap of runtime package GangaGaudi
2022-10-19 11:11:00,228 MainThread Runtime ::bootstrap :189 DEBUG : No module named 'GangaGaudi.BOOT'
2022-10-19 11:11:00,229 MainThread Runtime ::loadPlugins :291 DEBUG : Bootstrapping: /centos/ganga/ganga/ganga/GangaLHCb
2022-10-19 11:11:00,229 MainThread Runtime ::loadPlugins :306 DEBUG : Loading: /centos/ganga/ganga/ganga/GangaDirac
2022-10-19 11:11:00,229 MainThread Runtime ::loadPlugins :172 DEBUG : Loading Plugin: GangaDirac
2022-10-19 11:11:00,229 MainThread __init__ ::loadPlugins :127 DEBUG : Loading Backends
2022-10-19 11:11:00,229 MainThread __init__ ::loadPlugins :129 DEBUG : Loading RTHandlers
2022-10-19 11:11:00,232 MainThread GangaPlugin ::add :101 DEBUG : adding plugin DiracFile (category "gangafiles")
2022-10-19 11:11:00,234 MainThread __init__ ::loadPlugins :131 DEBUG : Loading Files
2022-10-19 11:11:00,234 MainThread Runtime ::loadPlugins :178 DEBUG : Finished Plugin: GangaDirac
2022-10-19 11:11:00,234 MainThread Runtime ::loadPlugins :306 DEBUG : Loading: /centos/ganga/ganga/ganga/GangaGaudi
2022-10-19 11:11:00,234 MainThread Runtime ::loadPlugins :172 DEBUG : Loading Plugin: GangaGaudi
2022-10-19 11:11:00,234 MainThread Runtime ::loadPlugins :178 DEBUG : Finished Plugin: GangaGaudi
2022-10-19 11:11:00,235 MainThread Runtime ::loadPlugins :306 DEBUG : Loading: /centos/ganga/ganga/ganga/GangaLHCb
2022-10-19 11:11:00,235 MainThread Runtime ::loadPlugins :172 DEBUG : Loading Plugin: GangaLHCb
2022-10-19 11:11:00,237 MainThread GangaPlugin ::add :101 DEBUG : adding plugin LogicalFile (category "gangafiles")
2022-10-19 11:11:00,237 MainThread GangaPlugin ::add :101 DEBUG : adding plugin PhysicalFile (category "gangafiles")
2022-10-19 11:11:00,238 MainThread GangaPlugin ::add :101 DEBUG : adding plugin LHCbDataset (category "datasets")
2022-10-19 11:11:00,238 MainThread Config ::convert_type :427 DEBUG : checking value type: <class 'str'> (while setting option [.]datasets = string_dataset_shortcut )
2022-10-19 11:11:00,239 MainThread Config ::convert_type :427 DEBUG : checking value type: <class 'str'> (while setting option [.]datasets = string_dataset_shortcut )
2022-10-19 11:11:00,239 MainThread GangaPlugin ::add :101 DEBUG : adding plugin LHCbCompressedFileSet (category "gangafiles")
2022-10-19 11:11:00,240 MainThread GangaPlugin ::add :101 DEBUG : adding plugin LHCbCompressedDataset (category "datasets")
2022-10-19 11:11:00,273 MainThread Schema ::_check_type :578 DEBUG : valType: <class 'dict'> defValueType: <class 'dict'> name: DiracBase.settings
2022-10-19 11:11:00,274 MainThread Schema ::_check_type :578 DEBUG : valType: <class 'dict'> defValueType: <class 'dict'> name: Dirac.settings
2022-10-19 11:11:00,274 MainThread GangaPlugin ::add :101 DEBUG : adding plugin Dirac (category "backends")
2022-10-19 11:11:00,275 MainThread Proxy ::raw_eval :184 DEBUG : Proxy Cannot evaluate v=: 'OK'
2022-10-19 11:11:00,275 MainThread Proxy ::raw_eval :185 DEBUG : Using raw value instead
2022-10-19 11:11:00,275 MainThread Proxy ::raw_eval :184 DEBUG : Proxy Cannot evaluate v=: 'Path'
2022-10-19 11:11:00,275 MainThread Proxy ::raw_eval :185 DEBUG : Using raw value instead
2022-10-19 11:11:00,275 MainThread GangaPlugin ::add :101 DEBUG : adding plugin BKQuery (category "query")
2022-10-19 11:11:00,276 MainThread Schema ::_check_type :578 DEBUG : valType: <class 'dict'> defValueType: <class 'dict'> name: BKQueryDict.dict
2022-10-19 11:11:00,276 MainThread GangaPlugin ::add :101 DEBUG : adding plugin BKQueryDict (category "")
2022-10-19 11:11:00,276 MainThread GangaPlugin ::add :101 DEBUG : adding plugin Bookkeeping (category "datasets")
2022-10-19 11:11:00,277 MainThread GangaPlugin ::add :101 DEBUG : adding plugin GaudiXMLSummary (category "")
2022-10-19 11:11:00,278 MainThread GangaPlugin ::add :101 DEBUG : adding plugin GaudiXMLSummaryMerger (category "postprocessors")
2022-10-19 11:11:00,280 MainThread Proxy ::raw_eval :184 DEBUG : Proxy Cannot evaluate v=: '-T'
2022-10-19 11:11:00,280 MainThread Proxy ::raw_eval :185 DEBUG : Using raw value instead
2022-10-19 11:11:00,282 MainThread GangaPlugin ::add :101 DEBUG : adding plugin GaudiPython (category "applications")
2022-10-19 11:11:00,283 MainThread Proxy ::raw_eval :184 DEBUG : Proxy Cannot evaluate v=: 'Bender'
2022-10-19 11:11:00,283 MainThread Proxy ::raw_eval :185 DEBUG : Using raw value instead
2022-10-19 11:11:00,283 MainThread GangaPlugin ::add :101 DEBUG : adding plugin Bender (category "applications")
2022-10-19 11:11:00,284 MainThread GangaPlugin ::add :101 DEBUG : adding plugin BenderScript (category "applications")
2022-10-19 11:11:00,285 MainThread GangaPlugin ::add :101 DEBUG : adding plugin Ostap (category "applications")
2022-10-19 11:11:00,286 MainThread Proxy ::raw_eval :184 DEBUG : Proxy Cannot evaluate v=: 'x86_64-centos7-gcc8-opt'
2022-10-19 11:11:00,286 MainThread Proxy ::raw_eval :185 DEBUG : Using raw value instead
2022-10-19 11:11:00,286 MainThread GangaPlugin ::add :101 DEBUG : adding plugin GaudiExec (category "applications")
2022-10-19 11:11:00,287 MainThread GangaPlugin ::add :101 DEBUG : adding plugin BenderModule (category "applications")
2022-10-19 11:11:00,288 MainThread GangaPlugin ::add :101 DEBUG : adding plugin BenderRun (category "applications")
2022-10-19 11:11:00,289 MainThread GangaPlugin ::add :101 DEBUG : adding plugin OstapRun (category "applications")
2022-10-19 11:11:00,290 MainThread __init__ ::<module> :24 DEBUG : User Added Apps
2022-10-19 11:11:00,290 MainThread __init__ ::<module> :35 DEBUG : Constructing AppsBase Apps
2022-10-19 11:11:00,290 MainThread __init__ ::<module> :47 DEBUG : Adding Gauss
2022-10-19 11:11:00,290 MainThread __init__ ::<module> :47 DEBUG : Adding Boole
2022-10-19 11:11:00,290 MainThread __init__ ::<module> :47 DEBUG : Adding Brunel
2022-10-19 11:11:00,290 MainThread __init__ ::<module> :47 DEBUG : Adding DaVinci
2022-10-19 11:11:00,290 MainThread __init__ ::<module> :47 DEBUG : Adding Moore
2022-10-19 11:11:00,290 MainThread __init__ ::<module> :47 DEBUG : Adding MooreOnline
2022-10-19 11:11:00,290 MainThread __init__ ::<module> :47 DEBUG : Adding Vetra
2022-10-19 11:11:00,290 MainThread __init__ ::<module> :47 DEBUG : Adding Panoptes
2022-10-19 11:11:00,290 MainThread __init__ ::<module> :47 DEBUG : Adding Erasmus
2022-10-19 11:11:00,291 MainThread __init__ ::<module> :47 DEBUG : Adding Alignment
2022-10-19 11:11:00,291 MainThread __init__ ::<module> :47 DEBUG : Adding Noether
2022-10-19 11:11:00,291 MainThread __init__ ::<module> :47 DEBUG : Adding Urania
2022-10-19 11:11:00,291 MainThread __init__ ::<module> :49 DEBUG : Adding apps
2022-10-19 11:11:00,304 MainThread GangaPlugin ::add :101 DEBUG : adding plugin Gauss (category "applications")
2022-10-19 11:11:00,305 MainThread GangaPlugin ::add :101 DEBUG : adding plugin Boole (category "applications")
2022-10-19 11:11:00,306 MainThread GangaPlugin ::add :101 DEBUG : adding plugin Brunel (category "applications")
2022-10-19 11:11:00,307 MainThread GangaPlugin ::add :101 DEBUG : adding plugin DaVinci (category "applications")
2022-10-19 11:11:00,307 MainThread GangaPlugin ::add :101 DEBUG : adding plugin Moore (category "applications")
2022-10-19 11:11:00,308 MainThread GangaPlugin ::add :101 DEBUG : adding plugin MooreOnline (category "applications")
2022-10-19 11:11:00,309 MainThread GangaPlugin ::add :101 DEBUG : adding plugin Vetra (category "applications")
2022-10-19 11:11:00,310 MainThread GangaPlugin ::add :101 DEBUG : adding plugin Panoptes (category "applications")
2022-10-19 11:11:00,310 MainThread GangaPlugin ::add :101 DEBUG : adding plugin Erasmus (category "applications")
2022-10-19 11:11:00,311 MainThread GangaPlugin ::add :101 DEBUG : adding plugin Alignment (category "applications")
2022-10-19 11:11:00,312 MainThread GangaPlugin ::add :101 DEBUG : adding plugin Noether (category "applications")
2022-10-19 11:11:00,313 MainThread GangaPlugin ::add :101 DEBUG : adding plugin Urania (category "applications")
2022-10-19 11:11:00,313 MainThread __init__ ::<module> :53 DEBUG : Fin
2022-10-19 11:11:00,314 MainThread GangaPlugin ::add :101 DEBUG : adding plugin LHCbFileMerger (category "postprocessor")
2022-10-19 11:11:00,314 MainThread GangaPlugin ::add :101 DEBUG : adding plugin LHCbFileMerger (category "postprocessor")
2022-10-19 11:11:00,314 MainThread GangaPlugin ::add :101 DEBUG : adding plugin GaudiExecMerger (category "postprocessor")
2022-10-19 11:11:00,315 MainThread GangaPlugin ::add :101 DEBUG : adding plugin GaudiInputDataSplitter (category "splitters")
2022-10-19 11:11:00,316 MainThread Proxy ::raw_eval :184 DEBUG : Proxy Cannot evaluate v=: 'OfflineGangaDiracSplitter'
2022-10-19 11:11:00,316 MainThread Proxy ::raw_eval :185 DEBUG : Using raw value instead
2022-10-19 11:11:00,316 MainThread GangaPlugin ::add :101 DEBUG : adding plugin SplitByFiles (category "splitters")
2022-10-19 11:11:00,316 MainThread GangaPlugin ::add :101 DEBUG : adding plugin OptionsFileSplitter (category "splitters")
2022-10-19 11:11:00,317 MainThread GangaPlugin ::add :101 DEBUG : adding plugin GaussSplitter (category "splitters")
2022-10-19 11:11:00,317 MainThread GangaPlugin ::add :101 DEBUG : adding plugin BKTestQuery (category "query")
2022-10-19 11:11:00,318 MainThread GangaPlugin ::add :101 DEBUG : adding plugin LHCbUnit (category "units")
2022-10-19 11:11:00,319 MainThread GangaPlugin ::add :101 DEBUG : adding plugin LHCbTransform (category "transforms")
2022-10-19 11:11:00,319 MainThread Config ::convert_type :422 DEBUG : applied eval(False) -> False (while setting option [.]submit_with_threads = False )
2022-10-19 11:11:00,319 MainThread Config ::convert_type :427 DEBUG : checking value type: [<class 'bool'>] (while setting option [.]submit_with_threads = False )
2022-10-19 11:11:00,320 MainThread GangaPlugin ::add :101 DEBUG : adding plugin LHCbTask (category "tasks")
2022-10-19 11:11:00,320 MainThread GangaPlugin ::add :101 DEBUG : adding plugin LHCbMetaDataChecker (category "postprocessor")
2022-10-19 11:11:00,320 MainThread Runtime ::loadPlugins :178 DEBUG : Finished Plugin: GangaLHCb
2022-10-19 11:11:00,355 MainThread GangaPlugin ::add :101 DEBUG : adding plugin Batch (category "backends")
2022-10-19 11:11:00,358 MainThread Schema ::_check_type :578 DEBUG : valType: <class 'dict'> defValueType: <class 'dict'> name: JobTree.folders
2022-10-19 11:11:00,358 MainThread GangaPlugin ::add :101 DEBUG : adding plugin JobTree (category "jobtrees")
2022-10-19 11:11:00,366 MainThread Repository_runtime ::bootstrap :144 DEBUG : Registry: prep
2022-10-19 11:11:00,367 MainThread Repository_runtime ::bootstrap :145 DEBUG : Loc: /centos/gangadir/repository/egede/LocalXML
2022-10-19 11:11:00,367 MainThread Registry ::startup :630 DEBUG : metadata startup
2022-10-19 11:11:00,367 MainThread Registry ::startup :635 DEBUG : repo startup
2022-10-19 11:11:00,415 MainThread GangaRepositoryXML ::update_index :551 DEBUG : updating index...
2022-10-19 11:11:00,416 MainThread GangaRepositoryXML ::update_index :558 DEBUG : Iterating over Items
2022-10-19 11:11:00,417 MainThread GangaRepositoryXML ::index_load :317 DEBUG : 0 != 1666135013.7140176
2022-10-19 11:11:00,418 MainThread GangaRepositoryXML ::update_index :620 DEBUG : Iterated over Items
2022-10-19 11:11:00,419 MainThread GangaRepositoryXML ::update_index :654 DEBUG : updated index done
2022-10-19 11:11:00,420 MainThread GangaRepositoryXML ::startup :261 DEBUG : GangaRepositoryLocal Finished Startup
2022-10-19 11:11:00,420 MainThread Registry ::startup :639 DEBUG : Registry 'prep.metadata' [LocalXML] startup time: 0.05321764945983887 sec
2022-10-19 11:11:00,420 MainThread Registry ::startup :633 DEBUG : Startup of prep.metadata took 0.05377459526062012 sec
2022-10-19 11:11:00,421 MainThread Registry ::startup :635 DEBUG : repo startup
2022-10-19 11:11:00,465 MainThread GangaRepositoryXML ::update_index :551 DEBUG : updating index...
2022-10-19 11:11:00,466 MainThread GangaRepositoryXML ::update_index :558 DEBUG : Iterating over Items
2022-10-19 11:11:00,466 MainThread GangaRepositoryXML ::update_index :620 DEBUG : Iterated over Items
2022-10-19 11:11:00,466 MainThread GangaRepositoryXML ::update_index :654 DEBUG : updated index done
2022-10-19 11:11:00,467 MainThread GangaRepositoryXML ::startup :261 DEBUG : GangaRepositoryLocal Finished Startup
2022-10-19 11:11:00,467 MainThread Registry ::startup :639 DEBUG : Registry 'prep' [LocalXML] startup time: 0.10022187232971191 sec
2022-10-19 11:11:00,468 MainThread Registry ::ids :362 DEBUG : ids
2022-10-19 11:11:00,468 MainThread Registry ::ids :362 DEBUG : ids
2022-10-19 11:11:00,468 MainThread Registry ::info :696 DEBUG : info
2022-10-19 11:11:00,469 MainThread Repository_runtime ::bootstrap :147 DEBUG : started registry 'prep': 0 objects
2022-10-19 11:11:00,469 MainThread Repository_runtime ::bootstrap :144 DEBUG : Registry: jobs
2022-10-19 11:11:00,470 MainThread Repository_runtime ::bootstrap :145 DEBUG : Loc: /centos/gangadir/repository/egede/LocalXML
2022-10-19 11:11:00,470 MainThread Registry ::startup :630 DEBUG : metadata startup
2022-10-19 11:11:00,471 MainThread Registry ::startup :635 DEBUG : repo startup
2022-10-19 11:11:00,524 MainThread GangaRepositoryXML ::update_index :551 DEBUG : updating index...
2022-10-19 11:11:00,525 MainThread GangaRepositoryXML ::update_index :558 DEBUG : Iterating over Items
2022-10-19 11:11:00,526 MainThread GangaRepositoryXML ::index_load :317 DEBUG : 0 != 1666134480.3743837
2022-10-19 11:11:00,527 MainThread GangaRepositoryXML ::update_index :620 DEBUG : Iterated over Items
2022-10-19 11:11:00,528 MainThread GangaRepositoryXML ::update_index :654 DEBUG : updated index done
2022-10-19 11:11:00,529 MainThread GangaRepositoryXML ::startup :261 DEBUG : GangaRepositoryLocal Finished Startup
2022-10-19 11:11:00,529 MainThread Registry ::startup :639 DEBUG : Registry 'jobs.metadata' [LocalXML] startup time: 0.05838918685913086 sec
2022-10-19 11:11:00,529 MainThread Registry ::startup :633 DEBUG : Startup of jobs.metadata took 0.05912637710571289 sec
2022-10-19 11:11:00,530 MainThread Registry ::startup :635 DEBUG : repo startup
2022-10-19 11:11:00,583 MainThread GangaRepositoryXML ::update_index :551 DEBUG : updating index...
2022-10-19 11:11:00,584 MainThread GangaRepositoryXML ::update_index :558 DEBUG : Iterating over Items
2022-10-19 11:11:00,585 MainThread GangaRepositoryXML ::index_load :317 DEBUG : 0 != 1666134480.4413846
2022-10-19 11:11:00,606 MainThread GangaRepositoryXML ::index_load :317 DEBUG : 0 != 1666134480.4423845
2022-10-19 11:11:00,617 MainThread GangaRepositoryXML ::index_load :317 DEBUG : 0 != 1666170585.5529547
2022-10-19 11:11:00,623 MainThread GangaRepositoryXML ::update_index :620 DEBUG : Iterated over Items
2022-10-19 11:11:00,624 MainThread GangaRepositoryXML ::update_index :654 DEBUG : updated index done
2022-10-19 11:11:00,624 MainThread GangaRepositoryXML ::startup :261 DEBUG : GangaRepositoryLocal Finished Startup
2022-10-19 11:11:00,624 MainThread Registry ::startup :639 DEBUG : Registry 'jobs' [LocalXML] startup time: 0.1542501449584961 sec
2022-10-19 11:11:00,624 MainThread Registry ::ids :362 DEBUG : ids
2022-10-19 11:11:00,625 MainThread Registry ::ids :362 DEBUG : ids
2022-10-19 11:11:00,625 MainThread Registry ::info :696 DEBUG : info
2022-10-19 11:11:00,625 MainThread Repository_runtime ::bootstrap :147 DEBUG : started registry 'jobs': 3 objects
2022-10-19 11:11:00,626 MainThread Repository_runtime ::bootstrap :144 DEBUG : Registry: templates
2022-10-19 11:11:00,626 MainThread Repository_runtime ::bootstrap :145 DEBUG : Loc: /centos/gangadir/repository/egede/LocalXML
2022-10-19 11:11:00,626 MainThread Registry ::startup :630 DEBUG : metadata startup
2022-10-19 11:11:00,626 MainThread Registry ::startup :635 DEBUG : repo startup
2022-10-19 11:11:00,666 MainThread GangaRepositoryXML ::update_index :551 DEBUG : updating index...
2022-10-19 11:11:00,667 MainThread GangaRepositoryXML ::update_index :558 DEBUG : Iterating over Items
2022-10-19 11:11:00,667 MainThread GangaRepositoryXML ::index_load :317 DEBUG : 0 != 1666134480.5753863
2022-10-19 11:11:00,667 MainThread GangaRepositoryXML ::update_index :620 DEBUG : Iterated over Items
2022-10-19 11:11:00,667 MainThread GangaRepositoryXML ::update_index :654 DEBUG : updated index done
2022-10-19 11:11:00,668 MainThread GangaRepositoryXML ::startup :261 DEBUG : GangaRepositoryLocal Finished Startup
2022-10-19 11:11:00,668 MainThread Registry ::startup :639 DEBUG : Registry 'templates.metadata' [LocalXML] startup time: 0.04176688194274902 sec
2022-10-19 11:11:00,668 MainThread Registry ::startup :633 DEBUG : Startup of templates.metadata took 0.0421292781829834 sec
2022-10-19 11:11:00,668 MainThread Registry ::startup :635 DEBUG : repo startup
2022-10-19 11:11:00,708 MainThread GangaRepositoryXML ::update_index :551 DEBUG : updating index...
2022-10-19 11:11:00,710 MainThread GangaRepositoryXML ::update_index :558 DEBUG : Iterating over Items
2022-10-19 11:11:00,710 MainThread GangaRepositoryXML ::update_index :620 DEBUG : Iterated over Items
2022-10-19 11:11:00,710 MainThread GangaRepositoryXML ::update_index :654 DEBUG : updated index done
2022-10-19 11:11:00,711 MainThread GangaRepositoryXML ::startup :261 DEBUG : GangaRepositoryLocal Finished Startup
2022-10-19 11:11:00,711 MainThread Registry ::startup :639 DEBUG : Registry 'templates' [LocalXML] startup time: 0.08527326583862305 sec
2022-10-19 11:11:00,712 MainThread Registry ::ids :362 DEBUG : ids
2022-10-19 11:11:00,712 MainThread Registry ::ids :362 DEBUG : ids
2022-10-19 11:11:00,714 MainThread Registry ::info :696 DEBUG : info
2022-10-19 11:11:00,714 MainThread Repository_runtime ::bootstrap :147 DEBUG : started registry 'templates': 0 objects
2022-10-19 11:11:00,715 MainThread Repository_runtime ::bootstrap :144 DEBUG : Registry: box
2022-10-19 11:11:00,715 MainThread Repository_runtime ::bootstrap :145 DEBUG : Loc: /centos/gangadir/repository/egede/LocalXML
2022-10-19 11:11:00,716 MainThread Registry ::startup :630 DEBUG : metadata startup
2022-10-19 11:11:00,716 MainThread Registry ::startup :635 DEBUG : repo startup
2022-10-19 11:11:00,775 MainThread GangaRepositoryXML ::update_index :551 DEBUG : updating index...
2022-10-19 11:11:00,777 MainThread GangaRepositoryXML ::update_index :558 DEBUG : Iterating over Items
2022-10-19 11:11:00,777 MainThread GangaRepositoryXML ::update_index :620 DEBUG : Iterated over Items
2022-10-19 11:11:00,777 MainThread GangaRepositoryXML ::update_index :654 DEBUG : updated index done
2022-10-19 11:11:00,778 MainThread GangaRepositoryXML ::startup :261 DEBUG : GangaRepositoryLocal Finished Startup
2022-10-19 11:11:00,778 MainThread Registry ::startup :639 DEBUG : Registry 'box.metadata' [LocalXML] startup time: 0.06201004981994629 sec
2022-10-19 11:11:00,779 MainThread Registry ::startup :633 DEBUG : Startup of box.metadata took 0.06297636032104492 sec
2022-10-19 11:11:00,779 MainThread Registry ::startup :635 DEBUG : repo startup
2022-10-19 11:11:00,834 MainThread GangaRepositoryXML ::update_index :551 DEBUG : updating index...
2022-10-19 11:11:00,835 MainThread GangaRepositoryXML ::update_index :558 DEBUG : Iterating over Items
2022-10-19 11:11:00,836 MainThread GangaRepositoryXML ::update_index :620 DEBUG : Iterated over Items
2022-10-19 11:11:00,836 MainThread GangaRepositoryXML ::update_index :654 DEBUG : updated index done
2022-10-19 11:11:00,836 MainThread GangaRepositoryXML ::startup :261 DEBUG : GangaRepositoryLocal Finished Startup
2022-10-19 11:11:00,837 MainThread Registry ::startup :639 DEBUG : Registry 'box' [LocalXML] startup time: 0.12105846405029297 sec
2022-10-19 11:11:00,837 MainThread Registry ::info :696 DEBUG : info
2022-10-19 11:11:00,838 MainThread Repository_runtime ::bootstrap :147 DEBUG : started registry 'box': 0 objects
2022-10-19 11:11:00,839 MainThread Repository_runtime ::bootstrap :144 DEBUG : Registry: tasks
2022-10-19 11:11:00,840 MainThread Repository_runtime ::bootstrap :145 DEBUG : Loc: /centos/gangadir/repository/egede/LocalXML
2022-10-19 11:11:00,841 MainThread Registry ::startup :635 DEBUG : repo startup
2022-10-19 11:11:00,901 MainThread GangaRepositoryXML ::update_index :551 DEBUG : updating index...
2022-10-19 11:11:00,902 MainThread GangaRepositoryXML ::update_index :558 DEBUG : Iterating over Items
2022-10-19 11:11:00,903 MainThread GangaRepositoryXML ::update_index :620 DEBUG : Iterated over Items
2022-10-19 11:11:00,903 MainThread GangaRepositoryXML ::update_index :654 DEBUG : updated index done
2022-10-19 11:11:00,904 MainThread GangaRepositoryXML ::startup :261 DEBUG : GangaRepositoryLocal Finished Startup
2022-10-19 11:11:00,904 MainThread Registry ::startup :639 DEBUG : Registry 'tasks' [LocalXML] startup time: 0.06281709671020508 sec
2022-10-19 11:11:00,907 MainThread Registry ::info :696 DEBUG : info
2022-10-19 11:11:00,907 MainThread Repository_runtime ::bootstrap :147 DEBUG : started registry 'tasks': 0 objects
2022-10-19 11:11:00,979 MainThread bootstrap ::bootstrap :943 DEBUG : Bootstrap Core Modules
2022-10-19 11:11:00,981 GANGA_Update_Thread_AsyncMonitoringService Registry ::keys :380 DEBUG : keys
2022-10-19 11:11:00,981 GANGA_Update_Thread_AsyncMonitoringService Registry ::ids :362 DEBUG : ids
2022-10-19 11:11:00,984 MainThread bootstrap ::bootstrap :953 DEBUG : Post-Bootstrap hooks
2022-10-19 11:11:00,985 GANGA_Update_Thread_AsyncMonitoringService MonitoringService ::_check_active_backends:78 DEBUG : Adding Dirac to list of backends to monitor.
2022-10-19 11:11:00,985 MainThread ICredentialInfo ::__init__ :128 DEBUG : Trying to wrap /tmp/x509up_u1000
2022-10-19 11:11:00,986 GANGA_Update_Thread_AsyncMonitoringService MonitoringService ::_check_backend :111 DEBUG : Checking backend Dirac
2022-10-19 11:11:00,986 MainThread ICredentialInfo ::exists :254 DEBUG : Checking for Credential at: '/tmp/x509up_u1000'
2022-10-19 11:11:00,986 GANGA_Update_Thread_AsyncMonitoringService IBackend ::master_updateMonitoringInformation:421 DEBUG : Running Monitoring for Jobs: ['2']
2022-10-19 11:11:00,986 GANGA_Update_Thread_AsyncMonitoringService Registry ::_locked_load :554 DEBUG : _locked_load
2022-10-19 11:11:00,986 MainThread ICredentialInfo ::__init__ :131 DEBUG : Wrapping existing file /tmp/x509up_u1000
2022-10-19 11:11:00,986 GANGA_Update_Thread_AsyncMonitoringService GangaRepositoryXML ::load :1032 DEBUG : Loading Repo object(s): [2]
2022-10-19 11:11:00,986 MainThread ICredentialInfo ::exists :254 DEBUG : Checking for Credential at: '/tmp/x509up_u1000'
2022-10-19 11:11:00,987 MainThread ICredentialInfo ::check_requirements :227 DEBUG : Credential exists, checking it
2022-10-19 11:11:00,987 MainThread DiracUtilities ::get_env :92 DEBUG : Running DIRAC source command nonsense
2022-10-19 11:11:00,989 GANGA_Update_Thread_AsyncMonitoringService GangaRepositoryXML ::_load_xml_from_obj :941 DEBUG : Loading XML file for ID: 2 took 0.0021812915802001953 sec
2022-10-19 11:11:00,989 GANGA_Update_Thread_AsyncMonitoringService GangaRepositoryXML ::_load_xml_from_obj :949 DEBUG : Checking children: 2
2022-10-19 11:11:00,992 GANGA_Update_Thread_AsyncMonitoringService SubJobXMLList ::countSubJobDirs :633 DEBUG : count: 0 len: 0
2022-10-19 11:11:00,992 GANGA_Update_Thread_AsyncMonitoringService GangaRepositoryXML ::_load_xml_from_obj :955 DEBUG : Found children: False
2022-10-19 11:11:00,994 GANGA_Update_Thread_AsyncMonitoringService GangaRepositoryXML ::_load_xml_from_obj :966 DEBUG : Finished Loading XML
2022-10-19 11:11:00,994 GANGA_Update_Thread_AsyncMonitoringService GangaRepositoryXML ::load :1091 DEBUG : Finished 'load'-ing of: [2]
2022-10-19 11:11:00,994 GANGA_Update_Thread_AsyncMonitoringService IBackend ::master_updateMonitoringInformation:504 DEBUG : Monitoring jobs: ['Job#2']
2022-10-19 11:11:00,995 GANGA_Update_Thread_AsyncMonitoringService IBackend ::master_updateMonitoringInformation:508 DEBUG : Finished Monitoring request
2022-10-19 11:11:00,995 GANGA_Update_Thread_AsyncMonitoringService MonitoringService ::_log_backend_summary:93 DEBUG : Active backends: {"Dirac" : [2, ], }
2022-10-19 11:11:00,996 GANGA_Update_Thread_AsyncMonitoringService ICredentialInfo ::__init__ :128 DEBUG : Trying to wrap /tmp/x509up_u1000
2022-10-19 11:11:00,996 MainThread execute ::execute :228 DEBUG : Executing Command:
'source nonsense;python -c "import base64;exec(base64.b64decode(b'CmltcG9ydCBvcwppbXBvcnQgcGlja2xlIGFzIHBpY2tsZQp3aXRoIG9zLmZkb3BlbigxMiwnd2InKSBhcyBlbnZwaXBlOgogICAgcGlja2xlLmR1bXAoZGljdChvcy5lbnZpcm9uKSwgZW52cGlwZSwgMikK'))"'
2022-10-19 11:11:00,996 GANGA_Update_Thread_AsyncMonitoringService ICredentialInfo ::exists :254 DEBUG : Checking for Credential at: '/tmp/x509up_u1000'
2022-10-19 11:11:00,996 GANGA_Update_Thread_AsyncMonitoringService ICredentialInfo ::__init__ :131 DEBUG : Wrapping existing file /tmp/x509up_u1000
2022-10-19 11:11:00,996 GANGA_Update_Thread_AsyncMonitoringService ICredentialInfo ::exists :254 DEBUG : Checking for Credential at: '/tmp/x509up_u1000'
2022-10-19 11:11:00,996 GANGA_Update_Thread_AsyncMonitoringService ICredentialInfo ::check_requirements :227 DEBUG : Credential exists, checking it
2022-10-19 11:11:01,006 GANGA_Update_Thread_GangaTasks Registry ::ids :362 DEBUG : ids
2022-10-19 11:11:01,006 GANGA_Update_Thread_GangaTasks TaskRegistry ::_thread_main :85 DEBUG : Entering main loop
2022-10-19 11:11:01,007 GANGA_Update_Thread_GangaTasks Registry ::ids :362 DEBUG : ids
2022-10-19 11:11:01,007 GANGA_Update_Thread_GangaTasks TaskRegistry ::_thread_main :114 DEBUG : TaskRegistry Sleeping for: 60.0 seconds
2022-10-19 11:11:01,032 MainThread execute ::execute :232 DEBUG : stdout:
2022-10-19 11:11:01,032 MainThread execute ::execute :233 DEBUG : stderr: bash: line 1: nonsense: No such file or directory
2022-10-19 11:11:01,032 MainThread execute ::execute :243 DEBUG : bash: line 1: nonsense: No such file or directory
2022-10-19 11:11:01,032 MainThread CredentialStore ::__getitem__ :199 DEBUG : No such file or directory
2022-10-19 11:11:01,033 MainThread Runtime ::postBootstrapHook :239 DEBUG : no postBootstrapHook() in runtime package GangaGaudi
2022-10-19 11:11:01,033 GANGA_Update_Thread_AsyncMonitoringService DiracUtilities ::get_env :92 DEBUG : Running DIRAC source command nonsense
2022-10-19 11:11:01,033 MainThread Config ::setSessionValue :608 DEBUG : trying to set session option [DIRAC]DiracEnvJSON = /centos/.cache/Ganga/GangaLHCb/x86_64-slc6-gcc49-opt/prod
2022-10-19 11:11:01,033 MainThread Config ::convert_type :424 DEBUG : ignored failed eval(/centos/.cache/Ganga/GangaLHCb/x86_64-slc6-gcc49-opt/prod): invalid syntax (<string>, line 1) (while setting option [.]DiracEnvJSON = /centos/.cache/Ganga/GangaLHCb/x86_64-slc6-gcc49-opt/prod )
2022-10-19 11:11:01,035 MainThread Config ::convert_type :427 DEBUG : checking value type: <class 'NoneType'> (while setting option [.]DiracEnvJSON = /centos/.cache/Ganga/GangaLHCb/x86_64-slc6-gcc49-opt/prod )
2022-10-19 11:11:01,036 MainThread Config ::setSessionValue :621 DEBUG : sucessfully set session option [DIRAC]DiracEnvJSON = /centos/.cache/Ganga/GangaLHCb/x86_64-slc6-gcc49-opt/prod
2022-10-19 11:11:01,036 MainThread Config ::setSessionValue :608 DEBUG : trying to set session option [DIRAC]userVO = lhcb
2022-10-19 11:11:01,036 MainThread Config ::convert_type :427 DEBUG : checking value type: <class 'str'> (while setting option [.]userVO = lhcb )
2022-10-19 11:11:01,036 MainThread Config ::setSessionValue :621 DEBUG : sucessfully set session option [DIRAC]userVO = lhcb
2022-10-19 11:11:01,036 MainThread Config ::setSessionValue :608 DEBUG : trying to set session option [DIRAC]allDiracSE = ['CERN-USER', 'CNAF-USER', 'GRIDKA-USER', 'RRCKI-USER', 'IN2P3-USER', 'SARA-USER', 'PIC-USER', 'RAL-USER']
2022-10-19 11:11:01,036 MainThread Config ::convert_type :427 DEBUG : checking value type: <class 'list'> (while setting option [.]allDiracSE = ['CERN-USER', 'CNAF-USER', 'GRIDKA-USER', 'RRCKI-USER', 'IN2P3-USER', 'SARA-USER', 'PIC-USER', 'RAL-USER'] )
2022-10-19 11:11:01,036 MainThread Config ::setSessionValue :621 DEBUG : sucessfully set session option [DIRAC]allDiracSE = ['CERN-USER', 'CNAF-USER', 'GRIDKA-USER', 'RRCKI-USER', 'IN2P3-USER', 'SARA-USER', 'PIC-USER', 'RAL-USER']
2022-10-19 11:11:01,037 MainThread Config ::setSessionValue :608 DEBUG : trying to set session option [DIRAC]noInputDataBannedSites = []
2022-10-19 11:11:01,037 MainThread Config ::convert_type :427 DEBUG : checking value type: <class 'list'> (while setting option [.]noInputDataBannedSites = [] )
2022-10-19 11:11:01,037 MainThread Config ::setSessionValue :621 DEBUG : sucessfully set session option [DIRAC]noInputDataBannedSites = []
2022-10-19 11:11:01,037 MainThread Config ::setSessionValue :608 DEBUG : trying to set session option [DIRAC]RequireDefaultSE = False
2022-10-19 11:11:01,037 MainThread Config ::convert_type :427 DEBUG : checking value type: <class 'bool'> (while setting option [.]RequireDefaultSE = False )
2022-10-19 11:11:01,037 MainThread Config ::setSessionValue :621 DEBUG : sucessfully set session option [DIRAC]RequireDefaultSE = False
2022-10-19 11:11:01,037 MainThread Config ::setSessionValue :608 DEBUG : trying to set session option [DIRAC]proxyInitCmd = lhcb-proxy-init
2022-10-19 11:11:01,037 MainThread Config ::convert_type :427 DEBUG : checking value type: <class 'str'> (while setting option [.]proxyInitCmd = lhcb-proxy-init )
2022-10-19 11:11:01,037 MainThread Config ::setSessionValue :621 DEBUG : sucessfully set session option [DIRAC]proxyInitCmd = lhcb-proxy-init
2022-10-19 11:11:01,037 MainThread Config ::setSessionValue :608 DEBUG : trying to set session option [DIRAC]proxyInfoCmd = dirac-proxy-info
2022-10-19 11:11:01,038 MainThread Config ::convert_type :427 DEBUG : checking value type: <class 'str'> (while setting option [.]proxyInfoCmd = dirac-proxy-info )
2022-10-19 11:11:01,038 MainThread Config ::setSessionValue :621 DEBUG : sucessfully set session option [DIRAC]proxyInfoCmd = dirac-proxy-info
2022-10-19 11:11:01,038 MainThread Config ::setSessionValue :608 DEBUG : trying to set session option [Output]FailJobIfNoOutputMatched = False
2022-10-19 11:11:01,038 MainThread Config ::convert_type :422 DEBUG : applied eval(False) -> False (while setting option [.]FailJobIfNoOutputMatched = False )
2022-10-19 11:11:01,038 MainThread Config ::convert_type :427 DEBUG : checking value type: <class 'bool'> (while setting option [.]FailJobIfNoOutputMatched = False )
2022-10-19 11:11:01,038 MainThread Config ::setSessionValue :621 DEBUG : sucessfully set session option [Output]FailJobIfNoOutputMatched = False
2022-10-19 11:11:01,038 MainThread Config ::setSessionValue :608 DEBUG : trying to set session option [PollThread]autoCheckCredentials = False
2022-10-19 11:11:01,039 MainThread Config ::convert_type :427 DEBUG : checking value type: <class 'bool'> (while setting option [.]autoCheckCredentials = False )
2022-10-19 11:11:01,039 GANGA_Update_Thread_AsyncMonitoringService execute ::execute :228 DEBUG : Executing Command:
'source nonsense;python -c "import base64;exec(base64.b64decode(b'CmltcG9ydCBvcwppbXBvcnQgcGlja2xlIGFzIHBpY2tsZQp3aXRoIG9zLmZkb3BlbigxMSwnd2InKSBhcyBlbnZwaXBlOgogICAgcGlja2xlLmR1bXAoZGljdChvcy5lbnZpcm9uKSwgZW52cGlwZSwgMikK'))"'
2022-10-19 11:11:01,039 MainThread Config ::setSessionValue :621 DEBUG : sucessfully set session option [PollThread]autoCheckCredentials = False
2022-10-19 11:11:01,039 MainThread Config ::setSessionValue :608 DEBUG : trying to set session option [defaults_DiracProxy]group = lhcb_user
2022-10-19 11:11:01,039 MainThread Config ::convert_type :424 DEBUG : ignored failed eval(lhcb_user): name 'lhcb_user' is not defined (while setting option [.]group = lhcb_user )
2022-10-19 11:11:01,039 MainThread Config ::convert_type :427 DEBUG : checking value type: [<class 'str'>, None] (while setting option [.]group = lhcb_user )
2022-10-19 11:11:01,039 MainThread Config ::setSessionValue :621 DEBUG : sucessfully set session option [defaults_DiracProxy]group = lhcb_user
2022-10-19 11:11:01,039 MainThread Config ::setSessionValue :608 DEBUG : trying to set session option [defaults_DiracProxy]encodeDefaultProxyFileName = False
2022-10-19 11:11:01,040 MainThread Config ::convert_type :427 DEBUG : checking value type: [<class 'bool'>] (while setting option [.]encodeDefaultProxyFileName = False )
2022-10-19 11:11:01,040 MainThread Config ::setSessionValue :621 DEBUG : sucessfully set session option [defaults_DiracProxy]encodeDefaultProxyFileName = False
2022-10-19 11:11:01,041 User_Worker_3 ICredentialInfo ::__init__ :128 DEBUG : Trying to wrap /tmp/x509up_u1000
2022-10-19 11:11:01,041 User_Worker_3 ICredentialInfo ::exists :254 DEBUG : Checking for Credential at: '/tmp/x509up_u1000'
2022-10-19 11:11:01,041 MainThread bootstrap ::run :1017 DEBUG : Entering run
2022-10-19 11:11:01,041 User_Worker_3 ICredentialInfo ::__init__ :131 DEBUG : Wrapping existing file /tmp/x509up_u1000
2022-10-19 11:11:01,041 MainThread Runtime ::loadTemplates :218 DEBUG : Problems adding templates for runtime package GangaDirac
2022-10-19 11:11:01,041 User_Worker_3 ICredentialInfo ::exists :254 DEBUG : Checking for Credential at: '/tmp/x509up_u1000'
2022-10-19 11:11:01,043 MainThread Runtime ::loadTemplates :218 DEBUG : Problems adding templates for runtime package GangaGaudi
2022-10-19 11:11:01,043 User_Worker_3 ICredentialInfo ::check_requirements :227 DEBUG : Credential exists, checking it
2022-10-19 11:11:01,043 MainThread Runtime ::loadTemplates :218 DEBUG : Problems adding templates for runtime package GangaLHCb
2022-10-19 11:11:01,044 MainThread bootstrap ::run :1055 DEBUG : loaded .ganga.py
2022-10-19 11:11:01,044 MainThread bootstrap ::check_IPythonDir :1186 DEBUG : Checking: /centos/.ipython-ganga/ipythonrc
[11:11:01]
Ganga In [1]:
[11:11:05]
Ganga In [1]: j = Job()
[11:11:12]
Ganga In [2]:
[11:11:13]
Ganga In [2]:
Do you really want to exit ([y]/n)?
Traceback (most recent call last):
File "/centos/ganga/ganga/ganga/GangaCore/Core/MonitoringComponent/MonitoringService.py", line 21, in log_exceptions
return await awaitable
File "/centos/ganga/ganga/ganga/GangaDirac/Lib/Backends/DiracBase.py", line 1607, in updateMonitoringInformation
await DiracBase.monitor_dirac_running_jobs(monitor_jobs_group, finalised_statuses)
File "/centos/ganga/ganga/ganga/GangaDirac/Lib/Backends/DiracBase.py", line 1483, in monitor_dirac_running_jobs
result = await dm.execute(dirac_status, args_dict={'job_ids': dirac_job_ids, 'statusmapping': statusmapping})
File "/centos/ganga/ganga/ganga/GangaDirac/Lib/Server/DiracProcessManager.py", line 96, in execute
await self.task_queues[env_hash].coro_put((task_done, task_id, cmd, args_dict))
File "/centos/ganga/lib/python3.9/site-packages/aioprocessing/executor.py", line 192, in coro_func
return self.run_in_executor(
File "/centos/ganga/lib/python3.9/site-packages/aioprocessing/executor.py", line 13, in wrapper
return func(self, *args, **kwargs)
File "/centos/ganga/lib/python3.9/site-packages/aioprocessing/executor.py", line 39, in run_in_executor
return util.run_in_executor(
File "/centos/ganga/lib/python3.9/site-packages/aioprocessing/util.py", line 12, in run_in_executor
return loop.run_in_executor(executor, callback, *args)
File "/cvmfs/lhcb.cern.ch/lib/var/lib/LbEnv/2541/stable/linux-64/lib/python3.9/asyncio/base_events.py", line 819, in run_in_executor
executor.submit(func, *args), loop=self)
File "/cvmfs/lhcb.cern.ch/lib/var/lib/LbEnv/2541/stable/linux-64/lib/python3.9/concurrent/futures/thread.py", line 167, in submit
raise RuntimeError('cannot schedule new futures after shutdown')
RuntimeError: cannot schedule new futures after shutdown
^CException ignored in: <module 'threading' from '/cvmfs/lhcb.cern.ch/lib/var/lib/LbEnv/2541/stable/linux-64/lib/python3.9/threading.py'>
Traceback (most recent call last):
File "/cvmfs/lhcb.cern.ch/lib/var/lib/LbEnv/2541/stable/linux-64/lib/python3.9/threading.py", line 1447, in _shutdown
atexit_call()
File "/cvmfs/lhcb.cern.ch/lib/var/lib/LbEnv/2541/stable/linux-64/lib/python3.9/concurrent/futures/thread.py", line 31, in _python_exit
t.join()
File "/cvmfs/lhcb.cern.ch/lib/var/lib/LbEnv/2541/stable/linux-64/lib/python3.9/threading.py", line 1060, in join
self._wait_for_tstate_lock()
File "/cvmfs/lhcb.cern.ch/lib/var/lib/LbEnv/2541/stable/linux-64/lib/python3.9/threading.py", line 1080, in _wait_for_tstate_lock
if lock.acquire(block, timeout):
KeyboardInterrupt:
^CERROR PLEASE DO NOT hit Ctrl+C on ganga exit before waiting a while!
ERROR This will more than likely lead to repo/job corruption
@egede Yeah it looks like the DIRAC subprocess is not even starting. I am 99% sure that it is because of the thing you mentioned, LHCbDirac and Dirac are two separate backends even though they inherit from the same class.
Take a look at the ini file in GangaLHCb. This might be relevant for the server start. Also notice that we set the Dirac environment in LHCb by loading a JSON file. This is done by setting the DiracEnvJSON configuration option.
Take a look at the ini file in GangaLHCb. This might be relevant for the server start. Also notice that we set the Dirac environment in LHCb by loading a JSON file. This is done by setting the DiracEnvJSON configuration option.
Ahh yes I think that is probably the issue. For the sake of the new DIRAC process I added a new command file which we should register in the GangaLHCb file
Also, for some reason now the udocker installation fails when running the test suites. I am not sure what is happening here because the only test suite that was failing in this PR was the LHCb integration one (which failed on the installation step, not on the actual testing), and when I requested another workflow run the udocker installations stopped working for the other tests.
Here you can see the workflow logs: https://github.com/ganga-devs/ganga/actions/runs/3279930274/attempts/1. On the top left you can switch between all of the runs for this specific branch.
Also, for some reason now the udocker installation fails when running the test suites. I am not sure what is happening here because the only test suite that was failing in this PR was the LHCb integration one (which failed on the installation step, not on the actual testing), and when I requested another workflow run the udocker installations stopped working for the other tests.
Here you can see the workflow logs: https://github.com/ganga-devs/ganga/actions/runs/3279930274/attempts/1. On the top left you can switch between all of the runs for this specific branch.
Issue #2077 created to deal with this.
First test with 100 subjobs worked fine. Then did a test with 400 subjobs. Before the first status changed was reported, this gave the error
Ganga In [29]: j.submit()
Traceback (most recent call last):
File "/afs/cern.ch/user/u/uegede/ganga-local/lib/python3.9/site-packages/ganga/GangaCore/Core/MonitoringComponent/MonitoringService.py", line 21, in log_exceptions
return await awaitable
File "/afs/cern.ch/user/u/uegede/ganga-local/lib/python3.9/site-packages/ganga/GangaDirac/Lib/Backends/DiracBase.py", line 1625, in updateMonitoringInformation
await DiracBase.monitor_dirac_running_jobs(job_chunk, finalised_statuses)
File "/afs/cern.ch/user/u/uegede/ganga-local/lib/python3.9/site-packages/ganga/GangaDirac/Lib/Backends/DiracBase.py", line 1490, in monitor_dirac_running_jobs
result = await dm.execute(dirac_status, args_dict={'job_ids': dirac_job_ids, 'statusmapping': statusmapping})
File "/afs/cern.ch/user/u/uegede/ganga-local/lib/python3.9/site-packages/ganga/GangaDirac/Lib/Server/DiracProcessManager.py", line 92, in execute
if not self.is_dirac_process_active(env_hash):
File "/afs/cern.ch/user/u/uegede/ganga-local/lib/python3.9/site-packages/ganga/GangaDirac/Lib/Server/DiracProcessManager.py", line 81, in is_dirac_process_active
if env_hash not in self.active_processes:
TypeError: argument of type 'NoneType' is not iterable
ERROR Exception in callback AsyncMonitoringService._check_active_backends()
handle: <TimerHandle when=1620835.001192903 AsyncMonitoringService._check_active_backends()>
Traceback (most recent call last):
File "/cvmfs/lhcb.cern.ch/lib/var/lib/LbEnv/2541/stable/linux-64/lib/python3.9/asyncio/events.py", line 80, in _run
self._context.run(self._callback, *self._args)
File "/afs/cern.ch/user/u/uegede/ganga-local/lib/python3.9/site-packages/ganga/GangaCore/Core/MonitoringComponent/MonitoringService.py", line 82, in _check_active_backends
self._cleanup_finished_backends(previously_active_backends, found_active_backends)
File "/afs/cern.ch/user/u/uegede/ganga-local/lib/python3.9/site-packages/ganga/GangaCore/Core/MonitoringComponent/MonitoringService.py", line 141, in _cleanup_finished_backends
self._cleanup_backend(backend_obj)
File "/afs/cern.ch/user/u/uegede/ganga-local/lib/python3.9/site-packages/ganga/GangaCore/Core/MonitoringComponent/MonitoringService.py", line 149, in _cleanup_backend
backend.tear_down_monitoring()
File "/afs/cern.ch/user/u/uegede/ganga-local/lib/python3.9/site-packages/ganga/GangaDirac/Lib/Backends/DiracBase.py", line 1063, in tear_down_monitoring
dm.kill_dirac_processes()
File "/afs/cern.ch/user/u/uegede/ganga-local/lib/python3.9/site-packages/ganga/GangaDirac/Lib/Server/DiracProcessManager.py", line 113, in kill_dirac_processes
for process in self.active_processes.values():
AttributeError: 'NoneType' object has no attribute 'values'
Stopping ganga and restarting seems to make the monitoring run again but I now get the messages below for every single subjob, and with repeated lines for each of them
ln: failed to create symbolic link ‘/afs/cern.ch/user/u/uegede/gangadir/workspace/uegede/LocalXML/28/182/output//stdout’: File exists
ln: failed to create symbolic link ‘/afs/cern.ch/user/u/uegede/gangadir/workspace/uegede/LocalXML/28/182/output//stdout’: File exists
ln: failed to create symbolic link ‘/afs/cern.ch/user/u/uegede/gangadir/workspace/uegede/LocalXML/28/182/output//stdout’: File exists
ln: failed to create symbolic link ‘/afs/cern.ch/user/u/uegede/gangadir/workspace/uegede/LocalXML/28/182/output//stdout’: File exists
ln: failed to create symbolic link ‘/afs/cern.ch/user/u/uegede/gangadir/workspace/uegede/LocalXML/28/182/output//stdout’: File exists
ln: failed to create symbolic link ‘/afs/cern.ch/user/u/uegede/gangadir/workspace/uegede/LocalXML/28/182/output//stdout’: File exists
ln: failed to create symbolic link ‘/afs/cern.ch/user/u/uegede/gangadir/workspace/uegede/LocalXML/28/182/output//stdout’: File exists
ln: failed to create symbolic link ‘/afs/cern.ch/user/u/uegede/gangadir/workspace/uegede/LocalXML/28/182/output//stdout’: File exists
ln: failed to create symbolic link ‘/afs/cern.ch/user/u/uegede/gangadir/workspace/uegede/LocalXML/28/182/output//stdout’: File exists
ln: failed to create symbolic link ‘/afs/cern.ch/user/u/uegede/gangadir/workspace/uegede/LocalXML/28/182/output//stdout’: File exists
ln: failed to create symbolic link ‘/afs/cern.ch/user/u/uegede/gangadir/workspace/uegede/LocalXML/28/183/output//stdout’: File exists
ln: failed to create symbolic link ‘/afs/cern.ch/user/u/uegede/gangadir/workspace/uegede/LocalXML/28/183/output//stdout’: File exists
ln: failed to create symbolic link ‘/afs/cern.ch/user/u/uegede/gangadir/workspace/uegede/LocalXML/28/183/output//stdout’: File exists
Next submission worked fine, but I still get the symbolic link errors.
Managed to get one more error while quitting Ganga (while the monitoring was still active processing status changes for jobs).
Process DiracProcess-4:
Traceback (most recent call last):
File "/afs/cern.ch/user/u/uegede/ganga-local/lib/python3.9/site-packages/ganga/GangaDirac/Lib/Server/DiracExecutorProcess.py", line 62, in run
is_done, task_id, cmd, args_dict = self.task_queue.get()
File "/cvmfs/lhcb.cern.ch/lib/var/lib/LbEnv/2541/stable/linux-64/lib/python3.9/multiprocessing/queues.py", line 103, in get
res = self._recv_bytes()
File "/cvmfs/lhcb.cern.ch/lib/var/lib/LbEnv/2541/stable/linux-64/lib/python3.9/multiprocessing/connection.py", line 221, in recv_bytes
buf = self._recv_bytes(maxlength)
File "/cvmfs/lhcb.cern.ch/lib/var/lib/LbEnv/2541/stable/linux-64/lib/python3.9/multiprocessing/connection.py", line 419, in _recv_bytes
buf = self._recv(4)
File "/cvmfs/lhcb.cern.ch/lib/var/lib/LbEnv/2541/stable/linux-64/lib/python3.9/multiprocessing/connection.py", line 384, in _recv
chunk = read(handle, remaining)
File "/afs/cern.ch/user/u/uegede/ganga-local/lib/python3.9/site-packages/ganga/GangaCore/Core/__init__.py", line 19, in handle_sigterm
raise TerminationSignalException
GangaCore.Core.exceptions.TerminationSignalException
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/cvmfs/lhcb.cern.ch/lib/var/lib/LbEnv/2541/stable/linux-64/lib/python3.9/multiprocessing/process.py", line 315, in _bootstrap
self.run()
File "/afs/cern.ch/user/u/uegede/ganga-local/lib/python3.9/site-packages/ganga/GangaDirac/Lib/Server/DiracExecutorProcess.py", line 66, in run
self.handle_termination()
File "/afs/cern.ch/user/u/uegede/ganga-local/lib/python3.9/site-packages/ganga/GangaDirac/Lib/Server/DiracExecutorProcess.py", line 48, in handle_termination
exit(0)
NameError: name 'exit' is not defined