pushy icon indicating copy to clipboard operation
pushy copied to clipboard

Published 20 hours ago • verified publisher icon jchambers

setConnectionTimeout is not working

Open SK-Yang opened this issue 3 years ago • 8 comments

I'm trying to use pushy's setConnectionTimeout to limit my APP's response time, but this function seem buggy so far and no response received nor exception popped up after 15 second of execution. Here's my code

SimpleDateFormat` sdf = new SimpleDateFormat("yyyy-MM-dd'T'HH:mm:ss'Z'");

Instant start = Instant.parse(sdf.format(new Date()));
Instant end = Instant.parse(sdf.format(new Date().getTime() + 10000));

Duration timeout = Duration.between(start, end);

apnsClient = new ApnsClientBuilder().setApnsServer(ApnsClientBuilder.PRODUCTION_APNS_HOST)
        .setSigningKey(ApnsSigningKey.loadFromPkcs8File(new File(p8File_Path), team_ID, key_ID))
        .setConnectionTimeout(timeout)
        .build();
// form msg with SimpleApnsPushNotification and use sendNotification afterward

SK-Yang avatar Mar 08 '21 07:03 SK-Yang

Hi, @SK-Yang. As far as I know, the param connectionTimeout only affects when a channel tries to connect to the APNs server. Therefore, it doesn't work after the channel connection is established.

In my humble opinion, you can consider using Java Future timeout.

KimTaehee avatar Mar 09 '21 02:03 KimTaehee

I think I agree with @KimTaehee, but it's hard to be sure what's going on in this case without more information. To be clear:

  1. Do you believe that opening the initial connection is taking more than ten seconds (your timeout)?
  2. Do you have any logs (HTTP/2 frame logs are especially helpful) to give hints as to what's going wrong with your slow messages?

Also (and this isn't immediately relevant to this issue), if you're new to java.time, you might find it easier to replace this:

SimpleDateFormat sdf = new SimpleDateFormat("yyyy-MM-dd'T'HH:mm:ss'Z'");

Instant start = Instant.parse(sdf.format(new Date()));
Instant end = Instant.parse(sdf.format(new Date().getTime() + 10000));

Duration timeout = Duration.between(start, end);

…with:

Duration timeout = Duration.ofSeconds(10);

jchambers avatar Mar 10 '21 20:03 jchambers

Hi, @SK-Yang. As far as I know, the param connectionTimeout only affects when a channel tries to connect to the APNs server. Therefore, it doesn't work after the channel connection is established.

In my humble opinion, you can consider using Java Future timeout.

Hmm, I'm not quiet often of doing that since this APP require synchronized behavior. So my APP must wait for APNS's result before next process.

I think I agree with @KimTaehee, but it's hard to be sure what's going on in this case without more information. To be clear:

1. Do you believe that opening the initial connection is taking more than ten seconds (your `timeout`)?

2. Do you have any logs (HTTP/2 frame logs are especially helpful) to give hints as to what's going wrong with your slow messages?

Also (and this isn't immediately relevant to this issue), if you're new to java.time, you might find it easier to replace this:

SimpleDateFormat` sdf = new SimpleDateFormat("yyyy-MM-dd'T'HH:mm:ss'Z'");

Instant start = Instant.parse(sdf.format(new Date()));
Instant end = Instant.parse(sdf.format(new Date().getTime() + 10000));

Duration timeout = Duration.between(start, end);

…with:

Duration timeout = Duration.ofSeconds(10);
  1. Can't get other explaination so far since no response received after it halted at pushy's sendNotification executed.
  2. Didn't setup the log config for netty, I'll try to set it up and get log.
  3. Never used Duration class before until pushy. HttpClient or netty only ask for millisecond of long type. Also wondering why use Duration instead of millisecond?

SK-Yang avatar Mar 11 '21 01:03 SK-Yang

Got time to re-execute this program again. Here's log

