Re: Kerberos login error: Message stream modified (41)

[Andor Molnar]

Hi Alessandro,

Thanks for the help. It looks like the issue is on our side: KDC hasn’t been 
properly setup for Zookeeper: required principals don’t exist. 

I just wonder why the error message cannot be more descriptive and if we could 
improve it by properly logging the original exception.

Andor




> On 2019. Oct 29., at 14:35, Alessandro Luccaroni - Diennea 
>  wrote:
> 
> Hi Andor,
> Enrico's collegue here.
> 
> If I remember correctly the issue in our case was related to the 
> ticket_lifetime and renew_lifetime options.
> These two krb.conf options didn't matter before Java 9 (see 
> https://bugs.openjdk.java.net/browse/JDK-8044500 and 
> https://bugs.openjdk.java.net/browse/JDK-8131051) and, as soon as we updated 
> the JDK version, we started to see weird issue related to the ticket 
> expiration. We simply decided to remove the option from the krb.conf and use 
> the Kerberos default.
> 
> With JDK8/Unlimited Strength the problem was related with the enctype: I see 
> that you fixed it on the krb.conf by adding the option to the client, we 
> instead changed the option at the krb level so to ensure that the keytab 
> generated were compatible (supported_enctypes option). I guess this is less 
> of a problem with modern JDKs.
> 
> Regards,
> Alessandro Luccaroni
> Platform Manager @ Diennea - MagNews
> Tel.: (+39) 0546 066100 Int. 924
> Viale G.Marconi 30/14 - 48018 Faenza (RA) - Italy
> 
>> -Messaggio originale-
>> Da: Enrico Olivelli 
>> Inviato: martedì 29 ottobre 2019 14:23
>> A: UserZooKeeper 
>> Oggetto: Re: Kerberos login error: Message stream modified (41)
>> 
>> Andor
>> did you try with a smaller file ?
>> 
>> Enrico
>> 
>> Il giorno mar 29 ott 2019 alle ore 11:09 Enrico Olivelli - Diennea <
>> enrico.olive...@diennea.com> ha scritto:
>> 
>>> I would try to shrink the file to the minimum and add one line at a time.
>>> 
>>> With JDK8 we also had problems with Unlimited Strength policy stuff
>>> 
>>> Hope that helps
>>> 
>>> Enrico Olivelli
>>> MagNews Platform Development Manager @ Diennea – MagNews
>>> Tel.: (+39) 0546 066100 - Int. 125
>>> Viale G.Marconi 30/14 - 48018 Faenza (RA)
>>> 
>>> 
>>> www.diennea.com/en <
>>> 
>> https://www.diennea.com/en?utm_source=Firma_medium=Web
>> m_campaig
>>> n=Firma_Outlook>
>>> | www.magnews.com <
>>> 
>> https://www.magnews.com/?utm_source=Firma_medium=Web
>> _campaign=
>>> Firma_Outlook
 
>>> <
>>> https://www.linkedin.com/company/diennea---
>> magnews/?utm_source=Firma
>>> tm_medium=Web_campaign=Firma_Outlook
 
>>> <
>>> 
>> https://twitter.com/DienneaMagNews?utm_source=Firma_medium=
>> Web
>>> _campaign=Firma_Outlook
 
>>> <
>>> 
>> https://www.facebook.com/DienneaMagNews/?utm_source=Firma_
>> medium=W
>>> eb_campaign=Firma_Outlook
 
>>> 
>>> 
>>> 
>>> Il giorno 29/10/19, 10:55 "Andor Molnar"  ha scritto:
>>> 
>>>Thanks Enrico for the quick help.
>>> 
>>>Here’s my krb5.conf:
>>> 
>>>[libdefaults]
>>>default_realm = STREAMANALYTICS
>>>dns_lookup_kdc = false
>>>dns_lookup_realm = false
>>>ticket_lifetime = 86400
>>>renew_lifetime = 604800
>>>forwardable = true
>>>default_tgs_enctypes = aes256-cts aes128-cts des3-hmac-sha1
>>> arcfour-hmac des3-hmac-sha1 des-cbc-md5
>>>default_tkt_enctypes = aes256-cts aes128-cts des3-hmac-sha1
>>> arcfour-hmac des3-hmac-sha1 des-cbc-md5
>>>permitted_enctypes = aes256-cts aes128-cts des3-hmac-sha1
>>> arcfour-hmac
>>> des3-hmac-sha1 des-cbc-md5
>>>udp_preference_limit = 1
>>>kdc_timeout = 3000
>>>[realms]
>>>STREAMANALYTICS = {
>>>  kdc = ldap0.mydomain.com
>>>  admin_server = ldap0.mydomain.com
>>>}
>>>[domain_realm]
>>> 
>>>;
>>> 
>>>I wonder if the default encryption type settings could be the problem.
>>> I need to verify if it works with Java 8, because it might be a Java
>>> 11 or ZK 3.5 thing. Or both.
>>> 
>>>Andor
>>> 
>>> 
>>> 
>>> 
>>> 
 On 2019. Oct 29., at 8:42, Enrico Olivelli - Diennea <
>>> enrico.olive...@diennea.com> wrote:
 
 Andor,
 this is a minimal krb5.conf file that is working from jdk8 to
>>> jdk13 and ZooKeeper
 
 maybe you can compare to your one and start dropping
>>> configuration lines that are not needed.
 
 Java is adding more and more capabilities to GSSAPI support and
>>> this sometimes leads to behavior changes
 
 
 [libdefaults]
 default_realm = MYDOMAIN
 
 [realms]
 MYDOMAIN  = {
 kdc = kerberos1.mydomain.com
 kdc = kerberos2. mydomain.com
 kdc = kerberos3. mydomain.com
 }
 
 
 
 Enrico Olivelli
 MagNews Platform Development Manager @ Diennea – MagNews
 Tel.: (+39) 0546 066100 - Int. 125
 Viale G.Marconi 30/14 - 48018 Faenza (RA)
 
 
 
 Il giorno 28/10/19, 17:56 "Enrico Olivelli"
>>>  ha scritto:
 
   Andor
 
   Il lun 28 ott 2019, 17:44 Andor Molnar  ha
>>> scritto:
 
> Hi,
> 
> I’m facing the following 

Re: Zookeeper 3.5.6 - Exception causing close of session 0x0: null

[Sebastian Schmitz]

Hello Enrico,

yes, a custom made client, that was updated and now is stopped again...

The difference is that in new version only this is the output:

Oct 25 10:56:23   zookeeper_node_1: 2019-10-24 21:56:23,119 [myid:1] - 
WARN  [NIOWorkerThread-6:NIOServerCnxn@370] - Exception causing close of 
session 0x0: null


