ActiveMQ ReplicatedLevelDB corruption

[mlange]

Recently I installed Apache ActiveMQ in a few different ways. One of those is
using ReplicatedLevelDB for a master/slave/slave setup.

Yesterday I did a bit of loadtesting: sending 100.000 messages with 100
threads producing the messages (used jmeter for that) (so each thread
produced 1000 messages); I had another process moving the messages from one
broker to another and back again (the queues had the same names across each
broker, so that was easy moving) and then went about processing the messages
which caused the messages to flow across various queues.

All seemed fine, everything looked okay... until I stopped the active
broker. (this is hours after the last message was consumed and procsesed):

Then I notice a few bouncing brokers, one comes up but crashes on an
EOFException; a bit later the other broker does the same.

In the log I see many messages like this:

[quote]
2016-09-23 13:38:52,950 | WARN | No reader available for position: 0,
log_infos:
{11534500540=LogInfo(/data/activemq/broker1-db/00000002af8282bc.log,11534500540,104858130),
12163654223=LogInfo(/data/activemq/broker1-db/00000002d502a24f.log,12163654223,104858162),
12897666570=LogInfo(/data/activemq/broker1-db/0000000300c2c60a.log,12897666570,104859912),
13002526482=LogInfo(/data/activemq/broker1-db/000000030702cf12.log,13002526482,104859038),
18455209795=LogInfo(/data/activemq/broker1-db/000000044c042743.log,18455209795,104859837),
22020442500=LogInfo(/data/activemq/broker1-db/0000000520854984.log,22020442500,104859288),
23173898306=LogInfo(/data/activemq/broker1-db/000000056545a042.log,23173898306,104860684),
24641928389=LogInfo(/data/activemq/broker1-db/00000005bcc5fcc5.log,24641928389,0)}
| org.apache.activemq.leveldb.RecordLog | Thread-1039
[/quote]

Then I see messages like this:
[quote]
2016-09-23 13:38:46,324 | WARN | Invalid log position: 11409726550 |
org.apache.activemq.leveldb.LevelDBClient | ActiveMQ BrokerService[broker1]
Task-3
[/quote]

After that, the broker starts and logs a few messages like this:
[quote]
2016-09-23 13:40:49,041 | WARN | Invalid log position: 0 |
org.apache.activemq.leveldb.LevelDBClient | Thread-1040
[/quote]

and then we get exception:
[quote]
2016-09-23 13:41:09,748 | INFO | Stopping BrokerService[broker1] due to
exception, java.io.EOFException: File
'/data/activemq/broker1-db/000000030702cf12.log' offset: 110647192 |
org.apache.activemq.util.DefaultIOExceptionHandler | LevelDB IOException
handler.
java.io.EOFException: File '/data/activemq/broker1-db/000000030702cf12.log'
offset: 110647192
[/quote]

This is a rince and repeat situation; both living brokers are now
alternating this sequence.

It seems like the load I generated caused corruption on the database; but
this should not be possible... What information can I provide to see how
this situation can be avoided?



--
View this message in context: http://activemq.2283324.n4.nabble.com/ActiveMQ-ReplicatedLevelDB-corruption-tp4716831.html
Sent from the ActiveMQ - User mailing list archive at Nabble.com.

[Tim Bain]

Just to confirm: your three brokers are writing their LevelDB files to
independent, separate disk locations, giving you three separate sets of
LevelDB files. Right?

Is the original master's set of data files corrupted? Or is it just the
two slaves for whom this happened?