[DEBUG] 2021-03-17 15:40:30.090 [WebContainer : 2] InternalLoggerFactory - Using SLF4J as the default logging framework
[DEBUG] 2021-03-17 15:40:30.090 [WebContainer : 2] ResourceLeakDetector - -Dio.netty.leakDetection.level: simple
[DEBUG] 2021-03-17 15:40:30.090 [WebContainer : 2] ResourceLeakDetector - -Dio.netty.leakDetection.targetRecords: 4
[DEBUG] 2021-03-17 15:40:30.137 [WebContainer : 2] PlatformDependent - Platform: Windows
[DEBUG] 2021-03-17 15:40:30.137 [WebContainer : 2] PlatformDependent0 - -Dio.netty.noUnsafe: false
[DEBUG] 2021-03-17 15:40:30.137 [WebContainer : 2] PlatformDependent0 - Java version: 8
[DEBUG] 2021-03-17 15:40:30.137 [WebContainer : 2] PlatformDependent0 - sun.misc.Unsafe.theUnsafe: available
[DEBUG] 2021-03-17 15:40:30.137 [WebContainer : 2] PlatformDependent0 - sun.misc.Unsafe.copyMemory: available
[DEBUG] 2021-03-17 15:40:30.137 [WebContainer : 2] PlatformDependent0 - java.nio.Buffer.address: available
[DEBUG] 2021-03-17 15:40:30.137 [WebContainer : 2] PlatformDependent0 - direct buffer constructor: available
[DEBUG] 2021-03-17 15:40:30.137 [WebContainer : 2] PlatformDependent0 - java.nio.Bits.unaligned: available, true
[DEBUG] 2021-03-17 15:40:30.137 [WebContainer : 2] PlatformDependent0 - jdk.internal.misc.Unsafe.allocateUninitializedArray(int): unavailable prior to Java9
[DEBUG] 2021-03-17 15:40:30.137 [WebContainer : 2] PlatformDependent0 - java.nio.DirectByteBuffer.<init>(long, int): available
[DEBUG] 2021-03-17 15:40:30.137 [WebContainer : 2] PlatformDependent - sun.misc.Unsafe: available
[DEBUG] 2021-03-17 15:40:30.137 [WebContainer : 2] PlatformDependent - maxDirectMemory: 939524096 bytes (maybe)
[DEBUG] 2021-03-17 15:40:30.153 [WebContainer : 2] PlatformDependent - -Dio.netty.tmpdir: C:\Windows\TEMP (java.io.tmpdir)
[DEBUG] 2021-03-17 15:40:30.153 [WebContainer : 2] PlatformDependent - -Dio.netty.bitMode: 64 (sun.arch.data.model)
[DEBUG] 2021-03-17 15:40:30.153 [WebContainer : 2] PlatformDependent - -Dio.netty.maxDirectMemory: 939524096 bytes
[DEBUG] 2021-03-17 15:40:30.153 [WebContainer : 2] PlatformDependent - -Dio.netty.uninitializedArrayAllocationThreshold: -1
[DEBUG] 2021-03-17 15:40:30.153 [WebContainer : 2] CleanerJava6 - java.nio.ByteBuffer.cleaner(): available
[DEBUG] 2021-03-17 15:40:30.153 [WebContainer : 2] PlatformDependent - -Dio.netty.noPreferDirect: false
[DEBUG] 2021-03-17 15:40:30.168 [WebContainer : 2] AbstractByteBuf - -Dio.netty.buffer.checkAccessible: true
[DEBUG] 2021-03-17 15:40:30.168 [WebContainer : 2] AbstractByteBuf - -Dio.netty.buffer.checkBounds: true
[DEBUG] 2021-03-17 15:40:30.168 [WebContainer : 2] ResourceLeakDetectorFactory - Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@11181310
[DEBUG] 2021-03-17 15:40:30.199 [WebContainer : 2] OpenSsl - netty-tcnative not in the classpath; OpenSslEngine will be unavailable.
[INFO ] 2021-03-17 15:40:30.199 [WebContainer : 2] ApnsClientBuilder - Native SSL provider not available; will use JDK SSL provider.
[DEBUG] 2021-03-17 15:40:30.246 [WebContainer : 2] JdkSslContext - Default protocols (JDK): [TLSv1] 
[DEBUG] 2021-03-17 15:40:30.246 [WebContainer : 2] JdkSslContext - Default cipher suites (JDK): [TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384, TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA, TLS_RSA_WITH_AES_128_GCM_SHA256, TLS_RSA_WITH_AES_128_CBC_SHA, TLS_RSA_WITH_AES_256_CBC_SHA]
[DEBUG] 2021-03-17 15:40:30.278 [WebContainer : 2] MultithreadEventLoopGroup - -Dio.netty.eventLoopThreads: 16
[DEBUG] 2021-03-17 15:40:30.309 [WebContainer : 2] InternalThreadLocalMap - -Dio.netty.threadLocalMap.stringBuilder.initialSize: 1024
[DEBUG] 2021-03-17 15:40:30.309 [WebContainer : 2] InternalThreadLocalMap - -Dio.netty.threadLocalMap.stringBuilder.maxSize: 4096
[DEBUG] 2021-03-17 15:40:30.324 [WebContainer : 2] NioEventLoop - -Dio.netty.noKeySetOptimization: false
[DEBUG] 2021-03-17 15:40:30.324 [WebContainer : 2] NioEventLoop - -Dio.netty.selectorAutoRebuildThreshold: 512
[DEBUG] 2021-03-17 15:40:30.356 [WebContainer : 2] PlatformDependent - org.jctools-core.MpscChunkedArrayQueue: available
[DEBUG] 2021-03-17 15:40:30.438 [WebContainer : 2] DefaultDnsServerAddressStreamProvider - Default DNS servers: [/1.1.1.1:53, /192.168.0.1:53] (sun.net.dns.ResolverConfiguration)
[DEBUG] 2021-03-17 15:40:30.478 [WebContainer : 2] NetUtil - -Djava.net.preferIPv4Stack: false
[DEBUG] 2021-03-17 15:40:30.478 [WebContainer : 2] NetUtil - -Djava.net.preferIPv6Addresses: false
[DEBUG] 2021-03-17 15:40:30.514 [WebContainer : 2] NetUtil - Loopback interface: lo (Software Loopback Interface 1, 127.0.0.1)
[DEBUG] 2021-03-17 15:40:30.514 [WebContainer : 2] NetUtil - Failed to get SOMAXCONN from sysctl and file \proc\sys\net\core\somaxconn. Default: 200
[DEBUG] 2021-03-17 15:40:30.639 [nioEventLoopGroup-2-1] DefaultChannelId - -Dio.netty.processId: 9168 (auto-detected)
[DEBUG] 2021-03-17 15:40:30.686 [nioEventLoopGroup-2-1] DefaultChannelId - -Dio.netty.machineId: 00:10:18:ff:fe:18:59:f3 (auto-detected)
[DEBUG] 2021-03-17 15:40:30.733 [nioEventLoopGroup-2-1] PooledByteBufAllocator - -Dio.netty.allocator.numHeapArenas: 9
[DEBUG] 2021-03-17 15:40:30.733 [nioEventLoopGroup-2-1] PooledByteBufAllocator - -Dio.netty.allocator.numDirectArenas: 9
[DEBUG] 2021-03-17 15:40:30.733 [nioEventLoopGroup-2-1] PooledByteBufAllocator - -Dio.netty.allocator.pageSize: 8192
[DEBUG] 2021-03-17 15:40:30.733 [nioEventLoopGroup-2-1] PooledByteBufAllocator - -Dio.netty.allocator.maxOrder: 11
[DEBUG] 2021-03-17 15:40:30.733 [nioEventLoopGroup-2-1] PooledByteBufAllocator - -Dio.netty.allocator.chunkSize: 16777216
[DEBUG] 2021-03-17 15:40:30.733 [nioEventLoopGroup-2-1] PooledByteBufAllocator - -Dio.netty.allocator.tinyCacheSize: 512
[DEBUG] 2021-03-17 15:40:30.748 [nioEventLoopGroup-2-1] PooledByteBufAllocator - -Dio.netty.allocator.smallCacheSize: 256
[DEBUG] 2021-03-17 15:40:30.748 [nioEventLoopGroup-2-1] PooledByteBufAllocator - -Dio.netty.allocator.normalCacheSize: 64
[DEBUG] 2021-03-17 15:40:30.748 [nioEventLoopGroup-2-1] PooledByteBufAllocator - -Dio.netty.allocator.maxCachedBufferCapacity: 32768
[DEBUG] 2021-03-17 15:40:30.748 [nioEventLoopGroup-2-1] PooledByteBufAllocator - -Dio.netty.allocator.cacheTrimInterval: 8192
[DEBUG] 2021-03-17 15:40:30.748 [nioEventLoopGroup-2-1] PooledByteBufAllocator - -Dio.netty.allocator.cacheTrimIntervalMillis: 0
[DEBUG] 2021-03-17 15:40:30.748 [nioEventLoopGroup-2-1] PooledByteBufAllocator - -Dio.netty.allocator.useCacheForAllThreads: true
[DEBUG] 2021-03-17 15:40:30.748 [nioEventLoopGroup-2-1] PooledByteBufAllocator - -Dio.netty.allocator.maxCachedByteBuffersPerChunk: 1023
[DEBUG] 2021-03-17 15:40:30.764 [nioEventLoopGroup-2-1] ByteBufUtil - -Dio.netty.allocator.type: pooled
[DEBUG] 2021-03-17 15:40:30.764 [nioEventLoopGroup-2-1] ByteBufUtil - -Dio.netty.threadLocalDirectBufferSize: 0
[DEBUG] 2021-03-17 15:40:30.764 [nioEventLoopGroup-2-1] ByteBufUtil - -Dio.netty.maxThreadLocalCharBufferSize: 16384
[DEBUG] 2021-03-17 15:40:31.028 [nioEventLoopGroup-2-1] ResourceLeakDetectorFactory - Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@d983b66b
[DEBUG] 2021-03-17 15:40:31.041 [nioEventLoopGroup-2-1] DnsQueryContext - [id: 0xa67b92d4] WRITE: UDP, [26400: /1.1.1.1:53], DefaultDnsQuestion(api.push.apple.com. IN A)
[DEBUG] 2021-03-17 15:40:31.057 [nioEventLoopGroup-2-1] Recycler - -Dio.netty.recycler.maxCapacityPerThread: 4096
[DEBUG] 2021-03-17 15:40:31.057 [nioEventLoopGroup-2-1] Recycler - -Dio.netty.recycler.maxSharedCapacityFactor: 2
[DEBUG] 2021-03-17 15:40:31.057 [nioEventLoopGroup-2-1] Recycler - -Dio.netty.recycler.linkCapacity: 16
[DEBUG] 2021-03-17 15:40:31.057 [nioEventLoopGroup-2-1] Recycler - -Dio.netty.recycler.ratio: 8
[DEBUG] 2021-03-17 15:40:31.088 [nioEventLoopGroup-2-1] DnsQueryContext - [id: 0xa67b92d4] WRITE: UDP, [52749: /1.1.1.1:53], DefaultDnsQuestion(api.push.apple.com. IN AAAA)
[DEBUG] 2021-03-17 15:40:31.119 [nioEventLoopGroup-2-1] DnsNameResolver - [id: 0xa67b92d4] RECEIVED: UDP [26400: /1.1.1.1:53], DatagramDnsResponse(from: /1.1.1.1:53, to: /0:0:0:0:0:0:0:0:56448, 26400, QUERY(0), NoError(0), RD RA)
	DefaultDnsQuestion(api.push.apple.com. IN A)
	DefaultDnsRawRecord(api.push.apple.com. 278 IN CNAME 31B)
	DefaultDnsRawRecord(api.push-apple.com.akadns.net. 8 IN A 4B)
	DefaultDnsRawRecord(api.push-apple.com.akadns.net. 8 IN A 4B)
	DefaultDnsRawRecord(api.push-apple.com.akadns.net. 8 IN A 4B)
	DefaultDnsRawRecord(api.push-apple.com.akadns.net. 8 IN A 4B)
	DefaultDnsRawRecord(api.push-apple.com.akadns.net. 8 IN A 4B)
	DefaultDnsRawRecord(api.push-apple.com.akadns.net. 8 IN A 4B)
	DefaultDnsRawRecord(api.push-apple.com.akadns.net. 8 IN A 4B)
	DefaultDnsRawRecord(api.push-apple.com.akadns.net. 8 IN A 4B)
	DefaultDnsRawRecord(OPT flags:0 udp:1232 0B)
