Hi,
Could not reproduce this directly, so tried this manually by removing the odl-aaa-netconf-plugin feature (to make authentication for loopback always fail) and installing odl-netconf-connector-all. Configs were pushed successfully, but the connection could not be established due to failed authentication. The attempts to establish the connection continued with failures until I installed the aaa feature manually. After that the loopback was successfully mounted.
This is the behavior on current master (Lithium release). In Helium and the first SR release the connection was not reattempted when the authentication failed, but this is fixed now.
Netconf SSH endpoint relies on the aaa service to perform authentication and it retrieves the service from the OSGi registry. It looks like the service is exposed to the OSGi registry but its not fully functional (the database lock exception). This looks like an AAA issue and AAA should check the database. However this will not be an issue after AAA is migrated to use MD-SAL instead of SQLite database.
ref: https://lists.opendaylight.org/pipermail/controller-dev/2015-March/008458.html
From: Devin Avery <davery@brocade.com>
Date: Tue, Mar 10, 2015 at 9:19 AM
Subject: Re: [controller-dev] [Aaa-dev] Cannot connect to database server Exception - Sporadic Error
To: Wojciech Dec <wdec.ietf@gmail.com>
Cc: controller-dev <controller-dev@lists.opendaylight.org>, "aaa-dev@lists.opendaylight.org" <aaa-dev@lists.opendaylight.org>
Hi Folks,
Following up on this. So the problem appears to be an internal race condition inside of MD-SAL / AAA / config system combined with logic flaws about retrying connections.
Basically, the way I get this to reproduce is Iist all of the features that I want to install in the featuresBoot list and then start a clean controller (I.e. delete data directory, delete /etc/opendaylight). When the controller starts up there is a race condition from the config subsystem injecting the self-referencing netconf connection and the AAA database being locked. When the problem occurs the AAA database file is locked and thus when netconf tries to connect and specifically authenticate the AAA fails because of an exception. Then because the config subsystem, or more specifically the netconf mounter is a try once and done (no retries) it fails to connect the self-referencing controller.
Potential fixes from what I can tell:
enhance AAA logic to handle issues when the database might be locked, and consider a wait retry mechanism (we would need to answer the question of “when would we expect this error” to implement something like this).
and/or enhance the netconf mounting logic to retry even if it got a failed authentication (though that seems a little strange)
I think ultimately #1 is the longer term fix. If you are trying to reproduce this note that I see this every once in a while - on 10 machines, I see it consistently on 1 of them every time I run a suite of tests.
For now I have worked around this by installing the features more slowly / independently, but this is clearly not an ideal solution. I’ll see if I can’t come up with a more consistent reproduction scenario but figured I would share what I know in the mean time.
Pone other comment - in the AAA code it would be really helpful it the entire exception was printed to the log, not just the message. In general the AAA code catches exceptions and logs the e.getMessage() or they use an overloaded toString on the exception to only print a simple message. It is better practice to print the stack trace too though to make it easier to debug 
log.info( “Caught exception “ + e.getMessage(), e ) <— passing the exception as a second argument will print the stack trace to the log for the exception and may provide additional information.
Thank you,
Devin
Devin Avery
Devin.Avery@Brocade.com
From: Wojciech Dec <wdec.ietf@gmail.com>
Date: Friday, March 6, 2015 at 5:20 AM
To: Devin Avery <davery@brocade.com>
Cc: "aaa-dev@lists.opendaylight.org" <aaa-dev@lists.opendaylight.org>, controller-dev <controller-dev@lists.opendaylight.org>
Subject: Re: [Aaa-dev] Cannot connect to database server Exception - Sporadic Error
Hi,
I must admit I didn't see this particular problem so far. It obviously looks like something thrown up by SQLite on reading/writing. We're going to replace SQLite with another db backend so hopefully that may redress that, in the meantime if you have more info on how to reproduce this please let us know.
Cheers,
Wojciech.
On 5 March 2015 at 16:11, Devin Avery <davery@brocade.com> wrote:
>
> Copying to the controller dev list as well as this issue manifests itself with the controller failing to mount itself as a netconf device. Perhaps others have seen it.
>
> Devin
>
> Devin Avery
> Devin.Avery@Brocade.com
>
>
>
> From: Devin Avery <davery@brocade.com>
> Date: Thursday, March 5, 2015 at 9:56 AM
> To: "aaa-dev@lists.opendaylight.org" <aaa-dev@lists.opendaylight.org>
> Subject: [Aaa-dev] Cannot connect to database server Exception - Sporadic Error
>
> Hello AAA Devs -
>
> I am seeing a sporadic error in my karaf log files stating that the database file is locked. This results in an authentication failure which unfortunetly prevents the controller from mounting itself as a netconf controller. Any hints or pointers that I could look at to try and understand what might be happening in these cases?
>
> Ubuntu 14.04
> Brand new controller, fresh controller start up (features are all getting installed via features.boot)
>
> 2015-03-05 05:45:05,694 | INFO | pool-8-thread-1 | GrantStore | 232 - org.opendaylight.aaa.idmlight - 0.1.2.Helium-SR2 | grants Table does not exist, creating table
> 2015-03-05 05:45:06,588 | ERROR | Thread-42 | StoreException | 232 - org.opendaylight.aaa.idmlight - 0.1.2.Helium-SR2 | Cannot connect to database server java.sql.SQLException: [SQLITE_BUSY] The database file is locked (database is locked)
> 2015-03-05 05:45:06,589 | INFO | 1]-nio2-thread-6 | ClientUserAuthServiceNew | 139 - org.apache.sshd.core - 0.12.0 | Received SSH_MSG_USERAUTH_FAILURE
> 2015-03-05 05:45:06,589 | WARN | 1]-nio2-thread-6 | AsyncSshHandler | 137 - org.opendaylight.controller.netconf-netty-util - 0.2.7.Helium-SR2 | Unable to setup SSH connection on channel: [id: 0x349bae66]
> 2015-03-05 05:45:06,595 | DEBUG | 1]-nio2-thread-6 | AsyncSshHandler | 137 - org.opendaylight.controller.netconf-netty-util - 0.2.7.Helium-SR2 | SSH session closed on channel: [id: 0x349bae66]
> 2015-03-05 05:45:06,595 | WARN | 1]-nio2-thread-6 | DefaultAuthFuture | 139 - org.apache.sshd.core - 0.12.0 | Listener threw an exception
> java.lang.NullPointerException: cause
> at io.netty.util.concurrent.DefaultPromise.setFailure0(DefaultPromise.java:475)[121:io.netty.common:4.0.23.Final]
> at io.netty.util.concurrent.DefaultPromise.setFailure(DefaultPromise.java:414)[121:io.netty.common:4.0.23.Final]
> at io.netty.channel.DefaultChannelPromise.setFailure(DefaultChannelPromise.java:87)[120:io.netty.transport:4.0.23.Final]
> at org.opendaylight.controller.netconf.nettyutil.handler.ssh.client.AsyncSshHandler.handleSshSetupFailure(AsyncSshHandler.java:154)[137:org.opendaylight.controller.netconf-netty-util:0.2.7.Helium-SR2]
> at org.opendaylight.controller.netconf.nettyutil.handler.ssh.client.AsyncSshHandler.access$100(AsyncSshHandler.java:32)[137:org.opendaylight.controller.netconf-netty-util:0.2.7.Helium-SR2]
> at org.opendaylight.controller.netconf.nettyutil.handler.ssh.client.AsyncSshHandler$2.operationComplete(AsyncSshHandler.java:103)[137:org.opendaylight.controller.netconf-netty-util:0.2.7.Helium-SR2]
> at org.opendaylight.controller.netconf.nettyutil.handler.ssh.client.AsyncSshHandler$2.operationComplete(AsyncSshHandler.java:97)[137:org.opendaylight.controller.netconf-netty-util:0.2.7.Helium-SR2]
> at org.apache.sshd.common.future.DefaultSshFuture.notifyListener(DefaultSshFuture.java:261)[139:org.apache.sshd.core:0.12.0]
> at org.apache.sshd.common.future.DefaultSshFuture.notifyListeners(DefaultSshFuture.java:247)[139:org.apache.sshd.core:0.12.0]
> at org.apache.sshd.common.future.DefaultSshFuture.setValue(DefaultSshFuture.java:175)[139:org.apache.sshd.core:0.12.0]
> at org.apache.sshd.client.future.DefaultAuthFuture.setAuthed(DefaultAuthFuture.java:68)[139:org.apache.sshd.core:0.12.0]
> at org.apache.sshd.client.session.ClientUserAuthServiceNew.tryNext(ClientUserAuthServiceNew.java:206)[139:org.apache.sshd.core:0.12.0]
> at org.apache.sshd.client.session.ClientUserAuthServiceNew.processUserAuth(ClientUserAuthServiceNew.java:178)[139:org.apache.sshd.core:0.12.0]
> at org.apache.sshd.client.session.ClientUserAuthServiceNew.process(ClientUserAuthServiceNew.java:131)[139:org.apache.sshd.core:0.12.0]
> at org.apache.sshd.client.session.ClientUserAuthService.process(ClientUserAuthService.java:80)[139:org.apache.sshd.core:0.12.0]
> at org.apache.sshd.common.session.AbstractSession.doHandleMessage(AbstractSession.java:399)[139:org.apache.sshd.core:0.12.0]
> at org.apache.sshd.common.session.AbstractSession.handleMessage(AbstractSession.java:295)[139:org.apache.sshd.core:0.12.0]
> at org.apache.sshd.client.session.ClientSessionImpl.handleMessage(ClientSessionImpl.java:256)[139:org.apache.sshd.core:0.12.0]
> at org.apache.sshd.common.session.AbstractSession.decode(AbstractSession.java:731)[139:org.apache.sshd.core:0.12.0]
> at org.apache.sshd.common.session.AbstractSession.messageReceived(AbstractSession.java:277)[139:org.apache.sshd.core:0.12.0]
> at org.apache.sshd.common.AbstractSessionIoHandler.messageReceived(AbstractSessionIoHandler.java:54)[139:org.apache.sshd.core:0.12.0]
> at org.apache.sshd.common.io.nio2.Nio2Session$1.onCompleted(Nio2Session.java:187)[139:org.apache.sshd.core:0.12.0]
> at org.apache.sshd.common.io.nio2.Nio2Session$1.onCompleted(Nio2Session.java:173)[139:org.apache.sshd.core:0.12.0]
> at org.apache.sshd.common.io.nio2.Nio2CompletionHandler$1.run(Nio2CompletionHandler.java:32)
> at java.security.AccessController.doPrivileged(Native Method)[:1.7.0_75]
> at org.apache.sshd.common.io.nio2.Nio2CompletionHandler.completed(Nio2CompletionHandler.java:30)[139:org.apache.sshd.core:0.12.0]
> at sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:126)[:1.7.0_75]
> at sun.nio.ch.Invoker$2.run(Invoker.java:218)[:1.7.0_75]
> at sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112)[:1.7.0_75]
> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)[:1.7.0_75]
> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)[:1.7.0_75]
> at java.lang.Thread.run(Thread.java:745)[:1.7.0_75]
>
> Thank you,
>
> Devin
>
> Devin Avery
> Devin.Avery@Brocade.com
>
>
>
> _______________________________________________
> aaa-dev mailing list
> aaa-dev@lists.opendaylight.org
> https://lists.opendaylight.org/mailman/listinfo/aaa-dev
>
_______________________________________________
controller-dev mailing list
controller-dev@lists.opendaylight.org
https://lists.opendaylight.org/mailman/listinfo/controller-dev
This appears to have been resolved, or at least not seen since the fix for AAA-37.
To be reopened if it is seen again.