search

ControlSystemStudio / cs-studio

Control System Studio is an Eclipse-based collections of tools to monitor and operate large scale control systems, such as the ones in the accelerator community.
https://controlsystemstudio.org/
Eclipse Public License 1.0
113 stars 96 forks source link

Strange PVManager error #2047

Open berryma4 opened 7 years ago

berryma4 commented 7 years ago

I keep getting this error from a BOY screen that uses this pv in a text input I'm not sure why only this pv.

2017-01-19 10:34:48 ERROR: Error from pv connection layer: 
java.lang.IllegalStateException: ConnectionCollector for 'REA_BTS19:RFC_D0983:ON_RSTS_RF' was closed.

If I remove the text input, there is no error. If I paste the text input with this pv into a new BOY screen, there is no error. If I paste the text input back with this pv, there is the same error again.

shroffk commented 7 years ago

Do you see this error with vtype.pv?

berryma4 commented 7 years ago

No, the error comes from pvmanager.

kasemir commented 7 years ago

The exception is caught by BOYPVFactory#exceptionHandler:

    private final static ExceptionHandler exceptionHandler = new ExceptionHandler() {
        @Override
        public void handleException(Exception ex) {
            ErrorHandlerUtil.handleError("Error from pv connection layer: ", ex);
        }
    };

That ErrorHandlerUtil then passes it on to a dialog etc., but also includes a plain java.util.logging log(WARNING, message, exception), so the console output should show the complete stack trace.

You already tested that the text input itself, used in another display, doesn't cause the problem.

Vague guess: Does the affected display use that same PV for 'write' actions? Usually, the BOY code connects to all PVs when a display is opened, and closes all when the display is closed. But for write actions, I remember some odd code that would create the PV when first touched. Maybe there's a life-cycle problem with such PVs.

berryma4 commented 7 years ago

Sorry I meant "java.lang.IllegalStateException: ConnectionCollector" comes from pvmanager.

berryma4 commented 7 years ago

What's strange is the point I can remove the text input, then there is no error. Then, if I add it back, there is an error. If I make a new screen with the text input, no error. This might sound like your "write" issue because it's a text input. I will use a ro widget and see if the same behavior.

kasemir commented 7 years ago

Right, the exception originates in the pvmanager. It's unclear if this is an internal error in the pvmanager, or if the BOY lifecycle of creating and closing the PVManager.reader/writer causes the error. For the vtype.pv implementation, I noticed that BOY doesn't always close those PVs that were created on the fly for write actions. Maybe now we have a case of closing them too early or too often.

berryma4 commented 7 years ago

Yes, it still happens with a "text update".

berryma4 commented 7 years ago

I'm not sure why only this PV as opposed to all the others on the page. It seem to really dislike this particular PV name.

kasemir commented 7 years ago

What's the full exception? Is that PV used in any other way in the same display? Grep for the PV name in the *.opi file.

shroffk commented 7 years ago

What kind of pv is this, what is the return/write type expected

berryma4 commented 7 years ago

I removed all instances of it, except the text update. Previously, it was used in a script too. So, no error without text update, error when pasted back. It's a VEnum.

CA Channel name = REA_BTS19:RFC_D0983:ON_RSTS_RF
CA Channel type = DBR_ENUM
CA Connection state = CONNECTED
CA Element count = 1
CA Hostname = xxx.xxx.xxx.xxx
CA Read access = true
CA Write access = true
Connected = true
Connection payload = JCAConnection [connected: true writeConnected: true channel: CAJChannel = { name = REA_BTS19:RFC_D0983:ON_RSTS_RF, connectionState = CONNECTED }]
Last message payload = Metadata gov.aps.jca.dbr.DBR_LABELS_Enum@6565f3 value gov.aps.jca.dbr.DBR_TIME_Enum@891f18f
Write Connected = true
isLongString = false
isPutCallback = false
berryma4 commented 7 years ago

Okay someone else has the same error. A lot of these are Enums, but not all.

2017-01-12 18:39:01 ERROR: Error from pv connection layer: 
java.lang.IllegalStateException: ConnectionCollector for 'REA_EBIT1:TEE_N0006:V_CSET' was closed.
2017-01-12 18:39:01 ERROR: Error from pv connection layer: 
java.lang.IllegalStateException: ConnectionCollector for 'REA_EBIT1:TEE_N0001:V_CSET' was closed.
2017-01-12 18:39:01 ERROR: Error from pv connection layer: 
java.lang.IllegalStateException: ConnectionCollector for 'REA_EBIT1:TEO_N0000:V_CSET' was closed.
2017-01-12 18:39:01 ERROR: Error from pv connection layer: 
java.lang.IllegalStateException: ConnectionCollector for 'REA_EBIT1:TEC_N0002:V_CSET' was closed.
2017-01-12 18:39:01 ERROR: Error from pv connection layer: 
java.lang.IllegalStateException: ConnectionCollector for 'REA_EBIT1:PSELI_D0858:V_CSET' was closed.
2017-01-13 18:10:08 ERROR: Error from pv connection layer: 
java.lang.IllegalStateException: ConnectionCollector for 'REA_EBIT1:PSOL_D0831:I_CSET' was closed.
2017-01-16 19:22:11 ERROR: Error from pv connection layer: 
java.lang.IllegalStateException: ConnectionCollector for 'REA_EBIT1:PSOL_D0832:I_CSET' was closed.
2017-01-16 19:22:11 ERROR: Error from pv connection layer: 
java.lang.IllegalStateException: ConnectionCollector for 'REA_EBIT1:PSOL_D0833:I_CSET' was closed.
2017-01-16 19:22:27 ERROR: Error from pv connection layer: 
java.lang.IllegalStateException: ConnectionCollector for 'REA_EBIT1:TECE_N0011:V_CSET' was closed.
2017-01-16 19:22:27 ERROR: Error from pv connection layer: 
java.lang.IllegalStateException: ConnectionCollector for 'REA_EBIT1:TEC_N0010:V_CSET' was closed.
2017-01-17 13:07:15 ERROR: Error from pv connection layer: 
java.lang.IllegalStateException: ConnectionCollector for 'REA_EBIT1:BEAM:PER_CO.PROC' was closed.
2017-01-17 13:07:48 ERROR: Error from pv connection layer: 
java.lang.IllegalStateException: ConnectionCollector for 'REA_EBIT1:BEAM:PER_CO.PROC' was closed.
2017-01-17 13:12:22 ERROR: Error from pv connection layer: 
java.lang.IllegalStateException: ConnectionCollector for 'REA_EBIT1:BEAM:PER_CO.PROC' was closed.
2017-01-17 13:12:55 ERROR: Error from pv connection layer: 
java.lang.IllegalStateException: ConnectionCollector for 'REA_EBIT1:BEAM:PER_CO.PROC' was closed.
2017-01-17 14:58:25 ERROR: Error from pv connection layer: 
java.lang.IllegalStateException: ConnectionCollector for 'REA_EBIT1:BEAM:PER_CO.PROC' was closed.
2017-01-17 14:58:41 ERROR: Error from pv connection layer: 
java.lang.IllegalStateException: ConnectionCollector for 'REA_EBIT1:BEAM:PER_CO.PROC' was closed.
2017-01-17 19:13:17 ERROR: Error from pv connection layer: 
java.lang.IllegalStateException: ConnectionCollector for 'REA_EBIT1:HVP_N0001:V_CSET' was closed.
2017-01-17 19:13:17 ERROR: Error from pv connection layer: 
java.lang.IllegalStateException: ConnectionCollector for 'REA_EBIT1:PSOL_D0831:I_CSET' was closed.
2017-01-17 19:13:17 ERROR: Error from pv connection layer: 
java.lang.IllegalStateException: ConnectionCollector for 'REA_EBIT1:PSOL_D0832:I_CSET' was closed.
2017-01-18 18:50:34 ERROR: Error from pv connection layer: 
java.lang.IllegalStateException: ConnectionCollector for 'REA_EBIT1:PSOL_D0831:I_CSET' was closed.
2017-01-19 10:39:29 ERROR: Error from pv connection layer: 
java.lang.IllegalStateException: ConnectionCollector for 'REA_EBIT1:TEE_N0004:V_CSET' was closed.
2017-01-19 10:39:29 ERROR: Error from pv connection layer: 
java.lang.IllegalStateException: ConnectionCollector for 'REA_EBIT1:TEE_N0001:V_CSET' was closed.
2017-01-19 10:40:38 ERROR: Error from pv connection layer: 
java.lang.IllegalStateException: ConnectionCollector for 'REA_EBIT1:TEE_N0006:ON_CMD' was closed.
2017-01-19 10:40:38 ERROR: Error from pv connection layer: 
java.lang.IllegalStateException: ConnectionCollector for 'REA_EBIT1:TEE_N0004:ON_CMD' was closed.
2017-01-19 10:40:38 ERROR: Error from pv connection layer: 
java.lang.IllegalStateException: ConnectionCollector for 'REA_EBIT1:TEE_N0005:ON_CMD' was closed.
2017-01-19 10:42:40 ERROR: Error from pv connection layer: 
java.lang.IllegalStateException: ConnectionCollector for 'REA_EBIT1:TECB_N0011:ON_CMD' was closed.
2017-01-19 10:42:40 ERROR: Error from pv connection layer: 
java.lang.IllegalStateException: ConnectionCollector for 'REA_EBIT1:TECE_N0011:ON_CMD' was closed.
2017-01-19 10:42:40 ERROR: Error from pv connection layer: 
java.lang.IllegalStateException: ConnectionCollector for 'REA_EBIT1:TEC_N0010:ON_CMD' was closed.
2017-01-19 10:42:40 ERROR: Error from pv connection layer: 
java.lang.IllegalStateException: ConnectionCollector for 'REA_EBIT1:TEC_N0012:ON_CMD' was closed.
2017-01-19 10:42:40 ERROR: Error from pv connection layer: 
java.lang.IllegalStateException: ConnectionCollector for 'REA_EBIT1:DCHE_D0855:ON_CMD' was closed.
2017-01-19 10:43:20 ERROR: Error from pv connection layer: 
java.lang.IllegalStateException: ConnectionCollector for 'REA_EBIT1:TEE_N0004:ON_CMD' was closed.
2017-01-19 10:43:20 ERROR: Error from pv connection layer: 
java.lang.IllegalStateException: ConnectionCollector for 'REA_EBIT1:TEE_N0006:ON_CMD' was closed.
2017-01-19 10:43:20 ERROR: Error from pv connection layer: 
java.lang.IllegalStateException: ConnectionCollector for 'REA_EBIT1:TEE_N0001:ON_CMD' was closed.
2017-01-19 10:43:20 ERROR: Error from pv connection layer: 
java.lang.IllegalStateException: ConnectionCollector for 'REA_EBIT1:TEO_N0000:ON_CMD' was closed.
2017-01-19 11:21:41 ERROR: Error from pv connection layer: 
java.lang.IllegalStateException: ConnectionCollector for 'REA_EBIT1:HVP_N0001:V_CSET' was closed.
2017-01-19 11:21:41 ERROR: Error from pv connection layer: 
java.lang.IllegalStateException: ConnectionCollector for 'REA_EBIT1:PSCA_D0834:V_CSET' was closed.
2017-01-19 11:53:18 ERROR: The file  does not exist.
2017-01-19 11:57:10 ERROR: Error from pv connection layer: 
java.lang.IllegalStateException: ConnectionCollector for 'REA_EBIT1:TEE_N0006:ON_CMD' was closed.
2017-01-19 11:57:10 ERROR: Error from pv connection layer: 
java.lang.IllegalStateException: ConnectionCollector for 'REA_EBIT1:TEE_N0005:ON_CMD' was closed.
2017-01-19 12:24:53 ERROR: Error from pv connection layer: 
java.lang.IllegalStateException: ConnectionCollector for 'REA_EBIT1:PSEL2_D0853:V_CSET' was closed.
2017-01-19 12:24:53 ERROR: Error from pv connection layer: 
java.lang.IllegalStateException: ConnectionCollector for 'REA_EBIT1:PSOL_D0854:I_CSET' was closed.
2017-01-19 12:24:53 ERROR: Error from pv connection layer: 
java.lang.IllegalStateException: ConnectionCollector for 'REA_EBIT1:PSEL_D0854:V_CSET' was closed.
kasemir commented 7 years ago

