WARN logs on Java Client reconnect?

[Dan Finkelstein]

Hi folks,

I see some WARN log lines about "The Future.set() method can only be called once." and I am trying to determine what they mean and how I can resolve them.

Let's say I have one ec2 server running two processes:
   1. The first with HZ in server mode, and
   2. The second with HZ as a Java Client. 
(This issue also happens if I have 2 ec2 instances, each running one of the two processes).

Now, let's say I stop and restart the first process.

At this point, the second process loses the connection and attempts to reconnect.  It is successful but I see some warnings from hz as shown below.  What do these mean?

Thanks,
Dan


2016-02-12 19:29:49,850 [hz.client_0_k12report.cluster-1] DEBUG com.hazelcast.cluster.impl.AwsUtil - Private addresses! size=1
2016-02-12 19:29:49,851 [hz.client_0_k12report.cluster-1] DEBUG com.hazelcast.cluster.impl.AwsUtil - - privateIpAddress=172.31.4.195
2016-02-12 19:29:49,851 [hz.client_0_k12report.cluster-1] INFO  com.hazelcast.client.spi.impl.AwsAddressProvider - Retrieved instance list from AWS! region=us-west-2; securityGroup=aws-fe2-dev-infr-WebServerSecurityGroup-1VI53JGHMMDCW; instances=[172.31.4.195]
2016-02-12 19:29:49,855 [hz.client_0_k12report.cluster-1] WARN  com.hazelcast.client.spi.impl.ClusterListenerSupport - Unable to get alive cluster connection, try in 19852 ms later, attempt 2 of 60.
2016-02-12 19:30:09,714 [hz.client_0_k12report.cluster-1] DEBUG com.hazelcast.cluster.impl.AwsUtil - Describing instances with request: {InstanceIds: [],Filters: [{Name: instance.group-name,Values: [aws-fe2-dev-infr-WebServerSecurityGroup-1VI53JGHMMDCW]}],}
2016-02-12 19:30:09,835 [hz.client_0_k12report.cluster-1] DEBUG com.hazelcast.cluster.impl.AwsUtil - Accepted instance: {InstanceId: i-7e81f7a4,ImageId: ami-5c455f3d,State: {Code: 16,Name: running},PrivateDnsName: ip-172-31-4-195.us-west-2.compute.internal,PublicDnsName: ec2-52-27-184-116.us-west-2.compute.amazonaws.com,StateTransitionReason: ,KeyName: spot-dev,AmiLaunchIndex: 0,ProductCodes: [],InstanceType: m3.large,LaunchTime: Thu Feb 11 16:50:28 UTC 2016,Placement: {AvailabilityZone: us-west-2c,GroupName: ,Tenancy: default},Monitoring: {State: enabled},SubnetId: subnet-7797522e,VpcId: vpc-9043eff5,PrivateIpAddress: 172.31.4.195,PublicIpAddress: 52.27.184.116,Architecture: x86_64,RootDeviceType: ebs,RootDeviceName: /dev/xvda,BlockDeviceMappings: [{DeviceName: /dev/xvda,Ebs: {VolumeId: vol-d497736d,Status: attached,AttachTime: Thu Feb 11 16:50:32 UTC 2016,DeleteOnTermination: true}}],VirtualizationType: hvm,ClientToken: bc8cd3f7-e08b-4091-89a8-5b6fa1439f00_us-west-2c_1,Tags: [{Key: aws:cloudformation:stack-id,Value: arn:aws:cloudformation:us-west-2:714048452643:stack/aws-fe2-dev-infr/fd34ef10-d0de-11e5-b33e-503f2a2ceee6}, {Key: aws:autoscaling:groupName,Value: aws-fe2-dev-infr-AutoScalingGroup-OPTUEEXCXMU6}, {Key: aws:cloudformation:logical-id,Value: AutoScalingGroup}, {Key: aws:cloudformation:stack-name,Value: aws-fe2-dev-infr}, {Key: Environment,Value: aws-fe2-dev-infr}, {Key: Name,Value: aws-fe2-dev-infr}],SecurityGroups: [{GroupName: aws-fe2-dev-infr-WebServerSecurityGroup-1VI53JGHMMDCW,GroupId: sg-5d35e73a}],SourceDestCheck: true,Hypervisor: xen,NetworkInterfaces: [{NetworkInterfaceId: eni-39efd663,SubnetId: subnet-7797522e,VpcId: vpc-9043eff5,Description: ,OwnerId: 714048452643,Status: in-use,MacAddress: 0a:53:d5:6e:c1:0d,PrivateIpAddress: 172.31.4.195,PrivateDnsName: ip-172-31-4-195.us-west-2.compute.internal,SourceDestCheck: true,Groups: [{GroupName: aws-fe2-dev-infr-WebServerSecurityGroup-1VI53JGHMMDCW,GroupId: sg-5d35e73a}],Attachment: {AttachmentId: eni-attach-b5fea1ba,DeviceIndex: 0,Status: attached,AttachTime: Thu Feb 11 16:50:28 UTC 2016,DeleteOnTermination: true},Association: {PublicIp: 52.27.184.116,PublicDnsName: ec2-52-27-184-116.us-west-2.compute.amazonaws.com,IpOwnerId: amazon},PrivateIpAddresses: [{PrivateIpAddress: 172.31.4.195,PrivateDnsName: ip-172-31-4-195.us-west-2.compute.internal,Primary: true,Association: {PublicIp: 52.27.184.116,PublicDnsName: ec2-52-27-184-116.us-west-2.compute.amazonaws.com,IpOwnerId: amazon}}]}],IamInstanceProfile: {Arn: arn:aws:iam::714048452643:instance-profile/aws-fe2-dev-infr-InstanceProfile-1MU3VDV8VEF49,Id: AIPAJPMI36TQEH5VH5PWI},EbsOptimized: false,}
2016-02-12 19:30:09,844 [hz.client_0_k12report.cluster-1] DEBUG com.hazelcast.cluster.impl.AwsUtil - Private addresses! size=1
2016-02-12 19:30:09,845 [hz.client_0_k12report.cluster-1] DEBUG com.hazelcast.cluster.impl.AwsUtil - - privateIpAddress=172.31.4.195
2016-02-12 19:30:09,845 [hz.client_0_k12report.cluster-1] INFO  com.hazelcast.client.spi.impl.AwsAddressProvider - Retrieved instance list from AWS! region=us-west-2; securityGroup=aws-fe2-dev-infr-WebServerSecurityGroup-1VI53JGHMMDCW; instances=[172.31.4.195]
2016-02-12 19:30:09,940 [hz.client_0_k12report.user-5] INFO  com.hazelcast.core.LifecycleService - HazelcastClient[hz.client_0_k12report][3.6] is CLIENT_CONNECTED
2016-02-12 19:30:09,964 [hz.client_0_k12report.event-2] INFO  com.hazelcast.client.spi.impl.ClientMembershipListener -