In the 3.4.14 it was also stating where the connection came from before 
giving the warning:


Oct 21 16:02:16 zookeeper_node_2: 2019-10-2103:02:16,679 [myid:2] - INFO 
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@222] - 
Accepted socket connection from /10.24.8.13:60517


Best regards

Sebastian


On 29-Oct-19 7:06 PM, Enrico Olivelli wrote:

Il mar 29 ott 2019, 00:52 Sebastian Schmitz <
sebastian.schm...@propellerhead.co.nz> ha scritto:


Hello again,

just as a final update on this. We had a weird consumer which
someone updated without informing me...


Can you please define 'weird'? A custom made client?



Turning it off also turned off

the errors from spamming the logs.

However it seems like the 3.5.6 is less informative than the 3.4.14 we
had before as 3.4.14 also had the IP-Address when the connection was
opened in the messages and not just the warnings...


If you can point to the differences we can bring back precious logs

Great to see you found the problem

Enrico


Best regards

Sebastian


On 25-Oct-19 1:26 PM, Sebastian Schmitz wrote:

Hello Enrico,

thanks for the reply. I'll try to find the exception, there was none
around 14:50 when it first appeared. I also try to find the client
that's connecting just before that as it's not a Kafka-node:

Oct 21 14:50:31 zookeeper_node_3: 2019-10-21 01:50:31,532 [myid:3] -
INFO
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@222] -
Accepted socket connection from /10.24.8.13:64261
Oct 21 14:50:31 zookeeper_node_3: 2019-10-21 01:50:31,544 [myid:3] -
WARN [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@383] -
Exception causing close of session 0x0: null
Oct 21 14:50:31 zookeeper_node_3: 2019-10-21 01:50:31,545 [myid:3] -
INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1056] -
Closed socket connection for client /10.24.8.13:64261 (no session
established for client)

The same IP is able to connect to Zookeeper successfully some time
before:

Oct 21 13:18:44 zookeeper_node_3: 2019-10-21 00:18:44,823 [myid:3] -
INFO
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@222] -
Accepted socket connection from /10.24.8.13:50212
Oct 21 13:18:44 zookeeper_node_3: 2019-10-21 00:18:44,825 [myid:3] -
INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@949] -
Client attempting to establish new session at /10.24.8.13:50212
Oct 21 13:18:44 zookeeper_node_3: 2019-10-21 00:18:44,833 [myid:3] -
INFO  [CommitProcessor:3:ZooKeeperServer@694] - Established session
0x30b2dfdd8ac with negotiated timeout 1 for client
/10.24.8.13:50212
Oct 21 13:18:53 zookeeper_node_3: 2019-10-21 00:18:53,374 [myid:3] -
INFO
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@222] -
Accepted socket connection from /10.24.8.13:50314
Oct 21 13:18:53 zookeeper_node_3: 2019-10-21 00:18:53,374 [myid:3] -
INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@949] -
Client attempting to establish new session at /10.24.8.13:50314
Oct 21 13:18:53 zookeeper_node_3: 2019-10-21 00:18:53,385 [myid:3] -
INFO  [CommitProcessor:3:ZooKeeperServer@694] - Established session
0x30b2dfdd8ac0001 with negotiated timeout 1 for client
/10.24.8.13:50314
Oct 21 13:18:53 zookeeper_node_3: 2019-10-21 00:18:53,588 [myid:3] -
INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1056] -
Closed socket connection for client /10.24.8.13:50314 which had
sessionid 0x30b2dfdd8ac0001

I also checked the Logs from the update I did on Wednesday night to
update to 3.5.6. This is the Log of the start of zookeeper_node_1
until the errors show up... Can't see any exceptions :(

Oct 23 02:07:03 zookeeper_node_1: setting ZOO_LOG4J_PROP=INFO,CONSOLE
Oct 23 02:07:03 zookeeper_node_1: ZooKeeper JMX enabled by default
Oct 23 02:07:03 zookeeper_node_1: Using config:
/opt/zookeeper-cluster/apache-zookeeper-3.5.6-bin/bin/../conf/zoo.cfg
Oct 23 02:07:05 zookeeper_node_1: Oct 22, 2019 13:07:05 + [1 1]
com.newrelic INFO: New Relic Agent: Loading configuration file
"/opt/zookeeper-cluster/newrelic/./newrelic.yml"
Oct 23 02:07:05 zookeeper_node_1: Oct 22, 2019 13:07:05 + [1 1]
com.newrelic INFO: Using default collector host: collector.newrelic.com
Oct 23 02:07:05 zookeeper_node_1: Oct 22, 2019 13:07:05 + [1 1]
com.newrelic INFO: New Relic Agent: Writing to log file:
/opt/zookeeper-cluster/newrelic/logs/newrelic_agent.log
Oct 23 02:07:28 zookeeper_node_1: 2019-10-22 13:07:28,743 [myid:] -
INFO  [main:QuorumPeerConfig@133] - Reading configuration from:
/opt/zookeeper-cluster/apache-zookeeper-3.5.6-bin/bin/../conf/zoo.cfg
Oct 23 02:07:28 zookeeper_node_1: 2019-10-22 13:07:28,764 [myid:] -
INFO  

R: Kerberos login error: Message stream modified (41)

[Alessandro Luccaroni - Diennea]

Hi Andor,
Enrico's collegue here.

If I remember correctly the issue in our case was related to the 
ticket_lifetime and renew_lifetime options.
These two krb.conf options didn't matter before Java 9 (see 
https://bugs.openjdk.java.net/browse/JDK-8044500 and 
https://bugs.openjdk.java.net/browse/JDK-8131051) and, as soon as we updated 
the JDK version, we started to see weird issue related to the ticket 
expiration. We simply decided to remove the option from the krb.conf and use 
the Kerberos default.

With JDK8/Unlimited Strength the problem was related with the enctype: I see 
that you fixed it on the krb.conf by adding the option to the client, we 
instead changed the option at the krb level so to ensure that the keytab 
generated were compatible (supported_enctypes option). I guess this is less of 
a problem with modern JDKs.

Regards,
Alessandro Luccaroni
Platform Manager @ Diennea - MagNews
Tel.: (+39) 0546 066100 Int. 924
Viale G.Marconi 30/14 - 48018 Faenza (RA) - Italy