If you get the error with a *.opi that has just that one text input, does the CSS instance still have something else open for that PV, so the PVManager has multiple uses for that data sources?

Maybe the complete stack trace helps. BOYPVFactory.exceptionHandler() calls ErrorHandlerUtil.handleError():

    public static void handleError(final String message,
            final Throwable exception, final boolean writeToConsole, final boolean popErrorDialog){
        OPIBuilderPlugin.getLogger().log(Level.WARNING,
            message, exception); //$NON-NLS-1$
        if(writeToConsole)
            ConsoleService.getInstance().writeError(message + "\n" + exception);

Looks like you copied the console, where we just see "ERROR: .." and the exception message. In the java util log you see a WARNING and then the full stack trace. Run CSS with -consoleLog to see that full log.

berryma4 commented 7 years ago

I can get the error in the debugger. This is what throws the exception: org.diirt.datasource.DataSource.java ln 182:

@Override
            public void run() {
                for (Map.Entry<ChannelHandler, Collection<ChannelReadRecipe>> entry : handlersWithSubscriptions.entrySet()) {
                    ChannelHandler channelHandler = entry.getKey();
                    Collection<ChannelReadRecipe> channelRecipes = entry.getValue();
                    for (ChannelReadRecipe channelRecipe : channelRecipes) {
                        try {
                            channelHandler.addReader(channelRecipe.getReadSubscription());
                        } catch(Exception ex) {
                            // If an error happens while adding the read subscription,
                            // notify the appropriate handler
                            channelRecipe.getReadSubscription().getExceptionWriteFunction().writeValue(ex);
                        }
                    }
                }
            }
berryma4 commented 7 years ago

Although, there is no stack trace, it just has: java.lang.IllegalStateException: ConnectionCollector for 'REA_BTS19:RFC_D0983:ON_RSTS_RF' was closed.

berryma4 commented 7 years ago

It must be a timing thing. If I step through the channelHandler.addReader above, I don't get the error.

shroffk commented 7 years ago

In the debugger was there any reference to calls from the pvmanagerPV class.

berryma4 commented 7 years ago

yes. that's what was calling it.

shroffk commented 7 years ago

What I was trying to ascertain from the previous inquiry was some details of the call from the pvmanagerPV that is giving you the error. i.e. the pvmanagerPV.start(), pvmanagerPV.isConnected(),...

I am trying to reproduce it with many enum read/write widgets, but not having much luck.

kasemir commented 7 years ago

I don't understand why the console (the real console of the process, not the console window) has no full stack trace. It must be calling OPIBuilderPlugin.getLogger().log(Level.WARNING, message, exception);

shroffk commented 7 years ago

Looking into diirt, I see that this exception message originates when a writeValue() is called. Should launching this page be triggering a write to the pv?

berryma4 commented 7 years ago

Putting a breakpoint at te BOYPVFactory line 29:

Daemon Thread [PVMgr JCADataSource Worker 1] (Suspended (breakpoint at line 29 in BOYPVFactory$1))  
    BOYPVFactory$1.handleException(Exception) line: 29  
    PVManagerPV$ExHandler.handleException(Exception) line: 60   
    ExceptionHandler$1.handleException(Exception) line: 37  
    LastExceptionCollector.writeValue(Exception) line: 24   
    LastExceptionCollector.writeValue(Object) line: 1   
    DataSource$1.run() line: 182    
    ThreadPoolExecutor.runWorker(ThreadPoolExecutor$Worker) line: not available 
    ThreadPoolExecutor$Worker.run() line: not available 
    Thread.run() line: not available

Breaking on the exception:

Daemon Thread [PVMgr JCADataSource Worker 1] (Suspended (exception IllegalStateException))  
    owns: Object  (id=416)  
    owns: JCAChannelHandler  (id=179)   
    ConnectionCollector$ConnectionWriteFunction.writeValue(Boolean) line: 45    
    ConnectionCollector$ConnectionWriteFunction.writeValue(Object) line: 1  
    MultiplexedChannelHandler$MonitorHandler.processConnection(boolean) line: 67    
    JCAChannelHandler(MultiplexedChannelHandler<ConnectionPayload,MessagePayload>).addReader(ChannelHandlerReadSubscription) line: 250  
    DataSource$1.run() line: 178    
    ThreadPoolExecutor.runWorker(ThreadPoolExecutor$Worker) line: not available 
    ThreadPoolExecutor$Worker.run() line: not available 
    Thread.run() line: not available

So, yes, it looks like it is doing a write?

berryma4 commented 7 years ago

The throw is probably because the ConnectionWriteFunction close is called, but why the write boolean?

berryma4 commented 7 years ago

Never mind, it's not writing, it's just saying it's connected.

berryma4 commented 7 years ago

The problem is here:

Thread [pool-4-thread-1] (Suspended (entry into method removeChannel in ConnectionCollector))   
    owns: Object  (id=1470) 
    owns: Object  (id=1471) 
    ConnectionCollector.removeChannel(String) line: 130 
    PVDirector<T>.disconnectReadExpression(DesiredRateExpression<?>) line: 181  
    PVDirector<T>.disconnect() line: 204    
    PVDirector<T>.close() line: 194 
    PVReaderImpl<T>.close() line: 241   
    PVManagerPV.stop() line: 390    
    PVManagerPV$6.run() line: 384   
    ThreadPoolExecutor.runWorker(ThreadPoolExecutor$Worker) line: not available 
    ThreadPoolExecutor$Worker.run() line: not available 
    Thread.run() line: not available

PVManagerPV calls stop -> close -> removeChannel -> ConnectionWriteFunction.writeValue -> isClosed -> throw.

Why does PVManagerPV close the write connection on startup?

berryma4 commented 7 years ago

Right here stops the PV : org.csstudio.opibuilder.editparts.PVWidgetEditpartDelegate.registerBasePropertyChangeHandlers().PVNamePropertyChangeHandler.handleChange(Object, Object, IFigure) oldPV.stop() line: 428 

       class PVNamePropertyChangeHandler implements IWidgetPropertyChangeHandler{
            private String pvNamePropID;
            public PVNamePropertyChangeHandler(String pvNamePropID) {
                this.pvNamePropID = pvNamePropID;
            }
            @Override
            public boolean handleChange(Object oldValue, Object newValue,
                    IFigure figure) {
                IPV oldPV = pvMap.get(pvNamePropID);
                editpart.removeFromConnectionHandler((String)oldValue);
                if(oldPV != null){
                    oldPV.stop();
                    oldPV.removeListener(pvListenerMap.get(pvNamePropID));
                }
kasemir commented 7 years ago

Is it a bogus notification where the old and new PV name are the same?

berryma4 commented 7 years ago

oldValue="" newValue="REA_BTS19:RFC_D0983:ON_RSTS_RF" Sorry, I'm trying to follow the logic of this "handleChange" function.

kasemir commented 7 years ago

Just guessing: The widget is started, connects to the PV etc. Meanwhile, to allow changing the PV name at runtime, there's a listener for the pv_name property. It closes the old PV, connects to the new PV. Problem is that this handler seems to run right away, and with a bad oldValue. Maybe it was triggered by some code change to support macros etc, forcing a re-evaluation of all properties?

berryma4 commented 7 years ago

So the function is using pvMap.get{"pv_name") to get the old PV value to disconnect. In which the handleChange(oldValue="",newValue="REA_BTS19:RFC_D0983:ON_RSTS_RF") Why have this extra holder of the old value (pvMap)?

berryma4 commented 7 years ago

It looks like the oldValue and pvMap are out of sync. ("" is the oldValue)

berryma4 commented 7 years ago

This is really odd. Why doesn't is just disconnect the old value, connect the new value? Why the extra pvMap?

berryma4 commented 7 years ago

Back at it .... I found a macro that becomes my PV in a rule. So there is a PV in a Rule, and a Text Update.

Okay I get it.

org.csstudio.opibuilder.editparts.AbstractBaseEditPart.activate() line 184 gets pvs from Rules. then BOYPVFactory.createPV(pvName, false, 2); at line 195 When doActivate() gets called line 239, org.csstudio.opibuilder.editparts.PVWidgetEditpartDelegate.registerBasePropertyChangeHandlers().PVNamePropertyChangeHandler.handleChange(Object, Object, IFigure) is trigger before the PV is started. So it enters line: 428, but it can't close. If you, of course, put a sleep after the Rules PV create: IPV pv = BOYPVFactory.createPV(pvName, false, 2); TimeUnit.MICROSECONDS.sleep(500); at org.csstudio.opibuilder.editparts.AbstractBaseEditPart.activate() line 196 you don't get the error.

So, the pvMap, oldPV has to do with scripts. Although, I'm not sure why the clean up here? Is this how Rules tied to widgets are closed?

Anyway, what to do.

Simple answer might be to go home for the day.

I should mention, Kay you seem right on with your comment: https://github.com/ControlSystemStudio/cs-studio/issues/2047#issuecomment-274869663

spreiter commented 6 years ago

I just observed the same error on CSS 4.4.2 after using a buttons that is supposed to write 10 PVs. Similar buttons did not show this so far. Not rules on the button applied. Everything is fixed from the beginning in the OPI.