firebase / firebase/firebase-tools

Cloud Tasks Emulator ignores `scheduleDelaySeconds` or `scheduleTime` and instantly executes enqueued tasks (v2)

Open
#8,254 3 comments 11 reactions 1 assignee Claimed by @taeold View on GitHub
emulators: functions type: feature request
Dominant language
TypeScript
Stars
4.5k
Forks
1.3k
Avg merge
1d 12h
Merged PRs (30d)
84

Description

### [REQUIRED] Environment info

**firebase-tools:** 13.31.2

**Platform:** macOS

Since the emulator uses java:
```
java --version
openjdk 17.0.5 2022-10-18
OpenJDK Runtime Environment Temurin-17.0.5+8 (build 17.0.5+8)
OpenJDK 64-Bit Server VM Temurin-17.0.5+8 (build 17.0.5+8, mixed mode)
```

### [REQUIRED] Test case

The minimal example is whatever minimal example can be derived from the Firebase docs, see reproduction steps below. For the enqueue call, include the `scheduleDelaySeconds` parameter:

```js
await myQueue.enqueue(
{
data: 'test'
},
{
scheduleDelaySeconds: 40,
}, () => { ... })
```
I'm not including an `uri` in the second parameter object here because it causes issues in my emulator environment, and this bug report is about the emulator.

### [REQUIRED] Steps to reproduce

