BadAppContextName error message with dcmqrscp server

[kumarm]

Hello,

I am using Linux version 3.6.3 of DCMTK Tool Kit to test the interfaces using CPPUnit testframe. I am running dcmqrscp.exe as a PACS server.
My server configuration is as follows:

Server configuration: dcmqrscp.cfg
NetworkTCPPort = 5432
MaxPDUSize = 16384
MaxAssociations = 16

HostTable BEGIN
storescp = (sscp_cppunit,localhost,4722)
HostTable END

AETable BEGIN
MANOJ_DEFAULT /home/manojk/data/db R (200, 1024) ANY
AETable END


I have started the server and storescp application using following commandline

dcmqrscp -c /home/manojk/settings/dcmqrscp.cfg -lc /home/manojk/settings/dcm_log4cplus.cfg
storescp -od /home/manojk/datain -p 4722

Tested whether both the applications are reachable or not using echoscu utility
echoscu -aec MANOJ_DEFAULT localhost 5432
echoscu -aec sscp_cppunit localhost 4722

Log messages generated shows 'Association Request Failed' and BadAppContextName. Could you pls. provide me the possible hints for the cause of these error message shown at the end.
Is there any configuration setting issue?

Thanks
Manoj

2019-06-18 17:03:48.696 DEBUG: $dcmtk: dcmqrscp v3.6.3 2018-02-05 $
2019-06-18 17:03:48.696 DEBUG:
2019-06-18 17:03:48.697 DEBUG: DcmDataDictionary: Loading file: /home/manojk/3rd_party/dcmtk/share/dcmtk/dicom.dic
2019-06-18 17:03:48.703 DEBUG: Association Received: localhost
2019-06-18 17:03:48.703 DEBUG: setting network send timeout to 60 seconds
2019-06-18 17:03:48.703 DEBUG: setting network receive timeout to 60 seconds
2019-06-18 17:03:48.703 DEBUG: PDU Type: Associate Request, PDU Length: 205 + 6 bytes PDU header
2019-06-18 17:03:48.703 DEBUG: 01 00 00 00 00 cd 00 01 00 00 53 54 52 59 4b 45
2019-06-18 17:03:48.703 DEBUG: 52 5f 44 45 46 41 55 4c 54 20 45 43 48 4f 53 43
2019-06-18 17:03:48.703 DEBUG: 55 20 20 20 20 20 20 20 20 20 00 00 00 00 00 00
2019-06-18 17:03:48.703 DEBUG: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
2019-06-18 17:03:48.703 DEBUG: 00 00 00 00 00 00 00 00 00 00 10 00 00 15 31 2e
2019-06-18 17:03:48.703 DEBUG: 32 2e 38 34 30 2e 31 30 30 30 38 2e 33 2e 31 2e
2019-06-18 17:03:48.703 DEBUG: 31 2e 31 20 00 00 2e 01 00 ff 00 30 00 00 11 31
2019-06-18 17:03:48.703 DEBUG: 2e 32 2e 38 34 30 2e 31 30 30 30 38 2e 31 2e 31
2019-06-18 17:03:48.703 DEBUG: 40 00 00 11 31 2e 32 2e 38 34 30 2e 31 30 30 30
2019-06-18 17:03:48.703 DEBUG: 38 2e 31 2e 32 50 00 00 3a 51 00 00 04 00 00 40
2019-06-18 17:03:48.703 DEBUG: 00 52 00 00 1b 31 2e 32 2e 32 37 36 2e 30 2e 37
2019-06-18 17:03:48.703 DEBUG: 32 33 30 30 31 30 2e 33 2e 30 2e 33 2e 36 2e 33
2019-06-18 17:03:48.703 DEBUG: 55 00 00 0f 4f 46 46 49 53 5f 44 43 4d 54 4b 5f
2019-06-18 17:03:48.703 DEBUG: 33 36 33
2019-06-18 17:03:48.703 DEBUG: Parsing an A-ASSOCIATE PDU
2019-06-18 17:03:48.703 INFO: Association Received (localhost:ECHOSCU -> MANOJ_DEFAULT)
2019-06-18 17:03:48.704 DEBUG: Parameters:
2019-06-18 17:03:48.704 DEBUG: ====================== BEGIN A-ASSOCIATE-RQ =====================
2019-06-18 17:03:48.704 DEBUG: Our Implementation Class UID: 1.2.276.0.7230010.3.0.3.6.3
2019-06-18 17:03:48.704 DEBUG: Our Implementation Version Name: OFFIS_DCMTK_363
2019-06-18 17:03:48.704 DEBUG: Their Implementation Class UID: 1.2.276.0.7230010.3.0.3.6.3
2019-06-18 17:03:48.704 DEBUG: Their Implementation Version Name: OFFIS_DCMTK_363
2019-06-18 17:03:48.704 DEBUG: Application Context Name: 1.2.840.10008.3.1.1.1
2019-06-18 17:03:48.704 DEBUG: Calling Application Name: ECHOSCU
2019-06-18 17:03:48.704 DEBUG: Called Application Name: MANOJ_DEFAULT
2019-06-18 17:03:48.704 DEBUG: Responding Application Name:
2019-06-18 17:03:48.704 DEBUG: Our Max PDU Receive Size: 16384
2019-06-18 17:03:48.704 DEBUG: Their Max PDU Receive Size: 16384
2019-06-18 17:03:48.704 DEBUG: Presentation Contexts:
2019-06-18 17:03:48.704 DEBUG: Context ID: 1 (Proposed)
2019-06-18 17:03:48.704 DEBUG: Abstract Syntax: =VerificationSOPClass
2019-06-18 17:03:48.704 DEBUG: Proposed SCP/SCU Role: Default
2019-06-18 17:03:48.704 DEBUG: Proposed Transfer Syntax(es):
2019-06-18 17:03:48.704 DEBUG: =LittleEndianImplicit
2019-06-18 17:03:48.704 DEBUG: Requested Extended Negotiation: none
2019-06-18 17:03:48.704 DEBUG: Accepted Extended Negotiation: none
2019-06-18 17:03:48.704 DEBUG: Requested User Identity Negotiation: none
2019-06-18 17:03:48.704 DEBUG: User Identity Negotiation Response: none
2019-06-18 17:03:48.704 DEBUG: ======================= END A-ASSOCIATE-RQ ======================
2019-06-18 17:03:48.704 DEBUG: Constructing Associate AC PDU
2019-06-18 17:03:48.704 INFO: Association Acknowledged (Max Send PDV: 16372)
2019-06-18 17:03:48.704 DEBUG: ====================== BEGIN A-ASSOCIATE-AC =====================
2019-06-18 17:03:48.704 DEBUG: Our Implementation Class UID: 1.2.276.0.7230010.3.0.3.6.3
2019-06-18 17:03:48.704 DEBUG: Our Implementation Version Name: OFFIS_DCMTK_363
2019-06-18 17:03:48.704 DEBUG: Their Implementation Class UID: 1.2.276.0.7230010.3.0.3.6.3
2019-06-18 17:03:48.704 DEBUG: Their Implementation Version Name: OFFIS_DCMTK_363
2019-06-18 17:03:48.704 DEBUG: Application Context Name: 1.2.840.10008.3.1.1.1
2019-06-18 17:03:48.704 DEBUG: Calling Application Name: ECHOSCU
2019-06-18 17:03:48.704 DEBUG: Called Application Name: MANOJ_DEFAULT
2019-06-18 17:03:48.704 DEBUG: Responding Application Name:
2019-06-18 17:03:48.704 DEBUG: Our Max PDU Receive Size: 16384
2019-06-18 17:03:48.704 DEBUG: Their Max PDU Receive Size: 16384
2019-06-18 17:03:48.704 DEBUG: Presentation Contexts:
2019-06-18 17:03:48.704 DEBUG: Context ID: 1 (Accepted)
2019-06-18 17:03:48.704 DEBUG: Abstract Syntax: =VerificationSOPClass
2019-06-18 17:03:48.704 DEBUG: Proposed SCP/SCU Role: Default
2019-06-18 17:03:48.704 DEBUG: Accepted SCP/SCU Role: Default
2019-06-18 17:03:48.704 DEBUG: Accepted Transfer Syntax: =LittleEndianImplicit
2019-06-18 17:03:48.704 DEBUG: Requested Extended Negotiation: none
2019-06-18 17:03:48.704 DEBUG: Accepted Extended Negotiation: none
2019-06-18 17:03:48.704 DEBUG: Requested User Identity Negotiation: none
2019-06-18 17:03:48.704 DEBUG: User Identity Negotiation Response: none
2019-06-18 17:03:48.704 DEBUG: ======================= END A-ASSOCIATE-AC ======================
2019-06-18 17:03:48.744 DEBUG: DcmDataset::read() TransferSyntax="Little Endian Implicit"
2019-06-18 17:03:48.744 INFO: Received Echo SCP RQ: MsgID 1
2019-06-18 17:03:48.788 INFO: Association Release
2019-06-18 17:03:49.035 DEBUG: Request Parameters:
2019-06-18 17:03:49.035 DEBUG: ====================== BEGIN A-ASSOCIATE-RQ =====================
2019-06-18 17:03:49.035 DEBUG: Our Implementation Class UID: 1.2.276.0.7230010.3.0.3.6.3
2019-06-18 17:03:49.035 DEBUG: Our Implementation Version Name: OFFIS_DCMTK_363
2019-06-18 17:03:49.035 DEBUG: Their Implementation Class UID:
2019-06-18 17:03:49.035 DEBUG: Their Implementation Version Name:
2019-06-18 17:03:49.035 DEBUG: Application Context Name: 1.2.840.10008.3.1.1.1
2019-06-18 17:03:49.035 DEBUG: Calling Application Name: MANOJ_DEFAULT
2019-06-18 17:03:49.035 DEBUG: Called Application Name: MANOJ_DEFAULT
2019-06-18 17:03:49.035 DEBUG: Responding Application Name: MANOJ_DEFAULT
2019-06-18 17:03:49.035 DEBUG: Our Max PDU Receive Size: 16384
2019-06-18 17:03:49.035 DEBUG: Their Max PDU Receive Size: 0
2019-06-18 17:03:49.035 DEBUG: Presentation Contexts:
2019-06-18 17:03:49.035 DEBUG: Context ID: 1 (Proposed)
2019-06-18 17:03:49.035 DEBUG: Abstract Syntax: =FINDStudyRootQueryRetrieveInformationModel
2019-06-18 17:03:49.035 DEBUG: Proposed SCP/SCU Role: Default
2019-06-18 17:03:49.035 DEBUG: Proposed Transfer Syntax(es):
2019-06-18 17:03:49.035 DEBUG: =LittleEndianExplicit
2019-06-18 17:03:49.035 DEBUG: =BigEndianExplicit
2019-06-18 17:03:49.035 DEBUG: =LittleEndianImplicit
2019-06-18 17:03:49.035 DEBUG: Requested Extended Negotiation: none
2019-06-18 17:03:49.035 DEBUG: Accepted Extended Negotiation: none
2019-06-18 17:03:49.035 DEBUG: Requested User Identity Negotiation: none
2019-06-18 17:03:49.035 DEBUG: User Identity Negotiation Response: none
2019-06-18 17:03:49.035 DEBUG: ======================= END A-ASSOCIATE-RQ ======================
2019-06-18 17:03:49.036 INFO: Requesting Association
2019-06-18 17:03:49.036 DEBUG: Association Received: localhost
2019-06-18 17:03:49.036 DEBUG: setting network send timeout to 60 seconds
2019-06-18 17:03:49.036 DEBUG: setting network receive timeout to 60 seconds
2019-06-18 17:03:54.042 INFO: Association Received (localhost: -> )
2019-06-18 17:03:54.042 DEBUG: Parameters:
2019-06-18 17:03:54.042 DEBUG: ====================== BEGIN A-ASSOCIATE-RQ =====================
2019-06-18 17:03:54.042 DEBUG: Our Implementation Class UID: 1.2.276.0.7230010.3.0.3.6.3
2019-06-18 17:03:54.042 DEBUG: Our Implementation Version Name: OFFIS_DCMTK_363
2019-06-18 17:03:54.042 DEBUG: Their Implementation Class UID:
2019-06-18 17:03:54.042 DEBUG: Their Implementation Version Name:
2019-06-18 17:03:54.042 DEBUG: Application Context Name:
2019-06-18 17:03:54.042 DEBUG: Calling Application Name:
2019-06-18 17:03:54.042 DEBUG: Called Application Name:
2019-06-18 17:03:54.042 DEBUG: Responding Application Name:
2019-06-18 17:03:54.042 DEBUG: Our Max PDU Receive Size: 16384
2019-06-18 17:03:54.042 DEBUG: Their Max PDU Receive Size: 0
2019-06-18 17:03:54.042 DEBUG: Presentation Contexts:
2019-06-18 17:03:54.042 DEBUG: Requested Extended Negotiation: none
2019-06-18 17:03:54.042 DEBUG: Accepted Extended Negotiation: none
2019-06-18 17:03:54.042 DEBUG: Requested User Identity Negotiation: none
2019-06-18 17:03:54.042 DEBUG: User Identity Negotiation Response: none
2019-06-18 17:03:54.042 DEBUG: ======================= END A-ASSOCIATE-RQ ======================
2019-06-18 17:03:54.042 INFO: Bad AppContextName:
2019-06-18 17:03:54.042 ERROR: Association Request Failed: 0006:031b Failed to establish association
2019-06-18 17:03:54.042 ERROR: 0006:0317 Peer aborted Association (or never connected)
2019-06-18 17:03:54.042 ERROR: 0006:031c TCP Initialization Error: Operation now in progress (Timeout)
2019-06-18 17:03:54.042 INFO: Refusing Association (BadAppContext)
2019-06-18 17:03:54.042 ERROR: Association Reject Failed: 0006:0303 DUL Finite State Machine Error: No action defined, state 1 event 7
2019-06-18 17:03:54.042 INFO: Cleaned up after child (12107)

