Separate Queueable runs are collected into one Log__c record

[reitffunk]

Hi,

I have a Queueable where I also set the parentLogTransactionId accordingly to the provided examples. At the end of this Queueable the same is chained again until there is no work left.

Regarding to the logs I would have expected that every separate execution of the Queueable creates its own Log__c record.

Instead all the runs are collected into one Log__c record. You can see it in the screenshot where on the right side it says for the first bunch of entries 1 and for the second bunch 2. These are basically the separate executions of the Queueable and every 1, 2 should be a separate Log__c record.

The funny thing: Somehow the same code produces multiple Log__c records within the Sandbox.

I do not understand how they are related at all as every separate Queueable execution should be its own transaction and therefore I thought the Logger gets also a new transaction id. I only reconnect them again by setting the parentLogTransactionId. And I call Logger.saveLog() at several places.

Does anybody have a hint how this could happen or what I might be doing wrong?

[jongpie]

Hi @reitffunk - that definitely looks like a bug, each execution of the queueable job should have its own Log__c record like you described. Do you happen to have any sample code that you could share that would demonstrate this issue? I've tried to reproduce the issue using the queueable class below, but it seems to work as expected every time (each execution of the queueable job creates its own Log__c recrd), so I'm not able to reproduce this issue.

public without sharing class Chained_Queueable_Logger_Example implements Queueable {
    private Integer numberOfJobsToChain;
    private String parentLogTransactionId;
    private List<LogEntryEvent__e> logEntryEvents = new List<LogEntryEvent__e>();

    public Chained_Queueable_Logger_Example(Integer numberOfJobsToChain) {
        this(numberOfJobsToChain, null);
    }

    private Chained_Queueable_Logger_Example(Integer numberOfJobsToChain, String parentLogTransactionId) {
        this.numberOfJobsToChain = numberOfJobsToChain;
        this.parentLogTransactionId = parentLogTransactionId;
    }

    public void execute(System.QueueableContext queueableContext) {
        Logger.setParentLogTransactionId(this.parentLogTransactionId);

        Logger.fine('queueableContext==' + queueableContext);
        Logger.info('this.numberOfJobsToChain==' + this.numberOfJobsToChain);
        Logger.info('this.parentLogTransactionId==' + this.parentLogTransactionId);

        Logger.saveLog();

        --this.numberOfJobsToChain;
        if (this.numberOfJobsToChain > 0) {
            String parentLogTransactionId = this.parentLogTransactionId != null ? this.parentLogTransactionId : Logger.getTransactionId();
            System.enqueueJob(new Account_Queueable_Logger_Example(this.numberOfJobsToChain, parentLogTransactionId));
        }
    }
} 

[reitffunk]

Hi @jongpie,

thanks for testing it directly. Following an observation and some code.

Different transaction id prefix

First weird thing is that the behavior differs from the Partial-Copy-Sandbox to the Production system. The Logger-Settings are the same and only one "Organization" record exists. Save method ist EVENT_BUS.

I just have noticed that the Transaction ID prefix differs for both systems. The "wrong" ones are prefixed with SLB. I cannot find anything on Google for SLB and currently I also don't have an idea what it means. The correctly separated ones in the partial copy are not prefixed and have it's own transaction ID for every log as expected.

The triggering action comes from an Aura-Component, it is prefixed with TID what just means transaction id I guess.

Production-System (unexpected behavior):

Partial-Copy-Sandbox (expected behavior) (ignore LOG-24, thats another platform event that is logged in this whole process):

Code

Now some code, I strip any other logic to focus on triggering the Queueable and the Logger.

Coming from the Aura-Component:

public static Map<String, String> updatePositions(Map<String, AM_Bestellposition__c > orderPositions, List<AM_DeliveryPositionDraftApexClass> orderPositionsDeliveries, String deliveryNoteNumber, Date deliveryNoteDate) {
    updateCounterViaQueueable(deliveryPositionDtos, Logger.getTransactionId());
}

private static void updateCounterViaQueueable(List<Delivery_Position_Item__c> deliveryPositionDtos, String loggerTransactionId) {

        UpdateCounterQueueable updateCounterQueueable = new UpdateCounterQueueable(deliveryPositionDtos, 1, loggerTransactionId);
        System.enqueueJob(updateCounterQueueable);
    }

