connect timed out getting Slack user's time zone

[martyychang]

I encountered unhandled timeout errors reported in Slack, which appear to be the result of a timeout from when Salesforce tried to reach Slack to get the user's time zone. The full stack trace logged below.

Class.SlackApiService.usersInfo: line 99, column 1 Class.SlackService.getTimeZoneSidKey: line 83, column 1 Class.SlashclockOutCommand.load: line 52, column 1 Class.SlashclockUtil.newCommand: line 39, column 1 Class.SlashclockService.execute: line 105, column 1 Class.ClockResource.post: line 10, column 1

A better way to do this may be to asynchronously grab the user's time zone shortly after a command is issued, so that a response is returned more quickly to the user and to avoid this timeout error.

[martyychang]

To minimize potentially duplicative asynchronous calls, I'm thinking of an intelligent batch process that works as follows.

• Callouts needed are made identifiable via a simple query
• The query informs a batch job
• The batch job is enqueued whenever time zones need to be determined or confirmed
• If the batch job is already running, a new batch job is NOT enqueued
• When the batch job finishes, it checks to see whether any records were missed. And if so, enqueue another instance of the batch job.

[martyychang]

Regarding the actual update to a Slack user's time zone, the process becomes a bit more complicated since the asynchronous update occurs later.

1. User clocks in under default time zone (new user) or last known time zone, resulting in the creation of a new Time Entry record
2. When the async job completes, the created time entry may need to be adjusted

To make this work, the system would need to know which time entries—or more specifically which times on time entries—had not yet been confirmed for a specific time zone.

I could possibly create one job to make this most generic, and that job would need the following pieces of information.

• ID of the record containing the Datetime value
• Name of the field containing the Datetime value
• Time zone assumed for the Datetime value
• Contact.Id, from which the Slack User ID and Slack Team ID can be obtained

To reduce complexity for now I will just assume we're only dealing with TimeEntry__c records.

[martyychang]

For a more closed-loop implementation, I'm going to use this approach.

• StartTime__c
• StartTimeZoneSidKey__c text field
• HasVerifiedStartTimeZone__c checkbox
• EndTime__c
• EndTimeZoneSidKey__c text field
• HasVerifiedEndTimeZone__c checkbox

By default, the verification checkbox will be unchecked until TimeEntryDataService.verifyTimeZone is invoked for a given list of records.

[martyychang]

For reference, the native TimeZone.getOffset method returns "the time zone offset, in milliseconds, of the specified date to the GMT time zone"

[martyychang]

Found a useful resource titled, "How Does Daylight Saving Time Work?" on timeanddate.com that quickly explained the two salient points on Daylight Savings Time as observed in the U.S.

• When DST starts, time progresses from 1:59am to 3:00am
• When DST ends, time progresses from 1:59am to 1:00am

[martyychang]

I'm going to defer fixing the DST date construction problems, since DST transitions in the United States occur on two Sundays out of the year, on which days I assume few users will be logging time. I've created bug #40 to make sure this problem is visible somewhere in the backlog.

[martyychang]

When trying to avoid executing duplicate batches, I wanted to check to see whether an existing AsyncApexJob record already existed for the processing job. Using SOQL query below, I was able to locate one record with Status "Completed" when calling ApexJobService.submitAndExecute with an empty job.

SELECT Id, CreatedDate, JobType, ApexClassId, Status
FROM AsyncApexJob
WHERE
    ApexClassId IN (
        SELECT Id
        FROM ApexClass
        WHERE Name = 'ApexJobRequestProcessJob'
    )
ORDER BY CreatedDate DESC

Running the broader SOQL query below revealed that in addition to the JobType "BatchApex" job that was completed, a seemingly related JobType "ApexToken" job was also completed.

SELECT Id, CreatedDate, JobType, ApexClassId, Status
FROM AsyncApexJob
ORDER BY CreatedDate DESC

[martyychang]

For some reason my ApexJobServiceTest.submitAndExecuteTwice method keeps failing with a puzzling error message.

System.UnexpectedException: No more than one executeBatch can be called from within a test method. Please make sure the iterable returned from your start method matches the batch size, resulting in one executeBatch invocation.

I thought perhaps that this was an Apex testing bug, but when I tried to reproduce this issue in a scratch org with a representative set of classes, the equivalent ApexJobServiceTest.submitAndExecuteTwice test passes!

[martyychang]

Actually I realize now what the difference is. In the sample project I'd created, I called Database.executeBatch without passing in a scope parameter. In the real slashclock-demo project, I'd set scope to 1 to avoid the "Too many queueable jobs added to the queue: 2" error.

Reconsidering my approach, however... since callouts and DML operations could create a mixed "pending" state, to be safe in the current framework of having jobs both making callouts and manipulating data, I will leave the scope at 1. Warning below from the Apex Developer Guide.

You can’t make a callout when there are pending operations in the same transaction. Things that result in pending operations are DML statements, asynchronous Apex (such as future methods and batch Apex jobs), scheduled Apex, or sending email. You can make callouts before performing these types of operations.

The question now is how to test the service.

[martyychang]

All my tests are passing... but I am now seeing HTTP 500 errors reported in Slack when I try to execute either /clock report or /clock entries. For what it's worth none of the time entries logged within the past two weeks are associated with my user contact in Salesforce, which may warrant a separate bug to be logged and resolved.

SELECT Id, StartTime__c, Contact__c, SlackUserId__c, SlackTeamId__c
FROM TimeEntry__c
WHERE StartTime__c IN (THIS_WEEK, LAST_WEEK)
ORDER BY StartTime__c DESC

[martyychang]

I turned on debug logging for the API Site Guest User and found the following error.

Insert failed. First exception on row 0; first error: DUPLICATE_VALUE, duplicate value found: SlackUserId__c duplicates value on record with id: 003f400000EkACm: []

[martyychang]

Turns out the problem was that I was executing the command from the wrong Slack org... And perhaps due to earlier problems in the code what happened was that in Salesforce I had a team account and a user contact, but the Contact.AccountId field was empty. So, SlackService in this was correctly deducing that there was not already a user contact for the user under the team account, but trying to create a new contact failed because the Slack User ID was already taken.

[martyychang]

I logged a help request to ask Slack whether the User ID is unique across all workspaces or just a single workspace. My assumption right now is that the ID is unique across all workspaces, and if this assumption is wrong then I need to log a bug and fix that for the first release.

[martyychang]

I checked my code and confirmed that TimeEntryDataService.getUnverifiedTimeEntries is indeed querying for a match on TimeEntry__c.Contact__c based on the given list of Contact ID values in the job. This means in order for the job to actually work as expected, time entries being created by the /clock in command must be associated with a contact.

[martyychang]

All tests are passing at the moment. I now need to write a test to make sure that when a user clocks in for the first time, a new TimeEntryVerifyTimeZoneJob is requested and ideally executed.

[martyychang]

I tried the following steps to manually test the code as a real user.

1. Change my user contact's Time Zone manually in Salesforce to "America/Los_Angeles"
2. Execute /clock entries in Slack. I confirmed that the entires were listed in West Coast local time.
3. Execute /clock out 1:15pm in Slack.
4. Execute /clock entries in Slack again. I saw that the entries were now listed in East Coast local time, but oddly enough the End Time for my latest entry showed 4:15pm instead of the expected 1:15pm.

I looked at the Apex job history in Salesforce and also the Apex job request, and I found that the job had failed with the following message, "Script-thrown exception". Stack trace below.

Class.System.TimeZone.getTimeZone: line 10, column 1 Class.TimeEntryUtil.verifyTimeZone: line 60, column 1 Class.TimeEntryUtil.verifyStartTimeZone: line 17, column 1 Class.TimeEntryUtil.verifyTimeZone: line 33, column 1 Class.TimeEntryDataService.verifyTimeZone: line 50, column 1 Class.TimeEntryVerifyTimeZoneJob.execute: line 30, column 1 Class.TimeEntryVerifyTimeZoneJob.execute: line 44, column 1 Class.ApexJobRequestProcessJob.execute: line 12, column 1