Post by mlange
Recently I installed Apache ActiveMQ in a few different ways. One of those is
using ReplicatedLevelDB for a master/slave/slave setup.
Yesterday I did a bit of loadtesting: sending 100.000 messages with 100
threads producing the messages (used jmeter for that) (so each thread
produced 1000 messages); I had another process moving the messages from one
broker to another and back again (the queues had the same names across each
broker, so that was easy moving) and then went about processing the messages
which caused the messages to flow across various queues.
All seemed fine, everything looked okay... until I stopped the active
Then I notice a few bouncing brokers, one comes up but crashes on an
EOFException; a bit later the other broker does the same.
[quote]
2016-09-23 13:38:52,950 | WARN | No reader available for position: 0,
{11534500540=LogInfo(/data/activemq/broker1-db/00000002af8282bc.log,
11534500540,104858130),
12163654223=LogInfo(/data/activemq/broker1-db/00000002d502a24f.log,
12163654223,104858162),
12897666570=LogInfo(/data/activemq/broker1-db/0000000300c2c60a.log,
12897666570,104859912),
13002526482=LogInfo(/data/activemq/broker1-db/000000030702cf12.log,
13002526482,104859038),
18455209795=LogInfo(/data/activemq/broker1-db/000000044c042743.log,
18455209795,104859837),
22020442500=LogInfo(/data/activemq/broker1-db/0000000520854984.log,
22020442500,104859288),
23173898306=LogInfo(/data/activemq/broker1-db/000000056545a042.log,
23173898306,104860684),
24641928389=LogInfo(/data/activemq/broker1-db/00000005bcc5fcc5.log,
24641928389,0)}
| org.apache.activemq.leveldb.RecordLog | Thread-1039
[/quote]
[quote]
2016-09-23 13:38:46,324 | WARN | Invalid log position: 11409726550 |
org.apache.activemq.leveldb.LevelDBClient | ActiveMQ
BrokerService[broker1]
Task-3
[/quote]
[quote]
2016-09-23 13:40:49,041 | WARN | Invalid log position: 0 |
org.apache.activemq.leveldb.LevelDBClient | Thread-1040
[/quote]
[quote]
2016-09-23 13:41:09,748 | INFO | Stopping BrokerService[broker1] due to
exception, java.io.EOFException: File
'/data/activemq/broker1-db/000000030702cf12.log' offset: 110647192 |
org.apache.activemq.util.DefaultIOExceptionHandler | LevelDB IOException
handler.
java.io.EOFException: File '/data/activemq/broker1-db/
000000030702cf12.log'
offset: 110647192
[/quote]
This is a rince and repeat situation; both living brokers are now
alternating this sequence.
It seems like the load I generated caused corruption on the database; but
this should not be possible... What information can I provide to see how
this situation can be avoided?
--
View this message in context: http://activemq.2283324.n4.
nabble.com/ActiveMQ-ReplicatedLevelDB-corruption-tp4716831.html
Sent from the ActiveMQ - User mailing list archive at Nabble.com.

[mlange]

Yes, the three brokers are on separate (virtual) machines that write to their
own disk.
It's hard to determine (at this point) whether the original master got
corrupted, as it (at least) got corrupted after starting said broker again
(or was already corrupted to begin with)





--
View this message in context: http://activemq.2283324.n4.nabble.com/ActiveMQ-ReplicatedLevelDB-corruption-tp4716831p4716842.html
Sent from the ActiveMQ - User mailing list archive at Nabble.com.

[mlange]

possibly of note is that I had the sync option on the default (quorum_mem).

I have moved the data directories for each broker as an ".org" (for
safekeeping) and will try and see if quorum_disk is the way to prevent this
situation from happening. It will take a little while though to get definite
results.



--
View this message in context: http://activemq.2283324.n4.nabble.com/ActiveMQ-ReplicatedLevelDB-corruption-tp4716831p4716850.html
Sent from the ActiveMQ - User mailing list archive at Nabble.com.

[mlange]

Concluded the test now; No good news though.

After sending the 100.000 messages (which got consumed by services that in
turn also produced new messages and so had a flow from one queue to another
and another etc... resulting in about 1.500.000 messages in the few hours
that this test ran) I restarted the master broker. Catching up went fine, no
errors

Shortly thereafter I restarted the new master (the slaves had caught up, I
had made sure of that message); Now the new master is giving multiple times
the message: "2016-09-23 19:10:37,644 | WARN | Invalid log position: 0 |
org.apache.activemq.leveldb.LevelDBClient | Thread-118"

While both slaves are spewing out many log messages along the lines of this:
"2016-09-23 19:15:33,892 | WARN | No reader available for position: 0,
log_infos:
{209718314=LogInfo(/data/activemq/broker1-db/000000000c800c2a.log,209718314,104859264),
2831214880=LogInfo(/data/activemq/broker1-db/00000000a8c0e920.log,2831214880,104859800),
3250651975=LogInfo(/data/activemq/broker1-db/00000000c1c10347.log,3250651975,104862133),
3355514108=LogInfo(/data/activemq/broker1-db/00000000c80114fc.log,3355514108,104859203),
4823542070=LogInfo(/data/activemq/broker1-db/000000011f816936.log,4823542070,0)}
| org.apache.activemq.leveldb.RecordLog | Thread-3
"

