You are here:
Troubleshoot Processes with Apex Debug Logs
Use debug logs to find detailed information about your running processes after they finish running. For example, investigate why a process doesn’t to trigger when a record meets the process’s criteria, or explore the sequence of processes being executed.
Required Editions
| Available in: both Salesforce Classic (not available in all orgs) and Lightning Experience |
| Available in: Essentials, Professional, Enterprise, Performance, Unlimited, and Developer Editions |
After December 31, 2025, existing processes continue to run, and you can activate, deactivate, and edit them; however, we recommend using Flow Builder. To migrate existing processes, plan your switch to Flow Builder and use the Migrate to Flow tool. For new automations, create flows in Flow Builder.
Make sure that your filters include FINER events in the WORKFLOW category. For details, see Debug Log Levels.
When using debug logs to troubleshoot a process, consider the following.
- Processes created in the Process Builder appear as flows and workflow rules in debug logs. The generated names have some resemblance to the process names, but they don’t map one-to-one.
- Record change processes appear as flows of type Workflow. Invocable processes appear as flows of type InvocableProcess. Event processes appear as flows of type CustomEvent.
- Immediate actions that are executed in a block are strung together in the flow. If one action fails in the middle, then the following actions aren’t executed.
- Scheduled actions are executed after a
FLOW_WAITelement. The actions are executed similarly to immediate actions after the process resumes. WF_CRITERIA_BEGINandWF_CRITERIA_ENDrefer to the workflow rule criteria that are always set to true and not the criteria defined in your process.- Here’s how elements in the Process Builder correspond to flow debug events.
Process Builder Element Flow Debug Event Criteria FLOW_RULE_...Create a Record FLOW_ELEMENT_...Update Records FLOW_ELEMENT_...Post to Chatter FLOW_ACTIONCALL_...Submit for Approval FLOW_ACTIONCALL_...Email Alerts FLOW_ACTIONCALL_...Flows FLOW_ACTIONCALL_...Processes FLOW_ACTIONCALL_...Apex FLOW_ACTIONCALL_...Schedule FLOW_WAIT_...
This example covers a process with an immediate Post to Chatter action.
Here’s what you can tell from this first snippet.
- A lead named “Madison Rigby” triggers the process.
- The name of the process is
Hello_World. The number appended to the name is the process version’s ID:301R000000009n0. - The process is set to trigger when a record is created (
ON_CREATE_ONLY).
10:11:26.594 (595241802)|EXECUTION_STARTED
10:11:26.594 (595255829)|CODE_UNIT_STARTED|[EXTERNAL]|Workflow:Lead
10:11:26.594 (685753138)|WF_RULE_EVAL_BEGIN|Workflow
10:11:26.594 (686312384)|WF_CRITERIA_BEGIN|
[Lead: Ms. Madison Rigsby 00QR0000001HqC4]|Hello_World301R000000009n0|
01QR00000000Nz8|ON_CREATE_ONLY|0In this snippet, the process compares the record’s current values to the values it had
before it was changed. myVariable_current contains
all the record’s current field values. myVariable_old contains all the field values of the record immediately
before it was changed. In this example,myVariable_old has no values (null), because the process is evaluating a
newly created lead.
10:11:26.594 (688919502)|WF_FORMULA|
Formula:ENCODED:[treatNullAsNull]true|Values:
10:11:26.594 (689128428)|WF_CRITERIA_END|
true
10:11:26.594 (695758445)|WF_SPOOL_ACTION_BEGIN|
Workflow
10:11:26.594 (714823342)|WF_ACTION|
Flow Trigger: 1;
10:11:26.594 (714900811)|WF_RULE_EVAL_END
10:11:26.594 (719777561)|WF_FLOW_ACTION_BEGIN|
09LR000000005Td10:11:26.594 (720281142)|WF_FLOW_ACTION_DETAIL|
09LR000000005Td|[Lead: Ms. Madison Rigsby 00QR0000001HqC4]|Id=09LR000000005Td|
CurrentRule:Hello_World301R000000009n0 (Id=01QR00000000Nz8)
10:11:26.722 (722465931)|FLOW_CREATE_INTERVIEW_BEGIN|
00DR00000000o82|300R00000004PQB|301R000000009n0
10:11:26.722 (740702983)|FLOW_CREATE_INTERVIEW_END|
2416dcc6212273331b3d50a38a161dd464e3e-7fdd|Hello World
10:11:26.594 (748183550)|WF_FLOW_ACTION_DETAIL|
Param Name: myVariable_current,
Param Value: ENCODED:{![treatNullAsNull]{!ID:this}},
Evaluated Param Value: {Entity type: Lead, id: 00QR0000001HqC4MAK}|
Param Name: myVariable_old,
Param Value: {!old},
Evaluated Param Value: nullWhen the process started:
- This instance of the process starts with the
FLOW_START_INTERVIEW_BEGINevent. - Each
FLOW_START_INTERVIEW_LIMIT_USAGEevent displays the usage of a given limit when the process started. In this example, the transaction hasn't done anything that counts toward a limit. - A handful of variables are set. The process uses these variables to perform logic later.
myVariable_oldis set to nothing because the record didn't exist before this transaction.myVariable_currentis set to the current values of the lead record.myVariable_waitStartTimeVariableis set to the current time.
10:11:26.750 (750700361)|FLOW_START_INTERVIEWS_BEGIN|1
10:11:26.750 (751285739)|FLOW_START_INTERVIEW_BEGIN|
2416dcc6212273331b3d50a38a161dd464e3e-7fdd|
Hello World
10:11:26.750 (751341782)|FLOW_START_INTERVIEW_LIMIT_USAGE|
SOQL queries: 0 out of 100
10:11:26.750 (751367432)|FLOW_START_INTERVIEW_LIMIT_USAGE|
SOQL query rows: 0 out of 50000
10:11:26.750 (751384035)|FLOW_START_INTERVIEW_LIMIT_USAGE|
SOSL queries: 0 out of 20
10:11:26.750 (751397896)|FLOW_START_INTERVIEW_LIMIT_USAGE|
DML statements: 0 out of 150
10:11:26.750 (751412225)|FLOW_START_INTERVIEW_LIMIT_USAGE|
DML rows: 0 out of 10000
10:11:26.750 (751427529)|FLOW_START_INTERVIEW_LIMIT_USAGE|
CPU time in ms: 0 out of 15000
10:11:26.750 (751472968)|FLOW_START_INTERVIEW_LIMIT_USAGE|
Heap size in bytes: 0 out of 6000000
10:11:26.750 (751490226)|FLOW_START_INTERVIEW_LIMIT_USAGE|
Callouts: 0 out of 100
10:11:26.750 (751505266)|FLOW_START_INTERVIEW_LIMIT_USAGE|
Email invocations: 0 out of 10
10:11:26.750 (751519128)|FLOW_START_INTERVIEW_LIMIT_USAGE|
Future calls: 0 out of 50
10:11:26.750 (751533892)|FLOW_START_INTERVIEW_LIMIT_USAGE|
Jobs in queue: 0 out of 50
10:11:26.750 (751547542)|FLOW_START_INTERVIEW_LIMIT_USAGE|
Push notifications: 0 out of 10
10:11:26.750 (752380627)|FLOW_VALUE_ASSIGNMENT|
2416dcc6212273331b3d50a38a161dd464e3e-7fdd|
myVariable_old|
10:11:26.750 (754872639)|FLOW_VALUE_ASSIGNMENT|
2416dcc6212273331b3d50a38a161dd464e3e-7fdd|
myVariable_current|
{LastModifiedDate=2018-02-28 18:11:26, Company=Acme Wireless, Email=null,
HasOptedOutOfFax=false, Latitude=null, MobilePhone=null, Industry=Apparel,
CreatedById=005R0000000J01RIAS, Street=null, PhotoUrl=null,
ConvertedOpportunityId=null, MasterRecordId=null,
LastModifiedByID=005R0000000J01RIAS, Status=Contacted, IsDeleted=false,
ConvertedAccountId=null, IsConverted=false, HasOptedOutOfEmail=false,
LastViewedDate=null, City=null, Longitude=null, LeadSource=External Referral,
CreatedByID=005R0000000J01RIAS, GeocodeAccuracy=null, State=null,
CreatedDate=2018-02-28 18:11:26, Country=null, Id=00QR0000001HqC4MAK,
LastName=Rigsby, AnnualRevenue=500000.0, Jigsaw=null, EmailBouncedDate=null,
Description=null, ConvertedDate=null, DoNotCall=false, Rating=null,
PostalCode=null, Website=null, LastReferencedDate=null, NumberOfEmployees=5,
Salutation=Ms., ConvertedContactId=null, OwnerId=005R0000000J01RIAS,
Phone=null, EmailBouncedReason=null, FirstName=Madison, IsUnreadByOwner=true,
Title=null, SystemModstamp=2018-02-28 18:11:26, LastActivityDate=null,
Fax=null, LastModifiedById=005R0000000J01RIAS,
LastTransferDate=2018-02-28 18:11:26, JigsawContactId=null}
10:11:26.750 (755116990)|FLOW_ELEMENT_BEGIN|
2416dcc6212273331b3d50a38a161dd464e3e-7fdd|
FlowAssignment|myVariable_waitStartTimeAssignment
10:11:26.750 (755457410)|FLOW_ASSIGNMENT_DETAIL|
2416dcc6212273331b3d50a38a161dd464e3e-7fdd|
myVariable_waitStartTimeVariable|ASSIGN|2/28/2018, 10:11 AM
10:11:26.750 (756105710)|FLOW_VALUE_ASSIGNMENT|
2416dcc6212273331b3d50a38a161dd464e3e-7fdd|myVariable_waitStartTimeVariable|2018-02-28T18:11:27Z
10:11:26.750 (756182849)|FLOW_ELEMENT_END|
2416dcc6212273331b3d50a38a161dd464e3e-7fdd|
FlowAssignment|myVariable_waitStartTimeAssignmentThe process evaluates the first criteria.
In debug logs, a FLOW_RULE_DETAIL event represents
a process criteria node. myRule_1 corresponds to
the first criteria node in the process. Because the result of myRule_1 is true, the process executes the actions
associated with the first criteria.
10:11:26.750 (757306870)|FLOW_ELEMENT_BEGIN|
2416dcc6212273331b3d50a38a161dd464e3e-7fdd|
FlowDecision|myDecision
10:11:26.750 (757582110)|FLOW_RULE_DETAIL|
2416dcc6212273331b3d50a38a161dd464e3e-7fdd|
myRule_1|true
10:11:26.750 (757616076)|FLOW_VALUE_ASSIGNMENT|
2416dcc6212273331b3d50a38a161dd464e3e-7fdd|
myRule_1|true
10:11:26.750 (757683580)|FLOW_ELEMENT_END|
2416dcc6212273331b3d50a38a161dd464e3e-7fdd|
FlowDecision|myDecisionIn this snippet, the immediate actions for the first criteria are executed. In the name
myRule_1_A1, “A1” indicates that this element
corresponds to the first action in the action group, which creates a task. The FLOW_BULK_ELEMENT_LIMIT_USAGE events indicate that the
action increased the transaction's usage count toward two limits: the number of DML
statements issued and the number DML rows processed.
10:11:26.750 (1898050716)|FLOW_ELEMENT_BEGIN|
68211d9d9f918ee32db47d21247161de215ce5-7d38|
FlowRecordCreate|myRule_1_A1
10:11:26.750 (1898121764)|FLOW_ELEMENT_DEFERRED|
FlowRecordCreate|myRule_1_A1
10:11:26.750 (1898261705)|FLOW_ELEMENT_END|
68211d9d9f918ee32db47d21247161de215ce5-7d38|
FlowRecordCreate|myRule_1_A1
10:11:26.750 (1345712687)|FLOW_START_INTERVIEW_END|
68211d9d9f918ee32db47d21247161de215ce5-7d38|Hello World
10:11:26.750 (1898350543)|FLOW_BULK_ELEMENT_BEGIN|
FlowRecordCreate|myRule_1_A1
10:11:26.750 (1928183118)|FLOW_BULK_ELEMENT_DETAIL|
FlowRecordCreate|myRule_1_A1|1
10:11:26.750 (2267557291)|FLOW_VALUE_ASSIGNMENT|
68211d9d9f918ee32db47d21247161de215ce5-7d38|
myRule_1_A1|true
10:11:26.750 (2267878414)|FLOW_BULK_ELEMENT_LIMIT_USAGE|
1 DML statements, total 1 out of 150
10:11:26.750 (2267929106)|FLOW_BULK_ELEMENT_LIMIT_USAGE|
1 DML rows, total 1 out of 10000
10:11:26.750 (2268002776)|FLOW_BULK_ELEMENT_END|
FlowRecordCreate|myRule_1_A1|1|370Then the process finishes.
10:11:27.977 (1978733709)|FLOW_START_INTERVIEWS_END|1
10:11:27.989 (1989764561)|WF_FLOW_ACTION_END|09LR000000005Td
10:11:27.989 (1998560773)|WF_ACTIONS_END| Flow Trigger: 1;
10:11:27.989 (1998600044)|CODE_UNIT_FINISHED|Workflow:Lead
10:11:27.989 (2000437095)|EXECUTION_FINISHEDDebugging Scheduled Actions
Scheduled actions are logged separately from immediate actions. After the scheduled time occurs, an automated process executes the scheduled actions. However, the actions are still executed as the user who originally caused the process to run. The log uses coordinated universal time (UTC) instead of the user’s time zone.
This example walks you through a debug log for a process with a scheduled Create a Record action.
Any events that start with FLOW_WAIT_ provide
information about a process schedule. myWait_myRule_int always indicates a schedule, where
int identifies which criteria node the schedule is associated
with.
In this snippet:
- The schedules that are associated with the first criteria node (
myWait_myRule_1) are evaluated. - The defined time for the first schedule has passed (
myWaitEvent_myWait_myRule_1_event_0). FLOW_WAIT_RESUMING_DETAILindicates that the interview is resumed so that the process can execute its scheduled actions.- The
myVariable_currentvariable is updated with the latest values from the record that started the process originally.
10:21:35.461 (1461109547)|FLOW_BULK_ELEMENT_BEGIN|
WaitInfo|myWait_myRule_1
10:21:35.461 (1467206801)|FLOW_WAIT_EVENT_RESUMING_DETAIL|
2ef1ba5afce469a1e74b7b869161e25400a2-7f29|
myWait_myRule_1|myWaitEvent_myWait_myRule_1_event_0|DateRefAlarmEvent
10:21:35.461 (1467428864)|FLOW_WAIT_RESUMING_DETAIL|
2ef1ba5afce469a1e74b7b869161e25400a2-7f29|
myWait_myRule_1|0FoRM0000004C9I
10:21:35.461 (1503485017)|FLOW_VALUE_ASSIGNMENT|
2ef1ba5afce469a1e74b7b869161e25400a2-7f29|
myWaitEvent_myWait_myRule_1_event_0|true10:21:35.461 (1509382975)|FLOW_VALUE_ASSIGNMENT|
2ef1ba5afce469a1e74b7b869161e25400a2-7f29|
myVariable_current|{Id=00QRM000003abIU2AY, IsDeleted=false,
MasterRecordId=null, Salutation=null, FirstName=Another, LastName=Lead,
Title=null, Company=Acme, Street=null, City=null, State=null, PostalCode=null,
Country=null, Latitude=null, Longitude=null, GeocodeAccuracy=null, Phone=null,
MobilePhone=null, Fax=null, Email=null, Website=null, PhotoUrl=null,
Description=null, LeadSource=Advertisement, Status=New, Industry=null,
Rating=null, AnnualRevenue=null, NumberOfEmployees=null, InternalSource=null,
OwnerId=005RM000001cEmFYAU, HasOptedOutOfEmail=false, IsConverted=false,
ConvertedDate=null, ConvertedAccountId=null, ConvertedContactId=null,
ConvertedOpportunityId=null, IsUnreadByOwner=false,
CreatedDate=2018-03-01 18:12:05, CreatedById=005RM000001cEmFYAU,
LastModifiedDate=2018-03-01 18:12:05, LastModifiedById=005RM000001cEmFYAU,
SystemModstamp=2018-03-01 18:12:05, LastActivityDate=null, DoNotCall=false,
CreatedByID=005RM000001cEmFYAU, LastModifiedByID=005RM000001cEmFYAU,
CampaignId=null, CampaignMemberStatus=null, HasOptedOutOfFax=false,
LastViewedDate=null, LastReferencedDate=null,
LastTransferDate=2018-03-01 18:12:05, Jigsaw=null, JigsawContactId=null,
ConnectionReceivedDate=null, ConnectionSentDate=null, EmailBouncedReason=null,
EmailBouncedDate=null}
10:21:35.461 (1512457819)|FLOW_BULK_ELEMENT_END|
WaitInfo|myWait_myRule_1|0|47In this snippet, the process makes sure that the record's date field isn't null. Specifically, it checks the date field that's referenced in the schedule.
10:21:35.461 (1514489368)|FLOW_ELEMENT_BEGIN|
2ef1ba5afce469a1e74b7b869161e25400a2-7f29|
FlowDecision|myPostWaitDecision_myWaitEvent_myWait_myRule_1_event_0
10:21:35.461 (1528928534)|FLOW_RULE_DETAIL|
2ef1ba5afce469a1e74b7b869161e25400a2-7f29|
myPostWaitRule_myWaitEvent_myWait_myRule_1_event_0|true
10:21:35.461 (1529027007)|FLOW_VALUE_ASSIGNMENT|
2ef1ba5afce469a1e74b7b869161e25400a2-7f29|
myPostWaitRule_myWaitEvent_myWait_myRule_1_event_0|true
10:21:35.461 (1529230456)|FLOW_ELEMENT_END|
2ef1ba5afce469a1e74b7b869161e25400a2-7f29|
FlowDecision|myPostWaitDecision_myWaitEvent_myWait_myRule_1_event_0Now to execute the actions associated with the schedule. First up is ..._myRule_1_event_0_SA1.
myRule_1corresponds to the first criteria nodeevent_0corresponds to the first schedule associated with the criteriaSA1corresponds to the first action in the schedule.
The action creates a record. With the FLOW_BULK_ELEMENT_LIMIT_USAGE events, we see that action increased the
transaction's usage count toward two limits: the number of DML statements issued and the
number DML rows processed.
10:21:35.461 (1529433132)|FLOW_ELEMENT_BEGIN|
2ef1ba5afce469a1e74b7b869161e25400a2-7f29|
FlowRecordCreate|myWaitEvent_myWait_myRule_1_event_0_SA1
10:21:35.461 (1529526210)|FLOW_ELEMENT_DEFERRED|
FlowRecordCreate|myWaitEvent_myWait_myRule_1_event_0_SA1
10:21:35.461 (1529619300)|FLOW_ELEMENT_END|
2ef1ba5afce469a1e74b7b869161e25400a2-7f29|
FlowRecordCreate|myWaitEvent_myWait_myRule_1_event_0_SA1
10:21:35.461 (1534801023)|FLOW_BULK_ELEMENT_BEGIN|
FlowRecordCreate|myWaitEvent_myWait_myRule_1_event_0_SA1
10:21:35.461 (1681358347)|FLOW_BULK_ELEMENT_DETAIL|
FlowRecordCreate|myWaitEvent_myWait_myRule_1_event_0_SA1|1
10:21:35.461 (1963485392)|FLOW_VALUE_ASSIGNMENT|
2ef1ba5afce469a1e74b7b869161e25400a2-7f29|
myWaitEvent_myWait_myRule_1_event_0_SA1|true
10:21:35.461 (1973349443)|FLOW_BULK_ELEMENT_LIMIT_USAGE|
1 DML statements, total 1 out of 150
10:21:35.461 (1973886332)|FLOW_BULK_ELEMENT_LIMIT_USAGE|
1 DML rows, total 1 out of 10000
10:21:35.461 (1974083134)|FLOW_BULK_ELEMENT_END|
FlowRecordCreate|myWaitEvent_myWait_myRule_1_event_0_SA1|1|429This snippet displays some internal logic that Process Builder performs for you. The process uses a variable to note that it has executed the action for this schedule, so that it doesn't accidentally duplicate the action.
10:21:41.527 (7529131090)|FLOW_ELEMENT_BEGIN|
2ef1ba5afce469a1e74b7b869161e25400a2-7f29|
FlowAssignment|myWaitEvent_myWait_myRule_1_event_0_postWaitExecutionAssignment
10:21:41.527 (7529875281)|FLOW_ASSIGNMENT_DETAIL|
2ef1ba5afce469a1e74b7b869161e25400a2-7f29|
myWaitEvent_myWait_myRule_1_event_0_postActionExecutionVariable|ASSIGN|true
10:21:41.527 (7529943822)|FLOW_VALUE_ASSIGNMENT|
2ef1ba5afce469a1e74b7b869161e25400a2-7f29|
myWaitEvent_myWait_myRule_1_event_0_postActionExecutionVariable|true
10:21:41.527 (7530040052)|FLOW_ELEMENT_END|
2ef1ba5afce469a1e74b7b869161e25400a2-7f29|
FlowAssignment|myWaitEvent_myWait_myRule_1_event_0_postWaitExecutionAssignmentThen the process evaluates whether to execute any of the other schedules. Notice that
the conditions are no longer met for ..._event_0.
Because of the variable assignment in the previous snippet, the process doesn't
re-execute the actions associated with that schedule.
There's only one schedule, so the process finishes.
10:21:41.527 (7530094566)|FLOW_ELEMENT_BEGIN|
2ef1ba5afce469a1e74b7b869161e25400a2-7f29|
WaitInfo|myWait_myRule_1
10:21:41.527 (7530148328)|FLOW_ELEMENT_DEFERRED|
WaitInfo|myWait_myRule_1
10:21:41.527 (7530225216)|FLOW_ELEMENT_END|
2ef1ba5afce469a1e74b7b869161e25400a2-7f29|
WaitInfo|myWait_myRule_1
10:21:41.527 (7530291079)|FLOW_BULK_ELEMENT_BEGIN|
WaitInfo|myWait_myRule_1
10:21:41.527 (7530832531)|FLOW_WAIT_EVENT_WAITING_DETAIL|
2ef1ba5afce469a1e74b7b869161e25400a2-7f29|
myWait_myRule_1|myWaitEvent_myWait_myRule_1_event_0|DateRefAlarmEvent|false
10:21:41.527 (7530895796)|FLOW_WAIT_WAITING_DETAIL|
2ef1ba5afce469a1e74b7b869161e25400a2-7f29|
myWait_myRule_1|0|
10:21:41.527 (7530968776)|FLOW_VALUE_ASSIGNMENT|
2ef1ba5afce469a1e74b7b869161e25400a2-7f29|
myWaitEvent_myWait_myRule_1_event_0|false
10:21:41.527 (7531068544)|FLOW_BULK_ELEMENT_END|
WaitInfo|myWait_myRule_1|0|1