Added detailed trace logging for FATE #1316

[keith-turner]

This change add detailed trace logging for FATE. To enable this add the following to log4j-service.properties

log4j.logger.org.apache.accumulo.fate.store=TRACE

The following is logging output when trace is enabled for create table FATE transaction.

2020-02-20 15:59:54,574 [fate.store] TRACE: created FATE[38dabaad752bd105]
2020-02-20 15:59:54,623 [fate.store] TRACE: pushed FATE[38dabaad752bd105] class org.apache.accumulo.master.tableOps.create.CreateTable {"tableInfo":{"tableName":"test99","namespaceId":{"canonical":"+default"},"timeType":"MILLIS","user":"root","initialTableState":"ONLINE","initialSplitSize":0,"props":{"table.iterator.majc.vers":"20,org.apache.accumulo.core.iterators.user.VersioningIterator","table.constraint.1":"org.apache.accumulo.core.constraints.DefaultKeySizeConstraint","table.iterator.scan.vers.opt.maxVersions":"1","table.iterator.minc.vers":"20,org.apache.accumulo.core.iterators.user.VersioningIterator","table.iterator.majc.vers.opt.maxVersions":"1","table.iterator.minc.vers.opt.maxVersions":"1","table.iterator.scan.vers":"20,org.apache.accumulo.core.iterators.user.VersioningIterator"}}}
2020-02-20 15:59:54,629 [fate.store] TRACE: setProperty FATE[38dabaad752bd105] debug CreateTable
2020-02-20 15:59:54,637 [fate.store] TRACE: setStatus FATE[38dabaad752bd105] IN_PROGRESS
2020-02-20 15:59:54,688 [fate.store] TRACE: pushed FATE[38dabaad752bd105] class org.apache.accumulo.master.tableOps.create.SetupPermissions {"tableInfo":{"tableName":"test99","tableId":{"canonical":"2"},"namespaceId":{"canonical":"+default"},"timeType":"MILLIS","user":"root","initialTableState":"ONLINE","initialSplitSize":0,"props":{"table.iterator.majc.vers":"20,org.apache.accumulo.core.iterators.user.VersioningIterator","table.constraint.1":"org.apache.accumulo.core.constraints.DefaultKeySizeConstraint","table.iterator.scan.vers.opt.maxVersions":"1","table.iterator.minc.vers":"20,org.apache.accumulo.core.iterators.user.VersioningIterator","table.iterator.majc.vers.opt.maxVersions":"1","table.iterator.minc.vers.opt.maxVersions":"1","table.iterator.scan.vers":"20,org.apache.accumulo.core.iterators.user.VersioningIterator"}}}
2020-02-20 15:59:54,763 [fate.store] TRACE: pushed FATE[38dabaad752bd105] class org.apache.accumulo.master.tableOps.create.PopulateZookeeper {"tableInfo":{"tableName":"test99","tableId":{"canonical":"2"},"namespaceId":{"canonical":"+default"},"timeType":"MILLIS","user":"root","initialTableState":"ONLINE","initialSplitSize":0,"props":{"table.iterator.majc.vers":"20,org.apache.accumulo.core.iterators.user.VersioningIterator","table.constraint.1":"org.apache.accumulo.core.constraints.DefaultKeySizeConstraint","table.iterator.scan.vers.opt.maxVersions":"1","table.iterator.minc.vers":"20,org.apache.accumulo.core.iterators.user.VersioningIterator","table.iterator.majc.vers.opt.maxVersions":"1","table.iterator.minc.vers.opt.maxVersions":"1","table.iterator.scan.vers":"20,org.apache.accumulo.core.iterators.user.VersioningIterator"}}}
2020-02-20 15:59:54,895 [fate.store] TRACE: pushed FATE[38dabaad752bd105] class org.apache.accumulo.master.tableOps.create.ChooseDir {"tableInfo":{"tableName":"test99","tableId":{"canonical":"2"},"namespaceId":{"canonical":"+default"},"timeType":"MILLIS","user":"root","initialTableState":"ONLINE","initialSplitSize":0,"props":{"table.iterator.majc.vers":"20,org.apache.accumulo.core.iterators.user.VersioningIterator","table.constraint.1":"org.apache.accumulo.core.constraints.DefaultKeySizeConstraint","table.iterator.scan.vers.opt.maxVersions":"1","table.iterator.minc.vers":"20,org.apache.accumulo.core.iterators.user.VersioningIterator","table.iterator.majc.vers.opt.maxVersions":"1","table.iterator.minc.vers.opt.maxVersions":"1","table.iterator.scan.vers":"20,org.apache.accumulo.core.iterators.user.VersioningIterator"}}}
2020-02-20 15:59:54,906 [fate.store] TRACE: pushed FATE[38dabaad752bd105] class org.apache.accumulo.master.tableOps.create.PopulateMetadata {"tableInfo":{"tableName":"test99","tableId":{"canonical":"2"},"namespaceId":{"canonical":"+default"},"timeType":"MILLIS","user":"root","initialTableState":"ONLINE","initialSplitSize":0,"props":{"table.iterator.majc.vers":"20,org.apache.accumulo.core.iterators.user.VersioningIterator","table.constraint.1":"org.apache.accumulo.core.constraints.DefaultKeySizeConstraint","table.iterator.scan.vers.opt.maxVersions":"1","table.iterator.minc.vers":"20,org.apache.accumulo.core.iterators.user.VersioningIterator","table.iterator.majc.vers.opt.maxVersions":"1","table.iterator.minc.vers.opt.maxVersions":"1","table.iterator.scan.vers":"20,org.apache.accumulo.core.iterators.user.VersioningIterator"}}}
2020-02-20 15:59:54,959 [fate.store] TRACE: pushed FATE[38dabaad752bd105] class org.apache.accumulo.master.tableOps.create.FinishCreateTable {"tableInfo":{"tableName":"test99","tableId":{"canonical":"2"},"namespaceId":{"canonical":"+default"},"timeType":"MILLIS","user":"root","initialTableState":"ONLINE","initialSplitSize":0,"props":{"table.iterator.majc.vers":"20,org.apache.accumulo.core.iterators.user.VersioningIterator","table.constraint.1":"org.apache.accumulo.core.constraints.DefaultKeySizeConstraint","table.iterator.scan.vers.opt.maxVersions":"1","table.iterator.minc.vers":"20,org.apache.accumulo.core.iterators.user.VersioningIterator","table.iterator.majc.vers.opt.maxVersions":"1","table.iterator.minc.vers.opt.maxVersions":"1","table.iterator.scan.vers":"20,org.apache.accumulo.core.iterators.user.VersioningIterator"}}}
2020-02-20 15:59:54,997 [fate.store] TRACE: setProperty FATE[38dabaad752bd105] return 2
2020-02-20 15:59:55,005 [fate.store] TRACE: setStatus FATE[38dabaad752bd105] SUCCESSFUL
2020-02-20 15:59:55,013 [fate.store] TRACE: popped FATE[38dabaad752bd105]
2020-02-20 15:59:55,019 [fate.store] TRACE: popped FATE[38dabaad752bd105]
2020-02-20 15:59:55,025 [fate.store] TRACE: popped FATE[38dabaad752bd105]
2020-02-20 15:59:55,031 [fate.store] TRACE: popped FATE[38dabaad752bd105]
2020-02-20 15:59:55,038 [fate.store] TRACE: popped FATE[38dabaad752bd105]
2020-02-20 15:59:55,045 [fate.store] TRACE: popped FATE[38dabaad752bd105]
2020-02-20 15:59:55,080 [fate.store] TRACE: deleted FATE[38dabaad752bd105]

