Operating System: All
Platform: All

Tried to repro this in local setup. Able to see "chain failed" error for BGPPeer which is kind of expected when update message has mandatory attribute missing as the peer connection is dropped in this case

Not able to repro the "chain failed" error for ApplicationPeer. Below is the message seen prior to that. So it hits "Node was created by other transaction" when trying to write data into adj-rib-in of app peer

2016-08-09 01:15:55,992 | INFO | h for user karaf | command | 307 - org.apache.karaf.log.command - 3.0.6 | ROBOT MESSAGE: Starting test Configure_App_Peer
2016-08-09 01:15:56,268 | WARN | lt-dispatcher-20 | ShardDataTree | 172 - org.opendaylight.controller.sal-distributed-datastore - 1.4.0.SNAPSHOT | member-1-shard-default-operational: Store Tx member-1-datastore-operational-fe-0-chn-62-txn-0: Conflicting modification for path /(urn:opendaylight:params:xml:ns:yang:bgp-rib?revision=2013-09-25)bgp-rib/rib/rib[

]/peer/peer[

]/adj-rib-in/tables/tables[

]/afi.
2016-08-09 01:15:56,269 | WARN | ult-dispatcher-2 | ConcurrentDOMDataBroker | 172 - org.opendaylight.controller.sal-distributed-datastore - 1.4.0.SNAPSHOT | Tx: DOM-CHAIN-61-0 Error during phase CAN_COMMIT, starting Abort
OptimisticLockFailedException

To get more details about the failure, is it possible to re-run this suite with debugs turned on and share the karaf logs?

I can see that Robot keywords are available to turn-on debugs but unsure how to trigger the test from ODL Jenkins after making the change. If you can throw some light on that for my understanding, that will be great too

KarafKeywords.Execute_Controller_Karaf_Command_On_Background log:set ${CONTROLLER_BGP_LOG_LEVEL} org.opendaylight.bgpcep
KarafKeywords.Execute_Controller_Karaf_Command_On_Background log:set ${CONTROLLER_BGP_LOG_LEVEL} org.opendaylight.protocol

> unsure how to trigger the test from ODL Jenkins after making the change

Most people cannot trigger jobs on RelEng. I can (as a releng/builder committer) so I have triggered [0]. The Robot variable values can be overridden using -v option in TESTOPTIONS job parameter.

Usually Sandbox [1] is the platform to run such tests, but Sandbox results are deleted every Saturday.

[0] https://jenkins.opendaylight.org/releng/view/bgpcep/job/bgpcep-csit-1node-userfeatures-only-boron/872
[1] https://nexus.opendaylight.org/content/repositories/site/org.opendaylight.releng.builder/master/jenkins.html#jenkins_sandbox

