Worker timeout

[robswc]

Happens when /webhook request can't be processed in time. Can be from various causes. Investigating...

[tlnet1981]

You did a great Tool !!!

But this timeout thing is really bad - any workaround for this maybe?

[robswc]

Hey! So there could be several reasons for this, depending on the logic of the run method. Are you able to paste in (omitting any personal information) your run method? I can take a look at it! @tlnet1981

The issue is more or less:

Signal Gets to Action/Event
Stuff is being done
Stuff doesn't finish in time
Time out

The "stuff" could be stuck somewhere. I will be adding a "timeout" option to increase the default timeout time to something more than 30 seconds. (usually more than this amount of time indicates an issue though)

[tlnet1981]

Hi!
thanks for all that :)

I found the same workaround: in line 62 i added a timeout to the server with 1 second:

run(f'gunicorn --bind {host}:{port} --timeout 1 wsgi:app'.split(' '))

As i set the timeout to 600, it wouldnt time out again, but the stuckness every about 30 seconds (meaning taking no new webhooks) remained.

with 1 second, it reboots often but is therefore more available because stuckness is limited to one second. doesnt solve the root cause though..

[robswc]

Hmm, in that case, I may try to change actions to be run with async. This should solve any timeout issues going forward!

You can "emulate" this by using multi threading for now if you wish. Something like this:
https://superfastpython.com/run-function-in-new-thread/

Are you able to locate where in your run method the script is taking a long time?

[tlnet1981]

I am totally not able to locate that :D
I can only tell you that the webhook logic functions very fast and well, until after about 30 seconds it doesn react anymore at all until it reboots or some time passes by and it will eventually react again

[robswc]

@tlnet1981 interesting!
Well, if its possible to paste your run method here (without any of your personal details) I can take a look at it and see if there's anything we can do to fix it :)

It's also ok if you're fine with how its working now.

[tlnet1981]

@robswc , sorry didnt understand you right - you mean the code of my "action" - sure no problem. I basically just pump it to a redis channel, and other stuff is picking it up from there:

`class test(Action):
def init(self):
super().init()

def run(self, *args, **kwargs):
    super().run(*args, **kwargs)  # this is required
    data = self.validate_data()  # always get data from webhook by calling this method!
    print('Data from webhook:', data)
    r = redis.Redis(host='localhost', port=6379, db=0)
    r.publish('tradingview', json.dumps(data))
    print(self.name, '---> action has run!')`

you mean the redis server is causing the delays? ...but the worker timeout or stuckness appears also during times when no webhook comes an, therefore no action is triggered.

[tlnet1981]

here you can see, no action triggered but reboots all the time (1 second timeout)

...pretty exactly every 1 minute

2022-10-13 02:06:33,869 [MainThread ] [INFO ] Registering action ---> test
2022-10-13 02:06:33,948 [MainThread ] [DEBUG] Imported action module ---> test
2022-10-13 02:06:33,948 [MainThread ] [INFO ] ACTION REGISTERED ---> test
2022-10-13 02:06:33,948 [MainThread ] [INFO ] Action "test" registered successfully!
2022-10-13 02:06:33,948 [MainThread ] [INFO ] Registering event ---> WebhookReceived
2022-10-13 02:06:33,992 [MainThread ] [DEBUG] Imported event module ---> webhook_received
2022-10-13 02:06:33,993 [MainThread ] [INFO ] Event "WebhookReceived" registered successfully!
2022-10-13 02:06:33,993 [MainThread ] [INFO ] Link "test -> WebhookReceived" registered successfully!
[2022-10-13 02:07:38 +0200] [23789] [CRITICAL] WORKER TIMEOUT (pid:24885)
[2022-10-13 02:07:38 +0200] [24885] [INFO] Worker exiting (pid: 24885)
[2022-10-13 02:07:38 +0200] [24886] [INFO] Booting worker with pid: 24886
2022-10-13 02:07:39,279 [MainThread ] [INFO ] Registering action ---> test
2022-10-13 02:07:39,353 [MainThread ] [DEBUG] Imported action module ---> test
2022-10-13 02:07:39,353 [MainThread ] [INFO ] ACTION REGISTERED ---> test
2022-10-13 02:07:39,353 [MainThread ] [INFO ] Action "test" registered successfully!
2022-10-13 02:07:39,353 [MainThread ] [INFO ] Registering event ---> WebhookReceived
2022-10-13 02:07:39,395 [MainThread ] [DEBUG] Imported event module ---> webhook_received
2022-10-13 02:07:39,395 [MainThread ] [INFO ] Event "WebhookReceived" registered successfully!
2022-10-13 02:07:39,395 [MainThread ] [INFO ] Link "test -> WebhookReceived" registered successfully!
[2022-10-13 02:08:42 +0200] [23789] [CRITICAL] WORKER TIMEOUT (pid:24886)
[2022-10-13 02:08:42 +0200] [24886] [INFO] Worker exiting (pid: 24886)
[2022-10-13 02:08:42 +0200] [24887] [INFO] Booting worker with pid: 24887
2022-10-13 02:08:43,677 [MainThread ] [INFO ] Registering action ---> test
2022-10-13 02:08:43,753 [MainThread ] [DEBUG] Imported action module ---> test
2022-10-13 02:08:43,753 [MainThread ] [INFO ] ACTION REGISTERED ---> test
2022-10-13 02:08:43,753 [MainThread ] [INFO ] Action "test" registered successfully!
2022-10-13 02:08:43,753 [MainThread ] [INFO ] Registering event ---> WebhookReceived
2022-10-13 02:08:43,794 [MainThread ] [DEBUG] Imported event module ---> webhook_received
2022-10-13 02:08:43,794 [MainThread ] [INFO ] Event "WebhookReceived" registered successfully!
2022-10-13 02:08:43,794 [MainThread ] [INFO ] Link "test -> WebhookReceived" registered successfully!
[2022-10-13 02:09:48 +0200] [23789] [CRITICAL] WORKER TIMEOUT (pid:24887)
[2022-10-13 02:09:48 +0200] [24887] [INFO] Worker exiting (pid: 24887)
[2022-10-13 02:09:48 +0200] [24888] [INFO] Booting worker with pid: 24888
2022-10-13 02:09:49,252 [MainThread ] [INFO ] Registering action ---> test
2022-10-13 02:09:49,331 [MainThread ] [DEBUG] Imported action module ---> test
2022-10-13 02:09:49,331 [MainThread ] [INFO ] ACTION REGISTERED ---> test
2022-10-13 02:09:49,331 [MainThread ] [INFO ] Action "test" registered successfully!
2022-10-13 02:09:49,331 [MainThread ] [INFO ] Registering event ---> WebhookReceived
2022-10-13 02:09:49,381 [MainThread ] [DEBUG] Imported event module ---> webhook_received
2022-10-13 02:09:49,381 [MainThread ] [INFO ] Event "WebhookReceived" registered successfully!
2022-10-13 02:09:49,381 [MainThread ] [INFO ] Link "test -> WebhookReceived" registered successfully!
[2022-10-13 02:10:53 +0200] [23789] [CRITICAL] WORKER TIMEOUT (pid:24888)
[2022-10-13 02:10:53 +0200] [24888] [INFO] Worker exiting (pid: 24888)
[2022-10-13 02:10:53 +0200] [24889] [INFO] Booting worker with pid: 24889
2022-10-13 02:10:53,948 [MainThread ] [INFO ] Registering action ---> test
2022-10-13 02:10:54,025 [MainThread ] [DEBUG] Imported action module ---> test
2022-10-13 02:10:54,026 [MainThread ] [INFO ] ACTION REGISTERED ---> test
2022-10-13 02:10:54,026 [MainThread ] [INFO ] Action "test" registered successfully!
2022-10-13 02:10:54,026 [MainThread ] [INFO ] Registering event ---> WebhookReceived
2022-10-13 02:10:54,064 [MainThread ] [DEBUG] Imported event module ---> webhook_received
2022-10-13 02:10:54,064 [MainThread ] [INFO ] Event "WebhookReceived" registered successfully!
2022-10-13 02:10:54,064 [MainThread ] [INFO ] Link "test -> WebhookReceived" registered successfully!
[2022-10-13 02:11:58 +0200] [23789] [CRITICAL] WORKER TIMEOUT (pid:24889)
[2022-10-13 02:11:58 +0200] [24889] [INFO] Worker exiting (pid: 24889)
[2022-10-13 02:11:58 +0200] [24890] [INFO] Booting worker with pid: 24890

