LocalDicomSendOperator fails during dcmsend execution
Failed operator logs
*** Found local files:
*** * /kaapana/mounted/workflows/logs/dag_id=service-process-incoming-dcm/run_id=service-process-incoming-dcm-240412051748293687/task_id=local-dcm-send/attempt=3.log
[2024-04-12, 07:20:07 CEST] {taskinstance.py:1979} INFO - Dependencies all met for dep_context=non-requeueable deps ti=<TaskInstance: service-process-incoming-dcm.local-dcm-send service-process-incoming-dcm-240412051748293687 [queued]>
[2024-04-12, 07:20:07 CEST] {taskinstance.py:1979} INFO - Dependencies all met for dep_context=requeueable deps ti=<TaskInstance: service-process-incoming-dcm.local-dcm-send service-process-incoming-dcm-240412051748293687 [queued]>
[2024-04-12, 07:20:07 CEST] {taskinstance.py:2193} INFO - Starting attempt 3 of 3
[2024-04-12, 07:20:07 CEST] {taskinstance.py:2217} INFO - Executing <Task(LocalDicomSendOperator): local-dcm-send> on 2024-04-12 05:17:48.297823+00:00
[2024-04-12, 07:20:07 CEST] {standard_task_runner.py:60} INFO - Started process 32944 to run task
[2024-04-12, 07:20:07 CEST] {standard_task_runner.py:87} INFO - Running: ['airflow', 'tasks', 'run', 'service-process-incoming-dcm', 'local-dcm-send', 'service-process-incoming-dcm-240412051748293687', '--job-id', '96', '--raw', '--subdir', 'DAGS_FOLDER/dag_service_process_incoming_dcm.py', '--cfg-path', '/tmp/tmp0jia1m2p']
[2024-04-12, 07:20:07 CEST] {standard_task_runner.py:88} INFO - Job 96: Subtask local-dcm-send
[2024-04-12, 07:20:07 CEST] {task_command.py:468} INFO - Running <TaskInstance: service-process-incoming-dcm.local-dcm-send service-process-incoming-dcm-240412051748293687 [running]> on host 10.1.44.171
[2024-04-12, 07:20:07 CEST] {taskinstance.py:2513} INFO - Exporting env vars: AIRFLOW_CTX_DAG_OWNER='system' AIRFLOW_CTX_DAG_ID='service-process-incoming-dcm' AIRFLOW_CTX_TASK_ID='local-dcm-send' AIRFLOW_CTX_EXECUTION_DATE='2024-04-12T05:17:48.297823+00:00' AIRFLOW_CTX_TRY_NUMBER='3' AIRFLOW_CTX_DAG_RUN_ID='service-process-incoming-dcm-240412051748293687'
[2024-04-12, 07:20:07 CEST] {HelperDcmWeb.py:65} INFO - Task belongs to a service dag-run
[2024-04-12, 07:20:07 CEST] {logging_mixin.py:188} INFO - input operator get-input-data
[2024-04-12, 07:20:07 CEST] {logging_mixin.py:188} INFO - /kaapana/mounted/workflows/data/service-process-incoming-dcm-240412051748293687/batch/1.2.276.0.7230010.3.1.3.17458972.32.1620060626.40111/get-input-data
[2024-04-12, 07:20:07 CEST] {logging_mixin.py:188} INFO - Number of instances to send: 1
[2024-04-12, 07:20:07 CEST] {logging_mixin.py:188} INFO - dcm-file: /kaapana/mounted/workflows/data/service-process-incoming-dcm-240412051748293687/batch/1.2.276.0.7230010.3.1.3.17458972.32.1620060626.40111/get-input-data/1.2.276.0.7230010.3.1.4.17458972.32.1620060626.40112.dcm
[2024-04-12, 07:20:08 CEST] {logging_mixin.py:188} INFO - Sending /kaapana/mounted/workflows/data/service-process-incoming-dcm-240412051748293687/batch/1.2.276.0.7230010.3.1.3.17458972.32.1620060626.40111/get-input-data to dcm4chee-service.services.svc 11115 with aetitle KAAPANA and aetitle_send kaapana
[2024-04-12, 07:20:08 CEST] {logging_mixin.py:188} INFO - The timeout is set to: 3540
[2024-04-12, 07:20:10 CEST] {logging_mixin.py:188} INFO - ############### Something went wrong with dcmsend!
[2024-04-12, 07:20:10 CEST] {logging_mixin.py:188} INFO - CompletedProcess(args=['dcmsend', '-v', 'dcm4chee-service.services.svc', '11115', '-aet', 'kaapana', '-aec', 'KAAPANA', '--scan-directories', '--scan-pattern', '*.dcm', '--recurse', '/kaapana/mounted/workflows/data/service-process-incoming-dcm-240412051748293687/batch/1.2.276.0.7230010.3.1.3.17458972.32.1620060626.40111/get-input-data'], returncode=0, stdout='', stderr='I: determining input files ...
[2024-04-12, 07:20:10 CEST] {logging_mixin.py:188} INFO - I: checking input files ...
[2024-04-12, 07:20:10 CEST] {logging_mixin.py:188} INFO - I: starting association #1
[2024-04-12, 07:20:10 CEST] {logging_mixin.py:188} INFO - I: initializing network ...
[2024-04-12, 07:20:10 CEST] {logging_mixin.py:188} INFO - I: negotiating network association ...
[2024-04-12, 07:20:10 CEST] {logging_mixin.py:188} INFO - I: Requesting Association
[2024-04-12, 07:20:10 CEST] {logging_mixin.py:188} INFO - I: Association Accepted (Max Send PDV: 16366)
[2024-04-12, 07:20:10 CEST] {logging_mixin.py:188} INFO - I: sending SOP instances ...
[2024-04-12, 07:20:10 CEST] {logging_mixin.py:188} INFO - I: Sending C-STORE Request (MsgID 1, SG)
[2024-04-12, 07:20:10 CEST] {logging_mixin.py:188} INFO - I: Received C-STORE Response (Unknown Status: 0x110)
[2024-04-12, 07:20:10 CEST] {logging_mixin.py:188} INFO - I: Releasing Association
[2024-04-12, 07:20:10 CEST] {logging_mixin.py:188} INFO - I:
[2024-04-12, 07:20:10 CEST] {logging_mixin.py:188} INFO - I: Status Summary
[2024-04-12, 07:20:10 CEST] {logging_mixin.py:188} INFO - I: --------------
[2024-04-12, 07:20:10 CEST] {logging_mixin.py:188} INFO - I: Number of associations : 1
[2024-04-12, 07:20:10 CEST] {logging_mixin.py:188} INFO - I: Number of pres. contexts : 1
[2024-04-12, 07:20:10 CEST] {logging_mixin.py:188} INFO - I: Number of SOP instances : 1
[2024-04-12, 07:20:10 CEST] {logging_mixin.py:188} INFO - I: - sent to the peer : 1
[2024-04-12, 07:20:10 CEST] {logging_mixin.py:188} INFO - I: * with unknown status : 1
[2024-04-12, 07:20:10 CEST] {logging_mixin.py:188} INFO - ')
[2024-04-12, 07:20:10 CEST] {logging_mixin.py:188} INFO - ##################################################
[2024-04-12, 07:20:10 CEST] {taskinstance.py:2731} ERROR - Task failed with exception
Traceback (most recent call last):
File "/usr/local/lib/python3.10/dist-packages/airflow/models/taskinstance.py", line 439, in _execute_task
result = _execute_callable(context=context, **execute_callable_kwargs)
File "/usr/local/lib/python3.10/dist-packages/airflow/models/taskinstance.py", line 414, in _execute_callable
return execute_callable(context=context, **execute_callable_kwargs)
File "/usr/local/lib/python3.10/dist-packages/airflow/operators/python.py", line 200, in execute
return_value = self.execute_callable()
File "/usr/local/lib/python3.10/dist-packages/airflow/operators/python.py", line 217, in execute_callable
return self.python_callable(*self.op_args, **self.op_kwargs)
File "/kaapana/mounted/workflows/plugins/kaapana/operators/LocalDicomSendOperator.py", line 92, in start
self.send_dicom_data(element_input_dir, series_uid)
File "/kaapana/mounted/workflows/plugins/kaapana/operators/LocalDicomSendOperator.py", line 56, in send_dicom_data
raise ValueError("ERROR")
ValueError: ERROR
[2024-04-12, 07:20:10 CEST] {taskinstance.py:1149} INFO - Marking task as FAILED. dag_id=service-process-incoming-dcm, task_id=local-dcm-send, execution_date=20240412T051748, start_date=20240412T052007, end_date=20240412T052010
[2024-04-12, 07:20:10 CEST] {standard_task_runner.py:107} ERROR - Failed to execute job 96 for task local-dcm-send (ERROR; 32944)
[2024-04-12, 07:20:10 CEST] {local_task_job_runner.py:234} INFO - Task exited with return code 1
[2024-04-12, 07:20:10 CEST] {taskinstance.py:3312} INFO - 0 downstream tasks scheduled from follow-on schedule check
I executed the failing command in the airflow-scheduler with verbose output
root@airflow-scheduler-76465c77f-kwccz:/kaapana/app# dcmsend -v dcm4chee-service.services.svc 11115 -aet kaapana -aec KAAPANA --scan-directories --scan-pattern '*.dcm' --recurse /kaapana/mounted/workflows/data/service-process-incoming-dcm-240412051748293687/batch/1.2.276.0.7230010.3.1.3.17458972.32.1620060626.40111/get-input-data/ --debug
D: $dcmtk: dcmsend v3.6.6 2021-01-14 $
D:
D: DcmDataDictionary: Loading file: /scripts/dicom.dic
I: determining input files ...
I: checking input files ...
D: adding DICOM file '/kaapana/mounted/workflows/data/service-process-incoming-dcm-240412051748293687/batch/1.2.276.0.7230010.3.1.3.17458972.32.1620060626.40111/get-input-data/1.2.276.0.7230010.3.1.4.17458972.32.1620060626.40112.dcm'
D: getting SOP Class UID, SOP Instance UID and Transfer Syntax UID from DICOM file
D: DcmMetaInfo::checkAndReadPreamble() TransferSyntax="Little Endian Explicit"
D: trying to get SOP Class UID, SOP Instance UID and Transfer Syntax UID from meta-header
D: successfully added SOP instance 1.2.276.0.7230010.3.1.4.17458972.32.1620060626.40112 to the transfer list
D: in total, there are 1 SOP instances to be sent, 0 invalid files are ignored
D: multiple associations allowed (option --multi-associations used)
D: preparing presentation context for SOP Class / Transfer Syntax: SegmentationStorage / Little Endian Explicit
D: added new presentation context with ID 1
D: -----------------------------------------------------------------
D: starting association #1
I: initializing network ...
D: Configured a total of 1 presentation contexts for SCU
I: negotiating network association ...
D: Request Parameters:
D: ====================== BEGIN A-ASSOCIATE-RQ =====================
D: Our Implementation Class UID: 1.2.276.0.7230010.3.0.3.6.6
D: Our Implementation Version Name: OFFIS_DCMTK_366
D: Their Implementation Class UID:
D: Their Implementation Version Name:
D: Application Context Name: 1.2.840.10008.3.1.1.1
D: Calling Application Name: kaapana
D: Called Application Name: KAAPANA
D: Responding Application Name: KAAPANA
D: Our Max PDU Receive Size: 16384
D: Their Max PDU Receive Size: 0
D: Presentation Contexts:
D: Context ID: 1 (Proposed)
D: Abstract Syntax: =SegmentationStorage
D: Proposed SCP/SCU Role: Default
D: Proposed Transfer Syntax(es):
D: =LittleEndianExplicit
D: =BigEndianExplicit
D: =LittleEndianImplicit
D: Requested Extended Negotiation: none
D: Accepted Extended Negotiation: none
D: Requested User Identity Negotiation: none
D: User Identity Negotiation Response: none
D: ======================= END A-ASSOCIATE-RQ ======================
I: Requesting Association
D: setting network send timeout to 60 seconds
D: setting network receive timeout to 60 seconds
D: Constructing Associate RQ PDU
D: PDU Type: Associate Accept, PDU Length: 173 + 6 bytes PDU header
D: 02 00 00 00 00 ad 00 01 00 00 4b 41 41 50 41 4e
D: 41 20 20 20 20 20 20 20 20 20 6b 61 61 70 61 6e
D: 61 20 20 20 20 20 20 20 20 20 00 00 00 00 00 00
D: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
D: 00 00 00 00 00 00 00 00 00 00 10 00 00 15 31 2e
D: 32 2e 38 34 30 2e 31 30 30 30 38 2e 33 2e 31 2e
D: 31 2e 31 21 00 00 1b 01 00 00 00 40 00 00 13 31
D: 2e 32 2e 38 34 30 2e 31 30 30 30 38 2e 31 2e 32
D: 2e 31 50 00 00 2d 51 00 00 04 00 00 3f fa 52 00
D: 00 0f 31 2e 32 2e 34 30 2e 30 2e 31 33 2e 31 2e
D: 33 55 00 00 0e 64 63 6d 34 63 68 65 2d 35 2e 33
D: 32 2e 30
D: Parsing an A-ASSOCIATE PDU
D: Association Parameters Negotiated:
D: ====================== BEGIN A-ASSOCIATE-AC =====================
D: Our Implementation Class UID: 1.2.276.0.7230010.3.0.3.6.6
D: Our Implementation Version Name: OFFIS_DCMTK_366
D: Their Implementation Class UID: 1.2.40.0.13.1.3
D: Their Implementation Version Name: dcm4che-5.32.0
D: Application Context Name: 1.2.840.10008.3.1.1.1
D: Calling Application Name: kaapana
D: Called Application Name: KAAPANA
D: Responding Application Name: KAAPANA
D: Our Max PDU Receive Size: 16384
D: Their Max PDU Receive Size: 16378
D: Presentation Contexts:
D: Context ID: 1 (Accepted)
D: Abstract Syntax: =SegmentationStorage
D: Proposed SCP/SCU Role: Default
D: Accepted SCP/SCU Role: Default
D: Accepted Transfer Syntax: =LittleEndianExplicit
D: Requested Extended Negotiation: none
D: Accepted Extended Negotiation: none
D: Requested User Identity Negotiation: none
D: User Identity Negotiation Response: none
D: ======================= END A-ASSOCIATE-AC ======================
I: Association Accepted (Max Send PDV: 16366)
I: sending SOP instances ...
D: sending SOP instance from file: /kaapana/mounted/workflows/data/service-process-incoming-dcm-240412051748293687/batch/1.2.276.0.7230010.3.1.3.17458972.32.1620060626.40111/get-input-data/1.2.276.0.7230010.3.1.4.17458972.32.1620060626.40112.dcm
D: DcmMetaInfo::checkAndReadPreamble() TransferSyntax="Little Endian Explicit"
D: DcmDataset::read() TransferSyntax="Little Endian Explicit"
D: checking whether SOP Class UID and SOP Instance UID in dataset are consistent with transfer list
D: getting SOP Class UID, SOP Instance UID and Transfer Syntax UID from DICOM dataset
I: Sending C-STORE Request
D: ===================== OUTGOING DIMSE MESSAGE ====================
D: Message Type : C-STORE RQ
D: Presentation Context ID : 1
D: Message ID : 1
D: Affected SOP Class UID : SegmentationStorage
D: Affected SOP Instance UID : 1.2.276.0.7230010.3.1.4.17458972.32.1620060626.40112
D: Data Set : present
D: Priority : medium
D: ======================= END DIMSE MESSAGE =======================
D: DcmDataset::read() TransferSyntax="Little Endian Implicit"
I: Received C-STORE Response
D: ===================== INCOMING DIMSE MESSAGE ====================
D: Message Type : C-STORE RSP
D: Presentation Context ID : 1
D: Message ID Being Responded To : 1
D: Affected SOP Class UID : none
D: Affected SOP Instance UID : none
D: Data Set : none
D: DIMSE Status : 0x0110: Failure
D: ======================= END DIMSE MESSAGE =======================
D: Response has status detail:
D:
D: # Dicom-Data-Set
D: # Used TransferSyntax: Little Endian Implicit
D: (0000,0902) LO [jakarta.ejb.EJBException: org.hibernate.exception.SQLGrammarExce] # 64, 1 ErrorComment
D:
I: Releasing Association
D: Cleaning up internal association and network structures
I:
I: Status Summary
I: --------------
I: Number of associations : 1
I: Number of pres. contexts : 1
I: Number of SOP instances : 1
I: - sent to the peer : 1
I: * with unknown status : 1