> -Messaggio originale-
> Da: Enrico Olivelli 
> Inviato: martedì 29 ottobre 2019 14:23
> A: UserZooKeeper 
> Oggetto: Re: Kerberos login error: Message stream modified (41)
>
> Andor
> did you try with a smaller file ?
>
> Enrico
>
> Il giorno mar 29 ott 2019 alle ore 11:09 Enrico Olivelli - Diennea <
> enrico.olive...@diennea.com> ha scritto:
>
> > I would try to shrink the file to the minimum and add one line at a time.
> >
> > With JDK8 we also had problems with Unlimited Strength policy stuff
> >
> > Hope that helps
> >
> > Enrico Olivelli
> > MagNews Platform Development Manager @ Diennea – MagNews
> > Tel.: (+39) 0546 066100 - Int. 125
> > Viale G.Marconi 30/14 - 48018 Faenza (RA)
> >
> >
> > www.diennea.com/en <
> >
> https://www.diennea.com/en?utm_source=Firma_medium=Web
> m_campaig
> > n=Firma_Outlook>
> > | www.magnews.com <
> >
> https://www.magnews.com/?utm_source=Firma_medium=Web
> _campaign=
> > Firma_Outlook
> > >
> >  <
> > https://www.linkedin.com/company/diennea---
> magnews/?utm_source=Firma
> > tm_medium=Web_campaign=Firma_Outlook
> > >
> >  <
> >
> https://twitter.com/DienneaMagNews?utm_source=Firma_medium=
> Web
> > _campaign=Firma_Outlook
> > >
> >  <
> >
> https://www.facebook.com/DienneaMagNews/?utm_source=Firma_
> medium=W
> > eb_campaign=Firma_Outlook
> > >
> >
> >
> >
> > Il giorno 29/10/19, 10:55 "Andor Molnar"  ha scritto:
> >
> > Thanks Enrico for the quick help.
> >
> > Here’s my krb5.conf:
> >
> > [libdefaults]
> > default_realm = STREAMANALYTICS
> > dns_lookup_kdc = false
> > dns_lookup_realm = false
> > ticket_lifetime = 86400
> > renew_lifetime = 604800
> > forwardable = true
> > default_tgs_enctypes = aes256-cts aes128-cts des3-hmac-sha1
> > arcfour-hmac des3-hmac-sha1 des-cbc-md5
> > default_tkt_enctypes = aes256-cts aes128-cts des3-hmac-sha1
> > arcfour-hmac des3-hmac-sha1 des-cbc-md5
> > permitted_enctypes = aes256-cts aes128-cts des3-hmac-sha1
> > arcfour-hmac
> > des3-hmac-sha1 des-cbc-md5
> > udp_preference_limit = 1
> > kdc_timeout = 3000
> > [realms]
> > STREAMANALYTICS = {
> >   kdc = ldap0.mydomain.com
> >   admin_server = ldap0.mydomain.com
> > }
> > [domain_realm]
> >
> > ;
> >
> > I wonder if the default encryption type settings could be the problem.
> > I need to verify if it works with Java 8, because it might be a Java
> > 11 or ZK 3.5 thing. Or both.
> >
> > Andor
> >
> >
> >
> >
> >
> > > On 2019. Oct 29., at 8:42, Enrico Olivelli - Diennea <
> > enrico.olive...@diennea.com> wrote:
> > >
> > > Andor,
> > > this is a minimal krb5.conf file that is working from jdk8 to
> > jdk13 and ZooKeeper
> > >
> > > maybe you can compare to your one and start dropping
> > configuration lines that are not needed.
> > >
> > > Java is adding more and more capabilities to GSSAPI support and
> > this sometimes leads to behavior changes
> > >
> > >
> > > [libdefaults]
> > > default_realm = MYDOMAIN
> > >
> > > [realms]
> > > MYDOMAIN  = {
> > >  kdc = kerberos1.mydomain.com
> > >  kdc = kerberos2. mydomain.com
> > >  kdc = kerberos3. mydomain.com
> > > }
> > >
> > >
> > >
> > > Enrico Olivelli
> > > MagNews Platform Development Manager @ Diennea – MagNews
> > > Tel.: (+39) 0546 066100 - Int. 125
> > > Viale G.Marconi 30/14 - 48018 Faenza (RA)
> > >
> > >
> > >
> > > Il giorno 28/10/19, 17:56 "Enrico Olivelli"
> >  ha scritto:
> > >
> > >Andor
> > >
> > >Il lun 28 ott 2019, 17:44 Andor Molnar  ha
> > scritto:
> > >
> > >> Hi,
> > >>
> > >> I’m facing the following error message when trying to run
> > ZooKeeper
> > 3.5.5
> > >> on Java 11 with Kerberos authentication:
> > >>
> > >> 2019-10-28 16:30:04,811 INFO
> > >> org.apache.zookeeper.server.ServerCnxnFactory: Using
> > >> 

Re: Issue Workaround

[Matthew Knight]

In my 3 node cluster if I stop one of the followers Zookeeper service
everything is fine, connections migrate and there's no interruption of
service.
If I stop the leader's Zookeeper service a lot of things *appear* fine, if
I run
echo "status" | nc  localhost 2181
The output looks normal:  a new node has been elected leader and
connections have moved.  Logs aren't showing anything out of the ordinary.
As far as you can tell from looking at the Zookeeper cluster at this point
everything should be fine.

However on the client side there's a different story (client is an Apache
NiFi 1.9.2 cluster).  The Curator client is in an infinite loop of:
o.a.c.f.state.ConnectionStateManager State change: RECONNECTED
o.a.c.f.state.ConnectionStateManager State change: SUSPENDED
o.a.c.f.imps.CuratorFrameworkImpl Background operation retry gave up
org.apache.zookeeper.KeeperException$ConnectionLossException:
KeeperErrorCode = ConnectionLoss
o.a.c.f.state.ConnectionStateManager State change: LOST
... series of attempts to reconnect which ultimately start the cycle over
again with ...
o.a.c.f.state.ConnectionStateManager State change: RECONNECTED

So while the Zookeeper cluster appears functional it is not actually
accepting client connections.  I spent the lot of time looking at the
client code but what makes me confident it's was a Zookeeper issue is that
when I try to start the Zookeeper service on the former leader again and run
'echo "status" | nc  localhost 2181'
It reports
This ZooKeeper instance is not currently serving requests
This is exactly the behavior described in the ZOOKEEPER-2164 comment trail
by Michael Durr.

The old leader now restarted has the following on loop in the logs:
2019-10-29 13:04:18,961 [myid:2] - INFO
 
[QuorumPeer[myid=2](plain=/0:0:0:0:0:0:0:0:2181)(secure=disabled):FastLeaderElection@919]
- Notification time out: 51200
2019-10-29 13:04:18,966 [myid:2] - INFO
 [WorkerSender[myid=2]:QuorumCnxManager@430] - Have smaller server
identifier, so dropping the connection: (3, 2)
2019-10-29 13:04:18,966 [myid:2] - INFO
 [WorkerReceiver[myid=2]:FastLeaderElection@679] - Notification: 2 (message
format version), 3 (n.leader), 0x2600c0 (n.zxid), 0x2 (n.round),
LOOKING (n.state), 2 (n.sid), 0x27 (n.peerEPoch), LOOKING (my state)0
(n.config version)
2019-10-29 13:04:18,969 [myid:2] - INFO
 [WorkerReceiver[myid=2]:FastLeaderElection@679] - Notification: 2 (message
format version), 3 (n.leader), 0x2600c0 (n.zxid), 0x2 (n.round),
FOLLOWING (n.state), 1 (n.sid), 0x28 (n.peerEPoch), LOOKING (my state)0
(n.config version)
It never comes on as a follower and continues to report it is not serving
requests.

The new leader's logs have this series of events:
2019-10-29 13:09:10,221 [myid:3] - INFO  [/0.0.0.0:3888
:QuorumCnxManager$Listener@888] - Received connection request /
10.251.0.7:43492
2019-10-29 13:09:10,221 [myid:3] - WARN
 [RecvWorker:3:QuorumCnxManager$RecvWorker@1176] - Connection broken for id
3, my id = 3, error =
java.io.EOFException
at
java.base/java.io.DataInputStream.readInt(DataInputStream.java:397)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager$RecvWorker.run(QuorumCnxManager.java:1161)
2019-10-29 13:09:10,222 [myid:3] - WARN
 [RecvWorker:3:QuorumCnxManager$RecvWorker@1179] - Interrupting SendWorker
2019-10-29 13:09:10,222 [myid:3] - WARN
 [RecvWorker:2:QuorumCnxManager$RecvWorker@1176] - Connection broken for id
2, my id = 3, error =
java.net.SocketException: Socket closed
at java.base/java.net.SocketInputStream.socketRead0(Native Method)
at
java.base/java.net.SocketInputStream.socketRead(SocketInputStream.java:115)
at
java.base/java.net.SocketInputStream.read(SocketInputStream.java:168)
at
java.base/java.net.SocketInputStream.read(SocketInputStream.java:140)
at
java.base/java.io.BufferedInputStream.fill(BufferedInputStream.java:252)
at
java.base/java.io.BufferedInputStream.read(BufferedInputStream.java:271)
at
java.base/java.io.DataInputStream.readInt(DataInputStream.java:392)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager$RecvWorker.run(QuorumCnxManager.java:1161)
2019-10-29 13:09:10,223 [myid:3] - WARN
 [RecvWorker:2:QuorumCnxManager$RecvWorker@1179] - Interrupting SendWorker
2019-10-29 13:09:10,221 [myid:3] - WARN
 [SendWorker:2:QuorumCnxManager$SendWorker@1092] - Interrupted while
waiting for message on queue
java.lang.InterruptedException
at
java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2056)
at
java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2133)
at
java.base/java.util.concurrent.ArrayBlockingQueue.poll(ArrayBlockingQueue.java:432)
at
org.apache.zookeeper.server.quorum.QuorumCnxManager.pollSendQueue(QuorumCnxManager.java:1243)
at

Re: Kerberos login error: Message stream modified (41)

[Enrico Olivelli]

Andor
did you try with a smaller file ?

Enrico

Il giorno mar 29 ott 2019 alle ore 11:09 Enrico Olivelli - Diennea <
enrico.olive...@diennea.com> ha scritto:

> I would try to shrink the file to the minimum and add one line at a time.
>
> With JDK8 we also had problems with Unlimited Strength policy stuff
>
> Hope that helps
>
> Enrico Olivelli
> MagNews Platform Development Manager @ Diennea – MagNews
> Tel.: (+39) 0546 066100 - Int. 125
> Viale G.Marconi 30/14 - 48018 Faenza (RA)
>
>
> www.diennea.com/en <
> https://www.diennea.com/en?utm_source=Firma_medium=Web_campaign=Firma_Outlook>
> | www.magnews.com <
> https://www.magnews.com/?utm_source=Firma_medium=Web_campaign=Firma_Outlook
> >
>  <
> https://www.linkedin.com/company/diennea---magnews/?utm_source=Firma_medium=Web_campaign=Firma_Outlook
> >
>  <
> https://twitter.com/DienneaMagNews?utm_source=Firma_medium=Web_campaign=Firma_Outlook
> >
>  <
> https://www.facebook.com/DienneaMagNews/?utm_source=Firma_medium=Web_campaign=Firma_Outlook
> >
>
>
>
> Il giorno 29/10/19, 10:55 "Andor Molnar"  ha scritto:
>
> Thanks Enrico for the quick help.
>
> Here’s my krb5.conf:
>
> [libdefaults]
> default_realm = STREAMANALYTICS
> dns_lookup_kdc = false
> dns_lookup_realm = false
> ticket_lifetime = 86400
> renew_lifetime = 604800
> forwardable = true
> default_tgs_enctypes = aes256-cts aes128-cts des3-hmac-sha1
> arcfour-hmac des3-hmac-sha1 des-cbc-md5
> default_tkt_enctypes = aes256-cts aes128-cts des3-hmac-sha1
> arcfour-hmac des3-hmac-sha1 des-cbc-md5
> permitted_enctypes = aes256-cts aes128-cts des3-hmac-sha1 arcfour-hmac
> des3-hmac-sha1 des-cbc-md5
> udp_preference_limit = 1
> kdc_timeout = 3000
> [realms]
> STREAMANALYTICS = {
>   kdc = ldap0.mydomain.com
>   admin_server = ldap0.mydomain.com
> }
> [domain_realm]
>
> ;
>
> I wonder if the default encryption type settings could be the problem.
> I need to verify if it works with Java 8, because it might be a Java 11 or
> ZK 3.5 thing. Or both.
>
> Andor
>
>
>
>
>
> > On 2019. Oct 29., at 8:42, Enrico Olivelli - Diennea <
> enrico.olive...@diennea.com> wrote:
> >
> > Andor,
> > this is a minimal krb5.conf file that is working from jdk8 to jdk13
> and ZooKeeper
> >
> > maybe you can compare to your one and start dropping configuration
> lines that are not needed.
> >
> > Java is adding more and more capabilities to GSSAPI support and this
> sometimes leads to behavior changes
> >
> >
> > [libdefaults]
> > default_realm = MYDOMAIN
> >
> > [realms]
> > MYDOMAIN  = {
> >  kdc = kerberos1.mydomain.com
> >  kdc = kerberos2. mydomain.com
> >  kdc = kerberos3. mydomain.com
> > }
> >
> >
> >
> > Enrico Olivelli
> > MagNews Platform Development Manager @ Diennea – MagNews
> > Tel.: (+39) 0546 066100 - Int. 125
> > Viale G.Marconi 30/14 - 48018 Faenza (RA)
> >
> >
> >
> > Il giorno 28/10/19, 17:56 "Enrico Olivelli" 
> ha scritto:
> >
> >Andor
> >
> >Il lun 28 ott 2019, 17:44 Andor Molnar  ha
> scritto:
> >
> >> Hi,
> >>
> >> I’m facing the following error message when trying to run ZooKeeper
> 3.5.5
> >> on Java 11 with Kerberos authentication:
> >>
> >> 2019-10-28 16:30:04,811 INFO
> >> org.apache.zookeeper.server.ServerCnxnFactory: Using
> >> org.apache.zookeeper.server.NIOServerCnxnFactory as server
> connection
> >> factory
> >> 2019-10-28 16:30:04,823 INFO org.apache.zookeeper.common.X509Util:
> Setting
> >> -D jdk.tls.rejectClientInitiatedRenegotiation=true to disable
> >> client-initiated TLS renegotiation
> >> 2019-10-28 16:30:05,012 ERROR
> >> org.apache.zookeeper.server.quorum.QuorumPeerMain: Unexpected
> exception,
> >> exiting abnormally
> >> java.io.IOException: Could not configure server because SASL
> configuration
> >> did not allow the  ZooKeeper server to authenticate itself properly:
> >> javax.security.auth.login.LoginException: Message stream modified
> (41)
> >>at
> >>
> org.apache.zookeeper.server.ServerCnxnFactory.configureSaslLogin(ServerCnxnFactory.java:243)
> >>at
> >>
> org.apache.zookeeper.server.NIOServerCnxnFactory.configure(NIOServerCnxnFactory.java:646)
> >>at
> >>
> org.apache.zookeeper.server.quorum.QuorumPeerMain.runFromConfig(QuorumPeerMain.java:148)
> >>at
> >>
> org.apache.zookeeper.server.quorum.QuorumPeerMain.initializeAndRun(QuorumPeerMain.java:123)
> >>at
> >>
> org.apache.zookeeper.server.quorum.QuorumPeerMain.main(QuorumPeerMain.java:82)
> >> …
> >>
> >> zoo.cfg:
> >> 
> >> tickTime=2000
> >> initLimit=10
> >> syncLimit=5
> >>
> >>
> 4lw.commands.whitelist=conf,cons,crst,dirs,dump,envi,gtmk,ruok,stmk,srst,srvr,stat,wchs,mntr,isro
> >> 

Re: Kerberos login error: Message stream modified (41)

[Enrico Olivelli - Diennea]

I would try to shrink the file to the minimum and add one line at a time.

With JDK8 we also had problems with Unlimited Strength policy stuff

Hope that helps

Enrico Olivelli
MagNews Platform Development Manager @ Diennea – MagNews
Tel.: (+39) 0546 066100 - Int. 125
Viale G.Marconi 30/14 - 48018 Faenza (RA)


www.diennea.com/en 

 | www.magnews.com 

 

 

 




Il giorno 29/10/19, 10:55 "Andor Molnar"  ha scritto:

Thanks Enrico for the quick help.

Here’s my krb5.conf:

[libdefaults]
default_realm = STREAMANALYTICS
dns_lookup_kdc = false
dns_lookup_realm = false
ticket_lifetime = 86400
renew_lifetime = 604800
forwardable = true
default_tgs_enctypes = aes256-cts aes128-cts des3-hmac-sha1 arcfour-hmac 
des3-hmac-sha1 des-cbc-md5
default_tkt_enctypes = aes256-cts aes128-cts des3-hmac-sha1 arcfour-hmac 
des3-hmac-sha1 des-cbc-md5
permitted_enctypes = aes256-cts aes128-cts des3-hmac-sha1 arcfour-hmac 
des3-hmac-sha1 des-cbc-md5
udp_preference_limit = 1
kdc_timeout = 3000
[realms]
STREAMANALYTICS = {
  kdc = ldap0.mydomain.com
  admin_server = ldap0.mydomain.com
}
[domain_realm]

;

I wonder if the default encryption type settings could be the problem. I 
need to verify if it works with Java 8, because it might be a Java 11 or ZK 3.5 
thing. Or both.

Andor





> On 2019. Oct 29., at 8:42, Enrico Olivelli - Diennea 
 wrote:
>
> Andor,
> this is a minimal krb5.conf file that is working from jdk8 to jdk13 and 
ZooKeeper
>
> maybe you can compare to your one and start dropping configuration lines 
that are not needed.
>
> Java is adding more and more capabilities to GSSAPI support and this 
sometimes leads to behavior changes
>
>
> [libdefaults]
> default_realm = MYDOMAIN
>
> [realms]
> MYDOMAIN  = {
>  kdc = kerberos1.mydomain.com
>  kdc = kerberos2. mydomain.com
>  kdc = kerberos3. mydomain.com
> }
>
>
>
> Enrico Olivelli
> MagNews Platform Development Manager @ Diennea – MagNews
> Tel.: (+39) 0546 066100 - Int. 125
> Viale G.Marconi 30/14 - 48018 Faenza (RA)
>
>
>
> Il giorno 28/10/19, 17:56 "Enrico Olivelli"  ha 
scritto:
>
>Andor
>
>Il lun 28 ott 2019, 17:44 Andor Molnar  ha scritto:
>
>> Hi,
>>
>> I’m facing the following error message when trying to run ZooKeeper 3.5.5
>> on Java 11 with Kerberos authentication:
>>
>> 2019-10-28 16:30:04,811 INFO
>> org.apache.zookeeper.server.ServerCnxnFactory: Using
>> org.apache.zookeeper.server.NIOServerCnxnFactory as server connection
>> factory
>> 2019-10-28 16:30:04,823 INFO org.apache.zookeeper.common.X509Util: 
Setting
>> -D jdk.tls.rejectClientInitiatedRenegotiation=true to disable
>> client-initiated TLS renegotiation
>> 2019-10-28 16:30:05,012 ERROR
>> org.apache.zookeeper.server.quorum.QuorumPeerMain: Unexpected exception,
>> exiting abnormally
>> java.io.IOException: Could not configure server because SASL 
configuration
>> did not allow the  ZooKeeper server to authenticate itself properly:
>> javax.security.auth.login.LoginException: Message stream modified (41)
>>at
>> 
org.apache.zookeeper.server.ServerCnxnFactory.configureSaslLogin(ServerCnxnFactory.java:243)
>>at
>> 
org.apache.zookeeper.server.NIOServerCnxnFactory.configure(NIOServerCnxnFactory.java:646)
>>at
>> 
org.apache.zookeeper.server.quorum.QuorumPeerMain.runFromConfig(QuorumPeerMain.java:148)
>>at
>> 
org.apache.zookeeper.server.quorum.QuorumPeerMain.initializeAndRun(QuorumPeerMain.java:123)
>>at
>> 
org.apache.zookeeper.server.quorum.QuorumPeerMain.main(QuorumPeerMain.java:82)
>> …
>>
>> zoo.cfg:
>> 
>> tickTime=2000
>> initLimit=10
>> syncLimit=5
>>
>> 
4lw.commands.whitelist=conf,cons,crst,dirs,dump,envi,gtmk,ruok,stmk,srst,srvr,stat,wchs,mntr,isro
>> dataDir=/var/lib/zookeeper
>> dataLogDir=/var/lib/zookeeper
>> clientPort=2181
>> maxClientCnxns=60
>> minSessionTimeout=4000
>> maxSessionTimeout=6
>> autopurge.purgeInterval=24
>> autopurge.snapRetainCount=5
>> quorum.auth.enableSasl=true
>> quorum.cnxn.threads.size=20
>> admin.enableServer=false
>> admin.serverPort=5181
>> server.1=cdf1-dc1.mydomain.com:3181:4181
>> server.2=cdf1-dc2.mydomain.com:3181:4181
>> 

Re: Kerberos login error: Message stream modified (41)

[Andor Molnar]

Thanks Enrico for the quick help.

Here’s my krb5.conf:

[libdefaults]
default_realm = STREAMANALYTICS
dns_lookup_kdc = false
dns_lookup_realm = false
ticket_lifetime = 86400
renew_lifetime = 604800
forwardable = true
default_tgs_enctypes = aes256-cts aes128-cts des3-hmac-sha1 arcfour-hmac 
des3-hmac-sha1 des-cbc-md5
default_tkt_enctypes = aes256-cts aes128-cts des3-hmac-sha1 arcfour-hmac 
des3-hmac-sha1 des-cbc-md5
permitted_enctypes = aes256-cts aes128-cts des3-hmac-sha1 arcfour-hmac 
des3-hmac-sha1 des-cbc-md5
udp_preference_limit = 1
kdc_timeout = 3000
[realms]
STREAMANALYTICS = {
  kdc = ldap0.mydomain.com
  admin_server = ldap0.mydomain.com
}
[domain_realm]

;

I wonder if the default encryption type settings could be the problem. I need 
to verify if it works with Java 8, because it might be a Java 11 or ZK 3.5 
thing. Or both.

Andor





> On 2019. Oct 29., at 8:42, Enrico Olivelli - Diennea 
>  wrote:
> 
> Andor,
> this is a minimal krb5.conf file that is working from jdk8 to jdk13 and 
> ZooKeeper
> 
> maybe you can compare to your one and start dropping configuration lines that 
> are not needed.
> 
> Java is adding more and more capabilities to GSSAPI support and this 
> sometimes leads to behavior changes
> 
> 
> [libdefaults]
> default_realm = MYDOMAIN
> 
> [realms]
> MYDOMAIN  = {
>  kdc = kerberos1.mydomain.com
>  kdc = kerberos2. mydomain.com
>  kdc = kerberos3. mydomain.com
> }
> 
> 
> 
> Enrico Olivelli
> MagNews Platform Development Manager @ Diennea – MagNews
> Tel.: (+39) 0546 066100 - Int. 125
> Viale G.Marconi 30/14 - 48018 Faenza (RA)
> 
> 
> 
> Il giorno 28/10/19, 17:56 "Enrico Olivelli"  ha scritto:
> 
>Andor
> 
>Il lun 28 ott 2019, 17:44 Andor Molnar  ha scritto:
> 
>> Hi,
>> 
>> I’m facing the following error message when trying to run ZooKeeper 3.5.5
>> on Java 11 with Kerberos authentication:
>> 
>> 2019-10-28 16:30:04,811 INFO
>> org.apache.zookeeper.server.ServerCnxnFactory: Using
>> org.apache.zookeeper.server.NIOServerCnxnFactory as server connection
>> factory
>> 2019-10-28 16:30:04,823 INFO org.apache.zookeeper.common.X509Util: Setting
>> -D jdk.tls.rejectClientInitiatedRenegotiation=true to disable
>> client-initiated TLS renegotiation
>> 2019-10-28 16:30:05,012 ERROR
>> org.apache.zookeeper.server.quorum.QuorumPeerMain: Unexpected exception,
>> exiting abnormally
>> java.io.IOException: Could not configure server because SASL configuration
>> did not allow the  ZooKeeper server to authenticate itself properly:
>> javax.security.auth.login.LoginException: Message stream modified (41)
>>at
>> org.apache.zookeeper.server.ServerCnxnFactory.configureSaslLogin(ServerCnxnFactory.java:243)
>>at
>> org.apache.zookeeper.server.NIOServerCnxnFactory.configure(NIOServerCnxnFactory.java:646)
>>at
>> org.apache.zookeeper.server.quorum.QuorumPeerMain.runFromConfig(QuorumPeerMain.java:148)
>>at
>> org.apache.zookeeper.server.quorum.QuorumPeerMain.initializeAndRun(QuorumPeerMain.java:123)
>>at
>> org.apache.zookeeper.server.quorum.QuorumPeerMain.main(QuorumPeerMain.java:82)
>> …
>> 
>> zoo.cfg:
>> 
>> tickTime=2000
>> initLimit=10
>> syncLimit=5
>> 
>> 4lw.commands.whitelist=conf,cons,crst,dirs,dump,envi,gtmk,ruok,stmk,srst,srvr,stat,wchs,mntr,isro
>> dataDir=/var/lib/zookeeper
>> dataLogDir=/var/lib/zookeeper
>> clientPort=2181
>> maxClientCnxns=60
>> minSessionTimeout=4000
>> maxSessionTimeout=6
>> autopurge.purgeInterval=24
>> autopurge.snapRetainCount=5
>> quorum.auth.enableSasl=true
>> quorum.cnxn.threads.size=20
>> admin.enableServer=false
>> admin.serverPort=5181
>> server.1=cdf1-dc1.mydomain.com:3181:4181
>> server.2=cdf1-dc2.mydomain.com:3181:4181
>> server.3=cdf1-dc3.mydomain.com:3181:4181
>> leaderServes=yes
>> authProvider.1=org.apache.zookeeper.server.auth.SASLAuthenticationProvider
>> kerberos.removeHostFromPrincipal=true
>> kerberos.removeRealmFromPrincipal=true
>> quorum.auth.kerberos.servicePrincipal=zookeeper/_HOST
>> quorum.auth.learnerRequireSasl=true
>> quorum.auth.serverRequireSasl=true
>> 
>> java -version:
>> ——
>> openjdk version "11.0.4" 2019-07-16
>> OpenJDK Runtime Environment AdoptOpenJDK (build 11.0.4+11)
>> OpenJDK 64-Bit Server VM AdoptOpenJDK (build 11.0.4+11, mixed mode)
>> 
>> 
>> Has anyone seen this problem before?
>> What does the error message mean?
>> 
>> Unfortunately we swallow the original exception in ServerCnxnFactory and
>> only log the message without stacktrace.
>> 
> 
>Did you enable debug?
>
> https://stackoverflow.com/questions/15382056/enable-detailed-logging-for-kerberos-in-java
> 
>I remember we had some issue while switching from jdk8 to jdk9
> 
>There were something in krb.conf that was not compatible due to some
>stricter condig check but we didn't need that line and we dropped it.
>I can check only tomorrow at work.
>Unfortunately java Kerberos client is not so verbose.
> 
>Can you share your krb config files? Without hostnames
> 