[DEBUG] 2021-03-17 15:40:31.119 [nioEventLoopGroup-2-1] DnsQueryContext - [id: 0xa67b92d4] WRITE: UDP, [15374: /1.1.1.1:53], DefaultDnsQuestion(api.push-apple.com.akadns.net. IN A)
[DEBUG] 2021-03-17 15:40:31.119 [nioEventLoopGroup-2-1] DnsNameResolver - [id: 0xa67b92d4] RECEIVED: UDP [52749: /1.1.1.1:53], DatagramDnsResponse(from: /1.1.1.1:53, to: /0:0:0:0:0:0:0:0:56448, 52749, QUERY(0), NoError(0), RD RA)
	DefaultDnsQuestion(api.push.apple.com. IN AAAA)
	DefaultDnsRawRecord(api.push.apple.com. 230 IN CNAME 31B)
	DefaultDnsRawRecord(akadns.net. 110 IN SOA 51B)
	DefaultDnsRawRecord(OPT flags:0 udp:1232 0B)
[DEBUG] 2021-03-17 15:40:31.119 [nioEventLoopGroup-2-1] DnsQueryContext - [id: 0xa67b92d4] WRITE: UDP, [37937: /1.1.1.1:53], DefaultDnsQuestion(api.push-apple.com.akadns.net. IN AAAA)
[DEBUG] 2021-03-17 15:40:31.119 [nioEventLoopGroup-2-1] DnsNameResolver - [id: 0xa67b92d4] RECEIVED: UDP [15374: /1.1.1.1:53], DatagramDnsResponse(from: /1.1.1.1:53, to: /0:0:0:0:0:0:0:0:56448, 15374, QUERY(0), NoError(0), RD RA)
	DefaultDnsQuestion(api.push-apple.com.akadns.net. IN A)
	DefaultDnsRawRecord(api.push-apple.com.akadns.net. 11 IN A 4B)
	DefaultDnsRawRecord(api.push-apple.com.akadns.net. 11 IN A 4B)
	DefaultDnsRawRecord(api.push-apple.com.akadns.net. 11 IN A 4B)
	DefaultDnsRawRecord(api.push-apple.com.akadns.net. 11 IN A 4B)
	DefaultDnsRawRecord(api.push-apple.com.akadns.net. 11 IN A 4B)
	DefaultDnsRawRecord(api.push-apple.com.akadns.net. 11 IN A 4B)
	DefaultDnsRawRecord(api.push-apple.com.akadns.net. 11 IN A 4B)
	DefaultDnsRawRecord(api.push-apple.com.akadns.net. 11 IN A 4B)
	DefaultDnsRawRecord(OPT flags:0 udp:1232 0B)
