+ Start a Discussion
Justin MitchellJustin Mitchell 

Trigger works in sandbox AND test class, but not when manually tested in production

I have a trigger to track how long opportunies remain in each stage. I wrote it in a full copy sandbox and it tested it manually and it works properly. I then wrote a test class which covers the trigger at 100% and the tests all passed. Next, I deployed it to production and ran the test upon deployment and it passed and deployed. I then ran the test a second time just to be extra sure and all tests passed. All good so far! Finally I tried manually testing the trigger in production (using the exact same method I used in the sandbox) and... it's not working. The trigger IS firing, I know, because one element is being updated properly, but the rest is not. 

It's a bit hard for me to read through the debug log but I believe I'm getting a null pointer exception error as a result of the trigger running, and since I have a try/catch method looking for that error, it's skipping over that block of code.
12:50:39.412 (436621934)|VARIABLE_SCOPE_BEGIN|[37]|npe|System.NullPointerException|true|false
12:50:39.412 (436760589)|VARIABLE_ASSIGNMENT|[37]|npe|"common.apex.runtime.impl.ExecutionException: Attempt to de-reference a null object"|0x66e078e8
What I can't figure out is why this works fine in the sandbox but produces this error in production??
Also, why isn't the test class producing the same error?

Here's my trigger and test class. I am always open to learning so if you have a more efficient way to write this I'd love to learn. 

Trigger
trigger trackOpportunityStageDuration on Opportunity (before insert, before update) {

  for(Opportunity o : Trigger.new) {
    //for all new Opportunities, update the current stage start to NOW()
    if(Trigger.isinsert) {
      o.Current_Stage_Start__c = datetime.now();
    }

    if(Trigger.isupdate) {
      try {
        Opportunity oldOpp = Trigger.oldMap.get(o.Id);
        Decimal elapsedTime = (Decimal.valueof(datetime.now().getTime()).setscale(2) - Decimal.valueof(o.Current_Stage_Start__c.getTime()).setscale(2)) / 86400000;

        //if the stage field is changed: 1) add the number of days between today and the current stage start date to the value currently in the appropriate "stage duration" field, then 2) update the "current stage start" field to now()
        if(oldOpp.StageName != o.StageName && elapsedTime != null) {
          if(oldOpp.StageName == 'Qualification') {
            o.Stage_Duration_Qualification__c = o.Stage_Duration_Qualification__c + elapsedTime;
          }
          if(oldOpp.StageName == 'Needs Analysis') {
            o.Stage_Duration_Needs_Analysis__c = o.Stage_Duration_Needs_Analysis__c + elapsedTime;
          }
          if(oldOpp.StageName == 'Proposal/Price Quote') {
            o.Stage_Duration_Proposal_Price_Quote__c = o.Stage_Duration_Proposal_Price_Quote__c + elapsedTime;
          }
          if(oldOpp.StageName == 'Negotiation/Review') {
            o.Stage_Duration_Negotiation_Review__c = o.Stage_Duration_Negotiation_Review__c + elapsedTime;
          }
          if(oldOpp.StageName == 'Contract Sent') {
            o.Stage_Duration_Contract_Sent__c = o.Stage_Duration_Contract_Sent__c + elapsedTime;
          }
          if(oldOpp.StageName == 'Closed - Billing Review') {
            o.Stage_Duration_Closed_Billing_Review__c = o.Stage_Duration_Closed_Billing_Review__c  + elapsedTime;
          }
          o.Current_Stage_Start__c = datetime.now();
        }
      }
      catch (NullPointerException npe) {
        o.Current_Stage_Start__c = datetime.now();
      }
    }
  }
}

Test Class
@isTest
private class trackOpportunitStageDuration_test2 {

	@isTest static void testStageDuration_Qualification() {
		//1. create new account and opportunity
		Account a = new Account(Name='Test Account',Type='Prospect',Industry='Advertising');
		insert a;
		Opportunity o = new Opportunity(Name='Test Opportunity',AccountId=a.id,CloseDate=date.today(),StageName='Qualification');
		insert o;

		//2. confirm that the current stage start field is equal to "now()"
		Opportunity resultOppty1 = [SELECT Current_Stage_Start__c FROM Opportunity WHERE Id = :o.Id];
    System.AssertNotEquals (null, resultOppty1.Current_Stage_Start__c);

		//3. update current stage start field, subtract some Time
		o.Current_Stage_Start__c = resultOppty1.Current_Stage_Start__c - 1;
		update o;

		//4. update stage field
		o.StageName = 'Needs Analysis';
		update o;

		//5. Check tha the proper Stage Duration field has been updated
		Opportunity resultOppty2 = [
			SELECT Stage_Duration_Qualification__c,Stage_Duration_Needs_Analysis__c,Stage_Duration_Proposal_Price_Quote__c,Stage_Duration_Negotiation_Review__c,Stage_Duration_Contract_Sent__c,Stage_Duration_Closed_Billing_Review__c
			FROM Opportunity
			WHERE Id = :o.Id];
		System.Assert (resultOppty2.Stage_Duration_Qualification__c > 0);

		//update Current Stage Start to blank, then update the stage again
		o.Current_Stage_Start__c = null;
		o.StageName = 'Needs Analysis';
		update o;

		//Check that the current stage start field is not blank
		Opportunity resultOppty3 = [
			SELECT Current_Stage_Start__c
			FROM Opportunity
			WHERE Id = :o.Id];
		System.AssertNotEquals (null,resultOppty3.Current_Stage_Start__c);
	}

//test Needs Analysis stage
	@isTest static void testStageDuration_NeedsAnalysis() {
		//1. create new account and opportunity
		Account a = new Account(Name='Test Account',Type='Prospect',Industry='Advertising');
		insert a;
		Opportunity o = new Opportunity(Name='Test Opportunity',AccountId=a.id,CloseDate=date.today(),StageName='Needs Analysis');
		insert o;
		Opportunity resultOppty1 = [SELECT Current_Stage_Start__c FROM Opportunity WHERE Id = :o.Id];

		//3. update current stage start field, subtract some Time
		o.Current_Stage_Start__c = resultOppty1.Current_Stage_Start__c - 1;
		update o;

		//4. update stage field
		o.StageName = 'Qualification';
		update o;

		//5. Check tha the proper Stage Duration field has been updated
		Opportunity resultOppty2 = [
			SELECT Stage_Duration_Qualification__c,Stage_Duration_Needs_Analysis__c,Stage_Duration_Proposal_Price_Quote__c,Stage_Duration_Negotiation_Review__c,Stage_Duration_Contract_Sent__c,Stage_Duration_Closed_Billing_Review__c
			FROM Opportunity
			WHERE Id = :o.Id];
		System.Assert (resultOppty2.Stage_Duration_Needs_Analysis__c > 0);
	}

	//test Proposal/Price Quote stage
	@isTest static void testStageDuration_ProposalPriceQuote() {
		//1. create new account and opportunity
		Account a = new Account(Name='Test Account',Type='Prospect',Industry='Advertising');
		insert a;
		Opportunity o = new Opportunity(Name='Test Opportunity',AccountId=a.id,CloseDate=date.today(),StageName='Proposal/Price Quote');
		insert o;
		Opportunity resultOppty1 = [SELECT Current_Stage_Start__c FROM Opportunity WHERE Id = :o.Id];

		//3. update current stage start field, subtract some Time
		o.Current_Stage_Start__c = resultOppty1.Current_Stage_Start__c - 1;
		update o;

		//4. update stage field
		o.StageName = 'Qualification';
		update o;

		//5. Check tha the proper Stage Duration field has been updated
		Opportunity resultOppty2 = [
			SELECT Stage_Duration_Qualification__c,Stage_Duration_Needs_Analysis__c,Stage_Duration_Proposal_Price_Quote__c,Stage_Duration_Negotiation_Review__c,Stage_Duration_Contract_Sent__c,Stage_Duration_Closed_Billing_Review__c
			FROM Opportunity
			WHERE Id = :o.Id];
		System.Assert (resultOppty2.Stage_Duration_Proposal_Price_Quote__c > 0);
	}

	//test Negotiation/Review stage
	@isTest static void testStageDuration_NegotiationReview() {
		//1. create new account and opportunity
		Account a = new Account(Name='Test Account',Type='Prospect',Industry='Advertising');
		insert a;
		Opportunity o = new Opportunity(Name='Test Opportunity',AccountId=a.id,CloseDate=date.today(),StageName='Negotiation/Review');
		insert o;
		Opportunity resultOppty1 = [SELECT Current_Stage_Start__c FROM Opportunity WHERE Id = :o.Id];

		//3. update current stage start field, subtract some Time
		o.Current_Stage_Start__c = resultOppty1.Current_Stage_Start__c - 1;
		update o;

		//4. update stage field
		o.StageName = 'Qualification';
		update o;

		//5. Check tha the proper Stage Duration field has been updated
		Opportunity resultOppty2 = [
			SELECT Stage_Duration_Qualification__c,Stage_Duration_Needs_Analysis__c,Stage_Duration_Proposal_Price_Quote__c,Stage_Duration_Negotiation_Review__c,Stage_Duration_Contract_Sent__c,Stage_Duration_Closed_Billing_Review__c
			FROM Opportunity
			WHERE Id = :o.Id];
		System.Assert (resultOppty2.Stage_Duration_Negotiation_Review__c > 0);
	}

