Dear all,
we are facing some problem to deploy a virtualized localization solution made of WLC, Prime Infrastructure and MSE.
We constructed, in our lab, on a UCS C220M3 with VMWare 5.1 the following solution:
- Virtual WLC version 7.3.101 (ip address 10.0.1.249)
- Prime Infrastructure 1.2.0.103 (ip address 10.0.1.250)
- Virtual MSE 7.3.101 (ip address 10.0.1.247)
WLC is working properly, can register APs and is properly integrated with the Prime. For the localization solution we deployed three access points:
-one 3502 in flex connect mode
-two 1142 in monitor mode
The problem came out when we started to work with the MSE. MSE has been registered inside Prime and synchronized with maps and controller.
After that we checked the maps but no information was displayed. So we started facing the problem and we found that the NMSP protocol remained inactive even if the troubleshooting windows didn't report any explicit issue.
At this stage we started checking the debug messages and in particular, for the NMSP we countinuously received the follwing message:
*nmspRxServerTask: Nov 17 17:55:09.777: Allocated new NMSP connection 0
*nmspRxServerTask: Nov 17 17:55:09.778: sslConnectionInit: SSL_new() conn ssl 0x2aaaae71ab88
*nmspRxServerTask: Nov 17 17:55:09.778: sslConnectionInit: SSL_do_handshake for conn ssl 0x2aaaae71ab88, conn state: INIT, SSL state: HANDSHAKING
*nmspRxServerTask: Nov 17 17:55:09.778: -- returns WANT_READ for conn ssl 0x2aaaae71ab88
*nmspRxServerTask: Nov 17 17:55:09.778: sslConnectionInit() success with Connection state: INIT, SSL state: HANDSHAKING
*nmspRxServerTask: Nov 17 17:55:09.785: doSSLRecvLoop: Handshake has not completed for conn 0
*nmspRxServerTask: Nov 17 17:55:09.785: sslConnectionInit: SSL_do_handshake for conn ssl 0x2aaaae71ab88, conn state: INIT, SSL state: HANDSHAKING
*nmspRxServerTask: Nov 17 17:55:09.785: -- returns WANT_READ for conn ssl 0x2aaaae71ab88
*nmspRxServerTask: Nov 17 17:55:10.100: doSSLRecvLoop: Handshake has not completed for conn 0
*nmspRxServerTask: Nov 17 17:55:10.100: sslConnectionInit: SSL_do_handshake for conn ssl 0x2aaaae71ab88, conn state: INIT, SSL state: HANDSHAKING
*nmspRxServerTask: Nov 17 17:55:10.100: -- handshake failed for conn ssl 0x2aaaae71ab88,error = error:00000000:lib(0):func(0):reason(0)
*nmspRxServerTask: Nov 17 17:55:10.100: freeing Nmsp conn ssl 0x2aaaae71ab88, conn id 0
Also the statistics for the NMSP protocol emphatized an SSL error:
(Cisco Controller) >show nmsp statistics summary
NMSP Global Counters
Client Measure Send Fail......................... 0
Send RSSI with no entry.......................... 0
APP msg too big.................................. 0
Failed Select on Accept Socket................... 0
Failed SSL write................................. 0
Partial SSL write................................ 0
SSL write returned zero.......................... 0
SSL write attempts to want read.................. 0
SSL write attempts to want write................. 0
SSL write got default error...................... 0
SSL write max data length sent................... 0
SSL write max attempts to write in loop.......... 0
SSL read returned zero........................... 0
SSL read attempts to want read................... 0
SSL read attempts to want write.................. 0
SSL read got default error....................... 0
Failed SSL read - Con Rx buf freed............... 0
Failed SSL read - Con/SSL freed.................. 0
Max records read before exiting SSL read......... 0
--More-- or (q)uit
Highest Prio Tx Q full........................... 0
Normal Prio Tx Q full............................ 0
Highest Prio Tx Q Sent........................... 0
Normal Prio Tx Q Sent............................ 0
Highest Prio Tx Q count.......................... 0
Normal Prio Tx Q count........................... 0
Messages sent by APPs to Highest Prio TxQ........ 0
Max Measure Notify Msg........................... 0
Max Info Notify Msg.............................. 0
Max Highest Prio Tx Q Size....................... 0
Max Normal Prio Tx Q Size........................ 0
Max Rx Size...................................... 1
Max Info Notify Q Size........................... 0
Max Client Info Notify Delay..................... 0
Max Rogue AP Info Notify Delay................... 0
Max Rogue Client Info Notify Delay............... 0
Max Client Measure Notify Delay.................. 0
Max Tag Measure Notify Delay..................... 0
Max Rogue AP Measure Notify Delay................ 0
Max Rogue Client Measure Notify Delay............ 0
Max Client Stats Notify Delay.................... 0
Max RFID Stats Notify Delay...................... 0
RFID Measurement Periodic........................ 0
--More-- or (q)uit
RFID Measurement Immediate....................... 0
SSL Handshake failed............................. 1319
NMSP Rx detected con failure..................... 0
NMSP Tx detected con failure..................... 0
NMSP Tx buf size exceeded........................ 0
NMSP Tx Invalid msg id .......................... 0
Reconnect Before Conn Timeout.................... 0
Rogue AP Info Changed DB Full.................... 0
Rogue AP Meas Changed DB Full.................... 0
Rogue Client Info Changed DB Full................ 0
Rogue Client Meas Changed DB Full................ 0
Looking around the Internet we found a similar case where the issue was solved dealing with the authorization list upon the wireless lan controller but after the suggested check we saw that the MSE is correctly authorized inside the controller: Here's the "show auth-list" on the WLC:
(Cisco Controller) >show auth-list
Authorize MIC APs against AAA ................... disabled
Authorize LSC APs against Auth-List ............. disabled
APs Allowed to Join
AP with Manufacturing Installed Certificate.... no
AP with Self-Signed Certificate................ no
AP with Locally Significant Certificate........ no
Mac Addr Cert Type Key Hash
----------------------- ---------- ------------------------------------------
00:0c:29:68:c8:57 LBS-SSC 6d6703ef9cccfb5a430e04b3ad128f8170fb435c
that perfectly matches what was on the MSE:
cmd> show server-auth-info
invoke command: com.aes.server.cli.CmdGetServerAuthInfo
AesLog queue high mark: 50000
AesLog queue low mark: 500
----------------
Server Auth Info
----------------
MAC Address: 00:0c:29:68:c8:57
Key Hash: 6d6703ef9cccfb5a430e04b3ad128f8170fb435c
Certificate Type: SSC
Finally I tried to look around the MSE logs and here what I found tailing the locserver errors:
==> /opt/mse/logs/locserver/locserver-error-0-0.log <==
11/17/12 17:54:13.513 ERROR[locp] [36] Error in ConnectHandler(endPoint) <LocpSessionTarget mode=CLIENT><LocpEndPoint status=HANDSHAKE totalBytesSent=72000 totalBytesReceived=1315800><LocpEndPoint.Key host=10.0.1.249 port=16113/></LocpEndPoint></LocpSessionTarget>
11/17/12 17:54:13.513 ERROR[com.aes] [36] [ConnectHandler:handle-09] THROW
javax.net.ssl.SSLHandshakeException: General SSLEngine problem
at com.sun.net.ssl.internal.ssl.Handshaker.checkThrown(Handshaker.java:1015)
at com.sun.net.ssl.internal.ssl.SSLEngineImpl.checkTaskThrown(SSLEngineImpl.java:485)
at com.sun.net.ssl.internal.ssl.SSLEngineImpl.writeAppRecord(SSLEngineImpl.java:1128)
at com.sun.net.ssl.internal.ssl.SSLEngineImpl.wrap(SSLEngineImpl.java:1100)
at javax.net.ssl.SSLEngine.wrap(SSLEngine.java:452)
at com.aes.server.locp.transport.IOChannelSecure.doHandshake(IOChannelSecure.java:230)
at com.aes.server.locp.transport.LocpTransportService$ConnectHandler.handle(LocpTransportService.java:354)
at com.aes.server.locp.transport.ChannelEventDispatcherImpl$HandlerTask.run(ChannelEventDispatcherImpl.java:348)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:662)
Caused by: javax.net.ssl.SSLHandshakeException: General SSLEngine problem
at com.sun.net.ssl.internal.ssl.Alerts.getSSLException(Alerts.java:174)
at com.sun.net.ssl.internal.ssl.SSLEngineImpl.fatal(SSLEngineImpl.java:1528)
at com.sun.net.ssl.internal.ssl.Handshaker.fatalSE(Handshaker.java:243)
at com.sun.net.ssl.internal.ssl.Handshaker.fatalSE(Handshaker.java:235)
at com.sun.net.ssl.internal.ssl.ClientHandshaker.serverCertificate(ClientHandshaker.java:1206)
at com.sun.net.ssl.internal.ssl.ClientHandshaker.processMessage(ClientHandshaker.java:136)
at com.sun.net.ssl.internal.ssl.Handshaker.processLoop(Handshaker.java:593)
at com.sun.net.ssl.internal.ssl.Handshaker$1.run(Handshaker.java:533)
at java.security.AccessController.doPrivileged(Native Method)
at com.sun.net.ssl.internal.ssl.Handshaker$DelegatedTask.run(Handshaker.java:952)
at com.aes.server.locp.transport.IOChannelSecure.doTasks(IOChannelSecure.java:265)
at com.aes.server.locp.transport.IOChannelSecure.doHandshake(IOChannelSecure.java:193)
... 8 more
Caused by: sun.security.validator.ValidatorException: No trusted certificate found
at sun.security.validator.SimpleValidator.buildTrustedChain(SimpleValidator.java:346)
at sun.security.validator.SimpleValidator.engineValidate(SimpleValidator.java:111)
at sun.security.validator.Validator.validate(Validator.java:218)
at com.sun.net.ssl.internal.ssl.X509TrustManagerImpl.validate(X509TrustManagerImpl.java:126)
at com.sun.net.ssl.internal.ssl.X509TrustManagerImpl.checkServerTrusted(X509TrustManagerImpl.java:209)
at com.sun.net.ssl.internal.ssl.X509TrustManagerImpl.checkServerTrusted(X509TrustManagerImpl.java:249)
at com.sun.net.ssl.internal.ssl.ClientHandshaker.serverCertificate(ClientHandshaker.java:1185)
... 15 more
Everything seems to bring to a certificate error but I don't know, from a side if this is the right direction of investigfation and, from the other, where to check for this certificate and how to find a solution.
May someone give us some help?
Thank in advance to all.
Regards.
Marco
