PacsOne.exe stops responding sometimes

Known bugs reported by PacsOne users
Post Reply
tburba
Posts:50
Joined:Fri Apr 23, 2010 5:02 pm
Contact:
Contact tburba
PacsOne.exe stops responding sometimes

Post by tburba » Mon Mar 31, 2014 10:27 am

PacsOne 6.3.7, Windows Server 2012. Local admins complain that it occasionally stops responding and "PacsOne.exe" must be killed (as just stopping the service does nothing).

Code: Select all

Fri Mar 14 12:58:53 2014 INFO - Session: <948> started from SCU: 172.16.1.45
Fri Mar 14 12:58:53 2014 INFO - <948> Receiving A-ASSOCIATE-RQ PDU
Fri Mar 14 12:58:53 2014 INFO - 1 record found in [applentity] table
Fri Mar 14 12:58:53 2014 INFO - <948> A-ASSOCIATE-RQ received successfully
Fri Mar 14 12:58:53 2014 INFO - <948> Sending A-ASSOCIATE-AC PDU
Fri Mar 14 12:58:53 2014 INFO - <948> A-ASSOCIATE-AC PDU sent successfully
Fri Mar 14 12:58:53 2014 INFO - <948> Receiving P-DATA-TF PDU
Fri Mar 14 12:58:53 2014 INFO - <948> C-FIND [3] command received in P-DATA-TF PDU
Fri Mar 14 12:58:53 2014 INFO - 14 record found in [study] table
Fri Mar 14 12:58:53 2014 INFO - 13 tags processed in CDataSetPdv
Fri Mar 14 12:58:57 2014 INFO - <948> C-FIND [3] command received in P-DATA-TF PDU
Fri Mar 14 12:58:57 2014 INFO - 1 record found in [series] table
Fri Mar 14 12:58:57 2014 INFO - 11 tags processed in CDataSetPdv
Fri Mar 14 12:58:57 2014 INFO - <948> C-FIND [3] command received in P-DATA-TF PDU
Fri Mar 14 12:58:57 2014 INFO - 2 record found in [series] table
Fri Mar 14 12:58:57 2014 INFO - 11 tags processed in CDataSetPdv
Fri Mar 14 12:58:58 2014 INFO - <948> C-FIND [3] command received in P-DATA-TF PDU
Fri Mar 14 12:58:58 2014 INFO - 1 record found in [series] table
Fri Mar 14 12:58:58 2014 INFO - 11 tags processed in CDataSetPdv
Fri Mar 14 12:58:58 2014 INFO - <948> C-FIND [3] command received in P-DATA-TF PDU
Fri Mar 14 12:58:58 2014 INFO - 2 record found in [series] table
Fri Mar 14 12:58:58 2014 INFO - 11 tags processed in CDataSetPdv
Fri Mar 14 12:58:58 2014 INFO - <948> C-FIND [3] command received in P-DATA-TF PDU
Fri Mar 14 12:58:58 2014 INFO - 1 record found in [series] table
Fri Mar 14 12:58:58 2014 INFO - 11 tags processed in CDataSetPdv
Fri Mar 14 12:58:58 2014 INFO - <948> C-FIND [3] command received in P-DATA-TF PDU
Fri Mar 14 12:58:58 2014 INFO - 4 record found in [series] table
Fri Mar 14 12:58:58 2014 INFO - 11 tags processed in CDataSetPdv
Fri Mar 14 12:58:58 2014 INFO - <948> C-FIND [3] command received in P-DATA-TF PDU
Fri Mar 14 12:58:58 2014 INFO - 4 record found in [series] table
Fri Mar 14 12:58:58 2014 INFO - 11 tags processed in CDataSetPdv
Fri Mar 14 12:58:59 2014 INFO - <948> C-FIND [3] command received in P-DATA-TF PDU
Fri Mar 14 12:58:59 2014 INFO - 5 record found in [series] table
Fri Mar 14 12:58:59 2014 INFO - 11 tags processed in CDataSetPdv
Fri Mar 14 12:58:59 2014 INFO - <948> C-FIND [3] command received in P-DATA-TF PDU
Fri Mar 14 12:58:59 2014 INFO - 1 record found in [series] table
Fri Mar 14 12:58:59 2014 INFO - 11 tags processed in CDataSetPdv
Fri Mar 14 12:58:59 2014 INFO - <948> C-FIND [3] command received in P-DATA-TF PDU
Fri Mar 14 12:58:59 2014 INFO - 4 record found in [series] table
Fri Mar 14 12:58:59 2014 INFO - 11 tags processed in CDataSetPdv
Fri Mar 14 12:58:59 2014 INFO - <948> C-FIND [3] command received in P-DATA-TF PDU
Fri Mar 14 12:58:59 2014 INFO - 9 record found in [series] table
Fri Mar 14 12:58:59 2014 INFO - 11 tags processed in CDataSetPdv
Fri Mar 14 12:58:59 2014 INFO - <948> C-FIND [3] command received in P-DATA-TF PDU
Fri Mar 14 12:58:59 2014 INFO - 7 record found in [series] table
Fri Mar 14 12:58:59 2014 INFO - 11 tags processed in CDataSetPdv
Fri Mar 14 12:59:00 2014 INFO - <948> C-FIND [3] command received in P-DATA-TF PDU
Fri Mar 14 12:59:00 2014 INFO - 7 record found in [series] table
Fri Mar 14 12:59:00 2014 INFO - 11 tags processed in CDataSetPdv
Fri Mar 14 12:59:00 2014 INFO - <948> C-FIND [3] command received in P-DATA-TF PDU
Fri Mar 14 12:59:00 2014 INFO - 4 record found in [series] table
Fri Mar 14 12:59:00 2014 INFO - 11 tags processed in CDataSetPdv
Fri Mar 14 12:59:08 2014 INFO - Session: <949> started from SCU: 172.16.1.45
Fri Mar 14 12:59:08 2014 INFO - <949> Receiving A-ASSOCIATE-RQ PDU
Fri Mar 14 12:59:08 2014 INFO - 1 record found in [applentity] table
Fri Mar 14 12:59:08 2014 INFO - <949> A-ASSOCIATE-RQ received successfully
Fri Mar 14 12:59:08 2014 INFO - <949> Sending A-ASSOCIATE-AC PDU
Fri Mar 14 12:59:08 2014 INFO - <949> A-ASSOCIATE-AC PDU sent successfully
Fri Mar 14 12:59:08 2014 INFO - <949> Receiving P-DATA-TF PDU
Fri Mar 14 12:59:08 2014 INFO - <949> C-MOVE [3] command received in P-DATA-TF PDU
Fri Mar 14 12:59:08 2014 INFO - 1 record found in [IMAGE] table
Fri Mar 14 12:59:08 2014 INFO - 4 tags processed in CDataSetPdv
Fri Mar 14 12:59:08 2014 INFO - C-STORE Sub-session: <950> started for SCP: 172.16.1.45 Port: 104
Fri Mar 14 12:59:08 2014 INFO - <950> Sending A-ASSOCIATE-RQ PDU
Fri Mar 14 12:59:08 2014 INFO - <950> Waiting for A-ASSOCIATE result
Fri Mar 14 12:59:08 2014 INFO - <950> A-ASSOCIATE-RQ accepted
Fri Mar 14 12:59:08 2014 INFO - <950> Sending P-DATA-TF PDU
Fri Mar 14 13:00:00 2014 ERROR - Session: <948> timed out for client: 172.16.1.45, aborting
Fri Mar 14 13:00:00 2014 INFO - Session: <948> disconnected for client: 172.16.1.45
Fri Mar 14 13:02:41 2014 INFO - Session: <951> started from SCU: 157.163.200.70
Fri Mar 14 13:02:41 2014 INFO - <951> Receiving A-ASSOCIATE-RQ PDU
Fri Mar 14 13:03:21 2014 INFO - Session: <952> started from SCU: 172.16.11.201
Fri Mar 14 13:03:21 2014 INFO - <952> Receiving A-ASSOCIATE-RQ PDU
Fri Mar 14 13:03:41 2014 ERROR - Session: <951> timed out for client: 157.163.200.70, aborting
Fri Mar 14 13:03:41 2014 INFO - Session: <951> disconnected for client: 157.163.200.70
Fri Mar 14 13:03:41 2014 INFO - Session: <953> started from SCU: 157.163.200.70
Fri Mar 14 13:03:41 2014 INFO - <953> Receiving A-ASSOCIATE-RQ PDU
Fri Mar 14 13:04:21 2014 ERROR - Session: <952> timed out for client: 172.16.11.201, aborting
Fri Mar 14 13:04:21 2014 INFO - Session: <952> disconnected for client: 172.16.11.201
They believe the cause is exactly 172.16.1.45 -- a SecurView mammography workstation. Its typical activity is just that, C-FIND + C-MOVE (images are not sent back to PacsOne).