	//test Contract Sent stage
	@isTest static void testStageDuration_ContractSent() {
		//1. create new account and opportunity
		Account a = new Account(Name='Test Account',Type='Prospect',Industry='Advertising');
		insert a;
		Opportunity o = new Opportunity(Name='Test Opportunity',AccountId=a.id,CloseDate=date.today(),StageName='Contract Sent');
		insert o;
		Opportunity resultOppty1 = [SELECT Current_Stage_Start__c FROM Opportunity WHERE Id = :o.Id];

		//3. update current stage start field, subtract some Time
		o.Current_Stage_Start__c = resultOppty1.Current_Stage_Start__c - 1;
		update o;

		//4. update stage field
		o.StageName = 'Qualification';
		update o;

		//5. Check tha the proper Stage Duration field has been updated
		Opportunity resultOppty2 = [
			SELECT Stage_Duration_Qualification__c,Stage_Duration_Needs_Analysis__c,Stage_Duration_Proposal_Price_Quote__c,Stage_Duration_Negotiation_Review__c,Stage_Duration_Contract_Sent__c,Stage_Duration_Closed_Billing_Review__c
			FROM Opportunity
			WHERE Id = :o.Id];
		System.Assert (resultOppty2.Stage_Duration_Contract_Sent__c > 0);
	}

	//test Closed - Billing Review stage
	@isTest static void testStageDuration_ClosedBillingReview() {
		//1. create new account and opportunity
		Account a = new Account(Name='Test Account',Type='Prospect',Industry='Advertising');
		insert a;
		Opportunity o = new Opportunity(Name='Test Opportunity',AccountId=a.id,CloseDate=date.today(),StageName='Closed - Billing Review');
		insert o;
		Opportunity resultOppty1 = [SELECT Current_Stage_Start__c FROM Opportunity WHERE Id = :o.Id];

		//3. update current stage start field, subtract some Time
		o.Current_Stage_Start__c = resultOppty1.Current_Stage_Start__c - 1;
		update o;

		//4. update stage field
		o.StageName = 'Qualification';
		update o;

		//5. Check tha the proper Stage Duration field has been updated
		Opportunity resultOppty2 = [
			SELECT Stage_Duration_Qualification__c,Stage_Duration_Needs_Analysis__c,Stage_Duration_Proposal_Price_Quote__c,Stage_Duration_Negotiation_Review__c,Stage_Duration_Contract_Sent__c,Stage_Duration_Closed_Billing_Review__c
			FROM Opportunity
			WHERE Id = :o.Id];
		System.Assert (resultOppty2.Stage_Duration_Closed_Billing_Review__c > 0);
	}
}


 
Best Answer chosen by Justin Mitchell
Justin MitchellJustin Mitchell
UPDATE
I don't understand it, but I figured out how to solve it. Here's what is happening (in production):

I am updating the Stage from Qualification to Needs Analysis, which is causing this portion of the code to attempt to run:
o.Stage_Duration_Qualification__c = o.Stage_Duration_Qualification__c + elapsedTime;
However, the value of Stage_Duration_Qualification__c is NULL, and it is at that point catching a NullPointerException. Apparently, it isn't able to add an integer (elapsedTime) to a null value. So the simple solution is to put a value of 0.00 in all these fields. I tested this out and it worked perfectly as expected. Problem essentially solved (once I add a default value in those fields).