Re: Kerberos login error: Message stream modified (41)

[Enrico Olivelli - Diennea]

Andor,
this is a minimal krb5.conf file that is working from jdk8 to jdk13 and 
ZooKeeper

maybe you can compare to your one and start dropping configuration lines that 
are not needed.

Java is adding more and more capabilities to GSSAPI support and this sometimes 
leads to behavior changes


[libdefaults]
 default_realm = MYDOMAIN

[realms]
 MYDOMAIN  = {
  kdc = kerberos1.mydomain.com
  kdc = kerberos2. mydomain.com
  kdc = kerberos3. mydomain.com
 }



Enrico Olivelli
MagNews Platform Development Manager @ Diennea – MagNews
Tel.: (+39) 0546 066100 - Int. 125
Viale G.Marconi 30/14 - 48018 Faenza (RA)



Il giorno 28/10/19, 17:56 "Enrico Olivelli"  ha scritto:

Andor

Il lun 28 ott 2019, 17:44 Andor Molnar  ha scritto:

> Hi,
>
> I’m facing the following error message when trying to run ZooKeeper 3.5.5
> on Java 11 with Kerberos authentication:
>
> 2019-10-28 16:30:04,811 INFO
> org.apache.zookeeper.server.ServerCnxnFactory: Using
> org.apache.zookeeper.server.NIOServerCnxnFactory as server connection
> factory
> 2019-10-28 16:30:04,823 INFO org.apache.zookeeper.common.X509Util: Setting
> -D jdk.tls.rejectClientInitiatedRenegotiation=true to disable
> client-initiated TLS renegotiation
> 2019-10-28 16:30:05,012 ERROR
> org.apache.zookeeper.server.quorum.QuorumPeerMain: Unexpected exception,
> exiting abnormally
> java.io.IOException: Could not configure server because SASL configuration
> did not allow the  ZooKeeper server to authenticate itself properly:
> javax.security.auth.login.LoginException: Message stream modified (41)
> at
> 
org.apache.zookeeper.server.ServerCnxnFactory.configureSaslLogin(ServerCnxnFactory.java:243)
> at
> 
org.apache.zookeeper.server.NIOServerCnxnFactory.configure(NIOServerCnxnFactory.java:646)
> at
> 
org.apache.zookeeper.server.quorum.QuorumPeerMain.runFromConfig(QuorumPeerMain.java:148)
> at
> 
org.apache.zookeeper.server.quorum.QuorumPeerMain.initializeAndRun(QuorumPeerMain.java:123)
> at
> 
org.apache.zookeeper.server.quorum.QuorumPeerMain.main(QuorumPeerMain.java:82)
> …
>
> zoo.cfg:
> 
> tickTime=2000
> initLimit=10
> syncLimit=5
>
> 
4lw.commands.whitelist=conf,cons,crst,dirs,dump,envi,gtmk,ruok,stmk,srst,srvr,stat,wchs,mntr,isro
> dataDir=/var/lib/zookeeper
> dataLogDir=/var/lib/zookeeper
> clientPort=2181
> maxClientCnxns=60
> minSessionTimeout=4000
> maxSessionTimeout=6
> autopurge.purgeInterval=24
> autopurge.snapRetainCount=5
> quorum.auth.enableSasl=true
> quorum.cnxn.threads.size=20
> admin.enableServer=false
> admin.serverPort=5181
> server.1=cdf1-dc1.mydomain.com:3181:4181
> server.2=cdf1-dc2.mydomain.com:3181:4181
> server.3=cdf1-dc3.mydomain.com:3181:4181
> leaderServes=yes
> authProvider.1=org.apache.zookeeper.server.auth.SASLAuthenticationProvider
> kerberos.removeHostFromPrincipal=true
> kerberos.removeRealmFromPrincipal=true
> quorum.auth.kerberos.servicePrincipal=zookeeper/_HOST
> quorum.auth.learnerRequireSasl=true
> quorum.auth.serverRequireSasl=true
>
> java -version:
> ——
> openjdk version "11.0.4" 2019-07-16
> OpenJDK Runtime Environment AdoptOpenJDK (build 11.0.4+11)
> OpenJDK 64-Bit Server VM AdoptOpenJDK (build 11.0.4+11, mixed mode)
>
>
> Has anyone seen this problem before?
> What does the error message mean?
>
> Unfortunately we swallow the original exception in ServerCnxnFactory and
> only log the message without stacktrace.
>

Did you enable debug?

https://stackoverflow.com/questions/15382056/enable-detailed-logging-for-kerberos-in-java

I remember we had some issue while switching from jdk8 to jdk9

There were something in krb.conf that was not compatible due to some
stricter condig check but we didn't need that line and we dropped it.
I can check only tomorrow at work.
Unfortunately java Kerberos client is not so verbose.

Can you share your krb config files? Without hostnames

Enrico


> Thanks,
> Andor
>
>
>





CONFIDENTIALITY & PRIVACY NOTICE
This e-mail (including any attachments) is strictly confidential and may also 
contain privileged information. If you are not the intended recipient you are 
not authorised to read, print, save, process or disclose this message. If you 
have received this message by mistake, please inform the sender immediately and 
destroy this e-mail, its attachments and any copies. Any use, distribution, 
reproduction or disclosure by any person other than the intended recipient is 
strictly prohibited and the person responsible may incur in penalties.
The use of this e-mail is only for professional purposes; there is no guarantee 
that the correspondence towards this 

Re: Zookeeper 3.5.6 - Exception causing close of session 0x0: null

[Enrico Olivelli]

Il mar 29 ott 2019, 00:52 Sebastian Schmitz <
sebastian.schm...@propellerhead.co.nz> ha scritto:

