openwallet-foundation / acapy

Hyperledger Aries Cloud Agent Python (ACA-Py) is a foundation for building decentralized identity applications and services running in non-mobile environments.
https://wiki.hyperledger.org/display/aries
Apache License 2.0
408 stars 512 forks source link

Noisy logs #3202

Open rngadam opened 1 month ago

rngadam commented 1 month ago

At the agent start, the stdout of the agent shows multiple banner messages and output from print statements.

Having noisy logs makes it more difficult to identify quickly actual problems.

Expect to:

list of print statements

https://gist.github.com/rngadam/3cccd0f515091544f745d681d8119ae4

WadeBarnes commented 1 month ago

The deprecation banner and notices should only be displayed when you are using deprecated features. Suppressing these messages defeats the purpose of the messages - to let you know you are using deprecated features and you should migrate to alternate (replacement) features. So, the best practice way to get rid of the messages is to migrate away from the deprecated features you're using.

I do agree the messages should be logged rather than being printed.

Regarding the standard ACA-Py startup banner. I think this is a very important piece of diagnostic information that should not be suppressed. It provides you with a summary of the agent configuration and version that can help you identify issues right off the bat.

rngadam commented 1 month ago

The deprecation banner and notices should only be displayed when you are using deprecated features. Suppressing these messages defeats the purpose of the messages - to let you know you are using deprecated features and you should migrate to alternate (replacement) features. So, the best practice way to get rid of the messages is to migrate away from the deprecated features you're using.

I expected that too, but if you look at the code the banner is printed everytime (there's no conditional):

from here:

https://github.com/hyperledger/aries-cloudagent-python/blob/90895bbc3f2bf203bbfe35f0464a9ea1f37ebeaa/aries_cloudagent/core/conductor.py#L321-L338

the only condition for printing the deprecation notice is having transports configured (aka transport is not disabled)

https://github.com/hyperledger/aries-cloudagent-python/blob/90895bbc3f2bf203bbfe35f0464a9ea1f37ebeaa/aries_cloudagent/config/logging.py#L389-L429

It's giving a deprecation notice whatever config and even though #2368 is not done yet. Correct me if I'm wrong, but there seems to be no way to "correctly" configure the agent to get rid of the deprecation notice.

rngadam commented 1 month ago

Regarding the standard ACA-Py startup banner. I think this is a very important piece of diagnostic information that should not be suppressed. It provides you with a summary of the agent configuration and version that can help you identify issues right off the bat.

Perhaps in regular usage but it interferes with testing (I'm forking 100 agents from the same parent process, creating a storm of output) and creates the habit of eventually ignoring output that could/should be important.

WadeBarnes commented 1 month ago

It's giving a deprecation notice whatever config and even though #2368 is not done yet. Correct me if I'm wrong, but there seems to be no way to "correctly" configure the agent to get rid of the deprecation notice.

@swcurran, @dbluhm, @jamshale, Can any of you comment on this?

jamshale commented 1 month ago

I don't think we'd want to add another configuration for this. We're really trying not to bloat the configurations. But, printing the banner nicely with the logger will be a bit tricky because it's configured to print the timestamp and class.

This seems like a pretty niche use case. The depreciation notice is only like 10 lines of output. If other maintainers don't care about adding a configuration than the open PR looks acceptable.

swcurran commented 1 month ago

I don’t like the idea of the flag to block the banner. The whole point of the messages is that they be ugly and in the face of the deployers so that they become aware of the need to evolve their deployment. Especially if they go away when the deployment removes the deprecated feature. That’s the behaviour we want to encourage — “This message will not be printed if you update your deployment to do X, Y and Z. Do it today!!”.

If a deployment simply adds that flag, they will not see the future messages and will not know about future deprecations.

I think we should not add this.

rngadam commented 1 month ago

@swcurran @jamshale as it is now, there's no way around the "deprecation notice".

It is deprecating something without any working alternatives to upgrade to.

For me, that is not deprecation, it is noise for which I cannot do anything about, polluting my stdout and causing me to miss actual important error messages.

jamshale commented 1 month ago

Why don't you just test with your own fork or image? Or you should be able to filter your log output for single instances. You could also spread your instances startups out do the logs aren't all mixed up.

There is a lot of ways around this and finding these errors easier isn't something we need to fix by adding another configuration parameter.

swcurran commented 1 month ago

What deprecation are you talking about? Do you mean this one?

:: Receiving a core DIDComm protocol with the `did:sov:BzCbsNYhMrjHiqZDTUASHg;spec` ::
:: prefix is deprecated. All parties sending this prefix should be notified that    ::
:: support for receiving such messages will be removed in a future release. Use     ::
:: https://didcomm.org/ instead. 

If so, that is not about “did:sov” vs. “did:indy”. Rather — it is the prefix to a DIDComm message type, such as: https://didcomm.org/basicmessage/1.0/ which used to be sent as did:sov:BzCbsNYhMrjHiqZDTUASHg;spec/basicmessage/1.0/. The did:sov… part of that is a specific DID and is treated as a hard-coded string in the initial DIDComm protocols. We’re trying to eliminate it from the code base.

I fully agree that there should be a way to suppress such messages, and I’m not sure about this one, since the message is saying “hey, if you get a message from another party using the old prefix you should yell at them”. There is a flag to ensure that your deployment is not sending out such a prefix (since 0.5.5), and that flag is now automatically active for all ACA-Py deployments (since 0.11.0).

How about we do this:

  1. Remove the did:sov DIDComm message type prefix deprecation message as it has been two full releases since ACA-Py was changed to only send out the https://didcomm.org replacement.
  2. Document that all deprecation messages SHOULD provide information (or a link) to how the message can be suppressed — usually by migrating to the replacement approach. That cannot be a universal “Don’t show deprecation messages”, since that defeats their very valuable purpose.
  3. Nice to have — update the existing messages according to 2.

Thoughts?