[
https://issues.apache.org/jira/browse/DIRMINA-842?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13061185#comment-13061185
]
Kaja Hovi commented on DIRMINA-842:
-----------------------------------
07-07 09:03:17.988: DEBUG/L4J(363): 9622 [NioProcessor-2] DEBUG
org.apache.vysper.xmpp.protocol.SessionStateHolder - session state changed to
= INITIATED
07-07 09:03:18.008: INFO/L4J(363): 9639 [NioProcessor-2] INFO
org.apache.vysper.mina.XmppIoHandlerAdapter - new session from
localhost/127.0.0.1:36058 has been opened
07-07 09:03:18.018: DEBUG/L4J(363): 9645 [NioProcessor-2] DEBUG
org.apache.mina.filter.codec.ProtocolCodecFilter - Processing a
MESSAGE_RECEIVED for session 1
07-07 09:03:18.128: DEBUG/L4J(363): 9764 [NioProcessor-2] DEBUG
org.apache.vysper.xml.decoder.XMPPContentHandler - Decoder writing stanza:
<stream:stream xmlns:stream="http://etherx.jabber.org/streams";
to="hovi.mk.zcu.cz" xml:lang="en" version="1.0"></stream:stream>
07-07 09:03:18.128: DEBUG/L4J(363): 9767 [NioProcessor-2] DEBUG stanza.client
- < <stream:stream xmlns:stream="http://etherx.jabber.org/streams";
to="hovi.mk.zcu.cz" xml:lang="en" version="1.0">
07-07 09:03:18.178: DEBUG/L4J(363): 9813 [pool-3-thread-1] DEBUG
org.apache.vysper.xmpp.protocol.SessionStateHolder - session state changed to
= STARTED
07-07 09:03:18.238: DEBUG/L4J(363): 9871 [NioProcessor-2] DEBUG
org.apache.mina.filter.codec.ProtocolCodecFilter - Processing a
MESSAGE_RECEIVED for session 1
07-07 09:03:18.259: DEBUG/L4J(363): 9896 [NioProcessor-2] DEBUG
org.apache.vysper.xml.decoder.XMPPContentHandler - Decoder writing stanza:
<starttls xmlns="urn:ietf:params:xml:ns:xmpp-tls"></starttls>
07-07 09:03:18.268: DEBUG/L4J(363): 9900 [NioProcessor-2] DEBUG stanza.client
- < <starttls xmlns="urn:ietf:params:xml:ns:xmpp-tls"></starttls>
07-07 09:03:18.298: DEBUG/L4J(363): 9928 [NioProcessor-2] DEBUG stanza.server
- > <stream:stream xmlns="jabber:client"
xmlns:stream="http://etherx.jabber.org/streams"; from="hovi.mk.zcu.cz"
version="1.0" id="e5a7b21bfa76489da1cdaea46d9ba96e"><stream:features
xmlns:stream="http://etherx.jabber.org/streams";><starttls
xmlns="urn:ietf:params:xml:ns:xmpp-tls"><required></required></starttls></stream:features>
07-07 09:03:18.298: DEBUG/L4J(363): 9931 [pool-3-thread-2] DEBUG
org.apache.vysper.xmpp.protocol.SessionStateHolder - session state changed to
= ENCRYPTION_STARTED
07-07 09:03:18.328: DEBUG/L4J(363): 9958 [pool-3-thread-2] DEBUG
org.apache.mina.filter.ssl.SslFilter - Adding the SSL Filter sslFilter to the
chain
07-07 09:03:18.337: DEBUG/L4J(363): 9972 [pool-3-thread-2] DEBUG
org.apache.mina.filter.ssl.SslHandler - Session Server[1](no sslEngine)
Initializing the SSL Handler
07-07 09:03:18.388: DEBUG/L4J(363): 10021 [pool-3-thread-2] DEBUG
org.apache.mina.filter.ssl.SslHandler - Session Server[1](no sslEngine) SSL
Handler Initialization done.
07-07 09:03:18.388: DEBUG/L4J(363): 10024 [pool-3-thread-2] DEBUG
org.apache.mina.filter.ssl.SslFilter - Session Server[1](ssl...) : Starting
the first handshake
07-07 09:03:18.397: DEBUG/L4J(363): 10029 [pool-3-thread-2] DEBUG
org.apache.mina.filter.ssl.SslHandler - Session Server[1](ssl...) processing
the NEED_UNWRAP state
07-07 09:03:18.448: DEBUG/L4J(363): 10085 [pool-3-thread-2] DEBUG
org.apache.mina.filter.ssl.SslFilter - Session Server[1](ssl...): Writing
Message : WriteRequest: HeapBuffer[pos=0 lim=59 cap=128: 3C 70 72 6F 63 65 65
64 20 78 6D 6C 6E 73 3D 22...]
07-07 09:03:18.498: DEBUG/L4J(363): 10132 [NioProcessor-2] DEBUG
org.apache.mina.filter.ssl.SslFilter - Session Server[1](ssl...): Message
received : HeapBuffer[pos=0 lim=124 cap=1024: 80 7A 01 03 01 00 51 00 00 00 20
00 00 39 00 00...]
07-07 09:03:18.498: DEBUG/L4J(363): 10135 [NioProcessor-2] DEBUG
org.apache.mina.filter.ssl.SslHandler - Session Server[1](ssl...) Processing
the received message
07-07 09:03:18.517: DEBUG/L4J(363): 10153 [NioProcessor-2] DEBUG
org.apache.mina.filter.ssl.SslHandler - Session Server[1](ssl...) processing
the NEED_UNWRAP state
07-07 09:03:18.538: DEBUG/L4J(363): 10175 [pool-3-thread-2] DEBUG
org.apache.mina.filter.ssl.SslFilter - Session Server[1](ssl...): Writing
Message : MessageWriteRequest, parent : WR WrapperWriteRequest: [ prolog=false,
open=true, close=true, content=true, stanza=[proceed]
07-07 09:03:19.188: DEBUG/L4J(363): 10819 [NioProcessor-2] DEBUG
org.apache.mina.filter.ssl.SslHandler - Session Server[1](ssl...) processing
the NEED_TASK state
07-07 09:03:19.288: DEBUG/L4J(363): 10921 [NioProcessor-2] DEBUG
org.apache.mina.filter.ssl.SslHandler - Session Server[1](ssl...) processing
the NEED_WRAP state
07-07 09:03:19.308: DEBUG/L4J(363): 10938 [NioProcessor-2] DEBUG
org.apache.mina.filter.ssl.SslFilter - Session Server[1](ssl...): Writing
Message : WriteRequest: HeapBuffer[pos=0 lim=758 cap=1152: 16 03 01 02 F1 02 00
00 46 03 01 4E 15 76 57 B5...]
07-07 09:03:19.308: DEBUG/L4J(363): 10941 [NioProcessor-2] DEBUG
org.apache.mina.filter.ssl.SslHandler - Session Server[1](ssl...) processing
the NEED_UNWRAP state
07-07 09:03:19.328: DEBUG/L4J(363): 10959 [NioProcessor-2] DEBUG
org.apache.mina.filter.ssl.SslFilter - Session Server[1](ssl...): Processing
the SSL Data
07-07 09:03:19.428: DEBUG/L4J(363): 11063 [NioProcessor-2] DEBUG
org.apache.mina.filter.ssl.SslFilter - Session Server[1](ssl...): Message
received : HeapBuffer[pos=0 lim=126 cap=1024: 16 03 01 00 46 10 00 00 42 00 40
36 CE CA 07 F6...]
07-07 09:03:19.428: DEBUG/L4J(363): 11067 [NioProcessor-2] DEBUG
org.apache.mina.filter.ssl.SslHandler - Session Server[1](ssl...) Processing
the received message
07-07 09:03:19.448: DEBUG/L4J(363): 11074 [NioProcessor-2] DEBUG
org.apache.mina.filter.ssl.SslHandler - Session Server[1](ssl...) processing
the NEED_UNWRAP state
07-07 09:03:19.638: DEBUG/L4J(363): 11274 [NioProcessor-2] DEBUG
org.apache.mina.filter.ssl.SslHandler - Session Server[1](ssl...) processing
the NEED_WRAP state
07-07 09:03:19.668: DEBUG/L4J(363): 11305 [NioProcessor-2] DEBUG
org.apache.mina.filter.ssl.SslFilter - Session Server[1](ssl...): Writing
Message : WriteRequest: HeapBuffer[pos=0 lim=6 cap=9: 14 03 01 00 01 01]
07-07 09:03:19.678: DEBUG/L4J(363): 11308 [NioProcessor-2] DEBUG
org.apache.mina.filter.ssl.SslHandler - Session Server[1](ssl...) processing
the NEED_WRAP state
07-07 09:03:19.688: DEBUG/L4J(363): 11324 [NioProcessor-2] DEBUG
org.apache.mina.filter.ssl.SslFilter - Session Server[1](ssl...): Writing
Message : WriteRequest: HeapBuffer[pos=0 lim=45 cap=72: 16 03 01 00 28 5A 40 52
41 F6 D2 BF B5 82 24 01...]
07-07 09:03:19.688: DEBUG/L4J(363): 11326 [NioProcessor-2] DEBUG
org.apache.mina.filter.ssl.SslHandler - Session Server[1](ssl...) processing
the FINISHED state
07-07 09:03:19.700: DEBUG/L4J(363): 11332 [NioProcessor-2] DEBUG
org.apache.mina.filter.ssl.SslHandler - Session Server[1](SSL) is now secured
07-07 09:03:19.700: DEBUG/L4J(363): 11335 [NioProcessor-2] DEBUG
org.apache.mina.filter.ssl.SslHandler - Session Server[1](SSL) processing the
FINISHED state
07-07 09:03:19.708: DEBUG/L4J(363): 11338 [NioProcessor-2] DEBUG
org.apache.mina.filter.ssl.SslHandler - Session Server[1](SSL) is now secured
07-07 09:03:19.708: DEBUG/L4J(363): 11342 [NioProcessor-2] DEBUG
org.apache.mina.filter.ssl.SslFilter - Session Server[1](SSL): Processing the
SSL Data
07-07 09:03:19.718: DEBUG/L4J(363): 11351 [NioProcessor-2] DEBUG
org.apache.mina.filter.codec.ProtocolCodecFilter - Processing a
MESSAGE_RECEIVED for session 1
07-07 09:03:19.718: DEBUG/L4J(363): 11354 [NioProcessor-2] DEBUG
org.apache.vysper.xmpp.protocol.SessionStateHolder - session state changed to
= ENCRYPTED
07-07 09:03:19.858: DEBUG/L4J(363): 11492 [NioProcessor-2] DEBUG
org.apache.mina.filter.ssl.SslFilter - Session Server[1](SSL): Message
received : HeapBuffer[pos=0 lim=266 cap=512: 17 03 01 00 18 58 65 14 F5 51 86
B3 91 CD 4D C2...]
07-07 09:03:19.878: DEBUG/L4J(363): 11514 [NioProcessor-2] DEBUG
org.apache.mina.filter.ssl.SslHandler - Session Server[1](SSL) Processing the
received message
07-07 09:03:19.908: DEBUG/L4J(363): 11544 [NioProcessor-2] DEBUG
org.apache.mina.filter.ssl.SslFilter - Session Server[1](SSL): Processing the
SSL Data
07-07 09:03:19.908: DEBUG/L4J(363): 11546 [NioProcessor-2] DEBUG
org.apache.mina.filter.codec.ProtocolCodecFilter - Processing a
MESSAGE_RECEIVED for session 1
07-07 09:03:19.967: DEBUG/L4J(363): 11601 [NioProcessor-2] DEBUG
org.apache.vysper.xml.decoder.XMPPContentHandler - Decoder writing stanza:
<stream:stream xmlns:stream="http://etherx.jabber.org/streams";
to="hovi.mk.zcu.cz" xml:lang="en" version="1.0"></stream:stream>
07-07 09:03:19.967: DEBUG/L4J(363): 11605 [NioProcessor-2] DEBUG stanza.client
- < <stream:stream xmlns:stream="http://etherx.jabber.org/streams";
to="hovi.mk.zcu.cz" xml:lang="en" version="1.0">
07-07 09:03:20.008: DEBUG/L4J(363): 11646 [pool-3-thread-3] DEBUG
org.apache.mina.filter.ssl.SslFilter - Session Server[1](SSL): Writing Message
: WriteRequest: HeapBuffer[pos=0 lim=374 cap=512: 3C 3F 78 6D 6C 20 76 65 72 73
69 6F 6E 3D 22 31...]
07-07 09:03:20.068: DEBUG/L4J(363): 11707 [pool-3-thread-3] DEBUG
org.apache.mina.filter.ssl.SslFilter - Session Server[1](SSL): Writing Message
: MessageWriteRequest, parent : WR WrapperWriteRequest: [ prolog=true,
open=true, close=false, content=true, stanza=[stream.features.mechanisms[PLAIN]]
07-07 09:03:20.088: DEBUG/L4J(363): 11726 [NioProcessor-2] DEBUG stanza.server
- > <stream:stream xmlns="jabber:client"
xmlns:stream="http://etherx.jabber.org/streams"; from="hovi.mk.zcu.cz"
version="1.0" id="e5a7b21bfa76489da1cdaea46d9ba96e"><stream:features
xmlns:stream="http://etherx.jabber.org/streams";><mechanisms
xmlns="urn:ietf:params:xml:ns:xmpp-sasl"><mechanism>PLAIN</mechanism></mechanisms></stream:features>
07-07 09:03:20.207: DEBUG/L4J(363): 11841 [NioProcessor-2] DEBUG
org.apache.mina.filter.ssl.SslFilter - Session Server[1](SSL): Message
received : HeapBuffer[pos=0 lim=154 cap=512: 17 03 01 00 18 DC FC 3B 15 7C 4D
8E 23 F8 DE 75...]
07-07 09:03:20.228: DEBUG/L4J(363): 11861 [NioProcessor-2] DEBUG
org.apache.mina.filter.ssl.SslHandler - Session Server[1](SSL) Processing the
received message
07-07 09:03:20.258: DEBUG/L4J(363): 11892 [NioProcessor-2] DEBUG
org.apache.mina.filter.ssl.SslFilter - Session Server[1](SSL): Processing the
SSL Data
07-07 09:03:20.258: DEBUG/L4J(363): 11894 [NioProcessor-2] DEBUG
org.apache.mina.filter.codec.ProtocolCodecFilter - Processing a
MESSAGE_RECEIVED for session 1
07-07 09:03:20.298: DEBUG/L4J(363): 11931 [NioProcessor-2] DEBUG
org.apache.vysper.xml.decoder.XMPPContentHandler - Decoder writing stanza:
<auth xmlns="urn:ietf:params:xml:ns:xmpp-sasl"
mechanism="PLAIN">AGhvdmkAcGFzc3dvcmQx</auth>
07-07 09:03:20.298: DEBUG/L4J(363): 11934 [NioProcessor-2] DEBUG stanza.client
- < <auth xmlns="urn:ietf:params:xml:ns:xmpp-sasl"
mechanism="PLAIN">AGhvdmkAcGFzc3dvcmQx</auth>
07-07 09:03:21.458: DEBUG/L4J(363): 13093 [NioProcessor-2] DEBUG stanza.server
- > <proceed xmlns="urn:ietf:params:xml:ns:xmpp-tls"></proceed>
> Crash on Android
> ----------------
>
> Key: DIRMINA-842
> URL: https://issues.apache.org/jira/browse/DIRMINA-842
> Project: MINA
> Issue Type: Bug
> Environment: android 2.2 (emulator)
> Reporter: Kaja Hovi
> Assignee: Niklas Gustavsson
> Labels: android, ssl
>
> I tried to run VYSPER on android, with just one fix - getting "bks" keystore
> instead of "jks" (or just KeyStore ks =
> KeyStore.getInstance(KeyStore.getDefaultType()); to make it work on both
> platforms) , I used portecle to convert VYSPER default jks certificate into
> bks format.
> When I run server on android and try to autenticate, I get following
> exception:
> 06-30 21:36:40.109: ERROR/L4J(342): 1178740 [NioProcessor-2] ERROR
> org.apache.mina.filter.ssl.SslHandler - Invalid Handshaking
> StateNOT_HANDSHAKING while processing the Handshake for session 3
> 06-30 21:36:40.109: WARN/L4J(342): 1178743 [NioProcessor-2] WARN
> org.apache.vysper.mina.XmppIoHandlerAdapter - error caught on transportation
> layer: {}
> 06-30 21:36:40.116: WARN/System.err(342): java.lang.IllegalStateException:
> Invalid Handshaking StateNOT_HANDSHAKING while processing the Handshake for
> session 3
> 06-30 21:36:40.116: WARN/System.err(342): at
> org.apache.mina.filter.ssl.SslHandler.handshake(SslHandler.java:593)
> 06-30 21:36:40.126: WARN/System.err(342): at
> org.apache.mina.filter.ssl.SslHandler.writeNetBuffer(SslHandler.java:632)
> 06-30 21:36:40.137: WARN/System.err(342): at
> org.apache.mina.filter.ssl.SslHandler.handshake(SslHandler.java:586)
> 06-30 21:36:40.137: WARN/System.err(342): at
> org.apache.mina.filter.ssl.SslHandler.messageReceived(SslHandler.java:349)
> 06-30 21:36:40.137: WARN/System.err(342): at
> org.apache.mina.filter.ssl.SslFilter.messageReceived(SslFilter.java:476)
> 06-30 21:36:40.137: WARN/System.err(342): at
> org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:434)
> 06-30 21:36:40.155: WARN/System.err(342): at
> org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoFilterChain.java:46)
> 06-30 21:36:40.155: WARN/System.err(342): at
> org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:796)
> 06-30 21:36:40.155: WARN/System.err(342): at
> org.apache.mina.core.filterchain.IoFilterAdapter.messageReceived(IoFilterAdapter.java:119)
> 06-30 21:36:40.166: WARN/System.err(342): at
> org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:434)
> 06-30 21:36:40.166: WARN/System.err(342): at
> org.apache.mina.core.filterchain.DefaultIoFilterChain.fireMessageReceived(DefaultIoFilterChain.java:426)
> 06-30 21:36:40.166: WARN/System.err(342): at
> org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:693)
> 06-30 21:36:40.176: WARN/System.err(342): at
> org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:646)
> 06-30 21:36:40.193: WARN/System.err(342): at
> org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:635)
> 06-30 21:36:40.196: WARN/System.err(342): at
> org.apache.mina.core.polling.AbstractPollingIoProcessor.access$400(AbstractPollingIoProcessor.java:67)
> 06-30 21:36:40.196: WARN/System.err(342): at
> org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:1079)
> 06-30 21:36:40.196: WARN/System.err(342): at
> org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
> 06-30 21:36:40.206: WARN/System.err(342): at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1068)
> 06-30 21:36:40.215: WARN/System.err(342): at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:561)
> 06-30 21:36:40.215: WARN/System.err(342): at
> java.lang.Thread.run(Thread.java:1096)
> Any ideas what might cause this and how to fix it?
> Same project works fine in JRE (with both bks and jks).
> I found similar issue here (mina+android):
> http://androiddiscuss.com/1-android-discuss/1022.html
> I hope I am posting in correct place, since it is also about project VYSPER
> and it seems possibly like android sdk bug, sorry if not.
--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira
