[🐛 BUG]: Ghost workers (pollers) in roadrunner version 2.7.5 #163
Closed
Description
No duplicates 🥲.
- I have searched for a similar issue in our bug tracker and didn't find any solutions.
What happened?
Hey guys 👋,
With version 2.7.5 I see duplicated or ghost workers in temporal. This causes temporal activities to fail with errors "ActivityNotRegisteredError: unable to find activityType=getTransactionOptions. Supported types: []" These "ghosts" workers are actually empty. Temporal tries a few times and stumbles upon the correct worker and everything is fine. Still, the workflows take a little longer than they should because of this 😀
2.7.4 doesn't cause this issue.
A few images from temporal page for an example:
2.7.4:
2.7.5:
Version
Roadrunner 2.7.5
Temporal 1.13.0
Relevant log output
Console output of 2.7.5:
2022-02-05T19:44:55.522Z INFO temporal connected to temporal server {"address": "temporal:7233"}
2022-02-05T19:44:55.925Z DEBUG server worker is allocated {"pid": 4541, "internal_event_name": "EventWorkerConstruct"}
2022-02-05T19:44:55.932Z DEBUG server worker is allocated {"pid": 4542, "internal_event_name": "EventWorkerConstruct"}
2022-02-05T19:44:55.932Z DEBUG temporal start fetching worker info for the activity
2022-02-05T19:44:55.932Z DEBUG temporal outgoing message {"data": "\u001b[32m\n\"\u0012\rGetWorkerInfo\u001a\u0011{\"rr_version\":\"\"} {}\u001b[0m"}
2022-02-05T19:44:56.066Z DEBUG temporal received message {"data": "\u001b[93m\n\ufffd\u0004*\ufffd\u0004\n\ufffd\u0004\n\u0016\n\u0008encoding\u0012\njson/plain\u0012\ufffd\u0004{\"TaskQueue\":\"events_hub_bridge_command_bus\",\"Options\":{\"MaxConcurrentActivityExecutionSize\":0,\"WorkerActivitiesPerSecond\":0.0,\"MaxConcurrentLocalActivityExecutionSize\":0,\"WorkerLocalActivitiesPerSecond\":0.0,\"TaskQueueActivitiesPerSecond\":0.0,\"MaxConcurrentActivityTaskPollers\":0,\"MaxConcurrentWorkflowTaskExecutionSize\":0,\"MaxConcurrentWorkflowTaskPollers\":0,\"StickyScheduleToStartTimeout\":null,\"WorkerStopTimeout\":null,\"EnableSessionWorker\":false,\"SessionResourceID\":null,\"MaxConcurrentSessionExecutionSize\":1000},\"Workflows\":[],\"Activities\":[{\"Name\":\"SendNotificationCommand\"}]}\u001b[0m"}
2022-02-05T19:44:56.066Z DEBUG temporal activity registered {"name": "SendNotificationCommand"}
2022-02-05T19:44:56.150Z INFO temporal Started Worker {"Namespace": "default", "TaskQueue": "events_hub_bridge_command_bus", "WorkerID": "events_hub_bridge_command_bus:ac908a7f-e885-4f1a-b657-6fca87ea2b6e"}
2022-02-05T19:44:56.150Z DEBUG temporal activity workers started {"num_workers": 1}
2022-02-05T19:44:56.457Z DEBUG server worker is allocated {"pid": 4563, "internal_event_name": "EventWorkerConstruct"}
2022-02-05T19:44:56.457Z DEBUG temporal outgoing message {"data": "\u001b[32m\n\"\u0012\rGetWorkerInfo\u001a\u0011{\"rr_version\":\"\"} {}\u001b[0m"}
2022-02-05T19:44:56.581Z DEBUG temporal received message {"data": "\u001b[93m\n\ufffd\u0004*\ufffd\u0004\n\ufffd\u0004\n\u0016\n\u0008encoding\u0012\njson/plain\u0012\ufffd\u0004{\"TaskQueue\":\"events_hub_bridge_command_bus\",\"Options\":{\"MaxConcurrentActivityExecutionSize\":0,\"WorkerActivitiesPerSecond\":0.0,\"MaxConcurrentLocalActivityExecutionSize\":0,\"WorkerLocalActivitiesPerSecond\":0.0,\"TaskQueueActivitiesPerSecond\":0.0,\"MaxConcurrentActivityTaskPollers\":0,\"MaxConcurrentWorkflowTaskExecutionSize\":0,\"MaxConcurrentWorkflowTaskPollers\":0,\"StickyScheduleToStartTimeout\":null,\"WorkerStopTimeout\":null,\"EnableSessionWorker\":false,\"SessionResourceID\":null,\"MaxConcurrentSessionExecutionSize\":1000},\"Workflows\":[],\"Activities\":[{\"Name\":\"SendNotificationCommand\"}]}\u001b[0m"}
2022-02-05T19:44:56.581Z DEBUG temporal worker info {"taskqueue": "events_hub_bridge_command_bus", "options": {"MaxConcurrentActivityExecutionSize":0,"WorkerActivitiesPerSecond":0,"MaxConcurrentLocalActivityExecutionSize":0,"WorkerLocalActivitiesPerSecond":0,"TaskQueueActivitiesPerSecond":0,"MaxConcurrentActivityTaskPollers":0,"MaxConcurrentWorkflowTaskExecutionSize":0,"MaxConcurrentWorkflowTaskPollers":0,"EnableLoggingInReplay":false,"DisableStickyExecution":false,"StickyScheduleToStartTimeout":0,"BackgroundActivityContext":null,"WorkflowPanicPolicy":0,"WorkerStopTimeout":0,"EnableSessionWorker":false,"MaxConcurrentSessionExecutionSize":1000,"DisableWorkflowWorker":false,"LocalActivityWorkerOnly":false,"Identity":"","DeadlockDetectionTimeout":0,"MaxHeartbeatThrottleInterval":0,"DefaultHeartbeatThrottleInterval":0,"Interceptors":null}}
2022-02-05T19:44:56.584Z INFO temporal Started Worker {"Namespace": "default", "TaskQueue": "events_hub_bridge_command_bus", "WorkerID": "events_hub_bridge_command_bus:48a25841-265a-4767-996a-070f12228277"}
2022-02-05T19:44:56.586Z INFO temporal Started Worker {"Namespace": "default", "TaskQueue": "events_hub_bridge_command_bus", "WorkerID": "events_hub_bridge_command_bus:ac908a7f-e885-4f1a-b657-6fca87ea2b6e"}
2022-02-05T19:44:56.586Z DEBUG rpc plugin was started {"address": "tcp://127.0.0.1:6001", "list of the plugins with RPC methods:": ["informer", "resetter", "temporal"]}
[INFO] RoadRunner server started; version: 2.7.5, buildtime: 2022-02-04T22:53:48+0000
Console output of 2.7.4:
2022-02-05T19:42:54.646Z INFO temporal connected to temporal server {"address": "temporal:7233"}
2022-02-05T19:42:55.015Z DEBUG server worker is allocated {"pid": 4488, "internal_event_name": "EventWorkerConstruct"}
2022-02-05T19:42:55.018Z DEBUG server worker is allocated {"pid": 4487, "internal_event_name": "EventWorkerConstruct"}
2022-02-05T19:42:55.018Z DEBUG temporal start fetching worker info for the activity
2022-02-05T19:42:55.019Z DEBUG temporal outgoing message {"data": "\u001b[32m\n\"\u0012\rGetWorkerInfo\u001a\u0011{\"rr_version\":\"\"} {}\u001b[0m"}
2022-02-05T19:42:55.153Z DEBUG temporal received message {"data": "\u001b[93m\n\ufffd\u0004*\ufffd\u0004\n\ufffd\u0004\n\u0016\n\u0008encoding\u0012\njson/plain\u0012\ufffd\u0004{\"TaskQueue\":\"events_hub_bridge_command_bus\",\"Options\":{\"MaxConcurrentActivityExecutionSize\":0,\"WorkerActivitiesPerSecond\":0.0,\"MaxConcurrentLocalActivityExecutionSize\":0,\"WorkerLocalActivitiesPerSecond\":0.0,\"TaskQueueActivitiesPerSecond\":0.0,\"MaxConcurrentActivityTaskPollers\":0,\"MaxConcurrentWorkflowTaskExecutionSize\":0,\"MaxConcurrentWorkflowTaskPollers\":0,\"StickyScheduleToStartTimeout\":null,\"WorkerStopTimeout\":null,\"EnableSessionWorker\":false,\"SessionResourceID\":null,\"MaxConcurrentSessionExecutionSize\":1000},\"Workflows\":[],\"Activities\":[{\"Name\":\"SendNotificationCommand\"}]}\u001b[0m"}
2022-02-05T19:42:55.153Z DEBUG temporal activity registered {"name": "SendNotificationCommand"}
2022-02-05T19:42:55.240Z DEBUG temporal No workflows registered. Skipping workflow worker start {"Namespace": "default", "TaskQueue": "events_hub_bridge_command_bus", "WorkerID": "events_hub_bridge_command_bus:440b9bf1-1b20-44cc-95e6-f34ea77b5715"}
2022-02-05T19:42:55.244Z INFO temporal Started Worker {"Namespace": "default", "TaskQueue": "events_hub_bridge_command_bus", "WorkerID": "events_hub_bridge_command_bus:440b9bf1-1b20-44cc-95e6-f34ea77b5715"}
2022-02-05T19:42:55.244Z DEBUG temporal activity workers started {"num_workers": 1}
2022-02-05T19:42:55.625Z DEBUG server worker is allocated {"pid": 4510, "internal_event_name": "EventWorkerConstruct"}
2022-02-05T19:42:55.626Z DEBUG temporal outgoing message {"data": "\u001b[32m\n\"\u0012\rGetWorkerInfo\u001a\u0011{\"rr_version\":\"\"} {}\u001b[0m"}
2022-02-05T19:42:55.721Z DEBUG temporal received message {"data": "\u001b[93m\n\ufffd\u0004*\ufffd\u0004\n\ufffd\u0004\n\u0016\n\u0008encoding\u0012\njson/plain\u0012\ufffd\u0004{\"TaskQueue\":\"events_hub_bridge_command_bus\",\"Options\":{\"MaxConcurrentActivityExecutionSize\":0,\"WorkerActivitiesPerSecond\":0.0,\"MaxConcurrentLocalActivityExecutionSize\":0,\"WorkerLocalActivitiesPerSecond\":0.0,\"TaskQueueActivitiesPerSecond\":0.0,\"MaxConcurrentActivityTaskPollers\":0,\"MaxConcurrentWorkflowTaskExecutionSize\":0,\"MaxConcurrentWorkflowTaskPollers\":0,\"StickyScheduleToStartTimeout\":null,\"WorkerStopTimeout\":null,\"EnableSessionWorker\":false,\"SessionResourceID\":null,\"MaxConcurrentSessionExecutionSize\":1000},\"Workflows\":[],\"Activities\":[{\"Name\":\"SendNotificationCommand\"}]}\u001b[0m"}
2022-02-05T19:42:55.721Z DEBUG temporal worker info {"taskqueue": "events_hub_bridge_command_bus", "options": {"MaxConcurrentActivityExecutionSize":0,"WorkerActivitiesPerSecond":0,"MaxConcurrentLocalActivityExecutionSize":0,"WorkerLocalActivitiesPerSecond":0,"TaskQueueActivitiesPerSecond":0,"MaxConcurrentActivityTaskPollers":0,"MaxConcurrentWorkflowTaskExecutionSize":0,"MaxConcurrentWorkflowTaskPollers":0,"EnableLoggingInReplay":false,"DisableStickyExecution":false,"StickyScheduleToStartTimeout":0,"BackgroundActivityContext":null,"WorkflowPanicPolicy":0,"WorkerStopTimeout":0,"EnableSessionWorker":false,"MaxConcurrentSessionExecutionSize":1000,"LocalActivityWorkerOnly":false,"Identity":"","DeadlockDetectionTimeout":0,"Interceptors":null}}
2022-02-05T19:42:55.722Z DEBUG temporal No workflows registered. Skipping workflow worker start {"Namespace": "default", "TaskQueue": "events_hub_bridge_command_bus", "WorkerID": "events_hub_bridge_command_bus:2d87a2ae-a8a7-4d3e-ae31-d4389af707c0"}
2022-02-05T19:42:55.722Z DEBUG temporal No activities registered. Skipping activity worker start {"Namespace": "default", "TaskQueue": "events_hub_bridge_command_bus", "WorkerID": "events_hub_bridge_command_bus:2d87a2ae-a8a7-4d3e-ae31-d4389af707c0"}
2022-02-05T19:42:55.722Z INFO temporal Started Worker {"Namespace": "default", "TaskQueue": "events_hub_bridge_command_bus", "WorkerID": "events_hub_bridge_command_bus:2d87a2ae-a8a7-4d3e-ae31-d4389af707c0"}
2022-02-05T19:42:55.722Z DEBUG temporal No workflows registered. Skipping workflow worker start {"Namespace": "default", "TaskQueue": "events_hub_bridge_command_bus", "WorkerID": "events_hub_bridge_command_bus:440b9bf1-1b20-44cc-95e6-f34ea77b5715"}
2022-02-05T19:42:55.724Z INFO temporal Started Worker {"Namespace": "default", "TaskQueue": "events_hub_bridge_command_bus", "WorkerID": "events_hub_bridge_command_bus:440b9bf1-1b20-44cc-95e6-f34ea77b5715"}
2022-02-05T19:42:55.724Z DEBUG rpc plugin was started {"address": "tcp://127.0.0.1:6001", "list of the plugins with RPC methods:": ["resetter", "temporal", "informer"]}
[INFO] RoadRunner server started; version: 2.7.4, buildtime: 2022-01-21T23:03:32+0000