[J. Riesmeier]

The C-ECHO request to MANOJ_DEFAULT seems to work. Then, there is another association negotiation where the Study Root Q/R Information Model FIND SOP class is proposed, but I cannot see any response. The final association request is invalid since mandatory parameters such as Implementation Class UID, Application Context Name or Calling/Called Application Name are empty. How did you send this request?

[kumarm]

Hello J. Riesmeier,

I did some more analysis of this issue and found that using the global time out dcmConnectionTimeout and setting the value > 0 results in the log messages

2019-06-18 17:03:54.042 INFO: Bad AppContextName:
2019-06-18 17:03:54.042 ERROR: Association Request Failed: 0006:031b Failed to establish association
2019-06-18 17:03:54.042 ERROR: 0006:0317 Peer aborted Association (or never connected)
2019-06-18 17:03:54.042 ERROR: 0006:031c TCP Initialization Error: Operation now in progress (Timeout)
2019-06-18 17:03:54.042 INFO: Refusing Association (BadAppContext)
2019-06-18 17:03:54.042 ERROR: Association Reject Failed: 0006:0303 DUL Finite State Machine Error: No action defined, state 1 event 7

I am setting the timeout value to 5 seconds for 'dcmConnectionTimeout' on Linux platform. On executing "performQuery" method of class DcmFindSCU, Failure happens and API result code gives error text as "Failed to establish association\n0006:0317 Peer aborted Association (or never connected)\n0006:031c TCP Initialization Error: Operation now in progress (Timeout)".