Members [1] {
        Member [172.31.4.195]:5701
}
2016-02-12 19:30:10,694 [hz.client_0_k12report.response-] WARN  com.hazelcast.client.spi.impl.ClientInvocationFuture - The Future.set() method can only be called once. Request: ClientMessage{length=58, correlationId=9275, messageType=305, partitionId=140, isComplete=true, isRetryable=false, isEvent=false, writeOffset=0}, current response: ClientMessage{length=23, correlationId=9268, messageType=69, partitionId=-1, isComplete=true, isRetryable=false, isEvent=false, writeOffset=0}, new response: ClientMessage{length=22, correlationId=9272, messageType=69, partitionId=-1, isComplete=false, isRetryable=false, isEvent=false, writeOffset=0}
2016-02-12 19:30:10,695 [hz.client_0_k12report.response-] WARN  com.hazelcast.client.spi.ClientInvocationService - No call for callId: 9272, response: ClientMessage{length=22, correlationId=9272, messageType=69, partitionId=-1, isComplete=false, isRetryable=false, isEvent=false, writeOffset=0}
2016-02-12 19:30:10,695 [hz.client_0_k12report.response-] WARN  com.hazelcast.client.spi.ClientInvocationService - No call for callId: 9272, response: ClientMessage{length=22, correlationId=9272, messageType=69, partitionId=-1, isComplete=false, isRetryable=false, isEvent=false, writeOffset=0}
2016-02-12 19:30:10,695 [hz.client_0_k12report.response-] WARN  com.hazelcast.client.spi.impl.ClientInvocationFuture - The Future.set() method can only be called once. Request: ClientMessage{length=58, correlationId=9275, messageType=305, partitionId=140, isComplete=true, isRetryable=false, isEvent=false, writeOffset=0}, current response: ClientMessage{length=23, correlationId=9268, messageType=69, partitionId=-1, isComplete=true, isRetryable=false, isEvent=false, writeOffset=0}, new response: ClientMessage{length=22, correlationId=9274, messageType=69, partitionId=-1, isComplete=false, isRetryable=false, isEvent=false, writeOffset=0}
2016-02-12 19:30:10,695 [hz.client_0_k12report.response-] WARN  com.hazelcast.client.spi.ClientInvocationService - No call for callId: 9274, response: ClientMessage{length=22, correlationId=9274, messageType=69, partitionId=-1, isComplete=false, isRetryable=false, isEvent=false, writeOffset=0}
2016-02-12 19:30:10,695 [hz.client_0_k12report.response-] WARN  com.hazelcast.client.spi.impl.ClientInvocationFuture - The Future.set() method can only be called once. Request: ClientMessage{length=58, correlationId=9275, messageType=305, partitionId=140, isComplete=true, isRetryable=false, isEvent=false, writeOffset=0}, current response: ClientMessage{length=23, correlationId=9268, messageType=69, partitionId=-1, isComplete=true, isRetryable=false, isEvent=false, writeOffset=0}, new response: ClientMessage{length=22, correlationId=9275, messageType=69, partitionId=-1, isComplete=false, isRetryable=false, isEvent=false, writeOffset=0}
2016-02-12 19:30:10,698 [hz.client_0_k12report.response-] WARN  com.hazelcast.client.spi.ClientInvocationService - No call for callId: 9272, response: ClientMessage{length=22, correlationId=9272, messageType=69, partitionId=-1, isComplete=false, isRetryable=false, isEvent=false, writeOffset=0}
2016-02-12 19:30:10,722 [hz.client_0_k12report.response-] WARN  com.hazelcast.client.spi.impl.ClientInvocationFuture - The Future.set() method can only be called once. Request: ClientMessage{length=58, correlationId=9277, messageType=305, partitionId=140, isComplete=true, isRetryable=false, isEvent=false, writeOffset=0}, current response: ClientMessage{length=23, correlationId=9268, messageType=69, partitionId=-1, isComplete=true, isRetryable=false, isEvent=false, writeOffset=0}, new response: ClientMessage{length=22, correlationId=9277, messageType=69, partitionId=-1, isComplete=false, isRetryable=false, isEvent=false, writeOffset=0}

[ihsan demir]

Can you write the client code you are using? what are the APIs that you are using and what is your client configuration.  What is your hazelcast version?

Regards,

ihsan

12 Şubat 2016 Cuma 23:39:30 UTC+2 tarihinde Dan Finkelstein yazdı:

[Dan Finkelstein]

As requested, here is some background on my environment:
- Running Hazelcast 3.6
- The client basically is accessing a hazlecast queue using poll().  It processes a message and then posts a reply message to a another queue.
- The client uses aws discovery to find our hazelcast server app.
- We use hazelcast's serialization (IdentifiedDataSerializable) for messages.
- Our hazelcast-client.xml is pretty simple. It sets up <network> for aws, and it adds some custom serialization classes.

[Efi Cohen]

We are seeing the exact same thing. any idea?

Efi