[FEATURE-REQUEST]- Using of DEBUG/TRACE logging related to queries being executed (and/or expanded).

[dturkelFerguson]

Is your feature request related to a problem? Please describe. It is extraordinarily difficult to figure out why this plug-in behaves the way it does when querying and evaluating data for migration. For instance, I have a very simple configuration related to transferring Account data:

{
    "objects": [
      {
        "query": "SELECT Id, Name, ERPPartyAccountID__c, updateable_true FROM Account",
        "operation": "Upsert",
        "externalId": "ERPPartyAccountID__c",
        "excludedFields": "Contact__c",
        "master": false 
      }
    ]
}

I can see in the STDOUT/logging that the basic COUNT of possible records is being queried, but whatever query is being used for the various phases of evaluation return no records (and I know there are many valid records in the source environment). The potential query above seems like it should result in something simple enough, but I have no basis available to evaluate what is going on:

sfdx sfdmu:run --verbose --loglevel TRACE --filelog --sourceusername *** --targetusername ***

[2022-12-24  15:37:49.097] Execution of the command sfdmu:run has been started.

=== LOADING AND VALIDATING THE PACKAGE SCRIPT ...

=== OBJECT SET #1 STARTED

Running Plugin version: 4.19.3
Running Add-On Api version: 1.3.0

[2022-12-24  15:37:49.105] Loading core Add-On declarations ...
[2022-12-24  15:37:49.177] Connecting to *** using SFDX force:org:display ...
[2022-12-24  15:37:52.330] Successfully connected to ***.
[2022-12-24  15:37:53.081] Connecting to *** using SFDX force:org:display ...
[2022-12-24  15:37:56.000] Successfully connected to ***.
Package script: /home/runner/work/x/export.json.
SOURCE:         ***.
TARGET:         ***.

=== GETTING AND ANALYSING OBJECTS METADATA ...
[2022-12-24  15:37:56.832] Processing the sObject Account ...
[2022-12-24  15:37:56.833] Getting metadata for Account (SOURCE)
[2022-12-24  15:37:57.748] Getting metadata for Account (TARGET)
[2022-12-24  15:37:59.073] Getting metadata for Group (SOURCE)
[2022-12-24  15:37:59.451] Processing the sObject Account ...

=== PREPARING DATA MIGRATION JOB ...
[2022-12-24  15:37:59.458] Building migration strategy ...
Order of objects to retrieve data: Account
Order of objects to delete data: Account
Order of objects to update data: Account
[2022-12-24  15:37:59.461] Preparing has been finished.

=== ANALYSING THE OVERALL DATA VOLUME ...
[2022-12-24  15:37:59.775] {Account} Total amount of the SOURCE records should be retrieved by the object's SOQL query: 14976
[2022-12-24  15:38:00.093] {Account} Total amount of the TARGET records should be retrieved by the object's SOQL query: 12983

=== PROCESSING ADD-ON EVENT HANDLERS ...
[2022-12-24  15:38:00.094] No Add-On modules found to process.

[2022-12-24  15:38:00.095] Ready to process the data.

=== DELETING OLD DATA FROM THE TARGET ...
[2022-12-24  15:38:00.096] {Account} No records to delete.
[2022-12-24  15:38:00.096] Deleting data was skipped.

=== RETRIEVING THE DATA STAGE 1 ...
[2022-12-24  15:38:00.101] No records
[2022-12-24  15:38:00.102] Retrieving the data STAGE 1 has been completed.

=== RETRIEVING THE DATA STAGE 2 ...
[2022-12-24  15:38:00.102] PASS 1
[2022-12-24  15:38:00.103] =============
[2022-12-24  15:38:00.103] No records

[2022-12-24  15:38:00.104] PASS 2
[2022-12-24  15:38:00.104] =============
[2022-12-24  15:38:00.104] No records

[2022-12-24  15:38:00.105] PASS 3
[2022-12-24  15:38:00.105] =============
[2022-12-24  15:38:00.109] No records