[martyychang]

I believe I found the debug log entry corresponding to the failed Verify Time Zone job. Looks like the operation I'm looking for in the debug log list view is "SerialBatchApexRangeChunkHandler" for the log entries created by actually executing each batch.

[martyychang]

The following are the relevant lines from the debug log showing the last operations before the system exited the verifyTimeZone method.

18:34:05.0 (370769125)|METHOD_ENTRY|[17]|01pf4000006PlNO|TimeEntryUtil.verifyTimeZone(TimeEntry__c, String, Schema.SObjectField, Schema.SObjectField, Schema.SObjectField)
18:34:05.0 (370794374)|VARIABLE_SCOPE_BEGIN|[46]|record|TimeEntry__c|true|false
18:34:05.0 (370822213)|VARIABLE_ASSIGNMENT|[46]|record|{"EndTime__c":"2018-02-12T14:45:00.000Z","HasVerifiedEndTimeZo (5 more) ...":false,"HasVerifiedStartTime (7 more) ...":false,"StartTime__c":"2018-02-12T14:15:00.000Z","Id":"a00f4000006764PAAQ"}|0xfe8c342
18:34:05.0 (370832233)|VARIABLE_SCOPE_BEGIN|[46]|timeZoneSidKey|String|false|false
18:34:05.0 (370841107)|VARIABLE_ASSIGNMENT|[46]|timeZoneSidKey|"America/New_York"
18:34:05.0 (370846815)|VARIABLE_SCOPE_BEGIN|[46]|timeField|Schema.SObjectField|true|false
18:34:05.0 (370921060)|VARIABLE_ASSIGNMENT|[46]|timeField|"common.apex.runtime.impl.ApexFieldToken@1bd57a1d"|0x1bd57a1d
18:34:05.0 (370932100)|VARIABLE_SCOPE_BEGIN|[46]|timeZoneField|Schema.SObjectField|true|false
18:34:05.0 (370960677)|VARIABLE_ASSIGNMENT|[46]|timeZoneField|"common.apex.runtime.impl.ApexFieldToken@1d5678ce"|0x1d5678ce
18:34:05.0 (370970214)|VARIABLE_SCOPE_BEGIN|[46]|verifiedField|Schema.SObjectField|true|false
18:34:05.0 (370995741)|VARIABLE_ASSIGNMENT|[46]|verifiedField|"common.apex.runtime.impl.ApexFieldToken@2d19213f"|0x2d19213f
18:34:05.0 (371005525)|STATEMENT_EXECUTE|[51]
18:34:05.0 (371145619)|STATEMENT_EXECUTE|[55]
18:34:05.0 (371148586)|STATEMENT_EXECUTE|[59]
18:34:05.0 (371261867)|HEAP_ALLOCATE|[60]|Bytes:15
18:34:05.0 (371278297)|SYSTEM_METHOD_ENTRY|[1]|TimeZone.TimeZone()
18:34:05.0 (371282799)|STATEMENT_EXECUTE|[1]
18:34:05.0 (371292165)|SYSTEM_METHOD_EXIT|[1]|TimeZone
18:34:05.0 (371305584)|METHOD_ENTRY|[60]||System.TimeZone.getTimeZone(String)
18:34:05.0 (371421486)|METHOD_EXIT|[60]||System.TimeZone.getTimeZone(String)
18:34:05.0 (371432928)|METHOD_EXIT|[17]|01pf4000006PlNO|TimeEntryUtil.verifyTimeZone(TimeEntry__c, String, Schema.SObjectField, Schema.SObjectField, Schema.SObjectField)

When I'd queried for historical time entries, I found a large number with empty StartTimeZoneSidKey__c and EndTimeZoneSidKey__c values. Based on this observation, I find it likely that the job failed because it tried to do a diff on the time zones but there was no reference time zone from which to calculate the diff.

[martyychang]

Fascinating... after removing the default value from the global value set, the Contact Time Zone field is no longer giving me a default value via Contact.TimeZoneSidKey__c.getDescribe().getDefaultValue() even though there is explicitly a default value set to the formula "America/New_York".