Bug #21612: a-c-r with --debug can try to log entire input/output objects, which can be too large for the logging system - Arvados

Actions

Copy link

Bug #21612

open

a-c-r with --debug can try to log entire input/output objects, which can be too large for the logging system

Added by Brett Smith 9 months ago. Updated 8 months ago.

Status:

New

Priority:

Normal

Assigned To:

Category:

CWL

Target version:

Future

Story points:

Description

User got this error while running aws-s3-bulk-download.cwl with >6K input URLs, using a-c-r --submit --debug.

I don't think it actually interfered with the workflow's run at all, but it clogs the logs and looks scary.

IMO a-c-r (along with the rest of our code) should not try to log data that can be arbitrarily large.

Three instances where this came up:

--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.7/logging/__init__.py", line 1037, in emit
    stream.write(msg + self.terminator)
BlockingIOError: [Errno 11] write could not complete without blocking
Call stack:
  File "/usr/bin/arvados-cwl-runner", line 8, in <module>
    sys.exit(main())
  File "/usr/share/python3/dist/python3-arvados-cwl-runner/lib/python3.7/site-packages/arvados_cwl/__init__.py", line 440, in main
    input_required=not workflow_op)
  File "/usr/share/python3/dist/python3-arvados-cwl-runner/lib/python3.7/site-packages/cwltool/main.py", line 1302, in main
    tool, initialized_job_order_object, runtimeContext, logger=_logger
  File "/usr/share/python3/dist/python3-arvados-cwl-runner/lib/python3.7/site-packages/arvados_cwl/executor.py", line 874, in arv_executor
    self.start_run(runnable, runtimeContext)
  File "/usr/share/python3/dist/python3-arvados-cwl-runner/lib/python3.7/site-packages/arvados_cwl/executor.py", line 248, in start_run
    self.workflow_eval_lock, self.stop_polling)
  File "/usr/share/python3/dist/python3-arvados-cwl-runner/lib/python3.7/site-packages/cwltool/task_queue.py", line 85, in add
    task()
  File "/usr/share/python3/dist/python3-arvados-cwl-runner/lib/python3.7/site-packages/cwltool/command_line_tool.py", line 202, in run
    self.output_callback(cast(Optional[CWLObjectType], ev), "success")
  File "/usr/share/python3/dist/python3-arvados-cwl-runner/lib/python3.7/site-packages/arvados_cwl/executor.py", line 321, in wrapped_callback
    cb(obj, st)
  File "/usr/share/python3/dist/python3-arvados-cwl-runner/lib/python3.7/site-packages/cwltool/workflow.py", line 429, in receive_output
    output_callback(output, processStatus)
  File "/usr/share/python3/dist/python3-arvados-cwl-runner/lib/python3.7/site-packages/cwltool/workflow_job.py", line 564, in receive_output
    _logger.debug("[%s] produced output %s", step.name, json_dumps(jobout, indent=4))

--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.7/logging/__init__.py", line 1037, in emit
    stream.write(msg + self.terminator)
BlockingIOError: [Errno 11] write could not complete without blocking
Call stack:
  File "/usr/bin/arvados-cwl-runner", line 8, in <module>
    sys.exit(main())
  File "/usr/share/python3/dist/python3-arvados-cwl-runner/lib/python3.7/site-packages/arvados_cwl/__init__.py", line 440, in main
    input_required=not workflow_op)
  File "/usr/share/python3/dist/python3-arvados-cwl-runner/lib/python3.7/site-packages/cwltool/main.py", line 1302, in main
    tool, initialized_job_order_object, runtimeContext, logger=_logger
  File "/usr/share/python3/dist/python3-arvados-cwl-runner/lib/python3.7/site-packages/arvados_cwl/executor.py", line 863, in arv_executor
    for runnable in jobiter:
  File "/usr/share/python3/dist/python3-arvados-cwl-runner/lib/python3.7/site-packages/cwltool/workflow.py", line 175, in job
    yield from job.job(builder.job, output_callbacks, runtimeContext)
  File "/usr/share/python3/dist/python3-arvados-cwl-runner/lib/python3.7/site-packages/cwltool/workflow_job.py", line 821, in job
    for newjob in step.iterable:
  File "/usr/share/python3/dist/python3-arvados-cwl-runner/lib/python3.7/site-packages/cwltool/workflow_job.py", line 751, in try_make_job
    yield from jobs
  File "/usr/share/python3/dist/python3-arvados-cwl-runner/lib/python3.7/site-packages/cwltool/workflow_job.py", line 77, in job
    yield from self.step.job(joborder, output_callback, runtimeContext)
  File "/usr/share/python3/dist/python3-arvados-cwl-runner/lib/python3.7/site-packages/cwltool/workflow.py", line 462, in job
    runtimeContext,
  File "/usr/share/python3/dist/python3-arvados-cwl-runner/lib/python3.7/site-packages/cwltool/workflow.py", line 175, in job
    yield from job.job(builder.job, output_callbacks, runtimeContext)
  File "/usr/share/python3/dist/python3-arvados-cwl-runner/lib/python3.7/site-packages/cwltool/workflow_job.py", line 821, in job
    for newjob in step.iterable:
  File "/usr/share/python3/dist/python3-arvados-cwl-runner/lib/python3.7/site-packages/cwltool/workflow_job.py", line 735, in try_make_job
    json_dumps(inputobj, indent=4),

--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.7/logging/__init__.py", line 1037, in emit
    stream.write(msg + self.terminator)
BlockingIOError: [Errno 11] write could not complete without blocking
Call stack:
  File "/usr/bin/arvados-cwl-runner", line 8, in <module>
    sys.exit(main())
  File "/usr/share/python3/dist/python3-arvados-cwl-runner/lib/python3.7/site-packages/arvados_cwl/__init__.py", line 440, in main
    input_required=not workflow_op)
  File "/usr/share/python3/dist/python3-arvados-cwl-runner/lib/python3.7/site-packages/cwltool/main.py", line 1302, in main
    tool, initialized_job_order_object, runtimeContext, logger=_logger
  File "/usr/share/python3/dist/python3-arvados-cwl-runner/lib/python3.7/site-packages/arvados_cwl/executor.py", line 874, in arv_executor
    self.start_run(runnable, runtimeContext)
  File "/usr/share/python3/dist/python3-arvados-cwl-runner/lib/python3.7/site-packages/arvados_cwl/executor.py", line 248, in start_run
    self.workflow_eval_lock, self.stop_polling)
  File "/usr/share/python3/dist/python3-arvados-cwl-runner/lib/python3.7/site-packages/cwltool/task_queue.py", line 85, in add
    task()
  File "/usr/share/python3/dist/python3-arvados-cwl-runner/lib/python3.7/site-packages/cwltool/command_line_tool.py", line 202, in run
    self.output_callback(cast(Optional[CWLObjectType], ev), "success")
  File "/usr/share/python3/dist/python3-arvados-cwl-runner/lib/python3.7/site-packages/arvados_cwl/executor.py", line 321, in wrapped_callback
    cb(obj, st)
  File "/usr/share/python3/dist/python3-arvados-cwl-runner/lib/python3.7/site-packages/cwltool/workflow.py", line 429, in receive_output
    output_callback(output, processStatus)
  File "/usr/share/python3/dist/python3-arvados-cwl-runner/lib/python3.7/site-packages/cwltool/workflow_job.py", line 582, in receive_output
    self.do_output_callback(final_output_callback)
  File "/usr/share/python3/dist/python3-arvados-cwl-runner/lib/python3.7/site-packages/cwltool/workflow_job.py", line 541, in do_output_callback
    _logger.debug("[%s] outputs %s", self.name, json_dumps(wo, indent=4))

Actions

Copy link

Updated by Brett Smith 9 months ago

Description updated (diff)
Subject changed from a-c-r with --debug can try to log its entire output, which can be too large for the logging system to a-c-r with --debug can try to log entire input/output objects, which can be too large for the logging system

Actions

Copy link