When I comment the code dcmConnectionTimeout.set(OFstatic_cast(Sint32, _conn_config->GetTimeout())) on Linux platform and run the API "performQuery", everything works without any failure.

I also tested the same code on windows platform with global timeout value set to 5 secs. On Windows, no failures due to dcmConnectionTimeout. performQuery API successfully worked.

So, Issue is global timeout setting works on Windows but it results in "performQuery" API failure on Linux platform.

Is there any other way of using dcmConnectionTimeout setting on Linux platform ?

Thanks
Manoj

[kumarm]

Hello J.Riesmeier,

One more analysis for the same time out variable with DcmSCU class.

I have used the new class DcmSCU to send C_FIND request and set the global connection timeout value to 5 secs. by calling the API "setConnectionTimeout". On Linux platform, I can see the API failure "negotiateAssociation" with same error message - "Failed to establish association\n0006:0317 Peer aborted Association (or never connected)\n0006:031c TCP Initialization Error: Operation now in progress (Timeout)".

If i don"t set this global timeout value on linux platform, no error message shown and C-FIND request works successfully.

I used the same code for C-FIND request with global timeout value set to 5 on Windows platform. This code works without any errors.

Thanks
Manoj

[J. Riesmeier]

I can confirm this issue with DCMTK 3.6.3 on Linux systems (for non-local connections), but neither with DCMTK 3.6.2 nor with DCMTK 3.6.4, so I guess it has been fixed already.
Without further analysis, my first guess would be that this issue has been introduced with this commit and fixed with this one.

[kumarm]

Hello J. Riesmeier,

Thanks for your input. I will build DCMTK 3.6.4 version.

Thanks
Manoj