---
The reason I don't understand is because it does not perform this way in the sandbox, nor does it before this way in a unit test. 
Here is an excerpt of the debug log from a manual test in production (with the nullpointerexception):
13:10:47.716 (746103146)|VARIABLE_SCOPE_BEGIN|[12]|elapsedTime|Decimal|false|false
13:10:47.716 (746142327)|VARIABLE_ASSIGNMENT|[12]|elapsedTime|5.01399871527777777777777777777778
13:10:47.716 (746238089)|USER_DEBUG|[13]|DEBUG|Previous Stage: Qualification
13:10:47.716 (746324490)|USER_DEBUG|[14]|DEBUG|New Stage: Needs Analysis
13:10:47.716 (746380114)|USER_DEBUG|[15]|DEBUG|Has Stage changed?
13:10:47.716 (746444799)|USER_DEBUG|[16]|DEBUG|true
13:10:47.716 (746580227)|USER_DEBUG|[17]|DEBUG|Elapsed Time: 5.01399871527777777777777777777778
13:10:47.716 (746622702)|USER_DEBUG|[18]|DEBUG|Is elapsedTime null?
13:10:47.716 (746653201)|USER_DEBUG|[19]|DEBUG|false

//NULL POINTER ERROR 
13:10:47.716 (746843632)|VARIABLE_SCOPE_BEGIN|[44]|npe|System.NullPointerException|true|false
13:10:47.716 (746979200)|VARIABLE_ASSIGNMENT|[44]|npe|"common.apex.runtime.impl.ExecutionException: Attempt to de-reference a null object"|0x7f15d91d

13:10:47.716 (748940968)|VARIABLE_ASSIGNMENT|[45]|this.Current_Stage_Start__c|"2017-07-31T20:10:48.490Z"|0x4c14819b
13:10:47.716 (748994843)|VARIABLE_ASSIGNMENT|[3]|o|null|
13:10:47.749 (749006211)|CUMULATIVE_LIMIT_USAGE
13:10:47.749 (749006211)|LIMIT_USAGE_FOR_NS|(default)|
  Number of SOQL queries: 0 out of 100
  Number of query rows: 0 out of 50000
  Number of SOSL queries: 0 out of 20
  Number of DML statements: 0 out of 150
  Number of DML rows: 0 out of 10000
  Maximum CPU time: 260 out of 10000
  Maximum heap size: 0 out of 6000000
  Number of callouts: 0 out of 100
  Number of Email Invocations: 0 out of 10
  Number of future calls: 0 out of 50
  Number of queueable jobs added to the queue: 0 out of 50
  Number of Mobile Apex push calls: 0 out of 10

And here's how it performs in a unit test (in production!)
13:17:38.598 (33727897242)|VARIABLE_SCOPE_BEGIN|[12]|elapsedTime|Decimal|false|false
13:17:38.598 (33727920777)|VARIABLE_ASSIGNMENT|[12]|elapsedTime|1.00002552083333333333333333333333
13:17:38.598 (33727956749)|USER_DEBUG|[13]|DEBUG|Previous Stage: Qualification
13:17:38.598 (33727984348)|USER_DEBUG|[14]|DEBUG|New Stage: Needs Analysis
13:17:38.598 (33727997305)|USER_DEBUG|[15]|DEBUG|Has Stage changed?
13:17:38.598 (33728026797)|USER_DEBUG|[16]|DEBUG|true
13:17:38.598 (33728075068)|USER_DEBUG|[17]|DEBUG|Elapsed Time: 1.00002552083333333333333333333333
13:17:38.598 (33728087336)|USER_DEBUG|[18]|DEBUG|Is elapsedTime null?
13:17:38.598 (33728100126)|USER_DEBUG|[19]|DEBUG|false

//INSTEAD OF AN ERROR, THE VALUE IS ASSIGNED CORRECTLY
13:17:38.598 (33730031264)|VARIABLE_ASSIGNMENT|[24]|this.Stage_Duration_Qualification__c|1.00002552083333333333333333333333|0x5affecbe

13:17:38.598 (33732157040)|VARIABLE_ASSIGNMENT|[41]|this.Current_Stage_Start__c|"2017-07-31T20:17:39.208Z"|0x5affecbe
13:17:38.598 (33732211187)|VARIABLE_ASSIGNMENT|[3]|o|null|
13:17:38.732 (33732225092)|CUMULATIVE_LIMIT_USAGE
13:17:38.732 (33732225092)|LIMIT_USAGE_FOR_NS|(default)|
  Number of SOQL queries: 4 out of 100
  Number of query rows: 4 out of 50000
  Number of SOSL queries: 0 out of 20
  Number of DML statements: 7 out of 150
  Number of DML rows: 7 out of 10000
  Maximum CPU time: 1812 out of 10000
  Maximum heap size: 0 out of 6000000
  Number of callouts: 0 out of 100
  Number of Email Invocations: 0 out of 10
  Number of future calls: 0 out of 50
  Number of queueable jobs added to the queue: 0 out of 50
  Number of Mobile Apex push calls: 0 out of 10