Only it's impossible to reproduce. There can be no hangups for the entire day, despite heavy traffic from that workstation. But sometimes there are multiple hangups per day which makes life hard for the admins. The following were found in the logs just before each hangup:

Code: Select all

Thu Mar 27 09:02:34 2014 INFO - C-STORE Sub-session: <529> started for SCP: 172.16.1.45 Port: 104
...
Wed Mar 26 12:23:40 2014 INFO - C-STORE Sub-session: <3777> started for SCP: 172.16.1.45 Port: 104
...
Tue Mar 25 10:26:44 2014 INFO - C-STORE Sub-session: <2996> started for SCP: 172.16.1.45 Port: 104
...
Fri Mar 21 10:15:46 2014 INFO - C-STORE Sub-session: <437> started for SCP: 172.16.1.45 Port: 104
...
Thu Mar 20 11:27:45 2014 INFO - C-STORE Sub-session: <2230> started for SCP: 172.16.1.45 Port: 104
...
Thu Mar 20 11:50:27 2014 INFO - C-STORE Sub-session: <146> started for SCP: 172.16.1.45 Port: 104
...
Thu Mar 20 12:25:53 2014 INFO - C-STORE Sub-session: <51> started for SCP: 172.16.1.45 Port: 104
Their license does not allow a free upgrade, otherwise I would recommend to install 6.4.1 and see what happens.

Isn't PacsOneSrv.exe capable of monitoring the child process and killing it when applicable? Do you by chance have some ready to use script or another "external" monitoring solution?
Top
pacsone
Site Admin
Posts:3149
Joined:Tue Sep 30, 2003 2:47 am

Post by pacsone » Mon Mar 31, 2014 2:59 pm

The only error you posted from the PacsOne Server logs were the timeout errors when PacsOne tried to establish a Dicom association with this remote AE at IP address 172.16.1.45 Port: 104, so as a sanity check can you run a Dicom Ping (click on the Echo URL link) to that remote AE at IP address 172.16.1.45 Port: 104 from the Dicom AE page of PacsOne Server?
Top
tburba
Posts:50
Joined:Fri Apr 23, 2010 5:02 pm
Contact:
Contact tburba

Post by tburba » Tue Apr 01, 2014 12:07 pm

Here's how it went today:

Code: Select all