1. Follow the [Enqueue functions with Cloud Tasks (2nd gen) docs](https://firebase.google.com/docs/functions/task-functions?gen=2nd)
2. Enqueue a task in the emulator with `scheduleDelaySeconds` > 0, in my example, 40 seconds.
3. Observe that `scheduleDelaySeconds` has no effect, as soon as the task is enqueued, it is executed virtually without delay. See debug logs below.

### [REQUIRED] Expected behavior

`scheduleDelaySeconds` should be respected as it behaves that way in deployed Firebase environments, and I don't see why the behavior should be different in local emulators.

If Emulator users want to manually invoke their schedules tasks more quickly in local testing, they can use the REST API designed for that.

I'd also like to quote from another Firebase user with same issue (3 weeks ago):

> Is a solution to this coming? Scheduling is the reason I'm using Cloud Tasks in the first place :)

_Originally posted by @starcrest in [#4884](https://github.com/firebase/firebase-tools/issues/4884#issuecomment-2638154466])_

Scheduling is also the main reason why I want to use Cloud Tasks. It's why I'm opening a new issue here to raise attention to this, since #4884 is closed, and I think this is still a bug.

### [REQUIRED] Actual behavior

The issue was already observed in #4884 but apparently never addressed:

> [...]
> The task will run immediately and not respect `scheduleTime` or `scheduleDelaySeconds` should you have one set.
> [...]

_Originally posted by @tzappia in [#4884](https://github.com/firebase/firebase-tools/issues/4884#issuecomment-2319047298)_

In my own testing, I could confirm that `scheduleDelaySeconds` was not respected.

It is interesting that `retryConfig.minBackoffSeconds` in the queue setup _is_ respected however.


Debug logs
I don't want to drop my full real application logs here, because I can't easily scan it for potentially sensitive data, but I'll try to extract relevant bits:

My queue handler method and exported `onTaskDispatched` return value are both called `checkContactCreation`.

When my queue listener is described:
```
"checkContactCreation":{"platform":"gcfv2","availableMemoryMb":null,"timeoutSeconds":null,"minInstances":null,"maxInstances":null,"ingressSettings":null,"concurrency":1,"serviceAccountEmail":null,"vpc":null,"cpu":1,"region":["europe-west1"],"labels":{},"taskQueueTrigger":{"retryConfig":{"maxAttempts":15,"maxDoublings":null,"maxBackoffSeconds":null,"maxRetrySeconds":null,"minBackoffSeconds":60},"rateLimits":{"maxConcurrentDispatches":6,"maxDispatchesPerSecond":null}},"entryPoint":"checkContactCreation"},"
```
When it is created:
```
[2025-02-25T16:48:06.511Z] addTaskQueueTrigger {"retryConfig":{"maxAttempts":15,"maxRetrySeconds":null,"maxBackoffSeconds":null,"maxDoublings":null,"minBackoffSeconds":60},"rateLimits":{"maxConcurrentDispatches":6,"maxDispatchesPerSecond":null}}
[2025-02-25T16:48:06.511Z] >>> [apiv2][query] POST http://127.0.0.1:9499/projects/demo-test/locations/europe-west1/queues/checkContactCreation [none]
[2025-02-25T16:48:06.511Z] >>> [apiv2][body] POST http://127.0.0.1:9499/projects/demo-test/locations/europe-west1/queues/checkContactCreation {"retryConfig":{"maxAttempts":15,"maxRetrySeconds":null,"maxBackoffSeconds":null,"maxDoublings":null,"minBackoffSeconds":60},"rateLimits":{"maxConcurrentDispatches":6,"maxDispatchesPerSecond":null},"defaultUri":"http://127.0.0.1:5001/demo-test/europe-west1/checkContactCreation"}
✔ tasks: Created queue with key: queue:demo-test-europe-west1-checkContactCreation {"metadata":{"emulator":{"name":"tasks"},"message":"Created queue with key: queue:demo-test-europe-west1-checkContactCreation"}}
[2025-02-25T16:48:06.519Z] Created task queue queue:demo-test-europe-west1-checkContactCreation with configuration: {"retryConfig":{"maxAttempts":15,"maxRetrySeconds":null,"maxBackoffSeconds":3600,"maxDoublings":16,"minBackoffSeconds":60},"rateLimits":{"maxConcurrentDispatches":6,"maxDispatchesPerSecond":500},"timeoutSeconds":10,"retry":false,"defaultUri":"http://127.0.0.1:5001/demo-test/europe-west1/checkContactCreation"} {"metadata":{"emulator":{"name":"tasks"},"message":"Created task queue queue:demo-test-europe-west1-checkContactCreation with configuration: {\"retryConfig\":{\"maxAttempts\":15,\"maxRetrySeconds\":null,\"maxBackoffSeconds\":3600,\"maxDoublings\":16,\"minBackoffSeconds\":60},\"rateLimits\":{\"maxConcurrentDispatches\":6,\"maxDispatchesPerSecond\":500},\"timeoutSeconds\":10,\"retry\":false,\"defaultUri\":\"http://127.0.0.1:5001/demo-test/europe-west1/checkContactCreation\"}"}}
[2025-02-25T16:48:06.521Z] <<< [apiv2][status] POST http://127.0.0.1:9499/projects/demo-test/locations/europe-west1/queues/checkContactCreation 200
[2025-02-25T16:48:06.521Z] <<< [apiv2][body] POST http://127.0.0.1:9499/projects/demo-test/locations/europe-west1/queues/checkContactCreation {"taskQueueConfig":{"retryConfig":{"maxAttempts":15,"maxRetrySeconds":null,"maxBackoffSeconds":3600,"maxDoublings":16,"minBackoffSeconds":60},"rateLimits":{"maxConcurrentDispatches":6,"maxDispatchesPerSecond":500},"timeoutSeconds":10,"retry":false,"defaultUri":"http://127.0.0.1:5001/demo-test/europe-west1/checkContactCreation"}}
✔ functions[europe-west1-checkContactCreation]: http function initialized (http://127.0.0.1:5001/demo-test/europe-west1/checkContactCreation). {"metadata":{"emulator":{"name":"functions"},"message":"http function initialized (http://127.0.0.1:5001/demo-test/europe-west1/checkContactCreation)."}}
[2025-02-25T16:48:06.521Z] addTaskQueueTrigger {"retryConfig":{"maxAttempts":1,"maxRetrySeconds":null,"maxBackoffSeconds":null,"maxDoublings":null,"minBackoffSeconds":null},"rateLimits":{"maxConcurrentDispatches":null,"maxDispatchesPerSecond":null}}
```

When an enqueue happens:
```
⚠ Google API requested!
- URL: "https://oauth2.googleapis.com/token"
- Be careful, this may be a production service. {"metadata":{"emulator":{"name":"functions"},"function":{"name":"europe-west1-onUserPrivateWriteV2"},"extension":{},"message":"Google API requested!\n - URL: \"https://oauth2.googleapis.com/token\"\n - Be careful, this may be a production service."}}
[2025-02-25T16:48:13.213Z] Enqueueing task /projects/demo-test/locations/europe-west1/queues/checkContactCreation/tasks/1815625063765355 onto queue:demo-test-europe-west1-checkContactCreation {"metadata":{"emulator":{"name":"tasks"},"message":"Enqueueing task /projects/demo-test/locations/europe-west1/queues/checkContactCreation/tasks/1815625063765355 onto queue:demo-test-europe-west1-checkContactCreation"}}
```

When it is picked up?
```
[2025-02-25T16:48:14.222Z] [work-queue] {"queuedWork":["/demo-test/europe-west1/checkContactCreation-2025-02-25T16:48:14.222Z"],"queueLength":1,"runningWork":["/functions/projects/demo-test/triggers/europe-west1-onUserPrivateWriteV2-0-2025-02-25T16:48:13.217Z"],"workRunningCount":1}
[2025-02-25T16:48:14.223Z] [work-queue] {"queuedWork":[],"queueLength":0,"runningWork":["/functions/projects/demo-test/triggers/europe-west1-onUserPrivateWriteV2-0-2025-02-25T16:48:13.217Z","/demo-test/europe-west1/checkContactCreation-2025-02-25T16:48:14.222Z"],"workRunningCount":2}
[2025-02-25T16:48:14.223Z] Accepted request POST /demo-test/europe-west1/checkContactCreation --> europe-west1-checkContactCreation
[2025-02-25T16:48:14.224Z] [functions] Runtime ready! Sending request! {"metadata":{"emulator":{"name":"functions"},"message":"[functions] Runtime ready! Sending request!"}}
[2025-02-25T16:48:14.224Z] [functions] Got req.url=/demo-test/europe-west1/checkContactCreation, mapping to path=/ {"metadata":{"emulator":{"name":"functions"},"message":"[functions] Got req.url=/demo-test/europe-west1/checkContactCreation, mapping to path=/"}}
```

When the handler first logs something (that my code logs):
```
[2025-02-25T16:48:14.938Z] [runtime-status] [36280] Functions runtime initialized. {"cwd":"/Users/thor/Code/slowby/welcometomygarden/api","node_version":"20.11.0"} {"metadata":{"emulator":{"name":"functions"},"function":{"name":"europe-west1-checkContactCreation"},"extension":{},"message":"[runtime-status] [36280] Functions runtime initialized. {\"cwd\":\"/Users/thor/Code/slowby/welcometomygarden/api\",\"node_version\":\"20.11.0\"}"}}
[2025-02-25T16:48:14.939Z] [runtime-status] [36280] Listening to port: /var/folders/0m/d2znfz1n41d599lzrhwyzfwh0000gn/T/fire_emu_423b906c9240954b.sock {"metadata":{"emulator":{"name":"functions"},"function":{"name":"europe-west1-checkContactCreation"},"extension":{},"message":"[runtime-status] [36280] Listening to port: /var/folders/0m/d2znfz1n41d599lzrhwyzfwh0000gn/T/fire_emu_423b906c9240954b.sock"}}
[2025-02-25T16:48:14.939Z] [runtime-status] [36279] Functions runtime initialized. {"cwd":"/Users/thor/Code/slowby/welcometomygarden/api","node_version":"20.11.0"} {"metadata":{"emulator":{"name":"functions"},"function":{"name":"europe-west1-checkContactCreation"},"extension":{},"message":"[runtime-status] [36279] Functions runtime initialized. {\"cwd\":\"/Users/thor/Code/slowby/welcometomygarden/api\",\"node_version\":\"20.11.0\"}"}}
[2025-02-25T16:48:14.941Z] [runtime-status] [36279] Listening to port: /var/folders/0m/d2znfz1n41d599lzrhwyzfwh0000gn/T/fire_emu_25a84222f4832042.sock {"metadata":{"emulator":{"name":"functions"},"function":{"name":"europe-west1-checkContactCreation"},"extension":{},"message":"[runtime-status] [36279] Listening to port: /var/folders/0m/d2znfz1n41d599lzrhwyzfwh0000gn/T/fire_emu_25a84222f4832042.sock"}}
[2025-02-25T16:48:14.978Z] [worker-europe-west1-checkContactCreation-4988a5a9-8cf2-4b51-9eda-3c1ade3d3b83]: IDLE {"metadata":{"emulator":{"name":"functions"},"function":{"name":"europe-west1-checkContactCreation"},"extension":{},"message":"[worker-europe-west1-checkContactCreation-4988a5a9-8cf2-4b51-9eda-3c1ade3d3b83]: IDLE"}}
[2025-02-25T16:48:14.978Z] [worker-pool] submitRequest(triggerId=europe-west1-checkContactCreation) {"metadata":{"emulator":{"name":"functions"},"message":"[worker-pool] submitRequest(triggerId=europe-west1-checkContactCreation)"}}
i functions: Beginning execution of "europe-west1-checkContactCreation" {"metadata":{"emulator":{"name":"functions"},"function":{"name":"europe-west1-checkContactCreation"},"extension":{},"message":"Beginning execution of \"europe-west1-checkContactCreation\""}}
[2025-02-25T16:48:14.978Z] [worker-europe-west1-checkContactCreation-4988a5a9-8cf2-4b51-9eda-3c1ade3d3b83]: BUSY {"metadata":{"emulator":{"name":"functions"},"function":{"name":"europe-west1-checkContactCreation"},"extension":{},"message":"[worker-europe-west1-checkContactCreation-4988a5a9-8cf2-4b51-9eda-3c1ade3d3b83]: BUSY"}}
> {"severity":"INFO","message":"Checking SG contact creation of uid UfdkoFg14zmjNRLjV7KdfY8AQoRC / jobId e1ed89d0-1803-4a63-8428-5c321bbe90c7 on creation attempt 1, check no. 1"} {"user":{"severity":"INFO","message":"Checking SG contact creation of uid UfdkoFg14zmjNRLjV7KdfY8AQoRC / jobId e1ed89d0-1803-4a63-8428-5c321bbe90c7 on creation attempt 1, check no. 1"},"metadata":{"emulator":{"name":"functions"},"function":{"name":"europe-west1-checkContactCreation"},"extension":{},"message":"> {\"severity\":\"INFO\",\"message\":\"Checking SG contact creation of uid UfdkoFg14zmjNRLjV7KdfY8AQoRC / jobId e1ed89d0-1803-4a63-8428-5c321bbe90c7 on creation attempt 1, check no. 1\"}"}}
```

In the logs above, notice the difference between the timestamps of the first enqueue, and the first log from the handler:
```
[2025-02-25T16:48:13.213Z]
[2025-02-25T16:48:14.978Z]
```

They should be at least 40 second apart, but they are ~1.7 seconds apart here.

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.