Is this a bug? Or expected behavior?
Either way, marking this one as solved, since I have the solution now. Thank you for your help Alain.

All Answers

Alain CabonAlain Cabon
Hi,

"it's not working." it is not clear: what assertion ( System.Assert ) failed?

As you are catching the exception, there is a result for o.Current_Stage_Start__c ( = datetime.now(); ) even when there is a null pointer exception.

 Are the results different when the tests above run in your full copy sandbox and for what assertion? 

Regards
Justin MitchellJustin Mitchell
Hi,
Sorry for not being more clear. When I say it's not working here is what I mean.

On insert, the trigger updates one field: Current_Stage_Start__c 
This is working properly everywhere.

On update, the trigger is supposed to update two fields if the stage is changed: Current_Stage_Start__c, and Stage_Duration_[X]__c (whichever stage it was last on). If a NullPointerException is caught, then only the Current_Stage_Start__c field is updated.

In my test class, in each method, I have a system.assert to check if the Stage_Duration value is greater than 0. If any errors were to happen, the assert would fail because the value would be null. 
System.Assert (resultOppty2.Stage_Duration_Qualification__c > 0);
When I run the test, it passes, in production and the sandbox. No failures.
When I manually update an Opportunity stage in the sandbox, the appropriate fields are updated as expected.
When I manually update an Opportunity stage in production however, only the Current_Stage_Start__c field is updated, as if it's catching a NullPointerException. This is further supported by that snippet I included from the debug log, though admitedly I am not great at reading debug logs.
Alain CabonAlain Cabon
Hi,

If your trigger is new and the field Current_Stage_Start__c is not new, there could be existing null values for Current_Stage_Start__c in the opportunities.

if(Trigger.isinsert) {       // will never happen again for existing opportunities
    o.Current_Stage_Start__c = datetime.now();   // all the existing Current_Stage_Start__c must different from null for the updates (otherwise nep)
 }

In the sandbox, you have perhaps initiate all the pre-existing values of Current_Stage_Start__c but not in production.
SELECT count(id) FROM Opportunity WHERE Current_Stage_Start__c  = null

The definition of Current_Stage_Start__c is exactly the same in the sandbox and the production org (if created after the full copy without change set)?
It is a full copy but I don't know if Current_Stage_Start__c is a new field.

Regards
Alain
Justin MitchellJustin Mitchell
Thank you for taking the time to look at this with me,
I'm not sure I am totally following, but I'll answer what I think you're asking the best I can.

1. Yes, it's a full copy sandbox (though it hasn't been refreshed in about 2 months).
2. I don't know what you mean by "the definition of the Current_Stage_Start__c". The field is a new field. It was created in the sandbox and pushed to production using a change set, along with all the other fields mentioned above, as well as the trigger and test class.
3. In the sandbox, I have not pre-populated all Opportunities with a value in the Current_Stage_Start__c field. Only the Opportunities I have tested. However, this isn't relevant in this case, because when I am testing this in production, I am making sure there is a value in that field before updating the Stage. 
 
Justin MitchellJustin Mitchell
UPDATE
I don't understand it, but I figured out how to solve it. Here's what is happening (in production):

I am updating the Stage from Qualification to Needs Analysis, which is causing this portion of the code to attempt to run:
o.Stage_Duration_Qualification__c = o.Stage_Duration_Qualification__c + elapsedTime;
However, the value of Stage_Duration_Qualification__c is NULL, and it is at that point catching a NullPointerException. Apparently, it isn't able to add an integer (elapsedTime) to a null value. So the simple solution is to put a value of 0.00 in all these fields. I tested this out and it worked perfectly as expected. Problem essentially solved (once I add a default value in those fields).

---
The reason I don't understand is because it does not perform this way in the sandbox, nor does it before this way in a unit test. 
Here is an excerpt of the debug log from a manual test in production (with the nullpointerexception):
13:10:47.716 (746103146)|VARIABLE_SCOPE_BEGIN|[12]|elapsedTime|Decimal|false|false
13:10:47.716 (746142327)|VARIABLE_ASSIGNMENT|[12]|elapsedTime|5.01399871527777777777777777777778
13:10:47.716 (746238089)|USER_DEBUG|[13]|DEBUG|Previous Stage: Qualification
13:10:47.716 (746324490)|USER_DEBUG|[14]|DEBUG|New Stage: Needs Analysis
13:10:47.716 (746380114)|USER_DEBUG|[15]|DEBUG|Has Stage changed?
13:10:47.716 (746444799)|USER_DEBUG|[16]|DEBUG|true
13:10:47.716 (746580227)|USER_DEBUG|[17]|DEBUG|Elapsed Time: 5.01399871527777777777777777777778
13:10:47.716 (746622702)|USER_DEBUG|[18]|DEBUG|Is elapsedTime null?
13:10:47.716 (746653201)|USER_DEBUG|[19]|DEBUG|false