The following is for rename table

2020-02-20 16:00:01,607 [fate.store] TRACE: created FATE[6ba118b80b85ba43]
2020-02-20 16:00:01,617 [fate.store] TRACE: pushed FATE[6ba118b80b85ba43] class org.apache.accumulo.master.tableOps.rename.RenameTable {"tableId":{"canonical":"2"},"namespaceId":{"canonical":"+default"},"oldTableName":"test99","newTableName":"test999"}
2020-02-20 16:00:01,622 [fate.store] TRACE: setProperty FATE[6ba118b80b85ba43] debug RenameTable
2020-02-20 16:00:01,631 [fate.store] TRACE: setStatus FATE[6ba118b80b85ba43] IN_PROGRESS
2020-02-20 16:00:01,699 [fate.store] TRACE: setStatus FATE[6ba118b80b85ba43] SUCCESSFUL
2020-02-20 16:00:01,705 [fate.store] TRACE: popped FATE[6ba118b80b85ba43]
2020-02-20 16:00:01,719 [fate.store] TRACE: deleted FATE[6ba118b80b85ba43]

The following is for delete table.

2020-02-20 16:00:07,884 [fate.store] TRACE: created FATE[321b6d88d8be627b]
2020-02-20 16:00:07,894 [fate.store] TRACE: pushed FATE[321b6d88d8be627b] class org.apache.accumulo.master.tableOps.delete.DeleteTable {"tableId":{"canonical":"2"},"namespaceId":{"canonical":"+default"}}
2020-02-20 16:00:07,899 [fate.store] TRACE: setProperty FATE[321b6d88d8be627b] debug DeleteTable
2020-02-20 16:00:07,908 [fate.store] TRACE: setStatus FATE[321b6d88d8be627b] IN_PROGRESS
2020-02-20 16:00:07,955 [fate.store] TRACE: pushed FATE[321b6d88d8be627b] class org.apache.accumulo.master.tableOps.delete.CleanUp {"tableId":{"canonical":"2"},"namespaceId":{"canonical":"+default"},"creationTime":1582214407948}
2020-02-20 16:00:08,306 [fate.store] TRACE: setStatus FATE[321b6d88d8be627b] SUCCESSFUL
2020-02-20 16:00:08,312 [fate.store] TRACE: popped FATE[321b6d88d8be627b]
2020-02-20 16:00:08,318 [fate.store] TRACE: popped FATE[321b6d88d8be627b]
2020-02-20 16:00:08,331 [fate.store] TRACE: deleted FATE[321b6d88d8be627b]

