authUserOnCreate() in emulator not supplying creationTime in UserRecordMetadata

[dsl101]

[REQUIRED] Environment info

firebase-tools: 11.16.0

Platform: Windows 10

[REQUIRED] Test case

exports = module.exports = functions.auth.user().onCreate(async user => {
  const initialProfile = {
    history: {},
  }

  console.log('user.metadata:', user.metadata)

  initialProfile.history.registered = admin.firestore.Timestamp.fromDate(new Date(user.metadata.creationTime))
  initialProfile.history.authEmail = user.email

  return afs.collection('users').doc(user.uid).set({ ...initialProfile }, { merge: true })

})

[REQUIRED] Steps to reproduce

Upgraded firebase functions & firebase-tools to latest versions, and existing code (running against previous 3.x version) is no longer working on new user creation.

1. Run emulators
2. Start client app, navigate to authentication page
3. Choose 'Sign in with Google'
4. Select 'Add new account' then 'Auto-generate user information'
5. Log in (app fails to finish navigation, as the onAuthCreate function never completes and the app profile data is not created)

[REQUIRED] Expected behavior

The metadata record would include valid creationTime and lastSignInTime properties.

[REQUIRED] Actual behavior

The following is shown in the emulators console output:

i  functions: Beginning execution of "authUserOnCreate"
>  user.metadata: UserRecordMetadata {
>    creationTime: undefined,
>    lastSignInTime: '2022-11-02T12:41:53.251Z'
>  }
!  functions: Error: Value for argument "seconds" is not a valid integer.

Running with --debug, the output is:

[2022-11-02T12:41:57.437Z] [worker-us-central1-authUserOnCreate-87b887f1-ae02-4006-8abf-2656e410aebd]: IDLE {"metadata":{"emulator":{"name":"functions"},"message":"[worker-us-central1-authUserOnCreate-87b887f1-ae02-4006-8abf-2656e410aebd]: IDLE"}}
[2022-11-02T12:41:57.453Z] [worker-pool] submitRequest(triggerId=us-central1-authUserOnCreate) {"metadata":{"emulator":{"name":"functions"},"message":"[worker-pool] submitRequest(triggerId=us-central1-authUserOnCreate)"}}
[2022-11-02T12:41:57.454Z] [worker-us-central1-authUserOnCreate-87b887f1-ae02-4006-8abf-2656e410aebd]: BUSY {"metadata":{"emulator":{"name":"functions"},"message":"[worker-us-central1-authUserOnCreate-87b887f1-ae02-4006-8abf-2656e410aebd]: BUSY"}}
i  functions: Beginning execution of "authUserOnCreate" {"metadata":{"emulator":{"name":"functions"},"function":{"name":"us-central1-authUserOnCreate"},"extension":{},"message":"Beginning execution of \"authUserOnCreate\""}}
[2022-11-02T12:41:57.480Z] [runtime-status] [15956] ProcessBackground: lifting resource.name from resource {"name":"projects/kistorm-development","service":"firebaseauth.googleapis.com"} {"metadata":{"emulator":{"name":"functions"},"function":{"name":"us-central1-authUserOnCreate"},"extension":{},"message":"[runtime-status] [15956] ProcessBackground: lifting resource.name from resource {\"name\":\"projects/kistorm-development\",\"service\":\"firebaseauth.googleapis.com\"}"}}
[2022-11-02T12:41:57.480Z] [runtime-status] [15956] RunBackground {"data":{"uid":"bl9ufSEYM0Mm475asAiOJNINeUWX","email":"grass.orange.310@example.com","emailVerified":true,"displayName":"Grass Orange","metadata":{"lastSignInTime":"2022-11-02T12:41:53.251Z"},"customClaims":{},"providerData":[{"providerId":"google.com","rawId":"9237101363942181374048753210812764061730","federatedId":"9237101363942181374048753210812764061730","displayName":"Grass Orange","email":"grass.orange.310@example.com","screenName":"orange_grass"}]},"context":{"eventId":"fff815b0-36a9-44e4-8732-4a1c4a13f187","eventType":"providers/firebase.auth/eventTypes/user.create","resource":"projects/kistorm-development","params":{},"timestamp":"2022-11-02T12:41:53.252Z"}} {"metadata":{"emulator":{"name":"functions"},"function":{"name":"us-central1-authUserOnCreate"},"extension":{},"message":"[runtime-status] [15956] RunBackground {\"data\":{\"uid\":\"bl9ufSEYM0Mm475asAiOJNINeUWX\",\"email\":\"grass.orange.310@example.com\",\"emailVerified\":true,\"displayName\":\"Grass Orange\",\"metadata\":{\"lastSignInTime\":\"2022-11-02T12:41:53.251Z\"},\"customClaims\":{},\"providerData\":[{\"providerId\":\"google.com\",\"rawId\":\"9237101363942181374048753210812764061730\",\"federatedId\":\"9237101363942181374048753210812764061730\",\"displayName\":\"Grass Orange\",\"email\":\"grass.orange.310@example.com\",\"screenName\":\"orange_grass\"}]},\"context\":{\"eventId\":\"fff815b0-36a9-44e4-8732-4a1c4a13f187\",\"eventType\":\"providers/firebase.auth/eventTypes/user.create\",\"resource\":\"projects/kistorm-development\",\"params\":{},\"timestamp\":\"2022-11-02T12:41:53.252Z\"}}"}}
>  user.metadata: UserRecordMetadata { {"user":"user.metadata: UserRecordMetadata {","metadata":{"emulator":{"name":"functions"},"function":{"name":"us-central1-authUserOnCreate"},"extension":{},"message":"\u001b[90m> \u001b[39m user.metadata: UserRecordMetadata {"}}
>    creationTime: undefined, {"user":"  creationTime: undefined,","metadata":{"emulator":{"name":"functions"},"function":{"name":"us-central1-authUserOnCreate"},"extension":{},"message":"\u001b[90m> \u001b[39m   creationTime: undefined,"}}
>    lastSignInTime: '2022-11-02T12:41:53.251Z' {"user":"  lastSignInTime: '2022-11-02T12:41:53.251Z'","metadata":{"emulator":{"name":"functions"},"function":{"name":"us-central1-authUserOnCreate"},"extension":{},"message":"\u001b[90m> \u001b[39m   lastSignInTime: '2022-11-02T12:41:53.251Z'"}}
>  } {"user":"}","metadata":{"emulator":{"name":"functions"},"function":{"name":"us-central1-authUserOnCreate"},"extension":{},"message":"\u001b[90m> \u001b[39m }"}}
!  functions: Error: Value for argument "seconds" is not a valid integer.
    at Object.validateInteger ([snip]\Firebase\functions\node_modules\@google-cloud\firestore\build\src\validate.js:200:19)
    at new Timestamp ([snip]\Firebase\functions\node_modules\@google-cloud\firestore\build\src\timestamp.js:70:20)
    at Function.fromMillis ([snip]\Firebase\functions\node_modules\@google-cloud\firestore\build\src\timestamp.js:126:16)
    at Function.fromDate ([snip]\Firebase\functions\node_modules\@google-cloud\firestore\build\src\timestamp.js:108:26)
    at [snip]\Firebase\functions\auth\user\onCreate.f.js:39:43
    at cloudFunction ([snip]\Firebase\functions\node_modules\firebase-functions\lib\cloud-functions.js:78:23)
    [snip]

The error is calling fromDate() with an invalid time, based on the undefined value.

I also commented here with a reference to where I suspect the bug was introduced, but that issue is closed, hence reposting here. Relevant parts:

I have an authUserOnCreate() trigger, that uses creationTime, and this is being passed in as undefined since firebase-tools 11.2.0 (I just ran the tests from 10.9.2 for each released tag, and 11.2.0 is where the error first shows up. Might it be related to this commit? See line 80 of src/emulator/auth/state.ts that was removed.

I also filed this bug, but suspect it should belong here. Since it hadn't had any attention, I'm reposting here with additional (debug) output, and will close that other issue.

[lisajian]

Thanks @dsl101 for filing the issue!

Confirmed against prod behavior that createdAt should match lastSignInTime by the time authUserOnCreate is triggered. The commit that was linked does remove setting createdAt from the state helper function and moves the responsibility of setting that to the caller of generateLocalId(); this was done to support Auth blocking functions. However, it looks like signInWithIdp() is missing that line.

#5260 should address the issue - this should go out with firebase-tools version 11.16.2