[2022-12-24  15:38:00.109] PASS 4
[2022-12-24  15:38:00.109] =============
[2022-12-24  15:38:00.113] No records

[2022-12-24  15:38:00.113] TARGET
[2022-12-24  15:38:00.113] =============
[2022-12-24  15:38:00.115] No records
[2022-12-24  15:38:00.115] Retrieving the data STAGE 2 has been completed.

=== PROCESSING ADD-ON EVENT HANDLERS ...
[2022-12-24  15:38:00.116] No Add-On modules found to process.

=== DATA RETRIEVING SUMMARY
[2022-12-24  15:38:00.116] {Account} Total retrieved within all stages (source/target): 0/0 records.

=== UPDATING THE TARGET STAGE 1 ...
[2022-12-24  15:38:00.120] Nothing was updated

=== UPDATING THE TARGET STAGE 2 ...
[2022-12-24  15:38:00.121] Nothing was updated

Describe the solution you'd like Add DEBUG or TRACE level logging to include the queries being executed at each step of the process. Consider even prior to this, log the parsing/expansion of queries being performed.

[hknokh]

Hello

I don't know to say you regarding the TRACE, I'm not really using it, but normally the SFDMU showing well the detailed log if you put --verbose at the end of the CLI string. It writes logs both to the stdout and to the .log file.

So, finally I would suggest you to to remove --loglevel TRACE and to run the sfdmu with the following command: sfdx sfdmu:run --path "C:\Path" --sourceusername SOURCE --targetusername TARGET --verbose This is simplest command required to see the detailed log. And I always put all additional flags at the end after the required.

If my suggestion still does not help (since you also have --verbose in your command string), it should be investigated and may be even debugged on your side, since it's not reproducable on my side.

BTW. The --filelog flag is not necessary here, since you don't use --quiet or --silent

[dturkelFerguson]

@hknokh - This is a feature request to add new logging since it's not there. Those logs (SOQL being executed) could be written at the DEBUG or TRACE level - at your (or a developer's discretion). The core issue is reproduceable. No record of SOQL being executed is put on STDOUT or in any logging.

[hknokh]

Hello @dturkelFerguson

As I understand you request and as the only architect and developer of this Plugin, I can say, that your requested feature of --loglevel flag is already implemented and so far it was working well.

Please see the below reference for the available flags: https://help.sfdmu.com/full-documentation/configuration-and-running/run-the-migration-job

You can also review other tickets opened by the SFDMU users and you can find a lot of log files containing performed query strings.

Regarding the loglevel There are 2 actual log levels are implemented: INFO and ERROR:

• By default the log level is INFO.
• WARN and DEBUG are also the same as INFO
• TRACE is also the same as INFO, but will print stack trace on errors.
• FATAL is the same as ERROR and outputs only error messages, nothing else.
• The --verbose flag just adds more verbosity into INFO log levels (you can choose the verbosity between NORMAL/MINIMAL/NONE/VERBOSE), by default it's NORMAL

Just try out it by putting --loglevel ERROR and you will see almost nothing printed into the stdout if no errors occur.

Finally, I am really sorry. I would like to help you more, but couldn't, since as I said, this issue is not reproducable at my end. Indeed, we have different environments and you can get different results due to variety of reasons. So I still suggest to debug the source code locally if you have such option.

Regarding my closing the ticket, it's just my normal workflow: I always close every ticket after I've responded on it and I see that I can do nothing else for that specific request.

Thank you for your patience and the understanding!

[dturkelFerguson]

The feature request is to add more logging as it relates to the queries being generated and executed. The plugin should be logging this information at a DEBUG or TRACE level so that users can understand and figure out why requested objects aren't being queried by the plugin.

This has nothing to do with the general implementation of logging.

This should remain an open feature request in the backlog, whether you or someone else wants to do the work.

[hknokh]

From my point of view, nothing to add is here. If for unknown reasons the query string simply does not return any results from the api call, what can we log else ? No errors or warnings here to write. If this is a bug, in order to be fixed it should be figured out by reproducing on my end and I couldn't.

And I will really appreciate any your help in debugging it on your end and pointing me what's wrong.

I never hold backlog tickets opened. Even marked as "Roadmap". Only tickets "In progress".

As you can refer to our contribution policy, we do not accept complex modifications to the core plugin code base from the third-party contributors. Logging is a kind of complex one across whole sfdmu engine and it can be done by me only. And again, as I said so far, I do not see what can be improved over the existing logging functionality.

Thanks again for the feature suggestion.

[dturkelFerguson]

If you're going to unilaterally convert this to a QUESTION, then please leave it open so someone will actually review the situation described, and can provide a probable cause/solution as to why such a simple query isn't processing any data. You haven't provided any answer. If for unknown reasons the query string simply does not return any results from the api call, what can we log else ? No errors or warnings here to write. How about writing the query string that was used? I'm not executing a complex query with filters here, but for some reason nothing is coming back from my org. What is the proposed set of field? Was the query/API even executed? etc. etc. etc.

I don't see how adding log entries about the evaluating and construction of the queries is "complex".

I'm not a node developer, but I can read enough to tell that adding some logger doesn't seem especially complex. While I get that it isn't necessarily a priority with respect to bug fixes or other significant features, having additional log entries (at the appropriate level of detail) could help answer questions that would normally fill this Issues list.

[hknokh]

@dturkelFerguson

First of all I agree with you that the logging is very important and can do our life happier. Just FYI, this is the short example "normal" log, provided by the SFDMU:

[2022-12-27 01:16:10.597] {RecordType} Retrieving the SOURCE data from Org (STAGE 1: all records) ... [2022-12-27 01:16:10.600] {RecordType} Query string: SELECT Id, $$DeveloperName$NamespacePrefix$SobjectType FROM RecordType. [2022-12-27 01:16:11.063] {RecordType} Retrieving the SOURCE data has been completed. Fetched 24 new records. [2022-12-27 01:16:11.065] {User} Retrieving the SOURCE data from Org (STAGE 1: all records) ... [2022-12-27 01:16:11.067] {User} Query string: SELECT Id, Name FROM User. [2022-12-27 01:16:12.273] {User} Retrieving the SOURCE data has been completed. Fetched 335 new records. [2022-12-27 01:16:12.276] {TestObject3c} Retrieving the SOURCE data from Org (STAGE 1: all records) ... **[2022-12-27 01:16:12.279] {TestObject3c} Query string: SELECT Id, anc, Datec, Testc, OwnerId, TestObject2c, Name, Owner.Name, TestObject2r.Id, TestObject2r.Name FROM TestObject3c.** [2022-12-27 01:16:12.717] {TestObject3c} Retrieving the SOURCE data has been completed. Fetched 3 new records.

and so on...

You can trust me that the architecture of this Plugin is very complex and even just "constructing the queries" and "adding a logging" is not so simple task as you probably imagine and must be done very very accurately.

I do not throw your case out or ignore it. Each case and yours also - is very important for me and I respect it, because only live testing by the users can improve the Plugin and so you help me a lot.

But what can I do with issues, which I can't reproduce on my end or I am sure that the requested feature is already done?.. Unfortunatelly, I can't help in this situation. And nobody can help. In your case check for the field permission issues. As I see you use updateable_true, it's a lot of fields to include. But it's no more than a blind guessing without investigate this locally on YOUR system.

Finally, you are definitely right about leaving case open for some time for review by others or me. I can't hold it open forever, it's completely useless but not to close imediatelly - yes it worth. So I will think about to start giving some stale period for any cases including "not reproducible" on my end or "wontfix". Thx for the good idea.

[github-actions[bot]]

This case has been marked as 'to-be-closed', since it has no activity for the 3 days.
It will be automatically closed in another 3 days of inactivity.

[github-actions[bot]]

This case has been closed, since it has no activity for the 3 days after was marked as a 'to-be-closed'. Feel free to reopen it at any time, if you need more help.

[hknokh]

Hello @dturkelFerguson I think it will be great to add logging about fields being excluded from the process and why. This info will be logged if --verbose flag is used. I I'm putting this feature on my development backlog.