The UpdateCounterQueueable() chains itself:

        public void execute(QueueableContext ctx) {
            try {
                if (this.parentLogTransactionId != null) {
                    Logger.setParentLogTransactionId(this.parentLogTransactionId);
                }

                // prepare which items to process now and which with the next round of the queueable
                List<Delivery_Position_Item__c> itemsToProcess = new List<Delivery_Position_Item__c>();
                List<Delivery_Position_Item__c> itemsToProcessNextRound = new List<Delivery_Position_Item__c>();

                Integer calculationCounter = this.items.size() > this.batchSize ? this.batchSize : this.items.size();

                for (Integer i = 0; i < calculationCounter; i++) {
                    itemsToProcess.add(this.items.get(i));
                }

                for (Integer i = calculationCounter; i < this.items.size(); i++) {
                    itemsToProcessNextRound.add(this.items.get(i));
                }

                try {
                    this.doTheActualProcessing(itemsToProcess);
                } catch (Exception e) {
                    // We catch it here also. That way the Queueable for the remaining items can
                    // continue.
                    Logger.error('Counter could not be updated: Exception: ' + e.getMessage() +
                            '\nStacktrace: ' + e.getStackTraceString() +
                            '\nItems: ' + JSON.serializePretty(this.items) +
                            '\nItemsToProcess: ' + JSON.serializePretty(itemsToProcess) +
                            '\nItemsToProcessNextRound: ' + JSON.serializePretty(itemsToProcessNextRound)
                    );
                    Logger.saveLog();

                    AM_DeliveryNote_ApexCtrl_Helper.notifyGroupAboutError(itemsToProcess);
                }

                // enqueue the remaining items
                if (itemsToProcessNextRound.size() > 0) {
                    if (itemsToProcessNextRound.size() >= this.batchSize) {
                        System.enqueueJob(new UpdateCounterQueueable(itemsToProcessNextRound, this.batchSize, this.parentLogTransactionId));
                    } else {
                        System.enqueueJob(new UpdateCounterQueueable(itemsToProcessNextRound, itemsToProcessNextRound.size(), this.parentLogTransactionId));
                    }
                }
            }
            catch (Exception ex) {
                Logger.error('Exception: ' + ex.getMessage() + '\nStacktrace: ' + ex.getStackTraceString());
            }
            finally {
                Logger.saveLog();
            }
        }

        private void doTheActualProcessing(List<Delivery_Position_Item__c> objectsToProcess) {
            AM_DeliveryPositionItem_Handler.updateCounters(objectsToProcess);
        }
    }

AM_DeliveryPositionItem_Handler.updateCounters(objectsToProcess); then calls Logger.setScenario('Blubb') (what should be in the execute() I just notice) but it does not make any more calls to Logger.save().

Maybe the surround try-catch somehow creates a context between the calls? Should also not be the case, just a desperate shot in the dark :D

[jongpie]

Hi @reitffunk, I don't do much directly to handle a new transaction/new request ID - I rely on the platform & Apex's behavior to help with setting a new transaction ID when needed. Specifically, I leverage Apex's way of setting static variables to set some fields only once per transaction - and in Apex, once a transaction ends, any static variables are discarded/they're recreated at the start of a new transaction. I do this for several variables/constants throughout the codebase, but there are 2 relevant variables:

1. Logger.TRANSACTION_ID - this is the private constant that's causing issues in your scenario. This is the value returned when you call Logger.getTransactionId(). Because it's final, and it's set when instantiated, the value should be the same within a single transaction, and should get a new value when a new transaction starts. However, since you're seeing multiple queueable jobs using the same transaction ID (thus, creating 1 Log__c), it makes me think that the platform is re-using values in System.Request.getCurrent().getRequestId()
2. Logger.currentTransactionEntryNumber - this is a private variable that's used to set the "Entry #" field that you circled in your original screenshot. This variable is similar to Logger.TRANSACTION_ID in that it has an initial value (1) set when the variable is instantiated - within the same transaction, it is then only incremented; the only time that it ever reset to 1 is when a new transaction starts. So the fact that your screenshot shows multiple LogEntry__c records with the same "Entry #" makes me think that this variable is being reset correctly when a new transaction starts, but the request ID is being re-used.

I think in the next release (v4.7.3) I'm going to go ahead & change the transaction ID to always be a UUID - once that release is ready, would you be able to test it in your production org? My hope is that you will start to see multiple Log__c records (1 record per execution of the queueable job).

[reitffunk]

Ah, that's interesting regarding the static variables!

And of course I will be able to test it. I am eagerly waiting for the new version - no pressure intended :D

[jongpie]

@reitffunk I've just released v4.7.3, which includes the change to only use a UUID for the transaction ID. Whenever you have a chance to install it in your prod org, let me know if it resolves your issue with the queueable jobs.

[reitffunk]

Hey @jongpie,

I have just looked into the Org and it's working as expected now.

Thank you very much! :)

[jongpie]

That's great to hear @reitffunk! Thanks for confirming, and let me know if you run into any other issues

[jongpie]

Just noting that this was fixed in v4.7.3 by switching to always using a UUID for the transaction ID.