[DEBUG] 2021-03-17 15:40:31.299 [nioEventLoopGroup-2-1] DnsNameResolver - [id: 0xa67b92d4] RECEIVED: UDP [37937: /1.1.1.1:53], DatagramDnsResponse(from: /1.1.1.1:53, to: /0:0:0:0:0:0:0:0:56448, 37937, QUERY(0), NoError(0), RD RA)
	DefaultDnsQuestion(api.push-apple.com.akadns.net. IN AAAA)
	DefaultDnsRawRecord(akadns.net. 180 IN SOA 54B)
	DefaultDnsRawRecord(OPT flags:0 udp:1232 0B)

No more lines after waited about 20 second. Seem like it jammed on resolve the domain name?

SK-Yang avatar Mar 17 '21 07:03 SK-Yang

I'm still not clear on what's going on here; can you please share your connect/send code (or a simplified version of it)? You wrote:

Hmm, I'm not quiet often of doing that since this APP require synchronized behavior. So my APP must wait for APNS's result before next process.

My worry is that you're somehow blocking the event loop and that's actually what's going on here, but I need more information to be able to provide helpful advice.

jchambers avatar Jul 18 '21 19:07 jchambers

My worry is that you're somehow blocking the event loop and that's actually what's going on here, but I need more information to be able to provide helpful advice.

