dnp3-slave startup issue, regression?

[Adam Todorski]

I have encountered a problem with dnp3-slave endpoints in Reef not starting up when reef is restarted after updating to Reef 0.4.7 and I am wondering if I have it misconfigured or if this is a bug.  This all worked fine under 0.4.0.

Here's what happens:
I define an endpoint using the dnp3-slave protocol:

....
    <cm:endpoint name="ENDPOINT" >
            <cm:protocol name="dnp3-slave">
                <common:configFile fileName="ENDPOINT.xml" />
            </cm:protocol>
            <cm:interface name="DNPIn" ip="10.0.0.2" netmask="255.255.255.0" port="9002" network="any" serverSocket="true"/>
           
            <cm:equipment name="SiteProfile">

                <cm:equipment name="EquipmentProfile">
               
                    <cm:analog name="A" index="0" unit="kW" />               
                    <cm:analog name="B" index="1" unit="kW" />                                       
                    <cm:analog name="C" index="2" unit="kW"/>     
                   
                    <!-- set by counterparty -->
                    <cm:setpoint name="A" index="0" unit="kW" />
                    <cm:setpoint name="B" index="1" unit="kW" />
                    <cm:setpoint name="C" index="2" unit="kW" />
                   
                </cm:equipment>

            </cm:equipment>
        </cm:endpoint>
....

Where ENDPOINT.xml contains:

<?xml version="1.0" encoding="UTF-8" standalone="yes"?>
<Slave xmlns:psi="org.psi.xml" xmlns="org.psi.xml.dnp3">
    <Stack>
        <LinkLayer NumRetries="3" AckTimeoutMS="1000" UseConfirmations="false" RemoteAddress="100" LocalAddress="1" IsMaster="false"/>
        <AppLayer NumRetries="0" MaxFragSize="2048" TimeoutMS="5000"/>
    </Stack>
    <psi:Log Filter="LOG_WARNING"/>
    <SlaveConfig OpenLayerDelay="1000" MaxCounterEvents="100" MaxAnalogEvents="100" MaxBinaryEvents="100">
        <TimeIINTask PeriodMS="60000" DoTask="true"/>
        <UnsolDefaults RetryMS="5000" PackDelayMS="50" DoClass3="true" DoClass2="true" DoClass1="true"/>
    </SlaveConfig>
</Slave>

Starting with a new database, Reef loads my config without issue and starts listening for connections on TCP port 9002.  If I restart Reef it will not start listening for connections as I had configured it to do.  When it does come up everything seems to work and I can also manually publish readings to the endpoint using the API.  When it does not come up there is no apparent indication in the log that something is wrong other than the following error when I try to manually publish a reading:

org.totalgrid.reef.client.exception.BadRequestException: No measurement stream assignment for endpoint: <endpoint name>
    at org.totalgrid.reef.services.core.MeasurementBatchService.org$totalgrid$reef$services$core$MeasurementBatchService$$convertEndpointToDestination(MeasurementBatchService.scala:92)[82:org.totalgrid.reef.services:0.4.7]
    at org.totalgrid.reef.services.core.MeasurementBatchService$$anonfun$1.apply(MeasurementBatchService.scala:72)[82:org.totalgrid.reef.services:0.4.7]
    at org.totalgrid.reef.services.core.MeasurementBatchService$$anonfun$1.apply(MeasurementBatchService.scala:44)[82:org.totalgrid.reef.services:0.4.7]
    at org.totalgrid.reef.services.metrics.DatabaseActionsCounter$$anonfun$transaction$1.apply(DatabaseActionsCounter.scala:31)[82:org.totalgrid.reef.services:0.4.7]
    at org.totalgrid.reef.services.metrics.DatabaseActionsCounter$$anonfun$transaction$1.apply(DatabaseActionsCounter.scala:29)[82:org.totalgrid.reef.services:0.4.7]
    at org.totalgrid.reef.services.framework.RequestContextSourceWithHeaders$$anonfun$transaction$1.apply(RequestContext.scala:111)[82:org.totalgrid.reef.services:0.4.7]
    at org.totalgrid.reef.services.framework.RequestContextSourceWithHeaders$$anonfun$transaction$1.apply(RequestContext.scala:108)[82:org.totalgrid.reef.services:0.4.7]
    at org.totalgrid.reef.services.DependenciesSource$$anonfun$transaction$1.apply(ServiceDependencies.scala:74)[82:org.totalgrid.reef.services:0.4.7]
    at org.totalgrid.reef.services.DependenciesSource$$anonfun$transaction$1.apply(ServiceDependencies.scala:74)[82:org.totalgrid.reef.services:0.4.7]
    at org.totalgrid.reef.services.framework.ServiceTransactable$$anonfun$1.apply(ServiceTransactable.scala:28)[82:org.totalgrid.reef.services:0.4.7]
    at org.squeryl.dsl.QueryDsl$class._using(QueryDsl.scala:46)[54:org.totalgrid.reef.dependencies:0.4.7]
    at org.squeryl.dsl.QueryDsl$class._executeTransactionWithin(QueryDsl.scala:105)[54:org.totalgrid.reef.dependencies:0.4.7]
    at org.squeryl.dsl.QueryDsl$class.transaction(QueryDsl.scala:60)[54:org.totalgrid.reef.dependencies:0.4.7]
    at org.squeryl.PrimitiveTypeMode$.transaction(PrimitiveTypeMode.scala:40)[54:org.totalgrid.reef.dependencies:0.4.7]
    at org.totalgrid.reef.persistence.squeryl.SessionDbConnection$$anonfun$1.apply(DbConnection.scala:59)[69:org.totalgrid.reef.persistence-api:0.4.7]
    at org.squeryl.dsl.QueryDsl$class._using(QueryDsl.scala:46)[54:org.totalgrid.reef.dependencies:0.4.7]
    at org.squeryl.dsl.QueryDsl$class.using(QueryDsl.scala:38)[54:org.totalgrid.reef.dependencies:0.4.7]
    at org.squeryl.PrimitiveTypeMode$.using(PrimitiveTypeMode.scala:40)[54:org.totalgrid.reef.dependencies:0.4.7]
    at org.totalgrid.reef.persistence.squeryl.SessionDbConnection.transaction(DbConnection.scala:58)[69:org.totalgrid.reef.persistence-api:0.4.7]
    at org.totalgrid.reef.persistence.squeryl.SessionDbConnection.inTransaction(DbConnection.scala:69)[69:org.totalgrid.reef.persistence-api:0.4.7]
    at org.totalgrid.reef.services.framework.ServiceTransactable$.doTransaction(ServiceTransactable.scala:26)[82:org.totalgrid.reef.services:0.4.7]
    at org.totalgrid.reef.services.DependenciesSource.transaction(ServiceDependencies.scala:74)[82:org.totalgrid.reef.services:0.4.7]
    at org.totalgrid.reef.services.framework.RequestContextSourceWithHeaders.transaction(RequestContext.scala:108)[82:org.totalgrid.reef.services:0.4.7]
    at org.totalgrid.reef.services.metrics.DatabaseActionsCounter.transaction(DatabaseActionsCounter.scala:29)[82:org.totalgrid.reef.services:0.4.7]
    at org.totalgrid.reef.services.core.MeasurementBatchService.putAsync(MeasurementBatchService.scala:44)[82:org.totalgrid.reef.services:0.4.7]
    at org.totalgrid.reef.services.core.MeasurementBatchService.putAsync(MeasurementBatchService.scala:37)[82:org.totalgrid.reef.services:0.4.7]
    at org.totalgrid.reef.services.framework.AsyncContextRestService$class.respondAsync(ServiceEntryPoint.scala:51)[82:org.totalgrid.reef.services:0.4.7]
    at org.totalgrid.reef.services.core.MeasurementBatchService.respondAsync(MeasurementBatchService.scala:37)[82:org.totalgrid.reef.services:0.4.7]
    at org.totalgrid.reef.services.metrics.ServiceMetricsInstrumenter.respondAsync(ServiceMetricsInstrumenter.scala:53)[82:org.totalgrid.reef.services:0.4.7]
    at org.totalgrid.reef.services.framework.ServiceMiddleware.handleRequest(ServiceMiddleware.scala:63)[82:org.totalgrid.reef.services:0.4.7]
    at org.totalgrid.reef.services.framework.ServiceMiddleware.respond(ServiceMiddleware.scala:40)[82:org.totalgrid.reef.services:0.4.7]
    at org.totalgrid.reef.client.sapi.client.rest.impl.DefaultServiceBinding$$anon$1$$anonfun$onMessage$1$$anonfun$apply$mcV$sp$1.apply$mcV$sp(DefaultServiceBinding.scala:49)[61:org.totalgrid.reef.client:0.4.7]
    at org.totalgrid.reef.client.sapi.client.rest.impl.DefaultServiceBinding.org$totalgrid$reef$client$sapi$client$rest$impl$DefaultServiceBinding$$safely(DefaultServiceBinding.scala:63)[61:org.totalgrid.reef.client:0.4.7]
    at org.totalgrid.reef.client.sapi.client.rest.impl.DefaultServiceBinding$$anon$1$$anonfun$onMessage$1.apply$mcV$sp(DefaultServiceBinding.scala:42)[61:org.totalgrid.reef.client:0.4.7]
    at net.agileautomata.executor4s.impl.FunRun.run(DecoratedExecutor.scala:28)[53:net.agile-automata.executor4s.2.9.0-1:0.1.10]
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)[:1.6.0_21]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)[:1.6.0_21]
    at java.lang.Thread.run(Thread.java:619)[:1.6.0_21]

[Sam Hendley]

Yes Adam this was a regression introduced in 0.4.6 and not noticed before 0.4.7 was published. The measurement processor (which handles the stream of measurement updates) was not being correctly re-registered after startup. If you run the karaf command "endpoint:list" you should see that the "Measurement processor" column is probably marked as "false". A workaround is to manually remove the measurement processor from the application:list which forces the measurement processor to be correctly assigned (until the next restart anyways). The command we were using is "application:remove node01-Processing" you then either restart the meas proc bundle or wait around 30 seconds for the processors next heartbeat to fail and it will re-register automatically

This bug has been fixed in 0.4.8, which we will be releasing in the next few days.

Sam

Bug fix commit:  https://github.com/gec/reef/commit/9099d7bb707e44773c3cdc255b058c76aa3167e0 

[Adam Todorski]

Excellent, thank you, Sam (and GEC)!

-Adam