//NULL POINTER ERROR 
13:10:47.716 (746843632)|VARIABLE_SCOPE_BEGIN|[44]|npe|System.NullPointerException|true|false
13:10:47.716 (746979200)|VARIABLE_ASSIGNMENT|[44]|npe|"common.apex.runtime.impl.ExecutionException: Attempt to de-reference a null object"|0x7f15d91d

13:10:47.716 (748940968)|VARIABLE_ASSIGNMENT|[45]|this.Current_Stage_Start__c|"2017-07-31T20:10:48.490Z"|0x4c14819b
13:10:47.716 (748994843)|VARIABLE_ASSIGNMENT|[3]|o|null|
13:10:47.749 (749006211)|CUMULATIVE_LIMIT_USAGE
13:10:47.749 (749006211)|LIMIT_USAGE_FOR_NS|(default)|
  Number of SOQL queries: 0 out of 100
  Number of query rows: 0 out of 50000
  Number of SOSL queries: 0 out of 20
  Number of DML statements: 0 out of 150
  Number of DML rows: 0 out of 10000
  Maximum CPU time: 260 out of 10000
  Maximum heap size: 0 out of 6000000
  Number of callouts: 0 out of 100
  Number of Email Invocations: 0 out of 10
  Number of future calls: 0 out of 50
  Number of queueable jobs added to the queue: 0 out of 50
  Number of Mobile Apex push calls: 0 out of 10

And here's how it performs in a unit test (in production!)
13:17:38.598 (33727897242)|VARIABLE_SCOPE_BEGIN|[12]|elapsedTime|Decimal|false|false
13:17:38.598 (33727920777)|VARIABLE_ASSIGNMENT|[12]|elapsedTime|1.00002552083333333333333333333333
13:17:38.598 (33727956749)|USER_DEBUG|[13]|DEBUG|Previous Stage: Qualification
13:17:38.598 (33727984348)|USER_DEBUG|[14]|DEBUG|New Stage: Needs Analysis
13:17:38.598 (33727997305)|USER_DEBUG|[15]|DEBUG|Has Stage changed?
13:17:38.598 (33728026797)|USER_DEBUG|[16]|DEBUG|true
13:17:38.598 (33728075068)|USER_DEBUG|[17]|DEBUG|Elapsed Time: 1.00002552083333333333333333333333
13:17:38.598 (33728087336)|USER_DEBUG|[18]|DEBUG|Is elapsedTime null?
13:17:38.598 (33728100126)|USER_DEBUG|[19]|DEBUG|false

//INSTEAD OF AN ERROR, THE VALUE IS ASSIGNED CORRECTLY
13:17:38.598 (33730031264)|VARIABLE_ASSIGNMENT|[24]|this.Stage_Duration_Qualification__c|1.00002552083333333333333333333333|0x5affecbe

13:17:38.598 (33732157040)|VARIABLE_ASSIGNMENT|[41]|this.Current_Stage_Start__c|"2017-07-31T20:17:39.208Z"|0x5affecbe
13:17:38.598 (33732211187)|VARIABLE_ASSIGNMENT|[3]|o|null|
13:17:38.732 (33732225092)|CUMULATIVE_LIMIT_USAGE
13:17:38.732 (33732225092)|LIMIT_USAGE_FOR_NS|(default)|
  Number of SOQL queries: 4 out of 100
  Number of query rows: 4 out of 50000
  Number of SOSL queries: 0 out of 20
  Number of DML statements: 7 out of 150
  Number of DML rows: 7 out of 10000
  Maximum CPU time: 1812 out of 10000
  Maximum heap size: 0 out of 6000000
  Number of callouts: 0 out of 100
  Number of Email Invocations: 0 out of 10
  Number of future calls: 0 out of 50
  Number of queueable jobs added to the queue: 0 out of 50
  Number of Mobile Apex push calls: 0 out of 10
Is this a bug? Or expected behavior?
Either way, marking this one as solved, since I have the solution now. Thank you for your help Alain.
This was selected as the best answer