Nope, it is designed to be a independent micro service. A standalone WAR to receive push token and msg through the servlet, then reply the status from APNS. So there's nothing blocks it because its NOT integrated to be part of a bigger project.

SK-Yang avatar Jul 23 '21 17:07 SK-Yang

Thank you for that update, but I still need more information to really investigate this. Again, can you please share your connect/send code or a simplified version of it?

jchambers avatar Jul 24 '21 15:07 jchambers

Well, here it is

public String send(String session_ID, boolean use_Prod, String p8File_Path, String msg_Title, String key_ID,
			String team_ID, String topic_ID, String apns_ID, String data) throws Exception {

		if (use_Prod) {

			if (apnsClient == null)
				apnsClient = new ApnsClientBuilder().setApnsServer(ApnsClientBuilder.PRODUCTION_APNS_HOST)
						.setSigningKey(ApnsSigningKey.loadFromPkcs8File(new File(p8File_Path), team_ID, key_ID))
						.setConnectionTimeout(timeout)
						.build();
		} else {

			if (apnsClient == null)
				apnsClient = new ApnsClientBuilder().setApnsServer(ApnsClientBuilder.DEVELOPMENT_APNS_HOST)
						.setSigningKey(ApnsSigningKey.loadFromPkcs8File(new File(p8File_Path), team_ID, key_ID))
						.setConnectionTimeout(timeout).build();
		}

		HashMap<String, Object> content = new HashMap<String, Object>();
		HashMap<String, String> aps = new HashMap<String, String>();
		aps.put("alert", msg_Title);
		aps.put("sound", "default");
		content.put("aps", aps);
		content.put("data", data);

		final String payloadStr = new Gson().toJson(content);

		final String token = TokenUtil.sanitizeTokenString(apns_ID);
		final SimpleApnsPushNotification pushNotification = new SimpleApnsPushNotification(token, topic_ID, payloadStr);

		final PushNotificationFuture<SimpleApnsPushNotification, PushNotificationResponse<SimpleApnsPushNotification>> sendNotificationFuture = apnsClient
				.sendNotification(pushNotification);

		String resp = sendNotificationFuture.get().toString();

		if (resp.indexOf("success=true") > -1)
			return ReturnCode.Success;
		else
			return ReturnCode.PushFail;
	}

Thank you for that update, but I still need more information to really investigate this. Again, can you please share your connect/send code or a simplified version of it?

SK-Yang avatar Jul 29 '21 08:07 SK-Yang

@SK-Yang I'm very sorry that so much time has passed since you opened this issue. I'm going to assume—with some embarrassment—that this is no longer an issue for you. If it is still an issue, please open a new discussion and we can investigate in more detail.

jchambers avatar Jan 15 '24 22:01 jchambers