Tue Apr 01 13:19:11 2014 INFO - Session: <2555> started from SCU: 172.16.1.44
Tue Apr 01 13:19:11 2014 INFO - <2555> Receiving A-ASSOCIATE-RQ PDU
Tue Apr 01 13:19:11 2014 INFO - 1 record found in [applentity] table
Tue Apr 01 13:19:11 2014 INFO - <2555> A-ASSOCIATE-RQ received successfully
Tue Apr 01 13:19:11 2014 INFO - <2555> Sending A-ASSOCIATE-AC PDU
Tue Apr 01 13:19:11 2014 INFO - <2555> A-ASSOCIATE-AC PDU sent successfully
Tue Apr 01 13:19:11 2014 INFO - <2555> Receiving P-DATA-TF PDU
Tue Apr 01 13:19:11 2014 INFO - <2555> C-MOVE [201] command received in P-DATA-TF PDU
Tue Apr 01 13:19:11 2014 INFO - 4 record found in [IMAGE] table
Tue Apr 01 13:19:11 2014 INFO - 3 tags processed in CDataSetPdv
Tue Apr 01 13:19:11 2014 INFO - C-STORE Sub-session: <2556> started for SCP: 172.16.1.44 Port: 4499
Tue Apr 01 13:19:11 2014 INFO - <2556> Sending A-ASSOCIATE-RQ PDU
Tue Apr 01 13:19:11 2014 INFO - <2556> Waiting for A-ASSOCIATE result
Tue Apr 01 13:19:11 2014 INFO - <2556> A-ASSOCIATE-RQ accepted
Tue Apr 01 13:19:11 2014 INFO - <2556> Sending P-DATA-TF PDU
Tue Apr 01 13:19:32 2014 INFO - Session: <2557> started from SCU: 172.16.1.44
Tue Apr 01 13:19:32 2014 INFO - <2557> Receiving A-ASSOCIATE-RQ PDU
Tue Apr 01 13:19:40 2014 ERROR - Session: <2544> timed out for client: 172.16.11.201, aborting
Tue Apr 01 13:19:40 2014 INFO - Session: <2544> disconnected for client: 172.16.11.201
Tue Apr 01 13:20:07 2014 INFO - Session: <2558> started from SCU: 172.16.1.44
Tue Apr 01 13:20:07 2014 INFO - <2558> Receiving A-ASSOCIATE-RQ PDU
Tue Apr 01 13:20:10 2014 ERROR - Session: <2551> timed out for client: 172.16.8.200, aborting
Tue Apr 01 13:20:10 2014 INFO - Session: <2551> disconnected for client: 172.16.8.200
Tue Apr 01 13:20:29 2014 INFO - Session: <2559> started from SCU: 172.16.1.44
Tue Apr 01 13:20:29 2014 INFO - <2559> Receiving A-ASSOCIATE-RQ PDU
Tue Apr 01 13:20:32 2014 ERROR - Session: <2557> timed out for client: 172.16.1.44, aborting
Tue Apr 01 13:20:32 2014 INFO - Session: <2557> disconnected for client: 172.16.1.44
Tue Apr 01 13:21:00 2014 INFO - Session: <2560> started from SCU: 127.0.0.1
Tue Apr 01 13:21:00 2014 INFO - <2560> Receiving A-ASSOCIATE-RQ PDU
Tue Apr 01 13:21:07 2014 ERROR - Session: <2558> timed out for client: 172.16.1.44, aborting
Tue Apr 01 13:21:07 2014 INFO - Session: <2558> disconnected for client: 172.16.1.44
Tue Apr 01 13:21:24 2014 INFO - Session: <2561> started from SCU: 172.16.1.44
Tue Apr 01 13:21:24 2014 INFO - <2561> Receiving A-ASSOCIATE-RQ PDU
Tue Apr 01 13:21:24 2014 INFO - Session: <2562> started from SCU: 172.16.1.44
Tue Apr 01 13:21:24 2014 INFO - <2562> Receiving A-ASSOCIATE-RQ PDU
Tue Apr 01 13:21:29 2014 ERROR - Session: <2559> timed out for client: 172.16.1.44, aborting
Tue Apr 01 13:21:29 2014 INFO - Session: <2559> disconnected for client: 172.16.1.44
Tue Apr 01 13:22:00 2014 ERROR - Session: <2560> timed out for client: 127.0.0.1, aborting
Tue Apr 01 13:22:00 2014 INFO - Session: <2560> disconnected for client: 127.0.0.1
Tue Apr 01 13:22:09 2014 INFO - Session: <2563> started from SCU: 172.16.1.39
Tue Apr 01 13:22:09 2014 INFO - <2563> Receiving A-ASSOCIATE-RQ PDU
Tue Apr 01 13:22:24 2014 ERROR - Session: <2561> timed out for client: 172.16.1.44, aborting
Tue Apr 01 13:22:24 2014 INFO - Session: <2561> disconnected for client: 172.16.1.44
Tue Apr 01 13:22:24 2014 ERROR - Session: <2562> timed out for client: 172.16.1.44, aborting
Tue Apr 01 13:22:24 2014 INFO - Session: <2562> disconnected for client: 172.16.1.44
A different imager this time, .44. The local admin now had time to press "Echo" URL for it, and the answer was (not surprisingly)

Code: Select all

C-ECHO command verified successfully from AE [JiveX]
Sessions 2555 and 2556 never completed -- they aren't referenced anymore in this log (a few minutes later the entire server was restarted). Subsequent attempts from the same AE time out after 60 seconds. Obviously the thread created for those sessions became stuck and also seized some common resources.

A monitor script based on dcmtk's echoscu.exe was running since yesterday. During the hangup its association requests failed. However, the error message from the tool is too generic and I can't rely on it for any automated actions. Will see what can be changed there.
Top
pacsone
Site Admin
Posts:3149
Joined:Tue Sep 30, 2003 2:47 am

Post by pacsone » Tue Apr 01, 2014 3:57 pm

From the PacsOne Server logs, it seems that no Dicom message can be exchanged between PacsOne and this remote AE at IP address 172.16.1.44 Port: 4499, as soon as PacsOne started the C-STORE sub-operation for that remote AE to send the retrieved Dicom images (C-MOVE). So can you provide the following information?

1. Can you check the Dicom Conformance Statement of that remote AE at IP address 172.16.1.44 Port: 4499, and verify it does support Dicom image storage (C-STORE) operation for that particular image SOP class?

2. How is this remote AE connected with the host where PacsOne is running, e.g., via LAN, WAN, VPN, etc? What's the slowest network link between them?

3. When this occurred, did you try running a Dicom Echo from a 3rd Dicom application (not from that remote AE) to PacsOne? Also, did you run a Dicom Echo from a 3rd Dicom app to that remote AE at IP address 172.16.1.44 Port: 4499? Those tests will verify independently if the problem is with the host where PacsOne is running, or that remote AE at IP address 172.16.1.44 Port: 4499 .
Top
tburba
Posts:50
Joined:Fri Apr 23, 2010 5:02 pm
Contact:
Contact tburba

Post by tburba » Wed Apr 02, 2014 2:10 pm

Regarding your Q1, I don't have this data at hand, but the point is that usually the same AEs communicate with PacsOne without problems. These two had no problems for more than one year until now; we can't identify what change caused this.

Today the problem appeared again. This time I was able to examine the system myself.

Regarding Q3, I had the following script ready:

Code: Select all

echoscu.exe -aet PACSONE -aec JiveX -d -to 20 172.16.1.44 4499 >ping_all.log 2>&1
echoscu.exe -aet PACSONE -aec SCR -d -to 20 172.16.1.45 104 >>ping_all.log 2>&1
echoscu.exe -aet DCMSND -aec PACSONE -d -to 20 172.16.1.6 104 >>ping_all.log 2>&1
The result:

Code: Select all

D: $dcmtk: echoscu v3.6.0 2011-01-06 $
D: 
D: Request Parameters:
D: ====================== BEGIN A-ASSOCIATE-RQ =====================
D: Our Implementation Class UID:      1.2.276.0.7230010.3.0.3.6.0
D: Our Implementation Version Name:   OFFIS_DCMTK_360
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:    PACSONE
D: Called Application Name:     JiveX
D: Responding Application Name: resp. AP Title
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: =VerificationSOPClass
D:     Proposed SCP/SCU Role: Default
D:     Proposed Transfer Syntax(es):
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: Constructing Associate RQ PDU
D: PDU Type: Associate Accept, PDU Length: 178 + 6 bytes PDU header
D:   02  00  00  00  00  b2  00  01  00  00  4a  69  76  65  58  20
D:   20  20  20  20  20  20  20  20  20  20  50  41  43  53  4f  4e
D:   45  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  19  01  00  00  00  40  00  00  11  31
D:   2e  32  2e  38  34  30  2e  31  30  30  30  38  2e  31  2e  32
D:   50  00  00  34  51  00  00  04  00  00  40  00  52  00  00  19
D:   31  2e  32  2e  32  37  36  2e  30  2e  35  30  2e  32  30  31
D:   30  30  33  30  31  2e  34  2e  34  55  00  00  0b  4a  49  56
D:   45  58  5f  54  4b  34  2e  34
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.0
D: Our Implementation Version Name:   OFFIS_DCMTK_360
D: Their Implementation Class UID:    1.2.276.0.50.20100301.4.4
D: Their Implementation Version Name: JIVEX_TK4.4
D: Application Context Name:    1.2.840.10008.3.1.1.1
D: Calling Application Name:    PACSONE
D: Called Application Name:     JiveX
D: Responding Application Name: JiveX
D: Our Max PDU Receive Size:    16384
D: Their Max PDU Receive Size:  16384
D: Presentation Contexts:
D:   Context ID:        1 (Accepted)
D:     Abstract Syntax: =VerificationSOPClass
D:     Proposed SCP/SCU Role: Default
D:     Accepted SCP/SCU Role: Default
D:     Accepted Transfer Syntax: =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-AC ======================
I: Association Accepted (Max Send PDV: 16372)
I: Sending Echo Request: MsgID 1
I: Received Echo Response (Status: Success)
I: Releasing Association

Code: Select all

D: $dcmtk: echoscu v3.6.0 2011-01-06 $
D: 
D: Request Parameters:
D: ====================== BEGIN A-ASSOCIATE-RQ =====================
D: Our Implementation Class UID:      1.2.276.0.7230010.3.0.3.6.0
D: Our Implementation Version Name:   OFFIS_DCMTK_360
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:    PACSONE
D: Called Application Name:     SCR
D: Responding Application Name: resp. AP Title
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: =VerificationSOPClass
D:     Proposed SCP/SCU Role: Default
D:     Proposed Transfer Syntax(es):
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: Constructing Associate RQ PDU
D: PDU Type: Associate Accept, PDU Length: 183 + 6 bytes PDU header
D:   02  00  00  00  00  b7  00  01  00  00  53  43  52  20  20  20
D:   20  20  20  20  20  20  20  20  20  20  50  41  43  53  4f  4e
D:   45  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  19  01  00  00  00  40  00  00  11  31
D:   2e  32  2e  38  34  30  2e  31  30  30  30  38  2e  31  2e  32
D:   50  00  00  39  51  00  00  04  00  00  70  00  52  00  00  1a
D:   31  2e  32  2e  32  37  36  2e  30  2e  32  38  2e  33  2e  30
D:   2e  31  32  2e  34  30  30  30  30  30  55  00  00  0f  4d  42
D:   43  5f  53  43  52  5f  30  34  30  30  30  30  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.0
D: Our Implementation Version Name:   OFFIS_DCMTK_360
D: Their Implementation Class UID:    1.2.276.0.28.3.0.12.400000
D: Their Implementation Version Name: MBC_SCR_0400000
D: Application Context Name:    1.2.840.10008.3.1.1.1
D: Calling Application Name:    PACSONE
D: Called Application Name:     SCR
D: Responding Application Name: SCR
D: Our Max PDU Receive Size:    16384
D: Their Max PDU Receive Size:  28672
D: Presentation Contexts:
D:   Context ID:        1 (Accepted)
D:     Abstract Syntax: =VerificationSOPClass
D:     Proposed SCP/SCU Role: Default
D:     Accepted SCP/SCU Role: Default
D:     Accepted Transfer Syntax: =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-AC ======================
I: Association Accepted (Max Send PDV: 28660)
I: Sending Echo Request: MsgID 1
I: Received Echo Response (Status: Success)
I: Releasing Association

Code: Select all

D: $dcmtk: echoscu v3.6.0 2011-01-06 $
D: 
D: Request Parameters:
D: ====================== BEGIN A-ASSOCIATE-RQ =====================
D: Our Implementation Class UID:      1.2.276.0.7230010.3.0.3.6.0
D: Our Implementation Version Name:   OFFIS_DCMTK_360
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:    DCMSND
D: Called Application Name:     PACSONE
D: Responding Application Name: resp. AP Title
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: =VerificationSOPClass
D:     Proposed SCP/SCU Role: Default
D:     Proposed Transfer Syntax(es):
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: Constructing Associate RQ PDU
F: Association Request Failed: 0006:0317 Peer aborted Association (or never connected)
This message is still too generic for me; unfortunately storescu.exe works only this way. Yesterday I didn't add the -d option, and it said basically the same:

Code: Select all

I: Requesting Association
F: Association Request Failed: 0006:0317 Peer aborted Association (or never connected)
Unfortunately there is no distinct message from storescu.exe when the other end establishes a TCP/IP connection but doesn't reply anything. The same is given if nobody is listening.

Due to pressure from doctors I needed to work quickly and there wasn't time to install Telnet Client for a simple test (telnet 127.0.0.1 104).

I noticed that PacsOneSrv.exe and PacsOne.exe are running. The latter is practically idle: 0% CPU, ~20 MB.

My script is able to automatically call

Code: Select all

taskkill /f /im PacsOne.exe
This doesn't have any effect. The command reports success but the process remains in memory with the same PID. It's worth noting that the script is run as an ordinary Task Scheduler job, without the checkbox "highest privileges". However when I opened a console window with administrative privileges, and ran taskkill from there, then it reported a failure with reason "access denied". The same from Task Manager: PacsOne.exe can't be killed in this state. Of course if I stop the service, the second executable remains running. It still can't be killed, though.

Finally I understand why local admins always did a whole system restart. Other means simply fail.

The server runs Windows 2012 Standard. That reminds me of this issue. On the other hand, inability to kill a process might be unrelated to malfunction of said process due to which it needs to be killed :)

The customer agreed for a PacsOne update. Let's see if that helps. I think a downgrade to Windows 2008 would do more good.

Mind you, a couple of Windows 2012 installations at a different local hospital also like to run into some strange problems where only system restart helps. These problems just aren't so critical.
Top
pacsone
Site Admin
Posts:3149
Joined:Tue Sep 30, 2003 2:47 am

Post by pacsone » Thu Apr 03, 2014 3:47 pm

1. Please do NOT stop PacsOne Server by killing the "PacsOne.exe" process, because doing so will result in resource leaks and the correct way to stop/restart PacsOne Server is through Control Panel->Administrative Tools->Services->PacsOne Server Premium Edition->Stop/Restart.

2. Did you check if port 104 is being listened to on that IP address 172.16.1.6? e.g., you can open a local command shell on that server and run the NETSTAT command to check if port 104 is being listened to, and which process is listening to that port:
C:\>netstat -aon -p tcp
Check if you see "0.0.0.0:104" in the 2nd column in the output of the command above, and the 5th column will list the Process ID (PID) of the program listening to that port. Then you can verify if that's the same PID of the "PacsOne.exe" process from the Windows Task Manager->Process tab.

3. If you've verified "PacsOne.exe" is indeed listening to port 104 from test#2 above, you can then check the PacsOne Server logs to see if it had actually received the incoming Dicom Echo request from the ECHOSCU client. If not, you should check your firewall settings and make sure inbound packets to port 104 is NOT being blocked by the firewall.
Top
tburba
Posts:50
Joined:Fri Apr 23, 2010 5:02 pm
Contact:
Contact tburba

Post by tburba » Thu Apr 03, 2014 9:55 pm

The verifier script mentioned earlier is run by Task Scheduler each 3 minutes, impersonating the default "SYSTEM" user. Connection attempts from 127.0.0.1 are nicely ticking below at 15:12:00, 15:15:00, 15:18:00, 15:21:00, 15:24:00. They all timed out.

Code: Select all