[bashor4life]

@robswc Is there an update on this issue? I saw an async commit but 1.0.2 did not solve the problem.

Here is my log without any changes on my side:

GUI` is set to [CLOSED] - it will be served at the path /?guiKey=<unique_key>
View GUI dashboard here: http://0.0.0.0:5000?guiKey=
To run the GUI in [OPEN] mode (for development purposes only), run the following command: tvwb start --open-gui
To learn more about GUI modes, visit: #43
Close server with Ctrl+C in terminal.
[2024-03-11 14:17:22 +0000] [7] [INFO] Starting gunicorn 20.1.0
[2024-03-11 14:17:22 +0000] [7] [INFO] Listening at: http://0.0.0.0:5000 (7)
[2024-03-11 14:17:22 +0000] [7] [INFO] Using worker: sync
[2024-03-11 14:17:22 +0000] [8] [INFO] Booting worker with pid: 8
2024-03-11 14:17:22,946 [MainThread ] [INFO ] Registering action ---> PrintData
2024-03-11 14:17:22,948 [MainThread ] [DEBUG] Imported action module ---> print_data
2024-03-11 14:17:22,948 [MainThread ] [INFO ] ACTION REGISTERED ---> PrintData
2024-03-11 14:17:22,948 [MainThread ] [INFO ] Action "PrintData" registered successfully!
2024-03-11 14:17:22,948 [MainThread ] [INFO ] Registering action ---> AsyncDemo
2024-03-11 14:17:22,950 [MainThread ] [DEBUG] Imported action module ---> async_demo
2024-03-11 14:17:22,950 [MainThread ] [INFO ] ACTION REGISTERED ---> AsyncDemo
2024-03-11 14:17:22,950 [MainThread ] [INFO ] Action "AsyncDemo" registered successfully!
2024-03-11 14:17:22,950 [MainThread ] [INFO ] Registering event ---> WebhookReceived
2024-03-11 14:17:22,951 [MainThread ] [DEBUG] Imported event module ---> webhook_received
2024-03-11 14:17:22,951 [MainThread ] [INFO ] Event "WebhookReceived" registered successfully!
2024-03-11 14:17:22,951 [MainThread ] [INFO ] Link "PrintData -> WebhookReceived" registered successfully!
2024-03-11 14:17:22,951 [MainThread ] [INFO ] Link "AsyncDemo -> WebhookReceived" registered successfully!
[2024-03-11 14:17:56 +0000] [7] [CRITICAL] WORKER TIMEOUT (pid:8)
[2024-03-11 14:17:56 +0000] [8] [INFO] Worker exiting (pid: 8)
[2024-03-11 14:17:56 +0000] [9] [INFO] Booting worker with pid: 9
2024-03-11 14:17:57,164 [MainThread ] [INFO ] Registering action ---> PrintData
2024-03-11 14:17:57,165 [MainThread ] [DEBUG] Imported action module ---> print_data
2024-03-11 14:17:57,165 [MainThread ] [INFO ] ACTION REGISTERED ---> PrintData
2024-03-11 14:17:57,165 [MainThread ] [INFO ] Action "PrintData" registered successfully!
2024-03-11 14:17:57,165 [MainThread ] [INFO ] Registering action ---> AsyncDemo
2024-03-11 14:17:57,166 [MainThread ] [DEBUG] Imported action module ---> async_demo
2024-03-11 14:17:57,166 [MainThread ] [INFO ] ACTION REGISTERED ---> AsyncDemo
2024-03-11 14:17:57,166 [MainThread ] [INFO ] Action "AsyncDemo" registered successfully!
2024-03-11 14:17:57,166 [MainThread ] [INFO ] Registering event ---> WebhookReceived
2024-03-11 14:17:57,167 [MainThread ] [DEBUG] Imported event module ---> webhook_received
2024-03-11 14:17:57,167 [MainThread ] [INFO ] Event "WebhookReceived" registered successfully!
2024-03-11 14:17:57,167 [MainThread ] [INFO ] Link "PrintData -> WebhookReceived" registered successfully!
2024-03-11 14:17:57,167 [MainThread ] [INFO ] Link "AsyncDemo -> WebhookReceived" registered successfully!