Question arises if LevelDB is a good choice or is it too easily corrupted?



--
View this message in context: http://activemq.2283324.n4.nabble.com/ActiveMQ-ReplicatedLevelDB-corruption-tp4716831p4716869.html
Sent from the ActiveMQ - User mailing list archive at Nabble.com.

[mlange]

Gave the system a weekend time to see if it could recover automatically...
alas that's not the case.

However, when I stopped all brokers, changed one of the brokers with
'replicas="1"' (rather than 3); started it (kind of single mode) and started
the other brokers one by one so they could catch up and then stopped them;
restarted the master broker but now the replicas back to 3 and the backup
brokers got started as well...

Now the brokers are back online in a consistent state. There are some issues
though...

As the broker that is now primary is one that apparently failed earlier
there are now messages on the queues that should've been consumed (I think);
So, is it possible that the brokers try to heal themselves? (with warnings
and errors in the logs, so the administrator knows to validate the
situation; remaining messages that are uncertain in the 'exactly once'
situation should be moved to the DLQ

Going through the logs I noticed a few things; for simplicty I will call the
HA brokers 'broker1, broker2 and broker3' although they're all 'broker1' :-)

I see that broker1 was online and accepting messages when the test started;
However, it missed some zookeeper pings and got demoted to slave. broker2
became the new master. After the test, all brokers got restarted; Raising
the issue, described in my previous post. This morning I "recovered" broker1
(I now realize I should've done this on the last known master: broker2;
alas...) there are now many messages that I _think_ (they're a bit too many
and the test too generic to determine this easily) have been processed
already.



--
View this message in context: http://activemq.2283324.n4.nabble.com/ActiveMQ-ReplicatedLevelDB-corruption-tp4716831p4716912.html
Sent from the ActiveMQ - User mailing list archive at Nabble.com.

[mlange]

Created a JIRA https://issues.apache.org/jira/browse/AMQ-6453 about this
issue; please let me know if you need more information.



--
View this message in context: http://activemq.2283324.n4.nabble.com/ActiveMQ-ReplicatedLevelDB-corruption-tp4716831p4717515.html
Sent from the ActiveMQ - User mailing list archive at Nabble.com.

[Tim Bain]

Thank you. Unfortunately there's currently no LevelDB expert active on
this mailing list, so most LevelDB questions with any degree of complexity
go unanswered.

Post by mlange
Created a JIRA https://issues.apache.org/jira/browse/AMQ-6453 about this
issue; please let me know if you need more information.
--
View this message in context: http://activemq.2283324.n4.
nabble.com/ActiveMQ-ReplicatedLevelDB-corruption-tp4716831p4717515.html
Sent from the ActiveMQ - User mailing list archive at Nabble.com.

[mlange]

thanks for providing a good idea of what to expect; yet I think it's good to
be aware of this.
I did notice upon searching that there has been done some work to get Kahadb
replicating; is that completely abandoned or is it still something that
might get implemented (in a somewhat near future) I think it's a great idea
to have the database replicating, to reduce the added complexity of shared
storage (which may itself fail, so needs to have it's own fault tolerance)

I'll explore what other options are available and work well.



--
View this message in context: http://activemq.2283324.n4.nabble.com/ActiveMQ-ReplicatedLevelDB-corruption-tp4716831p4717517.html
Sent from the ActiveMQ - User mailing list archive at Nabble.com.

[Tim Bain]

This is the first I'd heard of a replicated KahaDB implementation. I'd
heard of multi-KahaDB (mKahaDB), but that's multiple KahaDB databases on a
single broker (split by destination) rather than replicated. Maybe someone
else can provide more info...

Post by mlange
thanks for providing a good idea of what to expect; yet I think it's good to
be aware of this.
I did notice upon searching that there has been done some work to get Kahadb
replicating; is that completely abandoned or is it still something that
might get implemented (in a somewhat near future) I think it's a great idea
to have the database replicating, to reduce the added complexity of shared
storage (which may itself fail, so needs to have it's own fault tolerance)
I'll explore what other options are available and work well.
--
View this message in context: http://activemq.2283324.n4.
nabble.com/ActiveMQ-ReplicatedLevelDB-corruption-tp4716831p4717517.html
Sent from the ActiveMQ - User mailing list archive at Nabble.com.