Wed Apr 02 15:12:00 2014 INFO - Session: <1929> started from SCU: 127.0.0.1
Wed Apr 02 15:12:00 2014 INFO - <1929> Receiving A-ASSOCIATE-RQ PDU
Wed Apr 02 15:12:05 2014 ERROR - Session: <1924> timed out for client: 157.163.200.71, aborting
Wed Apr 02 15:12:05 2014 INFO - Session: <1924> disconnected for client: 157.163.200.71
Wed Apr 02 15:12:07 2014 INFO - Session: <1930> started from SCU: 172.16.8.200
Wed Apr 02 15:12:07 2014 INFO - <1930> Receiving A-ASSOCIATE-RQ PDU
Wed Apr 02 15:12:15 2014 ERROR - Session: <1925> timed out for client: 172.16.8.200, aborting
Wed Apr 02 15:12:15 2014 INFO - Session: <1925> disconnected for client: 172.16.8.200
Wed Apr 02 15:12:32 2014 ERROR - Session: <1926> timed out for client: 172.16.8.200, aborting
Wed Apr 02 15:12:32 2014 INFO - Session: <1926> disconnected for client: 172.16.8.200
Wed Apr 02 15:12:49 2014 ERROR - Session: <1927> timed out for client: 172.16.8.200, aborting
Wed Apr 02 15:12:49 2014 INFO - Session: <1927> disconnected for client: 172.16.8.200
Wed Apr 02 15:12:53 2014 INFO - Session: <1931> started from SCU: 157.163.200.60
Wed Apr 02 15:12:53 2014 INFO - <1931> Receiving A-ASSOCIATE-RQ PDU
Wed Apr 02 15:12:56 2014 ERROR - Session: <1928> timed out for client: 157.163.200.70, aborting
Wed Apr 02 15:12:56 2014 INFO - Session: <1928> disconnected for client: 157.163.200.70
Wed Apr 02 15:12:56 2014 INFO - Session: <1932> started from SCU: 157.163.200.70
Wed Apr 02 15:12:56 2014 INFO - <1932> Receiving A-ASSOCIATE-RQ PDU
Wed Apr 02 15:13:00 2014 ERROR - Session: <1929> timed out for client: 127.0.0.1, aborting
Wed Apr 02 15:13:00 2014 INFO - Session: <1929> disconnected for client: 127.0.0.1
Wed Apr 02 15:13:07 2014 ERROR - Session: <1930> timed out for client: 172.16.8.200, aborting
Wed Apr 02 15:13:07 2014 INFO - Session: <1930> disconnected for client: 172.16.8.200
Wed Apr 02 15:13:53 2014 ERROR - Session: <1931> timed out for client: 157.163.200.60, aborting
Wed Apr 02 15:13:53 2014 INFO - Session: <1931> disconnected for client: 157.163.200.60
Wed Apr 02 15:13:54 2014 INFO - Session: <1933> started from SCU: 157.163.200.60
Wed Apr 02 15:13:54 2014 INFO - <1933> Receiving A-ASSOCIATE-RQ PDU
Wed Apr 02 15:13:56 2014 ERROR - Session: <1932> timed out for client: 157.163.200.70, aborting
Wed Apr 02 15:13:56 2014 INFO - Session: <1932> disconnected for client: 157.163.200.70
Wed Apr 02 15:13:56 2014 INFO - Session: <1934> started from SCU: 157.163.200.70
Wed Apr 02 15:13:56 2014 INFO - <1934> Receiving A-ASSOCIATE-RQ PDU
Wed Apr 02 15:14:49 2014 INFO - Session: <1935> started from SCU: 172.16.1.44
Wed Apr 02 15:14:49 2014 INFO - <1935> Receiving A-ASSOCIATE-RQ PDU
Wed Apr 02 15:14:49 2014 INFO - Session: <1936> started from SCU: 172.16.1.44
Wed Apr 02 15:14:49 2014 INFO - <1936> Receiving A-ASSOCIATE-RQ PDU
Wed Apr 02 15:14:54 2014 ERROR - Session: <1933> timed out for client: 157.163.200.60, aborting
Wed Apr 02 15:14:54 2014 INFO - Session: <1933> disconnected for client: 157.163.200.60
Wed Apr 02 15:14:54 2014 INFO - Session: <1937> started from SCU: 157.163.200.60
Wed Apr 02 15:14:54 2014 INFO - <1937> Receiving A-ASSOCIATE-RQ PDU
Wed Apr 02 15:14:56 2014 ERROR - Session: <1934> timed out for client: 157.163.200.70, aborting
Wed Apr 02 15:14:56 2014 INFO - Session: <1934> disconnected for client: 157.163.200.70
Wed Apr 02 15:15:00 2014 INFO - Session: <1938> started from SCU: 127.0.0.1
Wed Apr 02 15:15:00 2014 INFO - <1938> Receiving A-ASSOCIATE-RQ PDU
Wed Apr 02 15:15:49 2014 ERROR - Session: <1935> timed out for client: 172.16.1.44, aborting
Wed Apr 02 15:15:49 2014 ERROR - Session: <1936> timed out for client: 172.16.1.44, aborting
Wed Apr 02 15:15:49 2014 INFO - Session: <1935> disconnected for client: 172.16.1.44
Wed Apr 02 15:15:49 2014 INFO - Session: <1936> disconnected for client: 172.16.1.44
Wed Apr 02 15:15:54 2014 ERROR - Session: <1937> timed out for client: 157.163.200.60, aborting
Wed Apr 02 15:15:54 2014 INFO - Session: <1937> disconnected for client: 157.163.200.60
Wed Apr 02 15:15:54 2014 INFO - Session: <1939> started from SCU: 157.163.200.60
Wed Apr 02 15:15:54 2014 INFO - <1939> Receiving A-ASSOCIATE-RQ PDU
Wed Apr 02 15:15:56 2014 INFO - Session: <1940> started from SCU: 157.163.200.70
Wed Apr 02 15:15:56 2014 INFO - <1940> Receiving A-ASSOCIATE-RQ PDU
Wed Apr 02 15:16:00 2014 ERROR - Session: <1938> timed out for client: 127.0.0.1, aborting
Wed Apr 02 15:16:00 2014 INFO - Session: <1938> disconnected for client: 127.0.0.1
Wed Apr 02 15:16:54 2014 ERROR - Session: <1939> timed out for client: 157.163.200.60, aborting
Wed Apr 02 15:16:54 2014 INFO - Session: <1939> disconnected for client: 157.163.200.60
Wed Apr 02 15:16:56 2014 ERROR - Session: <1940> timed out for client: 157.163.200.70, aborting
Wed Apr 02 15:16:56 2014 INFO - Session: <1940> disconnected for client: 157.163.200.70
Wed Apr 02 15:16:56 2014 INFO - Session: <1941> started from SCU: 157.163.200.70
Wed Apr 02 15:16:56 2014 INFO - <1941> Receiving A-ASSOCIATE-RQ PDU
Wed Apr 02 15:17:47 2014 INFO - Session: <1942> started from SCU: 172.16.1.44
Wed Apr 02 15:17:47 2014 INFO - <1942> Receiving A-ASSOCIATE-RQ PDU
Wed Apr 02 15:17:47 2014 INFO - Session: <1943> started from SCU: 172.16.1.44
Wed Apr 02 15:17:47 2014 INFO - <1943> Receiving A-ASSOCIATE-RQ PDU
Wed Apr 02 15:17:56 2014 ERROR - Session: <1941> timed out for client: 157.163.200.70, aborting
Wed Apr 02 15:17:56 2014 INFO - Session: <1941> disconnected for client: 157.163.200.70
Wed Apr 02 15:17:56 2014 INFO - Session: <1944> started from SCU: 157.163.200.70
Wed Apr 02 15:17:56 2014 INFO - <1944> Receiving A-ASSOCIATE-RQ PDU
Wed Apr 02 15:18:00 2014 INFO - Session: <1945> started from SCU: 127.0.0.1
Wed Apr 02 15:18:00 2014 INFO - <1945> Receiving A-ASSOCIATE-RQ PDU
Wed Apr 02 15:18:47 2014 ERROR - Session: <1942> timed out for client: 172.16.1.44, aborting
Wed Apr 02 15:18:47 2014 INFO - Session: <1942> disconnected for client: 172.16.1.44
Wed Apr 02 15:18:47 2014 ERROR - Session: <1943> timed out for client: 172.16.1.44, aborting
Wed Apr 02 15:18:47 2014 INFO - Session: <1946> started from SCU: 172.16.1.44
Wed Apr 02 15:18:47 2014 INFO - <1946> Receiving A-ASSOCIATE-RQ PDU
Wed Apr 02 15:18:47 2014 INFO - Session: <1943> disconnected for client: 172.16.1.44
Wed Apr 02 15:18:47 2014 INFO - Session: <1947> started from SCU: 172.16.1.44
Wed Apr 02 15:18:47 2014 INFO - <1947> Receiving A-ASSOCIATE-RQ PDU
Wed Apr 02 15:18:56 2014 ERROR - Session: <1944> timed out for client: 157.163.200.70, aborting
Wed Apr 02 15:18:56 2014 INFO - Session: <1944> disconnected for client: 157.163.200.70
Wed Apr 02 15:18:56 2014 INFO - Session: <1948> started from SCU: 157.163.200.70
Wed Apr 02 15:18:56 2014 INFO - <1948> Receiving A-ASSOCIATE-RQ PDU
Wed Apr 02 15:19:00 2014 ERROR - Session: <1945> timed out for client: 127.0.0.1, aborting
Wed Apr 02 15:19:00 2014 INFO - Session: <1945> disconnected for client: 127.0.0.1
Wed Apr 02 15:19:47 2014 ERROR - Session: <1946> timed out for client: 172.16.1.44, aborting
Wed Apr 02 15:19:47 2014 INFO - Session: <1946> disconnected for client: 172.16.1.44
Wed Apr 02 15:19:47 2014 ERROR - Session: <1947> timed out for client: 172.16.1.44, aborting
Wed Apr 02 15:19:47 2014 INFO - Session: <1947> disconnected for client: 172.16.1.44
Wed Apr 02 15:19:56 2014 ERROR - Session: <1948> timed out for client: 157.163.200.70, aborting
Wed Apr 02 15:19:56 2014 INFO - Session: <1948> disconnected for client: 157.163.200.70
Wed Apr 02 15:19:56 2014 INFO - Session: <1949> started from SCU: 157.163.200.70
Wed Apr 02 15:19:56 2014 INFO - <1949> Receiving A-ASSOCIATE-RQ PDU
Wed Apr 02 15:20:51 2014 INFO - Session: <1950> started from SCU: 172.16.1.44
Wed Apr 02 15:20:51 2014 INFO - <1950> Receiving A-ASSOCIATE-RQ PDU
Wed Apr 02 15:20:52 2014 INFO - Session: <1951> started from SCU: 172.16.1.44
Wed Apr 02 15:20:52 2014 INFO - <1951> Receiving A-ASSOCIATE-RQ PDU
Wed Apr 02 15:20:56 2014 ERROR - Session: <1949> timed out for client: 157.163.200.70, aborting
Wed Apr 02 15:20:56 2014 INFO - Session: <1949> disconnected for client: 157.163.200.70
Wed Apr 02 15:20:56 2014 INFO - Session: <1952> started from SCU: 157.163.200.70
Wed Apr 02 15:20:56 2014 INFO - <1952> Receiving A-ASSOCIATE-RQ PDU
Wed Apr 02 15:21:00 2014 INFO - Session: <1953> started from SCU: 127.0.0.1
Wed Apr 02 15:21:00 2014 INFO - <1953> Receiving A-ASSOCIATE-RQ PDU
Wed Apr 02 15:21:26 2014 INFO - Session: <1954> started from SCU: 172.16.1.6
Wed Apr 02 15:21:26 2014 INFO - <1954> Receiving A-ASSOCIATE-RQ PDU
Wed Apr 02 15:21:51 2014 ERROR - Session: <1950> timed out for client: 172.16.1.44, aborting
Wed Apr 02 15:21:51 2014 INFO - Session: <1950> disconnected for client: 172.16.1.44
Wed Apr 02 15:21:51 2014 INFO - Session: <1955> started from SCU: 172.16.1.44
Wed Apr 02 15:21:51 2014 INFO - <1955> Receiving A-ASSOCIATE-RQ PDU
Wed Apr 02 15:21:52 2014 ERROR - Session: <1951> timed out for client: 172.16.1.44, aborting
Wed Apr 02 15:21:52 2014 INFO - Session: <1951> disconnected for client: 172.16.1.44
Wed Apr 02 15:21:56 2014 ERROR - Session: <1952> timed out for client: 157.163.200.70, aborting
Wed Apr 02 15:21:56 2014 INFO - Session: <1952> disconnected for client: 157.163.200.70
Wed Apr 02 15:21:56 2014 INFO - Session: <1956> started from SCU: 157.163.200.70
Wed Apr 02 15:21:56 2014 INFO - <1956> Receiving A-ASSOCIATE-RQ PDU
Wed Apr 02 15:22:00 2014 ERROR - Session: <1953> timed out for client: 127.0.0.1, aborting
Wed Apr 02 15:22:00 2014 INFO - Session: <1953> disconnected for client: 127.0.0.1
Wed Apr 02 15:22:05 2014 INFO - Session: <1957> started from SCU: 157.163.200.71
Wed Apr 02 15:22:05 2014 INFO - <1957> Receiving A-ASSOCIATE-RQ PDU
Wed Apr 02 15:22:26 2014 ERROR - Session: <1954> timed out for client: 172.16.1.6, aborting
Wed Apr 02 15:22:26 2014 INFO - Session: <1954> disconnected for client: 172.16.1.6
Wed Apr 02 15:22:51 2014 ERROR - Session: <1955> timed out for client: 172.16.1.44, aborting
Wed Apr 02 15:22:51 2014 INFO - Session: <1955> disconnected for client: 172.16.1.44
Wed Apr 02 15:22:56 2014 ERROR - Session: <1956> timed out for client: 157.163.200.70, aborting
Wed Apr 02 15:22:56 2014 INFO - Session: <1956> disconnected for client: 157.163.200.70
Wed Apr 02 15:22:56 2014 INFO - Session: <1958> started from SCU: 157.163.200.70
Wed Apr 02 15:22:56 2014 INFO - <1958> Receiving A-ASSOCIATE-RQ PDU
Wed Apr 02 15:23:05 2014 ERROR - Session: <1957> timed out for client: 157.163.200.71, aborting
Wed Apr 02 15:23:05 2014 INFO - Session: <1957> disconnected for client: 157.163.200.71
Wed Apr 02 15:23:56 2014 ERROR - Session: <1958> timed out for client: 157.163.200.70, aborting
Wed Apr 02 15:23:56 2014 INFO - Session: <1958> disconnected for client: 157.163.200.70
Wed Apr 02 15:23:56 2014 INFO - Session: <1959> started from SCU: 157.163.200.70
Wed Apr 02 15:23:56 2014 INFO - <1959> Receiving A-ASSOCIATE-RQ PDU
Wed Apr 02 15:24:00 2014 INFO - Session: <1960> started from SCU: 127.0.0.1
Wed Apr 02 15:24:00 2014 INFO - <1960> Receiving A-ASSOCIATE-RQ PDU
Wed Apr 02 15:24:56 2014 ERROR - Session: <1959> timed out for client: 157.163.200.70, aborting
Wed Apr 02 15:24:56 2014 INFO - Session: <1959> disconnected for client: 157.163.200.70
Wed Apr 02 15:24:56 2014 INFO - Session: <1961> started from SCU: 157.163.200.70
Wed Apr 02 15:24:56 2014 INFO - <1961> Receiving A-ASSOCIATE-RQ PDU
Wed Apr 02 15:25:00 2014 ERROR - Session: <1960> timed out for client: 127.0.0.1, aborting
Wed Apr 02 15:25:00 2014 INFO - Session: <1960> disconnected for client: 127.0.0.1
On the other hand, the manual check (3 calls to echoscu.exe impersonating Administrator, from an elevated process on the same server) was run at 15:22:06 (according to the timestamp of ping_all.log). There is no such connection attempt in PacsOne logs!

172.16.1.6 is the external address for the same server. After the system restart later, PacsOne replied to C-ECHO as if nothing happened. I checked just now, too.
Top
tburba
Posts:50
Joined:Fri Apr 23, 2010 5:02 pm
Contact:
Contact tburba

Post by tburba » Thu Apr 03, 2014 10:03 pm

1. Please do NOT stop PacsOne Server by killing the "PacsOne.exe" process, because doing so will result in resource leaks and the correct way to stop/restart PacsOne Server is through Control Panel->Administrative Tools->Services->PacsOne Server Premium Edition->Stop/Restart.
Is the following safe, then?

net stop "PacsOne Server Premium Edition"
taskkill /f /im PacsOne.exe
net start "PacsOne Server Premium Edition"

Because on another system I saw a few times that PacsOne.exe remains in memory after stopping the service. The executable was occupying the entire CPU core and obviously not responding to whatever requests from PacsOneSrv.exe. On the other hand, killing such an orphan from Task Manager was easy there.
Top
pacsone
Site Admin
Posts:3149
Joined:Tue Sep 30, 2003 2:47 am

Post by pacsone » Fri Apr 04, 2014 2:56 pm

It seems that there maybe another application running on the same host listening to the same port 104, so can you check the following?

1. Stop PacsOne Server and make sure "PacsOne.exe" is NOT running (kill it from Task Manager if you have to).

2. Run the NETSTAT -aon -p tcp command again from a local shell, and check if you see "0.0.0.0:104" in the 2nd column of the command output.
Top
Post Reply

Return to “Known Bugs”