You signed in with another tab or window. Reload to refresh your session.You signed out in another tab or window. Reload to refresh your session.You switched accounts on another tab or window. Reload to refresh your session.Dismiss alert
Only allow one browser tab open at a time (same machine multiple tabs)
Timeout unused app instances (UX)
Only allow one session per a user at a time (different machines)
Only allow evaluation if queue is active
From Hypothesis 1:
When applicants are complete set all existing queue assignments members to false
Conclusion
There is no systemic risk of the system being faulty. Applicant DaF should have
the evaluation by SME_one invalidated, and a fuzzy checker should be run over
all hiring action to see if there are similar cases of SMEs using the tool in multiple tabs.
An advisory should be sent out to SMEs to keep a clean desktop environment and work
in only one tab. Alternatively, refreshing the page if you are unsure if you have multiple tabs
will also ensure that you are in the correct space.
An advisory should be sent out to SMEs to doublecheck the name matches before submitting
an evaluation.
A UX fix should go out to force the applicant name to be shown at all times to SMES.
A bug fix should go out to prevent multiple browser tabs from maintaining different states.
A bug fix should go out to prevent multiple user sessions from being valid.
SME names have been expunged and applicant names have been reduced to initials.
The two applicants of interest have been changed to JoH and DaF to make reading
and differentiating them easier.
Background - SME sees same applicant 3x times.
SME_one reported duplicate evaluations of an applicant, JoH and being presented
with the applicant 3x times.
While investigating this issue we found that there were no duplicate evaluations
of JoH, but that a review meant for JoH was actually applied to DaF.
To find out how such assignment we pulled the application_assignment table
for the SME_one, where rows are created in the table whenever a new assignment is
made:
SELECTa.name
, a.id
, asgn.created_at assignment_creation_date
, asgn.updated_at assignment_update_date
, expires
FROM application_assignments as asgn
LEFT JOIN app_user au ONau.id=asgn.evaluator_idLEFT JOIN applicant a ONa.id=asgn.applicant_idWHERE email='SME_one';
Which is displayed below:
name
id
assignment_creation_date
assignment_update_date
expires
ASGN:JR
6d1fe480-4bf6-4f4a-aeb6-a18e94755391
2021-11-23 21:21:00.499166
2021-11-23 21:29:36.715729
2021-11-23 21:21:00.499166
ASGN:DaF
6ce242a1-fde5-430f-b3da-dceb15c87ae9
2021-11-23 21:29:40.796335
2021-11-24 13:48:02.896608
2021-11-23 21:29:40.796335
ASGN:AK
6281f605-f322-44f2-be8a-d77534987d16
2021-11-24 13:35:54.345595
2021-11-24 13:37:40.199799
2021-11-24 13:35:54.345595
ASGN:JoH
602b1f78-6a01-49f6-a16a-5cfd1706fae5
2021-11-24 13:37:42.11964
2021-11-24 14:20:04.844465
2021-11-24 13:37:42.11964
ASGN:KS
5de4e9ad-58b7-4d19-9245-4d72b2fbd75e
2021-11-24 14:20:06.794886
2021-11-24 14:23:02.638973
2021-11-24 14:20:06.794886
As we can see, DaF was assigned before JoH, so an evaluation of JoH going to DaF
by system error would be extremely alarming.
Based on how the system works, this should be impossible under "normal"
operating conditions since evaluations are submitted with the UUID of the applicant
that is currently being displayed (i.e. there would have to be a custom server
request made by the SME_one to be able to send an evaluation meant for the applicant they
are evaluating to a different one - which SME_one's would have no incentive to do since
it is their evaluation either way.)
On interview with the SME_one while trying to find the cause of the error, it was
discovered that the SME_one had multiple browsers open that they were not aware of.
This led us to consider that it might be a human error, though we would need
confirmation because if it wasn't human error then there would be significant
issues with continuing to utilize the tool.
Hypothesis 1: Stale queue
The first hypothesis is that due to multiple windows, the following took place:
SME_one opens window_one to do evaluations on 2021-11-23
at 2021-11-23 21:29:40 the SME_one is assigned DaF in window_one
SME_one signs off for the day without closing window_one
the next day, the SME_one resumes reviewing, but opens a new window_two
SME_one is assigned and evaluates AK in window_two
This means that DaF will have had to have been "completed" in order for SME_one to be assigned a new applicant.
SME_one is assigned JoH in window_two [1st JoH]
SME_one accidentally changes to window_one while looking at JoH's resume
SME_one writes and submits JoH's evaluation in window_one, where the active applicant is DaF
window_one pulls JoH from the queue and the applicant is presented with JoH again [2nd JoH]
SME_one complete's review of JoH and submits it without error in window_one
At some point SME_one returns to window_two and see's JoH again [3rd JoH]
Flags are raised.
If that is the case we would expect to see the following in the database to confirm:
SME_one assignment to DaF is before SME_one assignment to JoH
DaF evaluations completed by 2 other SMEs before SME_one assignment to JoH[^1]
DaF and JoH evaluations have no evaluations between them[2^]
Unless there are 2 other SME evaluations before SME_one's evaluation of JoH
[1^]: This is the only way that SME_one would be able to get a new applicant,
as if the applicant was not yet complete, SME_one would not be able to be
assigned a new applicant.
[2^]: There should be no way for the SMEone to review _another applicant before JoH,
unless we repeat what happened with DaF.
As we already have assignment data, what we need is the application evaluation logs
for JoH and DaF with SME_one identified. This will either prove or disprove
the hypothesis.
SELECTau.name evaluator
, app.name applicant
, ae.created_at
, applicant_id
FROM application_evaluation ae
LEFT JOIN application a ONa.id=ae.application_idLEFT JOIN app_user au ONau.id=ae.evaluatorLEFT JOIN applicant app ONapp.id= applicant_id
WHERE applicant_id ='6ce242a1-fde5-430f-b3da-dceb15c87ae9'OR applicant_id ='602b1f78-6a01-49f6-a16a-5cfd1706fae5'OR applicant_id ='6281f605-f322-44f2-be8a-d77534987d16'ORDER BYae.created_at;
Evaluation history
evaluator
applicant
created_at
applicant_id
Eval: SME_three
AK
2021-11-23 22:13:24.319139
6281f605-f322-44f2-be8a-d77534987d16
Eval: SME_two
JoH
2021-11-23 22:37:22.043539
602b1f78-6a01-49f6-a16a-5cfd1706fae5
Eval: SME_one
DaF
2021-11-24 13:35:52.754871
6ce242a1-fde5-430f-b3da-dceb15c87ae9
Eval: SME_one
AK
2021-11-24 13:37:40.199799
6281f605-f322-44f2-be8a-d77534987d16
Eval: SME_one
JoH
2021-11-24 14:20:04.844465
602b1f78-6a01-49f6-a16a-5cfd1706fae5
Eval: SME_two
DaF
2021-11-24 17:06:53.484374
6ce242a1-fde5-430f-b3da-dceb15c87ae9
Eval: SME_three
DaF
2021-11-24 17:47:09.018914
6ce242a1-fde5-430f-b3da-dceb15c87ae9
Eval: SME_three
JoH
2021-11-24 18:17:33.792375
602b1f78-6a01-49f6-a16a-5cfd1706fae5
Hypothesis 1 invalidated: SMEtwo and SME_three evaluations followed _after SME_one's evaluation
Hypothesis 1 Mitigation:
When applicants are complete set all existing queue assignments members to false
Only allow evaluation if queue is active
Hypothesis 2 - Multi tabs
With that hypothesis invalidated, we then pulled all the assignment data for SME_one
and interleaved it with evaluation data for the three SMEs starting wtih DaF and
ending with JoH to see if there were any noticeable patterns[^3]:
evaluator
applicant
created_at
assignment_update_timestamp - UPDT
1 ASGN: SME_one
JR
2021-11-23 21:21:00.499166
2021-11-23 21:29:36.715729
2 ASGN: SME_one
DaF
2021-11-23 21:29:40.796335
2021-11-24 13:48:02.896608*
3 Eval: SME_three
AK
2021-11-23 22:13:24.319139
4 Eval: SME_two
JoH
2021-11-23 22:37:22.043539
5 Eval: SME_one
DaF
2021-11-24 13:35:52.754871
6 ASGN: SME_one
AK
2021-11-24 13:35:54.345595
2021-11-24 13:37:40.199799
7 Eval: SME_one
AK
2021-11-24 13:37:40.199799
8 ASGN: SME_one
JoH
2021-11-24 13:37:42.11964 *
2021-11-24 14:20:04.844465
9 Eval: SME_one
JoH
2021-11-24 14:20:04.844465*
10 ASGN: SME_one
KS
2021-11-24 14:20:06.794886
2021-11-24 14:23:02.638973
11 Eval: SME_two
DaF
2021-11-24 17:06:53.484374
12 Eval: SME_three
DaF
2021-11-24 17:47:09.018914
13 Eval: SME_three
JoH
2021-11-24 18:17:33.792375
From this we can see the usual pattern (see row 5) of evaluation creation and the
next assignment creation being within a second of each other:
But there is a significant offset for DaF's update, especially since it is after DaF's created date, which is very unusual since the update and evaluation
are in the same database transaction.
SME_one opens window_one to do evaluations on 2021-11-23
at 2021-11-23 21:29:40 the SME_one is assigned DaF in window_one
SME_one signs off for the day without closing window_one
the next day, the SME_one resumes reviewing, but opens a new window_two
SME_one is presented with DaF in window_two, and evaluates candidate
SME_one is then assigned and evaluates AK in window_two
SME_one is then assigned and sees JoH, and while changing between windows
and resume changes back to window_one, but does not see that the current
window is assigned to DaF [1st JoH]
SME_one places review into DaF's evaluation and submits it
This overwrites the previous evaluation and causes an update (2 UPDT)
Since SME_one is still assigned JoH, they are presented with JoH in window_one [2nd JoH]
SME_one then evaluates JoH in window_one - this time correctly so
At some point SME_one changes back to window_two and sees JoH again [3rd Joh]
Flags are raised.
If this is the case, we would see the example behavior as above (that the assignment
update time and the eval creation time are grossly out of sync - i.e. that the
assignment was updated after the evaluation was completed).
More than that, we would expect several entries in our audit log for DaF.
Pulling those out:
SELECT id
, name
, email
, hr_review_time
, approved
, evaluation_feedback
, passing
FROM application_evaluation_audit_trail
WHERE assessment_hurdle_id ='7b8d1165-04e4-4b86-8747-137249dc825d'AND name LIKE'%DaF%';
Which gives us this:
id
name
email
hr_review_time
approved
evaluation_feedback
passing
543b9458-4f5e-4bff-8b31-a86d095b23b4
DaF
SME_one
2021-11-29 21:43:34.212177
t
t
c3eea0b4-bd34-4d88-8b14-7641ccbd981f
DaF
SME_two
2021-11-29 21:44:28.402855
t
f
3bed613e-fbfe-49c6-9d5c-60aa09d52e2c
DaF
SME_three
2021-11-29 21:45:04.372087
t
f
Clearly not what we're after, the audit trail tracks only on HR actions.
So let's go to our application logs... which we have timestamps to search:
First we need to verify that the initial created at date for the evaluation had a real evaluation made:
2021-11-24 13:35:52.754871
Then we need to check for a second, erroneous evaluation at the assignment updated time:
2021-11-24 13:48:02.896608
If these both have two separate evaluations, then it is highly likely that this
is the order of events that transpired.
For Nov 24th there are 7 records of with both SME_one's id (99f4a68e) and DaFs
id (6ce242a1).
They are as follows:
[34mdebug[39m: Existing Active item in Queue for user: 99f4a68e-5720-4317-9127-9122906470b0 returning existing item 6ce242a1-fde5-430f-b3da-dceb15c87ae9 {"timestamp":"2021-11-24 08:32:40"}
Get applicant Information
Nov 24, 2021 @ 08:32:40.701
gsa-open-opportunities
USDS
smeqa-rr
[34mdebug[39m: 1ms Executed (default): SELECT "id", "evaluation_feedback", "applicant_id", "evaluator_id", "feedback_author_id", "feedback_timestamp", "created_at", "updated_at" FROM "public"."applicant_evaluation_feedback" AS "ApplicantEvaluationFeedback" WHERE "ApplicantEvaluationFeedback"."applicant_id" = '6ce242a1-fde5-430f-b3da-dceb15c87ae9' AND "ApplicantEvaluationFeedback"."evaluator_id" = '99f4a68e-5720-4317-9127-9122906470b0' LIMIT 1; {"timestamp":"2021-11-24 08:32:40"}
CompetencyEvaluation selection
Nov 24, 2021 @ 08:32:40.709
gsa-open-opportunities
USDS
smeqa-rr
[34mdebug[39m: 1ms Executed (default): SELECT "id", "evaluation_note", "evaluator", "applicant", "competency_id", "competency_selector_id", "created_at", "updated_at" FROM "public"."competency_evaluation" AS "CompetencyEvaluation" WHERE "CompetencyEvaluation"."competency_id" IN ('e4316443-7be8-40ab-b913-9dfc4c6b83b8', '984a2d5f-5d9d-426f-bf51-486d1bc42570') AND "CompetencyEvaluation"."evaluator" = '99f4a68e-5720-4317-9127-9122906470b0' AND "CompetencyEvaluation"."applicant" = '6ce242a1-fde5-430f-b3da-dceb15c87ae9'; {"timestamp":"2021-11-24 08:32:40"}
CompetencyEvaluation selection
Nov 24, 2021 @ 08:35:52.831
gsa-open-opportunities
USDS
smeqa-rr
[34mdebug[39m: 1ms Executed (default): SELECT "id", "evaluation_note", "evaluator", "applicant", "competency_id", "competency_selector_id", "created_at", "updated_at" FROM "public"."competency_evaluation" AS "CompetencyEvaluation" WHERE "CompetencyEvaluation"."competency_id" IN ('e4316443-7be8-40ab-b913-9dfc4c6b83b8', '984a2d5f-5d9d-426f-bf51-486d1bc42570') AND "CompetencyEvaluation"."evaluator" = '99f4a68e-5720-4317-9127-9122906470b0' AND "CompetencyEvaluation"."applicant" = '6ce242a1-fde5-430f-b3da-dceb15c87ae9'; {"timestamp":"2021-11-24 08:35:52"}
Update assignment to inactive
Nov 24, 2021 @ 08:35:52.844
gsa-open-opportunities
USDS
smeqa-rr
[34mdebug[39m: [Transaction] Updated evaluator [99f4a68e-5720-4317-9127-9122906470b0] assignment of 6ce242a1-fde5-430f-b3da-dceb15c87ae9 to inactive {"timestamp":"2021-11-24 08:35:52"}
CompetencyEvaluation selection
Nov 24, 2021 @ 08:48:02.973
gsa-open-opportunities
USDS
smeqa-rr
[34mdebug[39m: 1ms Executed (default): SELECT "id", "evaluation_note", "evaluator", "applicant", "competency_id", "competency_selector_id", "created_at", "updated_at" FROM "public"."competency_evaluation" AS "CompetencyEvaluation" WHERE "CompetencyEvaluation"."competency_id" IN ('e4316443-7be8-40ab-b913-9dfc4c6b83b8', '984a2d5f-5d9d-426f-bf51-486d1bc42570') AND "CompetencyEvaluation"."evaluator" = '99f4a68e-5720-4317-9127-9122906470b0' AND "CompetencyEvaluation"."applicant" = '6ce242a1-fde5-430f-b3da-dceb15c87ae9'; {"timestamp":"2021-11-24 08:48:02"}
Update assignment to inactive
Nov 24, 2021 @ 08:48:02.987
gsa-open-opportunities
USDS
smeqa-rr
[34mdebug[39m: [Transaction] Updated evaluator [99f4a68e-5720-4317-9127-9122906470b0] assignment of 6ce242a1-fde5-430f-b3da-dceb15c87ae9 to inactive {"timestamp":"2021-11-24 08:48:02"}
We can now move entirely to the "log time" instead of our "audit time" since we
can make the "update assignment to inactive" it our own log events confirming that we
twice updated the evaluator's assignment to inactive. We can now search the logs
around these timestamps for duplicate evaluations: specifically around 8:35 and 8:4
while searching only for the applicant by their id (6ce242a1):
[34mdebug[39m: Existing Active item in Queue for user: 99f4a68e-5720-4317-9127-9122906470b0 returning existing item 6ce242a1-fde5-430f-b3da-dceb15c87ae9 {"timestamp":"2021-11-24 08:32:40"}
2
Nov 24, 2021 @ 08:32:40.700
gsa-open-opportunities
USDS
smeqa-rr
[34mdebug[39m: 1ms Executed (default): SELECT "id", "name", "flag_type", "flag_message", "assessment_hurdle_id", "additional_note", "created_at", "updated_at" FROM "public"."applicant" AS "Applicant" WHERE "Applicant"."id" = '6ce242a1-fde5-430f-b3da-dceb15c87ae9'; {"timestamp":"2021-11-24 08:32:40"}
3
Nov 24, 2021 @ 08:32:40.701
gsa-open-opportunities
USDS
smeqa-rr
[34mdebug[39m: 1ms Executed (default): SELECT "id", "evaluation_feedback", "applicant_id", "evaluator_id", "feedback_author_id", "feedback_timestamp", "created_at", "updated_at" FROM "public"."applicant_evaluation_feedback" AS "ApplicantEvaluationFeedback" WHERE "ApplicantEvaluationFeedback"."applicant_id" = '6ce242a1-fde5-430f-b3da-dceb15c87ae9' AND "ApplicantEvaluationFeedback"."evaluator_id" = '99f4a68e-5720-4317-9127-9122906470b0' LIMIT 1; {"timestamp":"2021-11-24 08:32:40"}
4
Nov 24, 2021 @ 08:32:40.704
gsa-open-opportunities
USDS
smeqa-rr
[34mdebug[39m: 1ms Executed (default): SELECT "Application"."id", "Application"."applicant_id", "Application"."specialty_id", "Application"."created_at", "Application"."updated_at", "Specialty"."id" AS "Specialty.id" FROM "public"."application" AS "Application" INNER JOIN "public"."specialty" AS "Specialty" ON "Application"."specialty_id" = "Specialty"."id" WHERE "Application"."applicant_id" = '6ce242a1-fde5-430f-b3da-dceb15c87ae9'; {"timestamp":"2021-11-24 08:32:40"}
5
Nov 24, 2021 @ 08:32:40.709
gsa-open-opportunities
USDS
smeqa-rr
[34mdebug[39m: 1ms Executed (default): SELECT "id", "evaluation_note", "evaluator", "applicant", "competency_id", "competency_selector_id", "created_at", "updated_at" FROM "public"."competency_evaluation" AS "CompetencyEvaluation" WHERE "CompetencyEvaluation"."competency_id" IN ('e4316443-7be8-40ab-b913-9dfc4c6b83b8', '984a2d5f-5d9d-426f-bf51-486d1bc42570') AND "CompetencyEvaluation"."evaluator" = '99f4a68e-5720-4317-9127-9122906470b0' AND "CompetencyEvaluation"."applicant" = '6ce242a1-fde5-430f-b3da-dceb15c87ae9'; {"timestamp":"2021-11-24 08:32:40"}
6
Nov 24, 2021 @ 08:32:40.710
gsa-open-opportunities
USDS
smeqa-rr
[34mdebug[39m: 1ms Executed (default): SELECT "competency_id", "does_not_meet", "meets" FROM "public"."competency_evaluation_count" AS "CompetencyEvaluationCount" WHERE "CompetencyEvaluationCount"."applicant" = '6ce242a1-fde5-430f-b3da-dceb15c87ae9'; {"timestamp":"2021-11-24 08:32:40"}
7
Nov 24, 2021 @ 08:32:40.713
gsa-open-opportunities
USDS
smeqa-rr
[32minfo[39m: 127.0.0.1 - - [24/Nov/2021:13:32:40 +0000] "GET /api/evaluation/7b8d1165-04e4-4b86-8747-137249dc825d/display/6ce242a1-fde5-430f-b3da-dceb15c87ae9 HTTP/1.1" 200 - "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/96.0.4664.55 Safari/537.36" {"timestamp":"2021-11-24 08:32:40"}
8 Evaluation submission
Nov 24, 2021 @ 08:35:52.819
gsa-open-opportunities
USDS
smeqa-rr
[34mdebug[39m: Submit Evaluation for 6ce242a1-fde5-430f-b3da-dceb15c87ae9 {"timestamp":"2021-11-24 08:35:52"}
9
Nov 24, 2021 @ 08:35:52.820
gsa-open-opportunities
USDS
smeqa-rr
[34mdebug[39m: 1ms Executed (default): SELECT "id", "name", "flag_type", "flag_message", "assessment_hurdle_id", "additional_note", "created_at", "updated_at" FROM "public"."applicant" AS "Applicant" WHERE "Applicant"."id" = '6ce242a1-fde5-430f-b3da-dceb15c87ae9'; {"timestamp":"2021-11-24 08:35:52"}
10
Nov 24, 2021 @ 08:35:52.822
gsa-open-opportunities
USDS
smeqa-rr
[34mdebug[39m: 1ms Executed (default): SELECT "Application"."id", "Application"."applicant_id", "Application"."specialty_id", "Application"."created_at", "Application"."updated_at", "Specialty"."id" AS "Specialty.id", "Specialty"."name" AS "Specialty.name", "Specialty"."local_id" AS "Specialty.local_id", "Specialty"."assessment_hurdle_id" AS "Specialty.assessment_hurdle_id", "Specialty"."points_required" AS "Specialty.points_required", "Specialty"."created_at" AS "Specialty.created_at", "Specialty"."updated_at" AS "Specialty.updated_at", "Specialty->SpecialtyCompetencies"."id" AS "Specialty.SpecialtyCompetencies.id", "Specialty->SpecialtyCompetencies"."specialty_id" AS "Specialty.SpecialtyCompetencies.specialty_id", "Specialty->SpecialtyCompetencies"."competency_id" AS "Specialty.SpecialtyCompetencies.competency_id", "Specialty->SpecialtyCompetencies"."created_at" AS "Specialty.SpecialtyCompetencies.created_at", "Specialty->SpecialtyCompetencies"."updated_at" AS "Specialty.SpecialtyCompetencies.updated_at" FROM "public"."application" AS "Application" INNER JOIN "public"."specialty" AS "Specialty" ON "Application"."specialty_id" = "Specialty"."id" LEFT OUTER JOIN "public"."specialty_competencies" AS "Specialty->SpecialtyCompetencies" ON "Specialty"."id" = "Specialty->SpecialtyCompetencies"."specialty_id" WHERE "Application"."applicant_id" = '6ce242a1-fde5-430f-b3da-dceb15c87ae9'; {"timestamp":"2021-11-24 08:35:52"}
11
Nov 24, 2021 @ 08:35:52.827
gsa-open-opportunities
USDS
smeqa-rr
[34mdebug[39m: 1ms Executed (default): SELECT "Application"."id", "Application"."applicant_id", "Application"."specialty_id", "Application"."created_at", "Application"."updated_at", "Specialty"."id" AS "Specialty.id" FROM "public"."application" AS "Application" INNER JOIN "public"."specialty" AS "Specialty" ON "Application"."specialty_id" = "Specialty"."id" WHERE "Application"."applicant_id" = '6ce242a1-fde5-430f-b3da-dceb15c87ae9'; {"timestamp":"2021-11-24 08:35:52"}
12
Nov 24, 2021 @ 08:35:52.831
gsa-open-opportunities
USDS
smeqa-rr
[34mdebug[39m: 1ms Executed (default): SELECT "id", "evaluation_note", "evaluator", "applicant", "competency_id", "competency_selector_id", "created_at", "updated_at" FROM "public"."competency_evaluation" AS "CompetencyEvaluation" WHERE "CompetencyEvaluation"."competency_id" IN ('e4316443-7be8-40ab-b913-9dfc4c6b83b8', '984a2d5f-5d9d-426f-bf51-486d1bc42570') AND "CompetencyEvaluation"."evaluator" = '99f4a68e-5720-4317-9127-9122906470b0' AND "CompetencyEvaluation"."applicant" = '6ce242a1-fde5-430f-b3da-dceb15c87ae9'; {"timestamp":"2021-11-24 08:35:52"}
13
Nov 24, 2021 @ 08:35:52.832
gsa-open-opportunities
USDS
smeqa-rr
[34mdebug[39m: 1ms Executed (default): SELECT "competency_id", "does_not_meet", "meets" FROM "public"."competency_evaluation_count" AS "CompetencyEvaluationCount" WHERE "CompetencyEvaluationCount"."applicant" = '6ce242a1-fde5-430f-b3da-dceb15c87ae9'; {"timestamp":"2021-11-24 08:35:52"}
14
Nov 24, 2021 @ 08:35:52.833
gsa-open-opportunities
USDS
smeqa-rr
[34mdebug[39m: Creating evaluation results for 1 applications for applicant 6ce242a1-fde5-430f-b3da-dceb15c87ae9 {"timestamp":"2021-11-24 08:35:52"}
15
Nov 24, 2021 @ 08:35:52.844
gsa-open-opportunities
USDS
smeqa-rr
[34mdebug[39m: [Transaction] Updated evaluator [99f4a68e-5720-4317-9127-9122906470b0] assignment of 6ce242a1-fde5-430f-b3da-dceb15c87ae9 to inactive {"timestamp":"2021-11-24 08:35:52"}
16
Nov 24, 2021 @ 08:35:52.850
gsa-open-opportunities
USDS
smeqa-rr
[32minfo[39m: 127.0.0.1 - - [24/Nov/2021:13:35:52 +0000] "PUT /api/evaluation/7b8d1165-04e4-4b86-8747-137249dc825d/submit/6ce242a1-fde5-430f-b3da-dceb15c87ae9 HTTP/1.1" 201 - "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/96.0.4664.55 Safari/537.36" {"timestamp":"2021-11-24 08:35:52"}
17
Nov 24, 2021 @ 08:35:54.423
gsa-open-opportunities
USDS
smeqa-rr
AND active IS true) AS "current_queue_count" FROM "public"."applicant_queue" AS "ApplicantQueue" WHERE "ApplicantQueue"."assessment_hurdle_id" = '7b8d1165-04e4-4b86-8747-137249dc825d' AND "ApplicantQueue"."applicant_id" NOT IN ('ef0e42c5-17cf-4b06-a5ea-f5965c1f0858', '91a92152-074c-479e-8e7f-03be8c6e00c7', '7c29b42a-e2bf-4fbb-89d3-8bf1ed67dfa7', '7949f930-ef71-4248-b349-6aad67318c2c', '7831ec99-7ce7-4628-9d62-7e995b2c426d', '77c23896-66c7-4543-80bb-8920becff7cc', '779dfaa3-a0dd-4dc7-8670-1b63a3a5e060', '7679075a-913c-4291-a590-a8a659492194', '74a526dd-40ed-4b02-a70c-a5c887ac8e67', '6fb6b56c-ed15-45ed-881c-888f78093d7c', '6d8130f6-c2e5-4a59-bf8b-70c82337fa23', '6d1fe480-4bf6-4f4a-aeb6-a18e94755391', '6ce242a1-fde5-430f-b3da-dceb15c87ae9', '88414f59-43af-4e90-a5c7-95f30f86e3a7', 'fcc2e69f-49aa-4dfc-bb87-a5110f32aac0', '6f5a351e-71b7-426f-82f4-34f595bf616f', '646bbf9f-d1c6-4afa-83bb-8f441bb6d86e') GROUP BY "ApplicantQueue"."applicant_id", "evaluators" ORDER BY current_queue_count ASC NULLS FIRST, evaluators DESC NULLS LAST, applicant_id DESC LIMIT 1; {"timestamp":"2021-11-24 08:35:54"}
18
Nov 24, 2021 @ 08:37:42.108
gsa-open-opportunities
USDS
smeqa-rr
AND active IS true) AS "current_queue_count" FROM "public"."applicant_queue" AS "ApplicantQueue" WHERE "ApplicantQueue"."assessment_hurdle_id" = '7b8d1165-04e4-4b86-8747-137249dc825d' AND "ApplicantQueue"."applicant_id" NOT IN ('ef0e42c5-17cf-4b06-a5ea-f5965c1f0858', '91a92152-074c-479e-8e7f-03be8c6e00c7', '7c29b42a-e2bf-4fbb-89d3-8bf1ed67dfa7', '7949f930-ef71-4248-b349-6aad67318c2c', '7831ec99-7ce7-4628-9d62-7e995b2c426d', '77c23896-66c7-4543-80bb-8920becff7cc', '779dfaa3-a0dd-4dc7-8670-1b63a3a5e060', '7679075a-913c-4291-a590-a8a659492194', '74a526dd-40ed-4b02-a70c-a5c887ac8e67', '6fb6b56c-ed15-45ed-881c-888f78093d7c', '6d8130f6-c2e5-4a59-bf8b-70c82337fa23', '6d1fe480-4bf6-4f4a-aeb6-a18e94755391', '6ce242a1-fde5-430f-b3da-dceb15c87ae9', '6281f605-f322-44f2-be8a-d77534987d16', '88414f59-43af-4e90-a5c7-95f30f86e3a7', 'fcc2e69f-49aa-4dfc-bb87-a5110f32aac0', '6f5a351e-71b7-426f-82f4-34f595bf616f', '646bbf9f-d1c6-4afa-83bb-8f441bb6d86e') GROUP BY "ApplicantQueue"."applicant_id", "evaluators" ORDER BY current_queue_count ASC NULLS FIRST, evaluators DESC NULLS LAST, applicant_id DESC LIMIT 1; {"timestamp":"2021-11-24 08:37:42"}
19 Evaluation Submission
Nov 24, 2021 @ 08:48:02.961
gsa-open-opportunities
USDS
smeqa-rr
[34mdebug[39m: Submit Evaluation for 6ce242a1-fde5-430f-b3da-dceb15c87ae9 {"timestamp":"2021-11-24 08:48:02"}
20
Nov 24, 2021 @ 08:48:02.962
gsa-open-opportunities
USDS
smeqa-rr
[34mdebug[39m: 1ms Executed (default): SELECT "id", "name", "flag_type", "flag_message", "assessment_hurdle_id", "additional_note", "created_at", "updated_at" FROM "public"."applicant" AS "Applicant" WHERE "Applicant"."id" = '6ce242a1-fde5-430f-b3da-dceb15c87ae9'; {"timestamp":"2021-11-24 08:48:02"}
21
Nov 24, 2021 @ 08:48:02.965
gsa-open-opportunities
USDS
smeqa-rr
[34mdebug[39m: 2ms Executed (default): SELECT "Application"."id", "Application"."applicant_id", "Application"."specialty_id", "Application"."created_at", "Application"."updated_at", "Specialty"."id" AS "Specialty.id", "Specialty"."name" AS "Specialty.name", "Specialty"."local_id" AS "Specialty.local_id", "Specialty"."assessment_hurdle_id" AS "Specialty.assessment_hurdle_id", "Specialty"."points_required" AS "Specialty.points_required", "Specialty"."created_at" AS "Specialty.created_at", "Specialty"."updated_at" AS "Specialty.updated_at", "Specialty->SpecialtyCompetencies"."id" AS "Specialty.SpecialtyCompetencies.id", "Specialty->SpecialtyCompetencies"."specialty_id" AS "Specialty.SpecialtyCompetencies.specialty_id", "Specialty->SpecialtyCompetencies"."competency_id" AS "Specialty.SpecialtyCompetencies.competency_id", "Specialty->SpecialtyCompetencies"."created_at" AS "Specialty.SpecialtyCompetencies.created_at", "Specialty->SpecialtyCompetencies"."updated_at" AS "Specialty.SpecialtyCompetencies.updated_at" FROM "public"."application" AS "Application" INNER JOIN "public"."specialty" AS "Specialty" ON "Application"."specialty_id" = "Specialty"."id" LEFT OUTER JOIN "public"."specialty_competencies" AS "Specialty->SpecialtyCompetencies" ON "Specialty"."id" = "Specialty->SpecialtyCompetencies"."specialty_id" WHERE "Application"."applicant_id" = '6ce242a1-fde5-430f-b3da-dceb15c87ae9'; {"timestamp":"2021-11-24 08:48:02"}
22
Nov 24, 2021 @ 08:48:02.969
gsa-open-opportunities
USDS
smeqa-rr
[34mdebug[39m: 1ms Executed (default): SELECT "Application"."id", "Application"."applicant_id", "Application"."specialty_id", "Application"."created_at", "Application"."updated_at", "Specialty"."id" AS "Specialty.id" FROM "public"."application" AS "Application" INNER JOIN "public"."specialty" AS "Specialty" ON "Application"."specialty_id" = "Specialty"."id" WHERE "Application"."applicant_id" = '6ce242a1-fde5-430f-b3da-dceb15c87ae9'; {"timestamp":"2021-11-24 08:48:02"}
23
Nov 24, 2021 @ 08:48:02.973
gsa-open-opportunities
USDS
smeqa-rr
[34mdebug[39m: 1ms Executed (default): SELECT "id", "evaluation_note", "evaluator", "applicant", "competency_id", "competency_selector_id", "created_at", "updated_at" FROM "public"."competency_evaluation" AS "CompetencyEvaluation" WHERE "CompetencyEvaluation"."competency_id" IN ('e4316443-7be8-40ab-b913-9dfc4c6b83b8', '984a2d5f-5d9d-426f-bf51-486d1bc42570') AND "CompetencyEvaluation"."evaluator" = '99f4a68e-5720-4317-9127-9122906470b0' AND "CompetencyEvaluation"."applicant" = '6ce242a1-fde5-430f-b3da-dceb15c87ae9'; {"timestamp":"2021-11-24 08:48:02"}
24
Nov 24, 2021 @ 08:48:02.975
gsa-open-opportunities
USDS
smeqa-rr
[34mdebug[39m: 1ms Executed (default): SELECT "competency_id", "does_not_meet", "meets" FROM "public"."competency_evaluation_count" AS "CompetencyEvaluationCount" WHERE "CompetencyEvaluationCount"."applicant" = '6ce242a1-fde5-430f-b3da-dceb15c87ae9'; {"timestamp":"2021-11-24 08:48:02"}
25
Nov 24, 2021 @ 08:48:02.975
gsa-open-opportunities
USDS
smeqa-rr
[34mdebug[39m: Creating evaluation results for 1 applications for applicant 6ce242a1-fde5-430f-b3da-dceb15c87ae9 {"timestamp":"2021-11-24 08:48:02"}
26
Nov 24, 2021 @ 08:48:02.987
gsa-open-opportunities
USDS
smeqa-rr
[34mdebug[39m: [Transaction] Updated evaluator [99f4a68e-5720-4317-9127-9122906470b0] assignment of 6ce242a1-fde5-430f-b3da-dceb15c87ae9 to inactive {"timestamp":"2021-11-24 08:48:02"}
27
Nov 24, 2021 @ 08:48:02.992
gsa-open-opportunities
USDS
smeqa-rr
[32minfo[39m: 127.0.0.1 - - [24/Nov/2021:13:48:02 +0000] "PUT /api/evaluation/7b8d1165-04e4-4b86-8747-137249dc825d/submit/6ce242a1-fde5-430f-b3da-dceb15c87ae9 HTTP/1.1" 201 - "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/96.0.4664.55 Safari/537.36" {"timestamp":"2021-11-24 08:48:02"}`
It is worth nothing that all other evaluation submissions from other SMEs
happened >4 hours after the time window being examined, so all evaluations
would be from SME_one.
From the applications logs we see two evaluations: - Line (8) @ 8:32:52 - Line (19) @ 8:48:02
From the audit logs we have remarkable similar timestamps for the creation of the
initial evaluation and update of the assignments (we have to use the "updated at" of the
assignment as a proxy for the "evaluation update time" because actions taken on
the "evaluation" will update the "updated at" value ): - 2 ASGN: Updated at: 13:48:02 - 5 EVAL: 13:34:52
Hypothesis 2 validated: It's clear from the matching timestamps that the timezones are off by 5 hours, but otherwise
these are the same transactions. This shows that SME_one submitted twice not on JoH as expected, but actually on DaF due to multiple browser tabs being open.
Hypothesis 2 Mitigation:
Only allow one browser tab open at a time (same machine multiple tabs)
Timeout unused browser tabs (UX)
Only allow one session per a user at a time (different machines)
Only allow evaluation if queue is active
Root cause
Why did the SME submit an evaluation on the wrong applicant?
Application did not prevent multiple browser tabs from being open
Application allowed for multiple submissions on the same applicant (this is expected behavior).
Why didn't the application prevent multiple browser tabs from being open?
Unexpected use case, browser does not time out.
Root cause here is missing UX regarding common usage with multiple tabs/browsers.
Remediation
Only allow one browser tab open at a time (same machine multiple tabs)
Timeout unused browser tabs (UX)
Only allow one session per a user at a time (different machines)
Only allow evaluation if queue is active
From Hypothesis 1:
When applicants are complete set all existing queue assignments members to false
Conclusion
There is no systemic risk of the system being faulty. Applicant DaF should have
the evaluation by SME_one invalidated, and a fuzzy checker should be run over
all hiring action to see if there are similar cases of SMEs using the tool in multiple tabs.
An advisory should be sent out to SMEs to keep a clean desktop environment and work
in only one tab. Alternatively, refreshing the page if you are unsure if you have multiple tabs
will also ensure that you are in the correct space.
An advisory should be sent out to SMEs to doublecheck the name matches before submitting
an evaluation.
A UX fix should go out to force the applicant name to be shown at all times to SMES.
A bug fix should go out to prevent multiple browser tabs from maintaining different states.
A bug fix should go out to prevent multiple user sessions from being valid.
The text was updated successfully, but these errors were encountered:
From the bottom:
Remediation
From Hypothesis 1:
Conclusion
There is no systemic risk of the system being faulty. Applicant
DaF
should havethe evaluation by SME_one invalidated, and a fuzzy checker should be run over
all hiring action to see if there are similar cases of SMEs using the tool in multiple tabs.
in only one tab. Alternatively, refreshing the page if you are unsure if you have multiple tabs
will also ensure that you are in the correct space.
an evaluation.
SME names have been expunged and applicant names have been reduced to initials.
The two applicants of interest have been changed to
JoH
andDaF
to make readingand differentiating them easier.
Background - SME sees same applicant 3x times.
SME_one reported duplicate evaluations of an applicant,
JoH
and being presentedwith the applicant 3x times.
While investigating this issue we found that there were no duplicate evaluations
of
JoH
, but that a review meant forJoH
was actually applied toDaF
.To find out how such assignment we pulled the
application_assignment
tablefor the SME_one, where rows are created in the table whenever a new assignment is
made:
Which is displayed below:
As we can see,
DaF
was assigned beforeJoH
, so an evaluation ofJoH
going toDaF
by system error would be extremely alarming.
Based on how the system works, this should be impossible under "normal"
operating conditions since evaluations are submitted with the UUID of the applicant
that is currently being displayed (i.e. there would have to be a custom server
request made by the SME_one to be able to send an evaluation meant for the applicant they
are evaluating to a different one - which SME_one's would have no incentive to do since
it is their evaluation either way.)
On interview with the SME_one while trying to find the cause of the error, it was
discovered that the SME_one had multiple browsers open that they were not aware of.
This led us to consider that it might be a human error, though we would need
confirmation because if it wasn't human error then there would be significant
issues with continuing to utilize the tool.
Hypothesis 1: Stale queue
The first hypothesis is that due to multiple windows, the following took place:
DaF
in window_oneAK
in window_twoDaF
will have had to have been "completed" in order for SME_one to be assigned a new applicant.JoH
in window_two [1stJoH
]JoH
's resumeJoH
's evaluation in window_one, where the active applicant isDaF
JoH
from the queue and the applicant is presented withJoH
again [2ndJoH
]JoH
and submits it without error in window_oneJoH
again [3rdJoH
]If that is the case we would expect to see the following in the database to confirm:
DaF
is before SME_one assignment toJoH
DaF
evaluations completed by 2 other SMEs before SME_one assignment toJoH
[^1]DaF
andJoH
evaluations have no evaluations between them[2^]JoH
[1^]: This is the only way that SME_one would be able to get a new applicant,
as if the applicant was not yet complete, SME_one would not be able to be
assigned a new applicant.
[2^]: There should be no way for the SMEone to review _another applicant before
JoH
,unless we repeat what happened with
DaF
.As we already have assignment data, what we need is the application evaluation logs
for
JoH
andDaF
with SME_one identified. This will either prove or disprovethe hypothesis.
Evaluation history
Hypothesis 1invalidated: SMEtwo and SME_three evaluations followed _after SME_one's evaluationHypothesis 1 Mitigation:
Hypothesis 2 - Multi tabs
With that hypothesis invalidated, we then pulled all the assignment data for SME_one
and interleaved it with evaluation data for the three SMEs starting wtih DaF and
ending with JoH to see if there were any noticeable patterns[^3]:
From this we can see the usual pattern (see row 5) of evaluation creation and the
next assignment creation being within a second of each other:
The other interesting pattern is that the assignment update also correlates to the assignment:
But there is a significant offset for DaF's update, especially since it is after
DaF
's created date, which is very unusual since the update and evaluationare in the same database transaction.
This generates a new hypothesis:
DaF
in window_oneDaF
in window_two, and evaluates candidateAK
in window_twoJoH
, and while changing between windowsand resume changes back to window_one, but does not see that the current
window is assigned to
DaF
[1stJoH
]DaF
's evaluation and submits it2 UPDT
)JoH
, they are presented withJoH
in window_one [2ndJoH
]JoH
in window_one - this time correctly soJoH
again [3rdJoh
]If this is the case, we would see the example behavior as above (that the assignment
update time and the eval creation time are grossly out of sync - i.e. that the
assignment was updated after the evaluation was completed).
More than that, we would expect several entries in our audit log for
DaF
.Pulling those out:
Which gives us this:
Clearly not what we're after, the audit trail tracks only on HR actions.
So let's go to our application logs... which we have timestamps to search:
First we need to verify that the initial created at date for the evaluation had a real evaluation made:
Then we need to check for a second, erroneous evaluation at the assignment updated time:
If these both have two separate evaluations, then it is highly likely that this
is the order of events that transpired.
For Nov 24th there are 7 records of with both SME_one's id (99f4a68e) and
DaF
sid (6ce242a1).
They are as follows:
We can now move entirely to the "log time" instead of our "audit time" since we
can make the "update assignment to inactive" it our own log events confirming that we
twice updated the evaluator's assignment to inactive. We can now search the logs
around these timestamps for duplicate evaluations: specifically around 8:35 and 8:4
while searching only for the applicant by their id (6ce242a1):
It is worth nothing that all other evaluation submissions from other SMEs
happened >4 hours after the time window being examined, so all evaluations
would be from SME_one.
From the applications logs we see two evaluations: - Line (8) @ 8:32:52 - Line (19) @ 8:48:02
From the audit logs we have remarkable similar timestamps for the creation of the
initial evaluation and update of the assignments (we have to use the "updated at" of the
assignment as a proxy for the "evaluation update time" because actions taken on
the "evaluation" will update the "updated at" value ): - 2 ASGN: Updated at: 13:48:02 - 5 EVAL: 13:34:52
Hypothesis 2 validated: It's clear from the matching timestamps that the timezones are off by 5 hours, but otherwise
these are the same transactions. This shows that SME_one submitted twice not on
JoH
as expected, but actually onDaF
due to multiple browser tabs being open.Hypothesis 2 Mitigation:
Root cause
Why did the SME submit an evaluation on the wrong applicant?
Application did not prevent multiple browser tabs from being open
Application allowed for multiple submissions on the same applicant (this is expected behavior).
Why didn't the application prevent multiple browser tabs from being open?
Unexpected use case, browser does not time out.
Root cause here is missing UX regarding common usage with multiple tabs/browsers.
Remediation
From Hypothesis 1:
Conclusion
There is no systemic risk of the system being faulty. Applicant
DaF
should havethe evaluation by SME_one invalidated, and a fuzzy checker should be run over
all hiring action to see if there are similar cases of SMEs using the tool in multiple tabs.
in only one tab. Alternatively, refreshing the page if you are unsure if you have multiple tabs
will also ensure that you are in the correct space.
an evaluation.
The text was updated successfully, but these errors were encountered: