add query logging

[Blackbaud-MikeLueders]

I'm not sure if this is the right place - it seems to log all the queries I'd be interested in but I'm open to suggestions if there's a better place for it.

fixes #18639

[ghost]

Thank you for your contribution Blackbaud-MikeLueders! We will review the pull request and get back to you soon.

[moderakh]

Thank you @Blackbaud-EricSlater for your contribution.

@kushagraThapar FYI

[moderakh]

@mbhaskar is this the right place?

[mbhaskar]

queryDocuments would be a better place IMHO if all we want is to log the document/item queries.

azure-sdk-for-java/sdk/cosmos/azure-cosmos/src/main/java/com/azure/cosmos/implementation/RxDocumentClientImpl.java

Line 2204 in e01f66b

public Flux<FeedResponse<Document>> queryDocuments(String collectionLink, SqlQuerySpec querySpec,

Placing logging in createQueryInternal would log various other queries including databases/collections etc, which may not be the intention here.

[Blackbaud-MikeLueders]

makes sense, moved

[kushagraThapar]

Thanks for your contribution @Blackbaud-MikeLueders .

So far the reason we have not implemented query logging is because of privacy concerns for customer data.
We have heard from some customers, that their logs can be accessed by anyone (someone with not a lot of permissions), so we are reluctant to put these queries in logs.

But if the SDK team agrees to have logging for queries, we can proceed with this change. @moderakh @FabianMeiswinkel @mbhaskar @simplynaveen20 @kirankumarkolli

Also, please add a couple of test cases for this, so as to know what to expect in the logs.
And the public class surface change that I mentioned in the code review comment.

[check-enforcer]

This pull request is protected by Check Enforcer.

What is Check Enforcer?

Check Enforcer helps ensure all pull requests are covered by at least one check-run (typically an Azure Pipeline). When all check-runs associated with this pull request pass then Check Enforcer itself will pass.

Why am I getting this message?

You are getting this message because Check Enforcer did not detect any check-runs being associated with this pull request within five minutes. This may indicate that your pull request is not covered by any pipelines and so Check Enforcer is correctly blocking the pull request being merged.

What should I do now?

If the check-enforcer check-run is not passing and all other check-runs associated with this PR are passing (excluding license-cla) then you could try telling Check Enforcer to evaluate your pull request again. You can do this by adding a comment to this pull request as follows:
/check-enforcer evaluate
Typically evaulation only takes a few seconds. If you know that your pull request is not covered by a pipeline and this is expected you can override Check Enforcer using the following command:
/check-enforcer override
Note that using the override command triggers alerts so that follow-up investigations can occur (PRs still need to be approved as normal).

What if I am onboarding a new service?

Often, new services do not have validation pipelines associated with them, in order to bootstrap pipelines for a new service, you can issue the following command as a pull request comment:
/azp run prepare-pipelines
This will run a pipeline that analyzes the source tree and creates the pipelines necessary to build and validate your pull request. Once the pipeline has been created you can trigger the pipeline using the following comment:
/azp run java - [service] - ci

[Blackbaud-MikeLueders]

@kushagraThapar I don't understand the privacy concern issue. The query will only be logged if the com.azure.cosmos.implementation.SqlQuerySpecLogger logger is enabled at DEBUG and the query parameters will only be logged if the logger is enabled at TRACE. No reasonable organization is going to turn on trace logging of com.azure.cosmos.

And if they did, they would already be logging the query. If com.azure.cosmos.netty-network is enabled at INFO, the full query (including the query parameters) will be written to the logs, albeit in a much less digestable way...

|00000290| 33 2e 35 2e 30 2d 62 65 74 61 2e 31 0d 0a 41 63 |3.5.0-beta.1..Ac|
|000002a0| 63 65 70 74 3a 20 61 70 70 6c 69 63 61 74 69 6f |cept: applicatio|
|000002b0| 6e 2f 6a 73 6f 6e 0d 0a 63 6f 6e 74 65 6e 74 2d |n/json..content-|
|000002c0| 6c 65 6e 67 74 68 3a 20 31 32 31 0d 0a 0d 0a 7b |length: 121....{|
|000002d0| 22 71 75 65 72 79 22 3a 22 73 65 6c 65 63 74 20 |"query":"select |
|000002e0| 2a 20 66 72 6f 6d 20 72 20 77 68 65 72 65 20 72 |* from r where r|
|000002f0| 2e 69 64 20 3d 20 40 69 64 22 2c 22 70 61 72 61 |.id = @id","para|
|00000300| 6d 65 74 65 72 73 22 3a 5b 7b 22 6e 61 6d 65 22 |meters":[{"name"|
|00000310| 3a 22 40 69 64 22 2c 22 76 61 6c 75 65 22 3a 22 |:"@id","value":"|
|00000320| 30 35 62 63 32 32 36 39 2d 36 34 65 62 2d 34 66 |05bc2269-64eb-4f|
|00000330| 61 66 2d 38 64 64 33 2d 31 66 66 63 39 38 65 38 |af-8dd3-1ffc98e8|
|00000340| 34 37 37 37 22 7d 5d 7d                         |4777"}]}        |

So any motivated person can already see the complete query, including the parameters (at INFO, which is higher than DEBUG/TRACE).

But TBH, this wouldn't even be my main concern if I thought organizations were enabling com.azure.cosmos logging... I'd be MUCH more concerned about com.azure.cosmos.implementation.directconnectivity.rntbd.RntbdResponseDecoder, which logs the COMPLETE response if set to DEBUG.

10:31:09.026 [cosmos-rntbd-nio-2-8] DEBUG c.a.c.i.d.rntbd.RntbdResponseDecoder - [id: 0xd14be2db, L:/192.168.1.94:64783 - R:cdb-ms-prod-southcentralus1-fd25.documents.azure.com/104.214.18.42:14037] DECODE COMPLETE: RntbdResponse({"messageLength":842,"referenceCount":0,"frame":{"length":457,"status":201,"activityId":"dbd0de85-7c3d-11eb-86f5-1f04eb60f41e"},"headers":{"LSN":{"id":19,"name":"LSN","present":true,"required":false,"value":62,"tokenType":"LongLong"},"currentReplicaSetSize":{"id":31,"name":"CurrentReplicaSetSize","present":true,"required":false,"value":4,"tokenType":"ULong"},"currentWriteQuorum":{"id":30,"name":"CurrentWriteQuorum","present":true,"required":false,"value":3,"tokenType":"ULong"},"eTag":{"id":4,"name":"ETag","present":true,"required":false,"value":"\"00004900-0000-0500-0000-603fb9cd0000\"","tokenType":"String"},"globalCommittedLSN":{"id":41,"name":"GlobalCommittedLSN","present":true,"required":false,"value":61,"tokenType":"LongLong"},"lastStateChangeDateTime":{"id":2,"name":"LastStateChangeDateTime","present":true,"required":false,"value":"Mon, 01 Mar 2021 19:35:10.529 GMT","tokenType":"SmallString"},"localLSN":{"id":58,"name":"LocalLSN","present":true,"required":false,"value":62,"tokenType":"LongLong"},"numberOfReadRegions":{"id":48,"name":"NumberOfReadRegions","present":true,"required":false,"value":0,"tokenType":"ULong"},"ownerFullName":{"id":23,"name":"OwnerFullName","present":true,"required":false,"value":"dbs/testdb/colls/AuditableEntity","tokenType":"String"},"ownerId":{"id":24,"name":"OwnerId","present":true,"required":false,"value":"6UgWAKDqEXc=","tokenType":"String"},"partitionKeyRangeId":{"id":33,"name":"PartitionKeyRangeId","present":true,"required":false,"value":"0","tokenType":"String"},"payloadPresent":{"id":0,"name":"PayloadPresent","present":true,"required":true,"value":1,"tokenType":"Byte"},"quorumAckedLSN":{"id":26,"name":"QuorumAckedLSN","present":true,"required":false,"value":61,"tokenType":"LongLong"},"quorumAckedLocalLSN":{"id":59,"name":"QuorumAckedLocalLSN","present":true,"required":false,"value":61,"tokenType":"LongLong"},"requestCharge":{"id":21,"name":"RequestCharge","present":true,"required":false,"value":7.0476190476190474,"tokenType":"Double"},"schemaVersion":{"id":16,"name":"SchemaVersion","present":true,"required":false,"value":"1.11","tokenType":"SmallString"},"sessionToken":{"id":62,"name":"SessionToken","present":true,"required":false,"value":"-1#62","tokenType":"String"},"storageMaxResoureQuota":{"id":14,"name":"StorageMaxResoureQuota","present":true,"required":false,"value":"documentSize=51200;documentsSize=52428800;documentsCount=-1;collectionSize=52428800;","tokenType":"String"},"storageResourceQuotaUsage":{"id":15,"name":"StorageResourceQuotaUsage","present":true,"required":false,"value":"documentSize=0;documentsSize=2;documentsCount=1;collectionSize=2;","tokenType":"String"},"transportRequestID":{"id":53,"name":"TransportRequestID","present":true,"required":false,"value":3,"tokenType":"ULong"},"xpRole":{"id":38,"name":"XPRole","present":true,"required":false,"value":1,"tokenType":"ULong"}},"content":{"lengthInBytes":381,"hexDump":"7b226964223a2230356263323236392d363465622d346661662d386464332d316666633938653834373737222c225f65746167223a225c2230303030343930302d303030302d303530302d303030302d3630336662396364303030305c22222c22637265617465644279223a2261756469746f72222c226372656174656444617465223a312e36313437383930363431383437383445392c226c6173744d6f6469666965644279223a2261756469746f72222c226c6173744d6f646966696564427944617465223a312e36313437383930363431383437383445392c225f726964223a2236556757414b447145586362414141414141414141413d3d222c225f73656c66223a226462735c2f3655675741413d3d5c2f636f6c6c735c2f36556757414b44714558633d5c2f646f63735c2f36556757414b447145586362414141414141414141413d3d5c2f222c225f6174746163686d656e7473223a226174746163686d656e74735c2f222c225f7473223a313631343738393036397d","string":"{\"id\":\"05bc2269-64eb-4faf-8dd3-1ffc98e84777\",\"_etag\":\"\\\"00004900-0000-0500-0000-603fb9cd0000\\\"\",\"createdBy\":\"auditor\",\"createdDate\":1.614789064184784E9,\"lastModifiedBy\":\"auditor\",\"lastModifiedByDate\":1.614789064184784E9,\"_rid\":\"6UgWAKDqEXcbAAAAAAAAAA==\",\"_self\":\"dbs\\/6UgWAA==\\/colls\\/6UgWAKDqEXc=\\/docs\\/6UgWAKDqEXcbAAAAAAAAAA==\\/\",\"_attachments\":\"attachments\\/\",\"_ts\":1614789069}"}})

[kushagraThapar]

@Blackbaud-MikeLueders - Its not about enabling logging at com.azure.cosmos level, but rather just having things in the logs which others don't have access to. You bring a very good point, that Rntbd and netty are already logging these details, so I agree with you that this feature should be fine. Let's go ahead with this. Can you please resolve the conflicts and push another commit. I can start of the CIs and get it in :)

[Blackbaud-MikeLueders]

I should clarify, I don't think it's wrong to have those logs in the first place (although they do seem to be at the wrong level, I would suggest netty-network be at DEBUG or TRACE and RntbdResponseDecoder be at TRACE) - these libraries are executing complex operations, especially the higher in the stack you go (e.g. azure-spring-data-cosmos which creates queries based on method names and input parameters) and removing the ability for customers to see what is actually happening makes it extremely difficult or impossible to diagnose problems when they arise (and they will inevitably arise). That's the whole point of log levels, it gives the client fine grained control over what gets logged and what doesn't.

[Blackbaud-MikeLueders]

@kushagraThapar rebased and pushed, thanks for getting this in!

[kushagraThapar]

@kushagraThapar rebased and pushed, thanks for getting this in!

Seems like some of the unit tests you have added are failing, can you please fix those.

[Blackbaud-MikeLueders]

@kushagraThapar whoops, forgot to include the group in the @BeforeMethod annotation, fixed now. it looks like the check-enforcer has been running for over 21 hours, it might need to be kicked.

[moderakh]

LGTM. and thanks for your contribution.

please wait for @mbhaskar (our query expert) review as well to make sure we are not missing anything.

@mbhaskar could you review please?

[moderakh]

header is missing.

[Blackbaud-MikeLueders]

added header

[mbhaskar]

Two suggestions:

1. Move the logging to queryDocuments so that we log only document queries
2. Provide config options to log queryText only excluding the paramters as @FabianMeiswinkel suggested

[moderakh]

also it would be good if we only log the query text not the parameter values.
why would you need parameter values to be logged?

[Blackbaud-MikeLueders]

Partly because I was patterning it after hibernate logging

org.hibernate.SQL=debug logs the query
org.hibernate.type=trace logs the bound parameters

And party because they can be extremely useful when tracking down a misbehaving query or stored procedure.

it's worth nothing that spring-data-mongo also supports logging query parameters

org.springframework.data.mongodb.core.MongoTemplate=DEBUG

[Blackbaud-MikeLueders]

@mbhaskar I moved the statement to queryDocuments, thanks for the suggestion.

Re: a config option, could you help me understand what that accomplishes? Logging frameworks exist in order to solve this exact problem - to be able to change the output based on desired levels. Someone would have to specifically enable com.azure.cosmos.implementation.SqlQuerySpecLogger=TRACE in order to see the query params (DEBUG shows them the query, TRACE shows them the query + parameters). No other datasource integration that I'm aware of has a separate configuration option (outside of setting different logging levels) for query parameters. Also, as previously noted, query parameters are already being logged at a much higher level (INFO) in com.azure.cosmos.netty-network.

[Blackbaud-MikeLueders]

it looks like this PR #19536 broke the analysis stage, let me know if i need to rebase once it's resolved.

[kushagraThapar]

it looks like this PR #19536 broke the analysis stage, let me know if i need to rebase once it's resolved.

looking into this failure, will update once this is resolved

[mbhaskar]

Thank you @Blackbaud-MikeLueders for your contribution and iterating on this.

[JV-TMCZ]

Hello, thanks for your work. It helps a lot.
enabling com.azure.cosmos.implementation.SqlQuerySpecLogger=TRACE add queries and params to logs. Great.

Few remarks: I see 3 different type of logs, could you make it more consistent? Thanks.
1)

2021-05-17 12:11:11.873 DEBUG 25732 --- [nio-8080-exec-1] c.a.c.implementation.SqlQuerySpecLogger  : SELECT * FROM ROOT r WHERE r.myId = @myId223b0c88_91a4_4e32_9e2f_ab3ae5e305f7 
 > param: @myId223b0c88_91a4_4e32_9e2f_ab3ae5e305f7 = 85231013-7e8d-439e-9df9-dff0c5d00925

Where parameter name is concat from actual paramName and some UUID ?!? Unfortunatelly, I could not find any select query which would cause it. Could it be some automatic pre-load before save operation?

2021-05-17 12:11:14.180 DEBUG 25732 --- [nio-8080-exec-1] c.a.c.implementation.SqlQuerySpecLogger  : select * from m where m.begin < @endOfToday AND m['end'] > @startOfToday
 > param: @startOfToday = 2021-05-16T22:00:00Z
 > param: @endOfToday = 2021-05-17T21:59:59.999999999Z

as a result of this query

	@Query(value = "select * from m where m.begin < @endOfToday AND m['end'] > @startOfToday")
	List<Entity> findToday(Instant startOfToday, Instant endOfToday);

2021-05-17 12:11:08.247 DEBUG 25732 --- [nio-8080-exec-1] c.a.c.implementation.SqlQuerySpecLogger  : SELECT * FROM ROOT r  

as a result of

List<Entity> findAll();

here, it would be great if possible, to log target container/table. Instead of ROOT r log something like ContainerName r