> Hello again,
>
> just as a final update on this. We had a weird consumer which
> someone updated without informing me...


Can you please define 'weird'? A custom made client?



Turning it off also turned off
> the errors from spamming the logs.
>
> However it seems like the 3.5.6 is less informative than the 3.4.14 we
> had before as 3.4.14 also had the IP-Address when the connection was
> opened in the messages and not just the warnings...
>
If you can point to the differences we can bring back precious logs

Great to see you found the problem

Enrico

>
> Best regards
>
> Sebastian
>
>
> On 25-Oct-19 1:26 PM, Sebastian Schmitz wrote:
> > Hello Enrico,
> >
> > thanks for the reply. I'll try to find the exception, there was none
> > around 14:50 when it first appeared. I also try to find the client
> > that's connecting just before that as it's not a Kafka-node:
> >
> > Oct 21 14:50:31 zookeeper_node_3: 2019-10-21 01:50:31,532 [myid:3] -
> > INFO
> > [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@222] -
> > Accepted socket connection from /10.24.8.13:64261
> > Oct 21 14:50:31 zookeeper_node_3: 2019-10-21 01:50:31,544 [myid:3] -
> > WARN [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@383] -
> > Exception causing close of session 0x0: null
> > Oct 21 14:50:31 zookeeper_node_3: 2019-10-21 01:50:31,545 [myid:3] -
> > INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1056] -
> > Closed socket connection for client /10.24.8.13:64261 (no session
> > established for client)
> >
> > The same IP is able to connect to Zookeeper successfully some time
> > before:
> >
> > Oct 21 13:18:44 zookeeper_node_3: 2019-10-21 00:18:44,823 [myid:3] -
> > INFO
> > [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@222] -
> > Accepted socket connection from /10.24.8.13:50212
> > Oct 21 13:18:44 zookeeper_node_3: 2019-10-21 00:18:44,825 [myid:3] -
> > INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@949] -
> > Client attempting to establish new session at /10.24.8.13:50212
> > Oct 21 13:18:44 zookeeper_node_3: 2019-10-21 00:18:44,833 [myid:3] -
> > INFO  [CommitProcessor:3:ZooKeeperServer@694] - Established session
> > 0x30b2dfdd8ac with negotiated timeout 1 for client
> > /10.24.8.13:50212
> > Oct 21 13:18:53 zookeeper_node_3: 2019-10-21 00:18:53,374 [myid:3] -
> > INFO
> > [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@222] -
> > Accepted socket connection from /10.24.8.13:50314
> > Oct 21 13:18:53 zookeeper_node_3: 2019-10-21 00:18:53,374 [myid:3] -
> > INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@949] -
> > Client attempting to establish new session at /10.24.8.13:50314
> > Oct 21 13:18:53 zookeeper_node_3: 2019-10-21 00:18:53,385 [myid:3] -
> > INFO  [CommitProcessor:3:ZooKeeperServer@694] - Established session
> > 0x30b2dfdd8ac0001 with negotiated timeout 1 for client
> > /10.24.8.13:50314
> > Oct 21 13:18:53 zookeeper_node_3: 2019-10-21 00:18:53,588 [myid:3] -
> > INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1056] -
> > Closed socket connection for client /10.24.8.13:50314 which had
> > sessionid 0x30b2dfdd8ac0001
> >
> > I also checked the Logs from the update I did on Wednesday night to
> > update to 3.5.6. This is the Log of the start of zookeeper_node_1
> > until the errors show up... Can't see any exceptions :(
> >
> > Oct 23 02:07:03 zookeeper_node_1: setting ZOO_LOG4J_PROP=INFO,CONSOLE
> > Oct 23 02:07:03 zookeeper_node_1: ZooKeeper JMX enabled by default
> > Oct 23 02:07:03 zookeeper_node_1: Using config:
> > /opt/zookeeper-cluster/apache-zookeeper-3.5.6-bin/bin/../conf/zoo.cfg
> > Oct 23 02:07:05 zookeeper_node_1: Oct 22, 2019 13:07:05 + [1 1]
> > com.newrelic INFO: New Relic Agent: Loading configuration file
> > "/opt/zookeeper-cluster/newrelic/./newrelic.yml"
> > Oct 23 02:07:05 zookeeper_node_1: Oct 22, 2019 13:07:05 + [1 1]
> > com.newrelic INFO: Using default collector host: collector.newrelic.com
> > Oct 23 02:07:05 zookeeper_node_1: Oct 22, 2019 13:07:05 + [1 1]
> > com.newrelic INFO: New Relic Agent: Writing to log file:
> > /opt/zookeeper-cluster/newrelic/logs/newrelic_agent.log
> > Oct 23 02:07:28 zookeeper_node_1: 2019-10-22 13:07:28,743 [myid:] -
> > INFO  [main:QuorumPeerConfig@133] - Reading configuration from:
> > /opt/zookeeper-cluster/apache-zookeeper-3.5.6-bin/bin/../conf/zoo.cfg
> > Oct 23 02:07:28 zookeeper_node_1: 2019-10-22 13:07:28,764 [myid:] -
> > INFO  [main:QuorumPeerConfig@385] - clientPortAddress is
> > 0.0.0.0/0.0.0.0:2181
> > Oct 23 02:07:28 zookeeper_node_1: 2019-10-22 13:07:28,764 [myid:] -
> > INFO  [main:QuorumPeerConfig@389] - secureClientPort is not set
> > Oct 23 02:07:28 zookeeper_node_1: 2019-10-22 13:07:28,877 [myid:1] -
> > INFO  [main:DatadirCleanupManager@78] - autopurge.snapRetainCount set
> > to 3
> > Oct 23 02:07:28 

Re: Why are errors stored in the transaction logs?

[Andor Molnar]

Hi Sylvain,

That should not be the case. Txns are not going to be created from read 
requests and not hit SyncRequestProcessor which is responsible for maintaining 
txn and snap logs.

The error handling you see in processTxn() is for ignoring failures during log 
replaying inside processTxn() method (in the catch branch). Introduced in 
ZOOKEEPER-1269 and it’s related to multis afaics.

Andor




> On 2019. Oct 15., at 16:33, Sylvain Wallez  wrote:
> 
> Hi ZooKeepers,
> 
> We had an issue recently with a service hammering ZK to read a path that 
> doesn't exist. As a result the transaction logs grew quickly because errors 
> are stored there.
> 
> Looking at DataTree.processTxn() which is called from 
> FileTxnSnapLog.restore() it seems that errors read in the transaction log are 
> essentially ignored.
> 
> So what is storing errors in the txnlog useful for? Would it make sense to 
> have a configuration flag to not store them?
> 
> Thanks,
> Sylvain
>