OSError(16, 'Device or resource busy') in Parameters of a DIRAC job

[IgorPelevanyuk]

Hello,

I observe occasional job failures on one particular computing resource that characterized by the following features:

• OutputSandbox is missing
• There is an error in pilot output log:

2023-05-03 07:06:06 UTC None/JobWrapper[2948947] INFO: Job Wrapper is starting execution phase for job 2948947
Job raised exception during execution phase
Traceback (most recent call last):
  File "/zfs/tmp/dirac/DIRAC_YCzSdFpilot/job/Wrapper/Wrapper_2948947", line 179, in execute
    result = job.execute()
  File "/zfs/tmp/dirac/DIRAC_YCzSdFpilot/diracos/lib/python3.9/site-packages/DIRAC/WorkloadManagementSystem/JobWrapper/JobWrapper.py", line 435, in execute
    watchdog.calibrate()
  File "/zfs/tmp/dirac/DIRAC_YCzSdFpilot/diracos/lib/python3.9/site-packages/DIRAC/WorkloadManagementSystem/JobWrapper/Watchdog.py", line 791, in calibrate
    result = self.getNodeInformation()
  File "/zfs/tmp/dirac/DIRAC_YCzSdFpilot/diracos/lib/python3.9/site-packages/DIRAC/WorkloadManagementSystem/JobWrapper/Watchdog.py", line 973, in getNodeInformation
    result["CPU(MHz)"] = psutil.cpu_freq()[0]
  File "/zfs/tmp/dirac/DIRAC_YCzSdFpilot/diracos/lib/python3.9/site-packages/psutil/__init__.py", line 1864, in cpu_freq
    ret = _psplatform.cpu_freq()
  File "/zfs/tmp/dirac/DIRAC_YCzSdFpilot/diracos/lib/python3.9/site-packages/psutil/_pslinux.py", line 745, in cpu_freq
    max_ = int(bcat(pjoin(path, "scaling_max_freq"))) / 1000
  File "/zfs/tmp/dirac/DIRAC_YCzSdFpilot/diracos/lib/python3.9/site-packages/psutil/_common.py", line 776, in bcat
    return cat(fname, fallback=fallback, _open=open_binary)
  File "/zfs/tmp/dirac/DIRAC_YCzSdFpilot/diracos/lib/python3.9/site-packages/psutil/_common.py", line 765, in cat
    return f.read()
OSError: [Errno 16] Device or resource busy

Does anybody know what may be a reason for that behavior?

[IgorPelevanyuk]

And sometimes there is no error in pilot output. Log ends with the following lines:

2023-05-03T11:17:05.247135Z INFO [LaunchAgent] Executing command dirac-agent WorkloadManagement/JobAgent -o MaxCycles=10 -o PollingTime=20 -o StopOnApplicationFailure=True -o StopAfterFailedMatches=10 -o LogLevel=INFO -s /Resources/Computing/CEDefaults -o WorkingDirectory=/zfs/tmp/dirac/DIRAC_Yj08Krpilot -o /LocalSite/CPUTime=6190840 -o /LocalSite/InstancePath=/zfs/tmp/dirac/DIRAC_Yj08Krpilot  -o /AgentJobRequirements/ExtraOptions=pilot.cfg --cfg pilot.cfg
2023-05-03 11:17:05 UTC WorkloadManagement/JobAgent INFO: Loading WorkloadManagement/JobAgent
2023-05-03 11:17:05 UTC WorkloadManagement/JobAgent INFO: Trying to autodiscover WorkloadManagement/JobAgent
2023-05-03 11:17:05 UTC WorkloadManagement/JobAgent NOTICE: Loaded module WorkloadManagement/JobAgent
2023-05-03 11:17:06 UTC WorkloadManagement/JobAgent NOTICE: ========================================
2023-05-03 11:17:06 UTC WorkloadManagement/JobAgent NOTICE: Loaded agent module WorkloadManagement/JobAgent
2023-05-03 11:17:06 UTC WorkloadManagement/JobAgent NOTICE:  Site: DIRAC.GOVORUN.ru
2023-05-03 11:17:06 UTC WorkloadManagement/JobAgent NOTICE:  Setup: JINR-Production
2023-05-03 11:17:06 UTC WorkloadManagement/JobAgent NOTICE:  Base Module version: $Id$
2023-05-03 11:17:06 UTC WorkloadManagement/JobAgent NOTICE:  Agent version: 7.3.29
2023-05-03 11:17:06 UTC WorkloadManagement/JobAgent NOTICE:  DIRAC version: 7.3.29
2023-05-03 11:17:06 UTC WorkloadManagement/JobAgent NOTICE:  DIRAC platform: Linux_x86_64_glibc-2.17
2023-05-03 11:17:06 UTC WorkloadManagement/JobAgent NOTICE:  Polling time: 20 seconds
2023-05-03 11:17:06 UTC WorkloadManagement/JobAgent NOTICE:  Control dir: /zfs/tmp/dirac/DIRAC_Yj08Krpilot/control/WorkloadManagement/JobAgent
2023-05-03 11:17:06 UTC WorkloadManagement/JobAgent NOTICE:  Work dir: /zfs/tmp/dirac/DIRAC_Yj08Krpilot/work/WorkloadManagement/JobAgent
2023-05-03 11:17:06 UTC WorkloadManagement/JobAgent NOTICE:  Cycles: 10
2023-05-03 11:17:06 UTC WorkloadManagement/JobAgent NOTICE:  Watchdog interval: disabled
2023-05-03 11:17:06 UTC WorkloadManagement/JobAgent NOTICE: ========================================
2023-05-03 11:17:07 UTC WorkloadManagement/JobAgent NOTICE: ----------------------------------------
2023-05-03 11:17:07 UTC WorkloadManagement/JobAgent NOTICE: Starting cycle for module WorkloadManagement/JobAgent
2023-05-03 11:17:07 UTC WorkloadManagement/JobAgent NOTICE: Remaining 10 of 10 cycles
2023-05-03 11:17:07 UTC WorkloadManagement/JobAgent NOTICE: ----------------------------------------
2023-05-03 11:17:07 UTC WorkloadManagement/JobAgent INFO: Requirements: {'ExtraOptions': 'pilot.cfg'}
2023-05-03 11:17:07 UTC WorkloadManagement/JobAgent INFO: MatcherTime = 0.13 (s)
2023-05-03 11:17:07 UTC WorkloadManagement/JobAgent INFO: Received JobID=2951029, JobType=User, OwnerDN=/C=RU/O=RDIG/OU=users/OU=jinr.ru/CN=Andrey Moshkin, JobGroup=mpd_user
2023-05-03 11:17:07 UTC WorkloadManagement/JobAgent INFO: Requesting proxy', 'for /C=RU/O=RDIG/OU=users/OU=jinr.ru/CN=Andrey Moshkin@mpd_user
2023-05-03 11:17:07 UTC WorkloadManagement/JobAgent INFO: Found Job LogLevel JDL parameter with value: INFO
2023-05-03 11:17:07 UTC WorkloadManagement/JobAgent INFO: Submitting JobWrapper Job2951029 to InProcessCE
2023-05-03 11:17:07 UTC WorkloadManagement/JobAgent/InProcess INFO: Payload proxy information:

[fstagni]

For the second one, are you installing a python2 version of DIRAC? There's a known issue about the log flushing.

[IgorPelevanyuk]

No it is just standard DIRAC pilot installation using DIRACOS with version v7r3p29.

[fstagni]

DIRACOS or DIRACOS2 (are they python3 pilots?)

[IgorPelevanyuk]

They are python3 pilots.

[IgorPelevanyuk]

It looks like the issue is with psutil library. During change of scaling_max_frequency the file could be not accessible during small period of time. If psutil tries to read it in that moment, the exception will be raised. I am talking with psutil developers and also ask my colleagues who responsible for servers to make scaling_max_frequency static.

[IgorPelevanyuk]

@fstagni , How do you think, is it possible to add "try except" at that part of the code?
It is also not very clear for me how the data about cpu freq is used. Maybe it could be painlessly be removed from the DIRAC?

[fstagni]

Sure, would you give it a try?

[IgorPelevanyuk]

Well, I created an issue to refer to in the PR: #7109. But during work on that issue it appeared that this line of code was removed complitely in DIRAC 8. So I closed the issue.
The solution for me was to change Pilot version to newer one. I used 8.0.23. It work with server 7.3.29. And the plan is to move to DIRAC 8 server.

[IgorPelevanyuk]

So, I think the issue may be closed?