I support Jens' change until something better is identified. I think just this
minor change will have a big impact on our ability to decipher what is going on
in dunit tests. Thanks for making the change Jens!
Mark
On 1/4/22, 10:44 AM, "Dale Emery" <dem...@vmware.com> wrote:
Hi Jens and all,
A possibility to consider: Instead of generating an arbitrary-but-unique
ID, use an existing identifier from the test environment… such as the ID in the
test worker directory name. That might make it easier to map a given log line
to the other artifacts from the test. So if the test worker dir was
test-worker-000098, then use 000098 (or 98) as the ID in the logs.
ProcessManager could get the ID by parsing the current working directory. Or we
could change the “test isolation” stuff to set an environment variable that
ProcessManager could use.
Another possibility to look into: Teach Gradle to distinguish different
instances of the same test class, so that it doesn’t merge the logs. I don’t
know whether this is possible, but it may be worth exploring. (The challenge is
that Gradle assumes it will run a test class only once, and includes code to
ensure that. We bypass that code in order to run a test class multiple times,
but we don’t change how Gradle decides what log to append a test process’s
output to.)
Dale
From: Jens Deppe <jde...@vmware.com>
Date: Monday, January 3, 2022 at 1:03 PM
To: dev@geode.apache.org <dev@geode.apache.org>
Subject: PR to add unique ID to DUnit log output
Hi All.
Just a heads up that I have a PR up
(https://nam04.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fapache%2Fgeode%2Fpull%2F7232&data=04%7C01%7Chansonm%40vmware.com%7C7dbe022839934e3446e308d9cfb24749%7Cb39138ca3cee4b4aa4d6cd83d9dd62f0%7C0%7C0%7C637769186901894631%7CUnknown%7CTWFpbGZsb3d8eyJWIjoiMC4wLjAwMDAiLCJQIjoiV2luMzIiLCJBTiI6Ik1haWwiLCJXVCI6Mn0%3D%7C3000&sdata=rE6JFmAGYeINPRtBXccHx%2Bqy5pp2Wz2Br5xR2iRncWY%3D&reserved=0)
which, if merged, will slightly change the log output from DUnit runs. The PR
simply adds a 4 character unique ID to the log line. As in:
[vm0-51ec] [info 2021/12/24 15:43:54.367 UTC <RMI TCP
Connection(1)-10.138.0.70>; tid=0x1d] Reinitializing JarDeploymentService with
new working directory: null
[vm0-47b7] [info 2021/12/24 15:43:54.416 UTC <RMI TCP
Connection(1)-10.138.0.70> tid=0x1d] Reinitializing JarDeploymentService with
new working directory: null
[vm1-47b7] [info 2021/12/24 15:43:54.431 UTC <RMI TCP
Connection(1)-10.138.0.70> tid=0x1d] Received method:
org.apache.geode.test.dunit.internal.IdentifiableCallable.call with 0 args on
object: IdentifiableCallable(0:start locator in vm0)
The ID is intended to be unique per test run when tests are run repeatedly.
I did this to assist in debugging test output from repeated test runs
(StressNewTest) where individual tests’ log lines are simply interleaved making
debugging very difficult.
The change, unfortunately, does not affect log lines generated from the
test VM but only from VMs launched by the ProcessManager. If anyone has ideas
how to do that, I’d love to hear them.
Well, actually one approach I’ve used is related to this PR
(https://nam04.safelinks.protection.outlook.com/?url=https%3A%2F%2Fgithub.com%2Fapache%2Fgeode%2Fpull%2F7231&data=04%7C01%7Chansonm%40vmware.com%7C7dbe022839934e3446e308d9cfb24749%7Cb39138ca3cee4b4aa4d6cd83d9dd62f0%7C0%7C0%7C637769186901894631%7CUnknown%7CTWFpbGZsb3d8eyJWIjoiMC4wLjAwMDAiLCJQIjoiV2luMzIiLCJBTiI6Ik1haWwiLCJXVCI6Mn0%3D%7C3000&sdata=L5hedKNBMIilghxkFqAgTs%2B4SXOPHapSEcnKy3HEcmM%3D&reserved=0)
which lets one name ExecutorServiceRule threads. Using this, I can use the
ProcessManager.ID to name the executor threads and thus that ID becomes visible
when the thread name is logged. Kinda hacky, but it’s still effective.
Anyway, this is not a call to review (although you’re welcome to do so) but
just a FYI.
--Jens
