*** multiplex: connection terminated on receiving side

    Besides being a transfer syntax issue, what else actually can cause this? It happens time to time when I open up a lot of associations concurrently to another conquest server. After the tcp/ip timeout is reached it seems to starts accept more connections again but never really stops accepting connections. On the sending side it always just says


    20110414 10:27:42 *** ExportConverter9.1: Forward failed to connect to host SERVER
    20110414 10:27:42 *** Queue: holding processing of file C:\dicomserver1416rc6\Data\12345\1.2.840.113704.7.1.1.37086.dcm


    which isnt true because the server is accessible because it continues to receive on other threads. And once it tries again it goes through fine after the timoeut. It's just really weird...it only happens when it's sending a ton of images at the same time. Happens on LAN and WAN connections when using



    ForwardAssociationLevel = SERIES
    ForwardAssociationCloseDelay = 15
    ForwardAssociationRefreshDelay = 3600
    ForwardAssociationRelease = 1


    ExportConverters = 10
    ExportConverter0 = ifnumequal "%A0008,0018[0,0]", "0"; forward compressed as jk to SERVER
    ExportConverter1 = ifnumequal "%A0008,0018[0,0]", "1"; forward compressed as jk to SERVER
    ExportConverter2 = ifnumequal "%A0008,0018[0,0]", "2"; forward compressed as jk to SERVER
    ExportConverter3 = ifnumequal "%A0008,0018[0,0]", "3"; forward compressed as jk to SERVER
    ExportConverter4 = ifnumequal "%A0008,0018[0,0]", "4"; forward compressed as jk to SERVER
    ExportConverter5 = ifnumequal "%A0008,0018[0,0]", "5"; forward compressed as jk to SERVER
    ExportConverter6 = ifnumequal "%A0008,0018[0,0]", "6"; forward compressed as jk to SERVER
    ExportConverter7 = ifnumequal "%A0008,0018[0,0]", "7"; forward compressed as jk to SERVER
    ExportConverter8 = ifnumequal "%A0008,0018[0,0]", "8"; forward compressed as jk to SERVER
    ExportConverter9 = ifnumequal "%A0008,0018[0,0]", "9"; forward compressed as jk to SERVER

    I haven't seen any failed on sending side and multiplex on receiving side since making this change.


    I also came up with a new idea. If CRCs are pretty much random sort of speak. There is not really any consistency to how many of 10 images are going to go to each thread. I thought that since all images have an Instance Number (at least should have right) that using this way, you always distribute images evenly across 10 threads. Do you see any downside to this algorithm (last number in Instance Number string) or any case when an image would be left out and if so can I create a catch all thread for an image without a Instance Number NOT BETWEEN *0-*9?


    ForwardAssociationLevel = SERIES
    ForwardAssociationCloseDelay = 15
    ForwardAssociationRefreshDelay = 3600
    ForwardAssociationRelease = 0


    ExportConverters = 10
    ExportConverter0 = ifmatch "%V0020,0013", "*0"; forward compressed as jk to CONQUEST2
    ExportConverter1 = ifmatch "%V0020,0013", "*1"; forward compressed as jk to CONQUEST2
    ExportConverter2 = ifmatch "%V0020,0013", "*2"; forward compressed as jk to CONQUEST2
    ExportConverter3 = ifmatch "%V0020,0013", "*3"; forward compressed as jk to CONQUEST2
    ExportConverter4 = ifmatch "%V0020,0013", "*4"; forward compressed as jk to CONQUEST2
    ExportConverter5 = ifmatch "%V0020,0013", "*5"; forward compressed as jk to CONQUEST2
    ExportConverter6 = ifmatch "%V0020,0013", "*6"; forward compressed as jk to CONQUEST2
    ExportConverter7 = ifmatch "%V0020,0013", "*7"; forward compressed as jk to CONQUEST2
    ExportConverter8 = ifmatch "%V0020,0013", "*8"; forward compressed as jk to CONQUEST2
    ExportConverter9 = ifmatch "%V0020,0013", "*9"; forward compressed as jk to CONQUEST2

    Hi,


    the last digit of an UID may or may not distribute images evenly, dpeending on how the UIDs are made, while the CRC will get it even on average by definition.


    The 'client error' message indicates a malformed dicom request. Are you sure it comes from the sending conquest?


    In any case there is an issue with forwarders under high load. I have put it on the buglist.


    Marcel

    The only other connection to it is a Conquest Forwarder. It only happened once so far but the multiplex on receiver and failed to send and failed to connect on sending stopped after turning off the close association setting

    Hi,


    Can you estimate how often the error occurs (I am testing, so far not once in +/- 15000 images). And can you tell me something about your setup. I am forwarding from an 8-core I7 (latest build, mySQL) to a lowly AMD (latest build, SQlite), and get about 60% network use (but wildly varying). No errors so far with ForwardAssociationRelease = 1.


    Edit: the above test was with UN compression. I switched to JK and now get errors and even crashes ;->>>> Such as:


    20110419 22:29:48 ***Implicit_Parse encountered an invalid element length during load of DCM file (in 00000300)
    20110419 22:29:48 ***Length = 101057283


    and


    20110419 22:36:50 ***(Exp) Encountered an invalid group order during load of DCM file (after 64690100)
    20110419 22:36:50 ***Explicit_ParseRaw encountered an invalid element length during load of DCM file (in 524f4749)
    20110419 22:36:50 ***Length = 19521
    20110419 22:36:50 ***Continuing parsing
    20110419 22:36:50 ***VR:ReAlloc out of memory allocating -421075226 bytes


    With UN and N4 nothing seems to go wrong. Also J2 seems to behave well. Maybe JK is not fully thread safe....


    Marcel

    I am using JK on both forwarders. I've never seen this on a forwarder with multiple threads with UN either. It is basically two dual core conquest servers forwarding from 2 remote sites to a cloud conquest server. it kind of went away now that i turned release to 0 but occurred frequently before changing. No other errors like command failed FFFF either except the one and only time. I use the JK because it seems to be the highest ratio and didn't conflict with proprietary tags even though it takes a little longer to compress.


    using both rc6 and final latest build with 5.1 and 5.5 mysql. It seemed to happen when say the cloud box was receiving either multiple studies simultaneously from the same forwarder or from 2 forwarders at the same time. I think i was able reproduce by performing 2 cmoves to the forwarder and it started to happen. Could always have been a problem on receiving end with keeping up but I will try to collect for info.

    We moved cloud server to faster storage and haven't had the errors since. The disks were performing horribly under high load and I think when it couldn't handle it, it started to cause dicom communication errors and even a few SQL save issues. Hopefully it's gone. It's weird how the setting to 0 did help the issue at the time though.

    There's nothing left in the printer files folder...i don't know if these get cleaned nightly with interface running but they are all empty. today it has run flawless with forwardassociationrelease = 1 turned back on with jk after fixing disk slowness on receiving side. for whatever reason in my case. spreading images across 10 threads has been great and both the crc and image number method both work well. in my case it seems to distribute more equally with image number because they always end in 0-9 and usually are generated sequentially and match 10 threads where as my crc i was getting more of 1 or 2 values etc and that thread would end up with more images and have to run longer while other threads were free to send.... it's been fun trying to maximize throughput..


    it's very hard to make dicom saturate any more than 5-10Mb/s on Internet where there is a little latency with all the dicom association chatting going on. 700+ slices of CT in JK (100-200KB files) usually only takes 2-4 mins now which is great. It seems like multi threading on LAN conditions also speeds forwarding but in most cases probably isn't necessary.

    It's back.
    on receiving end
    20110422 11:11:04 *** multiplex: connection terminated
    20110422 11:11:07 *** multiplex: connection terminated
    20110422 11:11:13 *** multiplex: connection terminated
    20110422 11:11:15 *** multiplex: connection terminated
    20110422 11:11:18 *** multiplex: connection terminated
    20110422 11:11:21 *** multiplex: connection terminated
    20110422 11:11:24 *** multiplex: connection terminated
    20110422 11:11:27 *** multiplex: connection terminated
    20110422 11:11:30 *** multiplex: connection terminated
    20110422 11:11:33 *** multiplex: connection terminated



    on sending side...no tmp files in printer files etc.


    20110422 11:10:33 *** Queue: holding processing of file C:\dicomserver1416rc6\Data\P99142\1.2.840.113704.7.1.1.5888.1303484294.1_80488_000078_1303485021040c.dcm
    20110422 11:10:33 *** Queue: holding processing of file C:\dicomserver1416rc6\Data\P99142\1.2.840.113704.7.1.1.5888.1303484294.1_80488_000079_1303485021040d.dcm
    20110422 11:10:33 *** Queue: holding processing of file C:\dicomserver1416rc6\Data\P99142\1.2.840.113704.7.1.1.5888.1303484294.1_80488_000080_1303485021040e.dcm
    20110422 11:10:33 *** Queue: holding processing of file C:\dicomserver1416rc6\Data\P99142\1.2.840.113704.7.1.1.5888.1303484294.1_80488_000081_1303485021040f.dcm
    20110422 11:10:36 *** ExportConverter8.1: Forward failed to connect to host CONQUEST2
    20110422 11:10:42 *** ExportConverter8.1: Forward failed to connect to host CONQUEST2
    20110422 11:10:45 *** ExportConverter8.1: Forward failed to connect to host CONQUEST2
    20110422 11:10:48 *** ExportConverter8.1: Forward failed to connect to host CONQUEST2



    guess im going to turn back on forwardassociationrealease = 0 and see if it stays away long term.

    It sounds like it could be this. I did restart dicom server sometimes but didn't put frequency of it happening together with restarts. I will see if it stays away with this fix. With settings to 0 i still get a lot of command FFFFF errors and every few days a cannot save SQL for a few images. Thinking of trying j1 but hate to lose the extra compression ratio. I will try b update.

    Forwardassociationrelease = 1 enabled and no errors yet after patching both source and destination conquest servers with 1.4.16b executable. Sending conquest is 32-bit windows 7 pro and receiving is windows 2008 r2 64bit dgate. Keeping fingers crossed.


    I found one pitfall to my multi-thread export algorithm of exporting images. When an image for whatever reason does not have an ImageNumber it would not be exported. I had to add export line for null image number images. Forwarding by crc of image does not have this problem but seemed by luck of crc result to never be faster than by image number always 0-9 threads. I also put tcp/ip timeout back to 300 default instead of 60. not sure if that ever had any effect on errors. Hoping it was just a memory leak issue. I like the delete image export option to clean up database and file after being forwarded on. It seems to do this 10 minutes by default after being exported.


    # Configuration of forwarding and/or converter programs to export DICOM slices
    ForwardAssociationLevel = SERIES
    ForwardAssociationCloseDelay = 15
    ForwardAssociationRefreshDelay = 3600
    ForwardAssociationRelease = 1


    ExportConverters = 11
    ExportConverter0 = ifmatch "%V0020,0013", "*0"; forward compressed as jk to CONQUEST2; delete image;
    ExportConverter1 = ifmatch "%V0020,0013", "*1"; forward compressed as jk to CONQUEST2; delete image;
    ExportConverter2 = ifmatch "%V0020,0013", "*2"; forward compressed as jk to CONQUEST2; delete image;
    ExportConverter3 = ifmatch "%V0020,0013", "*3"; forward compressed as jk to CONQUEST2; delete image;
    ExportConverter4 = ifmatch "%V0020,0013", "*4"; forward compressed as jk to CONQUEST2; delete image;
    ExportConverter5 = ifmatch "%V0020,0013", "*5"; forward compressed as jk to CONQUEST2; delete image;
    ExportConverter6 = ifmatch "%V0020,0013", "*6"; forward compressed as jk to CONQUEST2; delete image;
    ExportConverter7 = ifmatch "%V0020,0013", "*7"; forward compressed as jk to CONQUEST2; delete image;
    ExportConverter8 = ifmatch "%V0020,0013", "*8"; forward compressed as jk to CONQUEST2; delete image;
    ExportConverter9 = ifmatch "%V0020,0013", "*9"; forward compressed as jk to CONQUEST2; delete image;
    ExportConverter10 = ifmatch "%V0020,0013", ""; forward compressed as jk to CONQUEST2; delete image;


    MaximumExportRetries = 0

    Problems went away hopefully forever.


    If you are running Windows XP unlike 2003/2008/7 where most likely the maxuserport settings are different and do not exhibit this problem, make sure to use this registry setting because I can see many many connections to mysql when receiving/forwarding at high rates ie netstat -an and this probably caused errors.


    viewtopic.php?f=33&t=786#p2450

    This comes and goes and maybe it's study content related. I thought it was gone. I even tried using dbaseIII to eliminate possibility of mysql related problems. I tried extending ForwardAssociationCloseDelay = 30 and changing to IMAGE association level all with no luck.


    I turned debugging up all the way during the errors on receiving end. Does this make any sense? It doesn't in the end fail to forward any images after reconnecting etc. It seems to always say similar info during the multiplex error. This is log from receiving end of forwarder. When multiplex happens it then created failed to connect failed to forward errors on sending side.




    [CONQUEST1] 20110516 13:53:29 Server Command := 0001
    [CONQUEST1] 20110516 13:53:29 Message ID := 76b1
    [CONQUEST1] 20110516 13:53:29 0000,0002 26 UI AffectedSOPClassUID "1.2.840.10008.5.1.4.1.1.2"
    [CONQUEST1] 20110516 13:53:29 0000,0100 2 US CommandField 1
    [CONQUEST1] 20110516 13:53:29 0000,0110 2 US MessageID 30385
    [CONQUEST1] 20110516 13:53:29 0000,0700 2 US Priority 0
    [CONQUEST1] 20110516 13:53:29 0000,0800 2 US DataSetType 258
    [CONQUEST1] 20110516 13:53:29 0000,1000 40 UI AffectedSOPInstanceU "1.2.840.113704.7.1.1.4504.1305559565.221"
    [CONQUEST1] 20110516 13:53:29 0002,0010 22 UI TransferSyntaxUID "1.2.840.10008.1.2.4.90"
    [CONQUEST1] 20110516 13:53:29 Connected by address: 0c094b0a
    [CONQUEST1] 20110516 13:53:30 Testing transfer: '1.2.840.10008.1.2.4.90' against list #0 = '1.2.840.10008.1.2'
    [CONQUEST1] 20110516 13:53:30 Testing transfer: '1.2.840.10008.1.2.4.90' against list #1 = '1.2.840.10008.1.2.1'
    [CONQUEST1] 20110516 13:53:30 Testing transfer: '1.2.840.10008.1.2.4.90' against list #2 = '1.2.840.10008.1.2.4.50'
    [CONQUEST1] 20110516 13:53:30 Testing transfer: '1.2.840.10008.1.2.4.90' against list #3 = '1.2.840.10008.1.2.4.51'
    [CONQUEST1] 20110516 13:53:30 Testing transfer: '1.2.840.10008.1.2.4.90' against list #4 = '1.2.840.10008.1.2.4.53'
    [CONQUEST1] 20110516 13:53:30 Testing transfer: '1.2.840.10008.1.2.4.90' against list #5 = '1.2.840.10008.1.2.4.55'
    [CONQUEST1] 20110516 13:53:30 Testing transfer: '1.2.840.10008.1.2.4.90' against list #6 = '1.2.840.10008.1.2.4.57'
    [CONQUEST1] 20110516 13:53:30 Testing transfer: '1.2.840.10008.1.2.4.90' against list #7 = '1.2.840.10008.1.2.4.70'
    [CONQUEST1] 20110516 13:53:30 Testing transfer: '1.2.840.10008.1.2.4.90' against list #8 = '1.2.840.10008.1.2.4.90'
    [CONQUEST1] 20110516 13:53:30 Testing transfer: '1.2.840.10008.1.2.4.90' against list #0 = '1.2.840.10008.1.2'
    [CONQUEST1] 20110516 13:53:30 Testing transfer: '1.2.840.10008.1.2.4.90' against list #1 = '1.2.840.10008.1.2.1'
    [CONQUEST1] 20110516 13:53:30 Testing transfer: '1.2.840.10008.1.2.4.90' against list #2 = '1.2.840.10008.1.2.4.50'
    [CONQUEST1] 20110516 13:53:30 Testing transfer: '1.2.840.10008.1.2.4.90' against list #3 = '1.2.840.10008.1.2.4.51'
    [CONQUEST1] 20110516 13:53:30 Testing transfer: '1.2.840.10008.1.2.4.90' against list #4 = '1.2.840.10008.1.2.4.53'
    [CONQUEST1] 20110516 13:53:30 Testing transfer: '1.2.840.10008.1.2.4.90' against list #5 = '1.2.840.10008.1.2.4.55'
    [CONQUEST1] 20110516 13:53:30 Testing transfer: '1.2.840.10008.1.2.4.90' against list #6 = '1.2.840.10008.1.2.4.57'
    [CONQUEST1] 20110516 13:53:30 Testing transfer: '1.2.840.10008.1.2.4.90' against list #7 = '1.2.840.10008.1.2.4.70'
    [CONQUEST1] 20110516 13:53:30 Testing transfer: '1.2.840.10008.1.2.4.90' against list #8 = '1.2.840.10008.1.2.4.90'
    [CONQUEST1] 20110516 13:53:30 Connected by address: 0c094b0a
    [CONQUEST1] 20110516 13:53:30 No valid presentation contexts found
    [CONQUEST1] 20110516 13:53:30 InterogateAAssociateRQ failed
    [CONQUEST1] 20110516 13:53:30 *** multiplex: connection terminated
    [CONQUEST1] 20110516 13:53:30




    [CONQUEST1] 20110516 13:53:14 Server Command := 0001
    [CONQUEST1] 20110516 13:53:14 Message ID := 6a5b
    [CONQUEST1] 20110516 13:53:14 0000,0002 26 UI AffectedSOPClassUID "1.2.840.10008.5.1.4.1.1.2"
    [CONQUEST1] 20110516 13:53:14 0000,0100 2 US CommandField 1
    [CONQUEST1] 20110516 13:53:14 0000,0110 2 US MessageID 27227
    [CONQUEST1] 20110516 13:53:14 0000,0700 2 US Priority 0
    [CONQUEST1] 20110516 13:53:14 0000,0800 2 US DataSetType 258
    [CONQUEST1] 20110516 13:53:14 0000,1000 42 UI AffectedSOPInstanceU "1.2.840.113704.1.111.2492.1305559142.4244"
    [CONQUEST1] 20110516 13:53:14 0002,0010 22 UI TransferSyntaxUID "1.2.840.10008.1.2.4.90"
    [CONQUEST1] 20110516 13:53:15 Query Tables: DICOMImages
    [CONQUEST1] 20110516 13:53:15 Columns : ObjectFile, DeviceName
    [CONQUEST1] 20110516 13:53:15 Where : SOPInstanc = '1.2.840.113704.1.111.2492.1305559159.4292' AND ImagePat = '123456'
    [CONQUEST1] 20110516 13:53:15 Order : (null)
    [CONQUEST1] 20110516 13:53:15 FreeStore Left 94727 on C:\
    [CONQUEST1] 20110516 13:53:15 Add to Table: DICOMImages
    [CONQUEST1] 20110516 13:53:15 Columns: SOPInstanc, SOPClassUI, ImageNumbe, ImageDate, ImageTime, AcqDate, AcqTime, SliceLocat, SamplesPer, PhotoMetri, Rows, Colums, BitsStored, ImageType, ImagePat, SeriesInst, AccessTime, ObjectFile, DeviceName
    [CONQUEST1] 20110516 13:53:15 Values: '1.2.840.113704.1.111.2492.1305559159.4292', '1.2.840.10008.5.1.4.1.1.2', '90', '20110516', '111836.556000', '20110516', '111821', '450.50', '1', 'MONOCHROME2', '512', '512', '12', 'ORIGINAL\\PRIMARY\\AXIAL\\HELIX', '123456', '1.2.840.113704.1.111.2616.1305559019.14', 1305568384, '123456\\1.2.840.113704.1.111.2616.1305559019.14_0003_000090_13055683952159.dcm', 'MAG0'
    [CONQUEST1] 20110516 13:53:15 Written file: C:\CONQUEST1\Data\123456\1.2.840.113704.1.111.2616.1305559019.14_0003_000090_13055683952159.dcm
    [CONQUEST1] 20110516 13:53:15 ExportConverter0.1: forward C:\CONQUEST1\Data\123456\1.2.840.113704.1.111.2616.1305559019.14_0003_000090_13055683952159.dcm to CONQUEST2
    [CONQUEST1] 20110516 13:53:15 Accepted compression: jk
    [CONQUEST1] 20110516 13:53:15 UPACS THREAD 6320: ENDED AT: Mon May 16 13:53:15 2011
    [CONQUEST1] 20110516 13:53:15 UPACS THREAD 6320: TOTAL RUNNING TIME: 48 SECONDS
    [CONQUEST1] 20110516 13:53:15 Exportconverter9.0 executes: ifmatch "90", "*9"
    [CONQUEST1] 20110516 13:53:15 Exportconverter9.1 not executed because of previous statement
    [CONQUEST1] 20110516 13:53:15 Exportconverter6.0 executes: ifmatch "90", "*6"
    [CONQUEST1] 20110516 13:53:15 Exportconverter6.1 not executed because of previous statement
    [CONQUEST1] 20110516 13:53:16 Query Tables: DICOMImages
    [CONQUEST1] 20110516 13:53:16 Columns : ObjectFile, DeviceName
    [CONQUEST1] 20110516 13:53:16 Where : SOPInstanc = '1.2.840.113704.1.111.2492.1305559157.4285' AND ImagePat = '123456'
    [CONQUEST1] 20110516 13:53:16 Order : (null)
    [CONQUEST1] 20110516 13:53:16 Connected by address: 0c094b0a
    [CONQUEST1] 20110516 13:53:16 FreeStore Left 94727 on C:\
    [CONQUEST1] 20110516 13:53:16 Add to Table: DICOMImages
    [CONQUEST1] 20110516 13:53:16 Columns: SOPInstanc, SOPClassUI, ImageNumbe, ImageDate, ImageTime, AcqDate, AcqTime, SliceLocat, SamplesPer, PhotoMetri, Rows, Colums, BitsStored, ImageType, ImagePat, SeriesInst, AccessTime, ObjectFile, DeviceName
    [CONQUEST1] 20110516 13:53:16 Values: '1.2.840.113704.1.111.2492.1305559157.4285', '1.2.840.10008.5.1.4.1.1.2', '83', '20110516', '111835.389000', '20110516', '111821', '415.50', '1', 'MONOCHROME2', '512', '512', '12', 'ORIGINAL\\PRIMARY\\AXIAL\\HELIX', '123456', '1.2.840.113704.1.111.2616.1305559019.14', 1305568384, '123456\\1.2.840.113704.1.111.2616.1305559019.14_0003_000083_1305568396215a.dcm', 'MAG0'
    [CONQUEST1] 20110516 13:53:16 No valid presentation contexts found
    [CONQUEST1] 20110516 13:53:16 InterogateAAssociateRQ failed
    [CONQUEST1] 20110516 13:53:16 *** multiplex: connection terminated
    [CONQUEST1] 20110516 13:53:16 Written file: C:\CONQUEST1\Data\123456\1.2.840.113704.1.111.2616.1305559019.14_0003_000083_1305568396215a.dcm
    [CONQUEST1] 20110516 13:53:16 ExportConverter3.1: forward C:\CONQUEST1\Data\123456\1.2.840.113704.1.111.2616.1305559019.14_0003_000083_1305568396215a.dcm to CONQUEST2
    [CONQUEST1] 20110516 13:53:16 Accepted compression: jk

    even if i restart 1 end or both ends. the next time i push the same study the same exact way it happens. the only way it seems to go through is by retry timeouts and the tcp/ip timeout expiring for that thread. It's very strange. It's only happening from Windows XP 32bit sending to Windows 2008 R2 64bit. I have a 32bit windows 7 pro sending to same 2008 box just fine and faster without errors. Maybe it's something in the studies itself but errors don't really say anything.

Participate now!

Don’t have an account yet? Register yourself now and be a part of our community!

Register Yourself Login