adding stack logging

[qqmyers]

What this PR does / why we need it: Documents the state of the command stack whenever it is added to to see if parallel actions are adding to the same stack and causing problems

Which issue(s) this PR closes:

Closes #7303

Special notes for your reviewer: This is just debug code - could be added to what @pdurbin has in the other PR. Have not gotten to test this but wanted to put it out as a proposal - if it works it should provide some insight.

Suggestions on how to test this: Turn on fine logging for the Ejb engine class and watch the log.

Does this PR introduce a user interface change? If mockups are available, please link/include them here:

Is there a release notes update needed for this change?:

Additional documentation:

[coveralls]

Coverage decreased (-0.005%) to 19.481% when pulling c9ca985 on GlobalDataverseCommunityConsortium:IQSS/7303 into 922b0cd on IQSS:develop.

[qqmyers]

Added a random number to the logging so that lines belonging to the same call can be identified.

Given that this would be quite chatty, should it send to a separate log file? Or should it do some testing? E.g. to report in anything but finalizePub is added to a stack with a Publish command? Or if a second Finalize is added, etc.? Or any time commands that refer to different datasets are in the same stack? (Feel free to decide and edit the PR).

[landreev]

Given that this would be quite chatty, should it send to a separate log file? Or should it do some testing? E.g. to report in anything but finalizePub is added to a stack with a Publish command? Or if a second Finalize is added, etc.?

We are only interested in seeing these log messages when there are multiple items on the stack - correct? Should we make it log only when the stack is more than 1 deep? Then the logging will only become chatty if/when something gets permanently stuck on the stack... but then we can turn it off - having learned/confirmed that it is indeed happening. Am I missing anything?

[qqmyers]

Thanks! I think that's true - I wasn't sure if there were cases where there should be more than one - e.g. from things like UpdateDatasetVersionCommand calling Delete File inside it. (That's only two, so I guess the only issue would be if something like Publish has any calls to things other than Finalize.) At a minimum, I think your suggestion would cut chatter way down, so it's probably good enough.

And yes, once it's clear, we just drop FINE logging and this stops.

I'll go ahead and make that change.

[landreev]

There may even be other cases, where one command calls another... But I still believe they are not as common, as to result in flooding the logs.

[landreev]

Let's try it!

[kcondon]

@qqmyers Would you update from develop to capture the version change?

[kcondon]

@qqmyers I am seeing tons of logging info when javax.enterprise.system.container.ejb=FINE . Is there a specific message you'd added? Otherwise would need to grep I suppose to make it useful.

Can you specify which class to turn fine logging on? From your test notes:
Suggestions on how to test this: Turn on fine logging for the Ejb engine class and watch the log.

[qqmyers]

I think you should just have
bin/asadmin set-log-levels edu.harvard.iq.dataverse.EjbDataverseEngine=FINE
and not do any additional ejb logging.

and, unless you can trigger the underlying problem, I think you won't see any new log messages. If you do, there should be a few messages after to "Current Command Stack (" + instance + "): " which have the same value for instance.
(We expect the problem comes from parallel calls to publish things/make other changes if you want to try.)

[kcondon]

OK, I misunderstood how list log levels was working, thought it included what could be altered, not only what has been explicitly been specified. Thanks @landreev

[qqmyers]

You can add any specific Dataverse class you want and it should then show in that list. The bin/asadmin command I sent should do it.