(In reply to Vratko Polák from comment #2)
> > unsure how to trigger the test from ODL Jenkins after making the change
>
> Most people cannot trigger jobs on RelEng. I can (as a releng/builder
> committer) so I have triggered [0]. The Robot variable values can be
> overridden using -v option in TESTOPTIONS job parameter.
>
> Usually Sandbox [1] is the platform to run such tests, but Sandbox results
> are deleted every Saturday.
>
> [0]
> https://jenkins.opendaylight.org/releng/view/bgpcep/job/bgpcep-csit-1node-
> userfeatures-only-boron/872
> [1]
> https://nexus.opendaylight.org/content/repositories/site/org.opendaylight.
> releng.builder/master/jenkins.html#jenkins_sandbox

Thanks. I accessed the logs at https://logs.opendaylight.org/releng/jenkins092/bgpcep-csit-1node-userfeatures-only-boron/872/archives/karaf.log.gz and unable to find the error there. Can you please re-run the test to see if it we can get the error to happen?

$ grep "chain failed" karaf-2.log
2016-08-11 14:17:41,591 | ERROR | CommitFutures-18 | BGPPeer | 324 - org.opendaylight.bgpcep.bgp-rib-impl - 0.7.0.SNAPSHOT | Transaction chain failed.
$

Errors from previous log file for reference:

$ grep "chain failed" karaf-1.log
2016-08-09 01:15:25,461 | ERROR | CommitFutures-0 | BGPPeer | 185 - org.opendaylight.bgpcep.bgp-rib-impl - 0.6.0.SNAPSHOT | Transaction chain failed.
2016-08-09 01:15:56,274 | ERROR | CommitFutures-3 | ApplicationPeer | 185 - org.opendaylight.bgpcep.bgp-rib-impl - 0.6.0.SNAPSHOT | Transaction chain failed.
2016-08-09 01:16:22,182 | ERROR | CommitFutures-3 | ApplicationPeer | 185 - org.opendaylight.bgpcep.bgp-rib-impl - 0.6.0.SNAPSHOT | Transaction chain failed.
2016-08-09 01:16:22,176 | ERROR | CommitFutures-4 | ApplicationPeer | 185 - org.opendaylight.bgpcep.bgp-rib-impl - 0.6.0.SNAPSHOT | Transaction chain failed.
2016-08-09 01:21:37,723 | ERROR | CommitFutures-1 | ApplicationPeer | 185 - org.opendaylight.bgpcep.bgp-rib-impl - 0.6.0.SNAPSHOT | Transaction chain failed.
2016-08-09 01:21:37,740 | ERROR | CommitFutures-3 | ApplicationPeer | 185 - org.opendaylight.bgpcep.bgp-rib-impl - 0.6.0.SNAPSHOT | Transaction chain failed.
2016-08-09 01:21:37,741 | ERROR | CommitFutures-3 | ApplicationPeer | 185 - org.opendaylight.bgpcep.bgp-rib-impl - 0.6.0.SNAPSHOT | Transaction chain failed.
2016-08-09 01:22:36,498 | ERROR | CommitFutures-1 | ApplicationPeer | 185 - org.opendaylight.bgpcep.bgp-rib-impl - 0.6.0.SNAPSHOT | Transaction chain failed.
2016-08-09 01:22:36,498 | ERROR | CommitFutures-4 | ApplicationPeer | 185 - org.opendaylight.bgpcep.bgp-rib-impl - 0.6.0.SNAPSHOT | Transaction chain failed.
2016-08-09 01:22:36,499 | ERROR | CommitFutures-0 | ApplicationPeer | 185 - org.opendaylight.bgpcep.bgp-rib-impl - 0.6.0.SNAPSHOT | Transaction chain failed.
$

> https://logs.opendaylight.org/releng/jenkins092/bgpcep-csit-1node-userfeatures-only-boron/872/archives/karaf.log.gz

Yeah, the consequences on the following suites are different in this debug run.

There is still the main issue that this expected error:
2016-08-11 14:17:41,576 | ERROR | ntLoopGroup-11-8 | BGPDocumentedException | 311 - org.opendaylight.bgpcep.bgp-parser-api - 0.7.0.SNAPSHOT | Error = WELL_KNOWN_ATTR_MISSING
org.opendaylight.protocol.bgp.parser.BGPDocumentedException: Well known mandatory attribute missing: ORIGIN

leads to this unexpected consequence:
2016-08-11 14:17:41,591 | ERROR | CommitFutures-18 | BGPPeer | 324 - org.opendaylight.bgpcep.bgp-rib-impl - 0.7.0.SNAPSHOT | Transaction chain failed.
TransactionCommitFailedException{message=Data did not pass validation., errorList=[RpcError [message=Data did not pass validation., severity=ERROR, errorType=APPLICATION, tag=operation-failed, applicationTag=null, info=null, cause=org.opendaylight.yangtools.yang.data.api.schema.tree.ModifiedNodeDoesNotExistException: Node /(urn:opendaylight:params:xml:ns:yang:bgp-rib?revision=2013-09-25)bgp-rib/rib/rib[

]/peer/peer[

] does not exist. Cannot apply modification to its children.]]}

I am not sure if there is anything wrong in the subsequent test, between test start:
2016-08-11 14:18:12,906 | INFO | h for user karaf | command | 302 - org.apache.karaf.log.command - 3.0.7 | ROBOT MESSAGE: Starting test L3vpn_Ipv4_To_Odl

and test giving up waiting on correct result:
2016-08-11 14:18:34,622 | DEBUG | ntLoopGroup-11-1 | BGPNotificationMessageParser | 313 - org.opendaylight.bgpcep.bgp-parser-impl - 0.7.0.SNAPSHOT | BGP Notification message was parsed: err = PEER_DECONFIGURED, data = [80, 101, 101, 114, 32, 68, 101, 45, 99, 111, 110, 102, 105, 103, 117, 114, 101, 100].

Scheduled #875 to see if the behavior repeats.

(In reply to Vratko Polák from comment #4)
> > https://logs.opendaylight.org/releng/jenkins092/bgpcep-csit-1node-userfeatures-only-boron/872/archives/karaf.log.gz
>
> Yeah, the consequences on the following suites are different in this debug
> run.
>
> There is still the main issue that this expected error:
> 2016-08-11 14:17:41,576 | ERROR | ntLoopGroup-11-8 | BGPDocumentedException
> | 311 - org.opendaylight.bgpcep.bgp-parser-api - 0.7.0.SNAPSHOT | Error =
> WELL_KNOWN_ATTR_MISSING
> org.opendaylight.protocol.bgp.parser.BGPDocumentedException: Well known
> mandatory attribute missing: ORIGIN
>
> leads to this unexpected consequence:
> 2016-08-11 14:17:41,591 | ERROR | CommitFutures-18 | BGPPeer
> | 324 - org.opendaylight.bgpcep.bgp-rib-impl - 0.7.0.SNAPSHOT | Transaction
> chain failed.
> TransactionCommitFailedException{message=Data did not pass validation.,
> errorList=[RpcError [message=Data did not pass validation., severity=ERROR,
> errorType=APPLICATION, tag=operation-failed, applicationTag=null, info=null,
> cause=org.opendaylight.yangtools.yang.data.api.schema.tree.
> ModifiedNodeDoesNotExistException: Node
> /(urn:opendaylight:params:xml:ns:yang:bgp-rib?revision=2013-09-25)bgp-rib/
> rib/rib[

]/peer/peer[

] does not exist. Cannot
> apply modification to its children.]]}
>
> I am not sure if there is anything wrong in the subsequent test, between
> test start:
> 2016-08-11 14:18:12,906 | INFO | h for user karaf | command
> | 302 - org.apache.karaf.log.command - 3.0.7 | ROBOT MESSAGE: Starting test
> L3vpn_Ipv4_To_Odl
>
> and test giving up waiting on correct result:
> 2016-08-11 14:18:34,622 | DEBUG | ntLoopGroup-11-1 |
> BGPNotificationMessageParser | 313 -
> org.opendaylight.bgpcep.bgp-parser-impl - 0.7.0.SNAPSHOT | BGP Notification
> message was parsed: err = PEER_DECONFIGURED, data = [80, 101, 101, 114, 32,
> 68, 101, 45, 99, 111, 110, 102, 105, 103, 117, 114, 101, 100].
>
> Scheduled #875 to see if the behavior repeats.

Thanks. #875 seems to have failed due to some infra issue
https://jenkins.opendaylight.org/releng/view/bgpcep/job/bgpcep-csit-1node-userfeatures-only-boron/875/console

. . .
SSH not responding on 10.29.13.79. Retrying in 10 seconds...
SSH not responding on 10.29.13.79. Retrying in 10 seconds...
SSH not responding on 10.29.13.79. Retrying in 10 seconds...
SSH not responding on 10.29.13.79. Retrying in 10 seconds...
SSH not responding on 10.29.13.79 after tries. Giving up.
Process 9622 failed to copy ssh keys.
Build step 'Execute shell' marked build as failure
Destroying nodes: [DFW/b72077cd-4885-43b0-8537-10a8b75928f2, DFW/64517f31-5f55-4d84-98ea-a7358b136dc6]
[ssh-agent] Stopped.
Robot results publisher started...
-Parsing output xml:
No public addresses found, so using private address.
No public addresses found, so using private address.
Failed!

Looking at past few test runs on Jenkins, the last time this error (i.e. "chain failed" on ApplicationPeer) was seen was on job #882 (ref. [0]). #883 to #886 does not have karaf.log, and #887 to latest #892 does not have this error. Request you to run the test again a few more times with DEBUG enabled to see if debugs can be collected when problem happens. Else we can park the issue till the error happens consistently again

[0] https://jenkins.opendaylight.org/releng/view/bgpcep/job/bgpcep-csit-1node-userfeatures-only-boron/

#894 scheduled.

Looks like "close" is invoked twice after the termination - see "Closing session:" info log message.

(In reply to Milos Fabian from comment #8)
> Looks like "close" is invoked twice after the termination - see "Closing
> session:" info log message.

Yeah thats right. Also noticed while trying to repro that connected-peer-counter was getting decremented twice in BGPPeer:dropConnection() and becoming negative. However I am not sure that it is causing the issue with application-peer mentioned in this bug. So I will open separate bug to track those

https://bugs.opendaylight.org/show_bug.cgi?id=6468 has been opened for the duplicate cleanup issue

There seem to be some changes pending in this area (e.g. https://git.opendaylight.org/gerrit/#/c/44229/). Once those are merged, please try again and if issue is still seen attach karaf.log with DEBUG enabled. Thx

When doing Sandbox testing for this suite change [0], this Bug was not seen, so it was probably fixed.

[0] https://git.opendaylight.org/gerrit/45165