Seeing this output makes me wish we stored FATE Repos in Zookeeper as JSon instead of using java serialization because whats in ZK would be human readable.

[jmark99]

@keith-turner do you think this invalidates the need for #1249? I have been looking into this ticket and working to create a dedicated Fate logger with standardized output for each operation.

[keith-turner]

@keith-turner do you think this invalidates the need for #1249?

I don't think it does. I think materializing the goal and status info into a human readable form would still be useful. Could possibly store that info in FATE properties.

Also, the work in the PR is extremely low level and very verbose. I suspect no one would turn this on w/o a good reason.

[keith-turner]

@jmark99 if you have any branches for #1249 with work in progress commits and want me to take a look I would be happy to.

[jmark99]

@keith-turner Ok thanks! I will continue to look into the ticket. Where are the FATE properties to which you refer?

[keith-turner]

Where are the FATE properties to which you refer?

@jmark99 I was thinking of the following.

accumulo/core/src/main/java/org/apache/accumulo/fate/Fate.java

Line 259 in 1d95efe

store.setProperty(tid, DEBUG_PROP, repo.getDescription());

Maybe could do something like store.setProperty(tid, GOAL_PROP, theGoal)

[jmark99]

@keith-turner thanks for the reference

[phrocker]

I added some minor comments. The changes look good on the whole. Feel free to take note of them and make changes or ignore them. I'm not particularly tied to them so +1 is warranted.

[ctubbsii]

Looks fine to me. I'm curious about investigating the workaround you adopted for Gson serialization of Repo objects, to see if there's a better solution, but moving it to Master seems fine to me if it works there.

[ctubbsii]

Oh @keith-turner , you should probably test with log4j2 configuration files, since those changes were already merged and your description above mentions the old log4j1 files.