Unexpected protocol: <empty>

[ddrachau]

I am not able to connect to Apple's development apn Using pushy-0.7.2 with Java 8 (various versions with the matching alpn-boot lib).

2016-05-23 09:10:41,861 INFO  [com.relayrides.pushy.apns.ApnsClient] (ServerService Thread Pool -- 102) OpenSSL (via netty-tcnative) not available; will use JDK SSL provider.
2016-05-23 09:10:41,968 WARN  [com.relayrides.pushy.apns.ApnsClient] (ServerService Thread Pool -- 102) Asked for socket channel class to work with null event loop group, returning NioSocketChannel class.
2016-05-23 09:10:42,680 ERROR [com.relayrides.pushy.apns.ApnsClient] (nioEventLoopGroup-2-1) Unexpected protocol: 
2016-05-23 09:10:42,684 INFO  [com.relayrides.pushy.apns.ApnsClient] (nioEventLoopGroup-2-1) Failed to connect.: java.lang.IllegalStateException: Channel closed before HTTP/2 preface completed.
    at com.relayrides.pushy.apns.ApnsClient$2.operationComplete(ApnsClient.java:708) [pushy-0.7.2.jar:]
    at com.relayrides.pushy.apns.ApnsClient$2.operationComplete(ApnsClient.java:700) [pushy-0.7.2.jar:]
    at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:683) [netty-common-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:568) [netty-common-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.util.concurrent.DefaultPromise.trySuccess(DefaultPromise.java:407) [netty-common-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.channel.DefaultChannelPromise.trySuccess(DefaultChannelPromise.java:82) [netty-transport-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.channel.AbstractChannel$CloseFuture.setClosed(AbstractChannel.java:1064) [netty-transport-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.channel.AbstractChannel$AbstractUnsafe.doClose0(AbstractChannel.java:689) [netty-transport-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.channel.AbstractChannel$AbstractUnsafe.close(AbstractChannel.java:667) [netty-transport-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.channel.AbstractChannel$AbstractUnsafe.close(AbstractChannel.java:611) [netty-transport-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.channel.DefaultChannelPipeline$HeadContext.close(DefaultChannelPipeline.java:1416) [netty-transport-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.channel.ChannelHandlerInvokerUtil.invokeCloseNow(ChannelHandlerInvokerUtil.java:133) [netty-transport-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.channel.DefaultChannelHandlerInvoker.invokeClose(DefaultChannelHandlerInvoker.java:297) [netty-transport-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.channel.AbstractChannelHandlerContext.invokeClose(AbstractChannelHandlerContext.java:379) [netty-transport-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.channel.AbstractChannelHandlerContext.close(AbstractChannelHandlerContext.java:226) [netty-transport-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.channel.ChannelOutboundHandlerAdapter.close(ChannelOutboundHandlerAdapter.java:71) [netty-transport-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.channel.ChannelHandlerInvokerUtil.invokeCloseNow(ChannelHandlerInvokerUtil.java:133) [netty-transport-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.channel.DefaultChannelHandlerInvoker.invokeClose(DefaultChannelHandlerInvoker.java:297) [netty-transport-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.channel.AbstractChannelHandlerContext.invokeClose(AbstractChannelHandlerContext.java:379) [netty-transport-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.channel.AbstractChannelHandlerContext.close(AbstractChannelHandlerContext.java:226) [netty-transport-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.handler.ssl.SslHandler$8.operationComplete(SslHandler.java:1447) [netty-handler-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.handler.ssl.SslHandler$8.operationComplete(SslHandler.java:1433) [netty-handler-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:683) [netty-common-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.util.concurrent.DefaultPromise.notifyLateListener(DefaultPromise.java:624) [netty-common-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.util.concurrent.DefaultPromise.addListener(DefaultPromise.java:139) [netty-common-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.channel.DefaultChannelPromise.addListener(DefaultChannelPromise.java:93) [netty-transport-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.channel.DefaultChannelPromise.addListener(DefaultChannelPromise.java:28) [netty-transport-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.handler.ssl.SslHandler.safeClose(SslHandler.java:1433) [netty-handler-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.handler.ssl.SslHandler.closeOutboundAndChannel(SslHandler.java:1261) [netty-handler-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.handler.ssl.SslHandler.close(SslHandler.java:459) [netty-handler-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.channel.ChannelHandlerInvokerUtil.invokeCloseNow(ChannelHandlerInvokerUtil.java:133) [netty-transport-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.channel.DefaultChannelHandlerInvoker.invokeClose(DefaultChannelHandlerInvoker.java:297) [netty-transport-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.channel.AbstractChannelHandlerContext.invokeClose(AbstractChannelHandlerContext.java:379) [netty-transport-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.channel.AbstractChannelHandlerContext.close(AbstractChannelHandlerContext.java:226) [netty-transport-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.channel.AbstractChannelHandlerContext.close(AbstractChannelHandlerContext.java:185) [netty-transport-4.1.0.CR7.jar:4.1.0.CR7]
    at com.relayrides.pushy.apns.ApnsClient$1$1.configurePipeline(ApnsClient.java:486) [pushy-0.7.2.jar:]
    at io.netty.handler.ssl.ApplicationProtocolNegotiationHandler.userEventTriggered(ApplicationProtocolNegotiationHandler.java:92) [netty-handler-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.channel.ChannelHandlerInvokerUtil.invokeUserEventTriggeredNow(ChannelHandlerInvokerUtil.java:75) [netty-transport-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.channel.DefaultChannelHandlerInvoker.invokeUserEventTriggered(DefaultChannelHandlerInvoker.java:136) [netty-transport-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.channel.AbstractChannelHandlerContext.invokeUserEventTriggered(AbstractChannelHandlerContext.java:350) [netty-transport-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.channel.AbstractChannelHandlerContext.fireUserEventTriggered(AbstractChannelHandlerContext.java:138) [netty-transport-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.handler.ssl.SslHandler.setHandshakeSuccess(SslHandler.java:1197) [netty-handler-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1012) [netty-handler-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:904) [netty-handler-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:387) [netty-codec-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:245) [netty-codec-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.channel.ChannelHandlerInvokerUtil.invokeChannelReadNow(ChannelHandlerInvokerUtil.java:83) [netty-transport-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.channel.DefaultChannelHandlerInvoker.invokeChannelRead(DefaultChannelHandlerInvoker.java:154) [netty-transport-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:354) [netty-transport-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:145) [netty-transport-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:1078) [netty-transport-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:117) [netty-transport-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:527) [netty-transport-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:484) [netty-transport-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:398) [netty-transport-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:370) [netty-transport-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:742) [netty-common-4.1.0.CR7.jar:4.1.0.CR7]
    at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:145) [netty-common-4.1.0.CR7.jar:4.1.0.CR7]
    at java.lang.Thread.run(Thread.java:745) [rt.jar:1.8.0_92]

The ssl negotiation should have been successful but the protocol is empty

[ddrachau]

If you dig deep enough in the engine and session objects, you can see the protocol version ist TLSv1.2

But the applicationProtocol property of ApplicationProtocolAccessor is null and never set. The only place I could find is the JdkBaseApplicationProtocolNegotiator where the applicationProtocol is set but this code is never called.

[jchambers]

I don't want to just dismiss this problem outright, but I would like to begin by noting that at least one APNs development server has been afflicted by evil spirits for some time now. To help isolate the problem, does this happen all the time? Can you give us the IP of the server that isn't working? And does this happen in production, too?

[ddrachau]

Yes, it happens 'all the time'. Just one time there was a timeout.

dig +short api.development.push.apple.com
api.sandbox.push-apple.com.akadns.net.
17.172.238.203

I switched to apnsClient.connect(ApnsClient.PRODUCTION_APNS_HOST); and got the same logging:

�[0m�[0m16:07:31,237 INFO  [com.relayrides.pushy.apns.ApnsClient] (ServerService Thread Pool -- 4) OpenSSL (via netty-tcnative) not available; will use JDK SSL provider.
�[0m�[33m16:07:31,327 WARN  [com.relayrides.pushy.apns.ApnsClient] (ServerService Thread Pool -- 4) Asked for socket channel class to work with null event loop group, returning NioSocketChannel class.
�[0m�[31m16:07:31,819 ERROR [com.relayrides.pushy.apns.ApnsClient] (nioEventLoopGroup-2-1) Unexpected protocol: 
�[0m�[0m16:07:31,823 INFO  [com.relayrides.pushy.apns.ApnsClient] (nioEventLoopGroup-2-1) Failed to connect.: java.lang.IllegalStateException: Channel closed before HTTP/2 preface completed.

I debugged the call chain a bit and found a place where protocols to check are: ["h2"] but somewhere along the way I could not find the part where the actual check against the supported protocols is performed.

[jchambers]

Understood. Thanks for the clarification! Will investigate shortly.

[ddrachau]

I should have mentioned, that the application is a web archive in a Wildly application server.

In order to get rid of as many as possible side effects as possible I recreated the necessary code for push in a plain Java application and it works. So I have to continue searching for the root problem, maybe the way the certificate is loaded.

[ddrachau]

Hello Jon,

please consider the issue as resolved. For those of you with a similar problem:

• I use the alpn implementation - so you have to select the correct alpn-boot lib for your JRE and add it to the boot class path
• after this change pushy works in a standalone application
• If you use a Wildfly/JBoss application server like me it gets a bit more complicated
• Due to classloader isolation pushy cannot find the needed alpn interfaces
• if you add the alpa-api jar to the class path, pushy can find the needed classes. It even detects if the alpn-boot implementation is present or not
• BUT the needed api classes are already present in the alpn-boot jar. Now you have instances of interface classes in the root and war-class loader. The implementations rely on instance of checks which might have failed (due to the two loader)

The 'solution' for the JBoss/Wildfly application server:

• DO NOT add the alpn-api jar to your class path an make the alpn-boot classes available to your application
• add a file jboss-deployment-structure.xml to your META-INF/WEB-INF directory on the highest level

<jboss-deployment-structure xmlns="urn:jboss:deployment-structure:1.1">
    <deployment>
        <dependencies>
            <system export="true">
                <paths>
                    <path name="org/eclipse/jetty/alpn"/>
                </paths>
            </system>
        </dependencies>
    </deployment>
</jboss-deployment-structure>

and expose the alpn classes to your application

see also: https://docs.jboss.org/author/display/WFLY8/Class+Loading+in+WildFly

[jchambers]

Yow. Thanks, @ddrachau, for the detailed explanation! This will certainly be a big help to others.

[hubres]

Hello,
Small addition to the solution from @ddrachau
If you are using a EAR deployment you need to add the xml to the META-INF of the EAR (and not WAR or EJB).
Also it was not clear tome but it is pretty obvious: you still need to add the correct alpn-bot jar to the boot class path.
And if like me you are using eclipse, the server startup configuration is not in the wildfly folders but it is part of the Server configuration in eclipse (Open launch configuration).
Hope this helps.

[matzew]

With the version this should not be needed.

I have 0.9.3 and 2.0.0.Final of netty-tcnative-boringssl-static this should not be needed.

Having the following dependency on the WAR's pom, file is good enought:

        <dependency>
            <groupId>com.relayrides</groupId>
            <artifactId>pushy</artifactId>
            <version>0.9.3</version>
        </dependency>
        <dependency>
            <groupId>io.netty</groupId>
            <artifactId>netty-tcnative-boringssl-static</artifactId>
            <version>2.0.0.Final</version>
        </dependency>

[jchambers]

…and, conveniently enough, Pushy now depends on `netty-tcnative-boringssl-static` directly, so it reduces even further to just: <dependency> <groupId>com.relayrides</groupId> <artifactId>pushy</artifactId> <version>0.9.3</version> </dependency> Cheers!

…

-Jon

On Mon, Apr 10, 2017 at 11:07 AM, Matthias Wessendorf < ***@***.***> wrote: With the version this should not be needed. I have 0.9.3 and 2.0.0.Final of netty-tcnative-boringssl-static this should not be needed. Having the following dependency on the WAR's pom, file is good enought: <dependency> <groupId>com.relayrides</groupId> <artifactId>pushy</artifactId> <version>0.9.3</version> </dependency> <dependency> <groupId>io.netty</groupId> <artifactId>netty-tcnative-boringssl-static</artifactId> <version>2.0.0.Final</version> </dependency> — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#300 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AAB6eJjbkTCqaTtxmUq5gik96NGw74Fsks5rukXIgaJpZM4IkRT7> .

[alexvan]

Please, someone can clarify where the alpn-boot jar has to be put?

Thanks

[jchambers]

Please see https://github.com/relayrides/pushy/wiki/Using-a-JDK-SSL-provider and https://groups.google.com/d/msg/pushy-apns/CWvgNPp9yqk/PR1sXViBDAAJ. In the future, please go directly to the mailing list for support; comments added to long-closed issues are likely to go unnoticed.