search

golemfactory / yagna

An open platform and marketplace for distributed computations
GNU General Public License v3.0
399 stars 61 forks source link

Providers fail to create activity in time #1899

Open mfranciszkiewicz opened 2 years ago

mfranciszkiewicz commented 2 years ago

This behavior can be currently observed on hybrid devnet but was also visible during polygon outage.

In yapapi, this issue manifests as in the following example:

[2022-03-25T14:59:42.172+0100 DEBUG yapapi.summary] [Job 1] Worker started for provider 'witek.h'
[2022-03-25T14:59:42.706+0100 DEBUG ya_payment.rest] request: {'method': 'GET', 'url': 'http://127.0.0.1:7465/payment-api/v1/debitNoteEvents?afterTimestamp=2022-03-25T13%3A59%3A24.038000%2B00%3A00', 'timeout': 300, 'headers': {'Accept': 'application/json', 'authorization': 'Bearer 42bd7aa0420f4dd4b1d2e459c92dab12', 'User-Agent': 'OpenAPI-Generator//python', 'Content-Type': 'application/json'}}
[2022-03-25T14:59:43.400+0100 DEBUG ya_market.rest] response body: b'[]'
[2022-03-25T14:59:44.401+0100 DEBUG ya_market.rest] request: {'method': 'GET', 'url': 'http://127.0.0.1:7465/market-api/v1/demands/c529e555f8d24e309dc95214b145c043-a9117e9f5a8cf8bdb43d01a9c79884cc861530e1904d7434ed47de60d0db120b/events?timeout=5&maxEvents=10', 'timeout': 300, 'headers': {'Accept': 'application/json', 'authorization': 'Bearer 42bd7aa0420f4dd4b1d2e459c92dab12', 'User-Agent': 'OpenAPI-Generator//python', 'Content-Type': 'application/json'}}
[2022-03-25T14:59:45.704+0100 DEBUG ya_payment.rest] response body: b'[]'
[2022-03-25T14:59:46.705+0100 DEBUG ya_payment.rest] request: {'method': 'GET', 'url': 'http://127.0.0.1:7465/payment-api/v1/invoiceEvents?afterTimestamp=2022-03-25T13%3A59%3A27.905000%2B00%3A00', 'timeout': 300, 'headers': {'Accept': 'application/json', 'authorization': 'Bearer 42bd7aa0420f4dd4b1d2e459c92dab12', 'User-Agent': 'OpenAPI-Generator//python', 'Content-Type': 'application/json'}}
[2022-03-25T14:59:47.195+0100 DEBUG ya_activity.rest] response body: b'{"message":"Timeout"}'
[2022-03-25T14:59:47.195+0100 DEBUG yapapi.events] ActivityCreateFailed(exception=ApiException(), job=Job(id=1), agreement=Agreement(id=bd38be3897e3a8c9c017c3b6c93b5746271373e1d92381a2998176093915d6b9))
Traceback (most recent call last):
  File "/home/mf/Projects/yapapi/venv/lib/python3.9/site-packages/yapapi/engine.py", line 652, in worker_task
    activity = await self.create_activity(agreement.id)
  File "/home/mf/Projects/yapapi/venv/lib/python3.9/site-packages/yapapi/engine.py", line 632, in create_activity
    return await self._activity_api.new_activity(
  File "/home/mf/Projects/yapapi/venv/lib/python3.9/site-packages/yapapi/rest/activity.py", line 47, in new_activity
    activity_id = await self._api.create_activity(agreement_id)
  File "/home/mf/Projects/yapapi/venv/lib/python3.9/site-packages/ya_activity/api_client.py", line 205, in __call_api
    raise e
  File "/home/mf/Projects/yapapi/venv/lib/python3.9/site-packages/ya_activity/api_client.py", line 193, in __call_api
    response_data = await self.request(
  File "/home/mf/Projects/yapapi/venv/lib/python3.9/site-packages/ya_activity/rest.py", line 268, in POST
    return await self.request(
  File "/home/mf/Projects/yapapi/venv/lib/python3.9/site-packages/ya_activity/rest.py", line 180, in request
    raise ApiException(http_resp=r)
ya_activity.exceptions.ApiException: (408)
Reason: Request Timeout
HTTP response headers: <CIMultiDictProxy('Content-Length': '21', 'Content-Type': 'application/json', 'Date': 'Fri, 25 Mar 2022 13:59:47 GMT')>
HTTP response body: {"message":"Timeout"}

yagna / ya-provider example:

2022-03-25 15:59:57 yagna   [2022-03-25T15:59:57.028+0100 DEBUG ya_market::db::dao::agreement_events] Event timestamp: 2022-03-25 14:59:57.027824970, type: Approved
2022-03-25 15:59:57 yagna   [2022-03-25T15:59:57.028+0100 INFO  ya_market::negotiation::provider] Agreement [P-caeb5959222c4e1b9a0feb5ba49940a2d6dfb011d6dfac08d69a539405b98c3d] approved (committed) by [0xee9b0706c981400d856611367c4f3d34984e0531].
2022-03-25 15:59:57 yagna   [2022-03-25T15:59:57.028+0100 INFO  actix_web::middleware::logger] 127.0.0.1:37152 "POST /market-api/v1/agreements/caeb5959222c4e1b9a0feb5ba49940a2d6dfb011d6dfac08d69a539405b98c3d/approve?appSessionId=witek.h-5601&timeout=10 HTTP/1.1" 204 0 "-" "-" 0.063946
2022-03-25 15:59:57 yagna   [2022-03-25T15:59:57.038+0100 INFO  actix_web::middleware::logger] 127.0.0.1:37106 "GET /market-api/v1/agreementEvents?timeout=20&afterTimestamp=2022-03-25T14%3A59%3A49.807575330%2B00%3A00&maxEvents=15&appSessionId=witek.h-5601 HTTP/1.1" 200 166 "-" "-" 7.143437
2022-03-25 15:59:57 ya-provider [2022-03-25T15:59:57.029+0100 DEBUG ya_client::web] doing GET on http://0.0.0.0:17665/market-api/v1/offers/aa58ba01f25a4005a6152a5d3f6b134e-b2be9d6c699ba5f1e2a5f6c488ec1275ed624fda44687131774514a726133bb2/events?timeout=20&maxEvents=5
2022-03-25 15:59:57 ya-provider [2022-03-25T15:59:57.038+0100 DEBUG ya_client::web] WebRequest.json(). method=GET url=http://0.0.0.0:17665/market-api/v1/agreementEvents?timeout=20&afterTimestamp=2022-03-25T14%3A59%3A49.807575330%2B00%3A00&maxEvents=15&appSessionId=witek.h-5601, resp='[{"eventDate":"2022-03-25T14:59:57.027824970Z","agreementId":"caeb5959222c4e1b9a0feb5ba49940a2d6dfb011d6dfac08d69a539405b98c3d","eventtype":"AgreementApprovedEvent"}]'
2022-03-25 15:59:57 ya-provider [2022-03-25T15:59:57.039+0100 DEBUG ya_client::web] doing GET on http://0.0.0.0:17665/market-api/v1/agreementEvents?timeout=20&afterTimestamp=2022-03-25T14%3A59%3A57.027824970%2B00%3A00&maxEvents=15&appSessionId=witek.h-5601
2022-03-25 15:59:57 yagna   [2022-03-25T15:59:57.096+0100 DEBUG ya_activity::provider::service] activity inserted: 43416f3400eb43d29af023891d2e621f
2022-03-25 15:59:57 yagna   [2022-03-25T15:59:57.096+0100 DEBUG ya_activity::dao::activity_state] waiting 750ms for activity states: [StatePair(Initialized, None), StatePair(Terminated, None)]
2022-03-25 15:59:57 yagna   [2022-03-25T15:59:57.096+0100 DEBUG ya_activity::dao::activity_state] getting activity state
2022-03-25 15:59:57 yagna   [2022-03-25T15:59:57.096+0100 DEBUG ya_activity::dao::activity_state] got state: StatePair(New, None) != [StatePair(Initialized, None), StatePair(Terminated, None)]. Waiting...
2022-03-25 15:59:57 yagna   [2022-03-25T15:59:57.562+0100 DEBUG smoltcp::socket::tcp] tcp:fa13:f16a:50e6:d57a:aa84:4ba9:b7e6:73e6:1:ee9b:706:c981:400d:8566:1136:7c4f:3d34:21798: segment not in receive window (3320501769..3320502117 not intersecting 3320502117..3320507709), will send challenge ACK
2022-03-25 15:59:57 yagna   [2022-03-25T15:59:57.562+0100 DEBUG smoltcp::socket::tcp] sending sACK option with current assembler ranges
2022-03-25 15:59:57 ya-provider [2022-03-25T15:59:57.889+0100 DEBUG ya_client::web] doing GET on http://0.0.0.0:17665/activity-api/v1/events?afterTimestamp=2022-03-25T14%3A59%3A48.807411311%2B00%3A00&appSessionId=witek.h-5601&timeout=3
2022-03-25 15:59:58 yagna   [2022-03-25T15:59:57.848+0100 DEBUG ya_activity::dao::activity_state] getting activity state
2022-03-25 15:59:58 yagna   [2022-03-25T15:59:57.848+0100 DEBUG ya_activity::dao::activity_state] got state: StatePair(New, None) != [StatePair(Initialized, None), StatePair(Terminated, None)]. Waiting...2022-03-25 15:59:58 yagna   [2022-03-25T15:59:58.600+0100 DEBUG ya_activity::dao::activity_state] getting activity state
2022-03-25 15:59:58 yagna   [2022-03-25T15:59:58.600+0100 DEBUG ya_activity::dao::activity_state] got state: StatePair(New, None) != [StatePair(Initialized, None), StatePair(Terminated, None)]. Waiting...
2022-03-25 15:59:59 yagna   [2022-03-25T15:59:59.351+0100 DEBUG ya_activity::dao::activity_state] getting activity state
2022-03-25 15:59:59 yagna   [2022-03-25T15:59:59.352+0100 DEBUG ya_activity::dao::activity_state] got state: StatePair(New, None) != [StatePair(Initialized, None), StatePair(Terminated, None)]. Waiting...
2022-03-25 15:59:59 yagna   [2022-03-25T15:59:59.696+0100 INFO  actix_web::middleware::logger] 127.0.0.1:37118 "GET /payment-api/v1/invoiceEvents?timeout=50&afterTimestamp=2022-03-25T13%3A09%3A57.676Z&appSessionId=witek.h-5601 HTTP/1.1" 200 2 "-" "-" 50.003218
2022-03-25 15:59:59 ya-provider [2022-03-25T15:59:59.696+0100 DEBUG ya_client::web] WebRequest.json(). method=GET url=http://0.0.0.0:17665/payment-api/v1/invoiceEvents?timeout=50&afterTimestamp=2022-03-25T13%3A09%3A57.676Z&appSessionId=witek.h-5601, resp='[]'
2022-03-25 15:59:59 ya-provider [2022-03-25T15:59:59.696+0100 DEBUG ya_client::web] doing GET on http://0.0.0.0:17665/payment-api/v1/invoiceEvents?timeout=50&afterTimestamp=2022-03-25T13%3A09%3A57.676Z&appSessionId=witek.h-5601
2022-03-25 16:00:00 yagna   [2022-03-25T16:00:00.072+0100 INFO  actix_web::middleware::logger] 127.0.0.1:37088 "GET /market-api/v1/offers/b7ee59b533c246e9899e424a47aa16b5-970b92cfcfdb2342b49793b6ae60485f0ff037b83bf4fe7c752957ff1134c153/events?timeout=20&maxEvents=5 HTTP/1.1" 200 2 "-" "-" 20.002365
2022-03-25 16:00:00 ya-provider [2022-03-25T16:00:00.073+0100 DEBUG ya_client::web] WebRequest.json(). method=GET url=http://0.0.0.0:17665/market-api/v1/offers/b7ee59b533c246e9899e424a47aa16b5-970b92cfcfdb2342b49793b6ae60485f0ff037b83bf4fe7c752957ff1134c153/events?timeout=20&maxEvents=5, resp='[]'
2022-03-25 16:00:00 ya-provider [2022-03-25T16:00:00.073+0100 DEBUG ya_client::web] doing GET on http://0.0.0.0:17665/market-api/v1/offers/b7ee59b533c246e9899e424a47aa16b5-970b92cfcfdb2342b49793b6ae60485f0ff037b83bf4fe7c752957ff1134c153/events?timeout=20&maxEvents=5
2022-03-25 16:00:00 yagna   [2022-03-25T16:00:00.103+0100 DEBUG ya_activity::dao::activity_state] getting activity state
2022-03-25 16:00:00 yagna   [2022-03-25T16:00:00.104+0100 DEBUG ya_activity::dao::activity_state] got state: StatePair(New, None) != [StatePair(Initialized, None), StatePair(Terminated, None)]. Waiting...
2022-03-25 16:00:01 yagna   [2022-03-25T16:00:00.856+0100 DEBUG ya_activity::dao::activity_state] getting activity state
2022-03-25 16:00:01 yagna   [2022-03-25T16:00:00.856+0100 DEBUG ya_activity::dao::activity_state] got state: StatePair(New, None) != [StatePair(Initialized, None), StatePair(Terminated, None)]. Waiting...
2022-03-25 16:00:01 yagna   [2022-03-25T16:00:01.607+0100 DEBUG ya_activity::dao::activity_state] getting activity state
2022-03-25 16:00:01 yagna   [2022-03-25T16:00:01.607+0100 DEBUG ya_activity::dao::activity_state] got state: StatePair(New, None) != [StatePair(Initialized, None), StatePair(Terminated, None)]. Waiting...
2022-03-25 16:00:01 yagna   [2022-03-25T16:00:01.751+0100 DEBUG ya_service_api_web::middleware::auth] skipping authorization for uri=/metrics-api/v1/expose
2022-03-25 16:00:01 yagna   [2022-03-25T16:00:01.810+0100 INFO  actix_web::middleware::logger] 10.30.10.112:47072 "GET /metrics-api/v1/expose HTTP/1.1" 200 159143 "-" "Prometheus/2.24.0" 0.058832
2022-03-25 16:00:02 yagna   [2022-03-25T16:00:02.097+0100 DEBUG ya_activity::provider::service] Enqueueing a Destroy event for activity 43416f3400eb43d29af023891d2e621f
2022-03-25 16:00:02 yagna   [2022-03-25T16:00:02.098+0100 DEBUG ya_service_bus::typed] Call to CreateActivity failed: Timeout
2022-03-25 16:00:03 ya-provider [2022-03-25T16:00:03.111+0100 DEBUG ya_client::web] WebRequest.json(). method=GET url=http://0.0.0.0:17665/market-api/v1/agreementEvents?timeout=20&afterTimestamp=2022-03-25T14%3A59%3A57.027824970%2B00%3A00&maxEvents=15&appSessionId=witek.h-5601, resp='[{"eventDate":"2022-03-25T15:00:03.103500892Z","agreementId":"caeb5959222c4e1b9a0feb5ba49940a2d6dfb011d6dfac08d69a539405b98c3d","eventtype":"AgreementTerminatedEvent","terminator":"Requestor","signature":"","reason":{"message":"Work cancelled","golem.requestor.code":"Cancelled"}}]'
2022-03-25 16:00:03 ya-provider [2022-03-25T16:00:03.111+0100 INFO  ya_provider::market::provider_market] Agreement [caeb5959222c4e1b9a0feb5ba49940a2d6dfb011d6dfac08d69a539405b98c3d] terminated by Requestor. Reason: Work cancelled
2022-03-25 16:00:03 ya-provider [2022-03-25T16:00:03.112+0100 DEBUG ya_client::web] doing GET on http://0.0.0.0:17665/market-api/v1/agreementEvents?timeout=20&afterTimestamp=2022-03-25T15%3A00%3A03.103500892%2B00%3A00&maxEvents=15&appSessionId=witek.h-5601
2022-03-25 16:00:03 ya-provider [2022-03-25T16:00:03.113+0100 INFO  ya_provider::payments::payments] Payments - agreement [caeb5959222c4e1b9a0feb5ba49940a2d6dfb011d6dfac08d69a539405b98c3d] closed. Computing cost summary...
2022-03-25 16:00:03 ya-provider [2022-03-25T16:00:03.113+0100 INFO  ya_provider::market::negotiator::builtin::max_agreements] Negotiator: 1 free slot(s) for agreements.
2022-03-25 16:00:03 ya-provider [2022-03-25T16:00:03.113+0100 INFO  ya_provider::market::provider_market] Re-negotiating all demands
2022-03-25 16:00:03 ya-provider [2022-03-25T16:00:03.113+0100 DEBUG ya_provider::payments::agreement] Waiting for all activities to finish.
2022-03-25 16:00:03 ya-provider [2022-03-25T16:00:03.113+0100 DEBUG ya_provider::payments::agreement] Num active activities left: 0.
2022-03-25 16:00:03 ya-provider [2022-03-25T16:00:03.113+0100 DEBUG ya_provider::payments::agreement] All activities finished.
2022-03-25 16:00:03 ya-provider [2022-03-25T16:00:03.114+0100 INFO  ya_provider::payments::payments] Final cost for agreement [caeb5959222c4e1b9a0feb5ba49940a2d6dfb011d6dfac08d69a539405b98c3d]: 0, usage [0.0, 0.0].
2022-03-25 16:00:03 ya-provider [2022-03-25T16:00:03.114+0100 DEBUG ya_provider::payments::payments] Issuing invoice {"agreementId":"caeb5959222c4e1b9a0feb5ba49940a2d6dfb011d6dfac08d69a539405b98c3d","activityIds":[],"amount":"0","paymentDueDate":"2022-03-26T15:00:03.114169441Z"}.
2022-03-25 16:00:03 ya-provider [2022-03-25T16:00:03.114+0100 DEBUG ya_client::web] doing POST on http://0.0.0.0:17665/payment-api/v1/invoices
2022-03-25 16:00:03 ya-provider [2022-03-25T16:00:03.116+0100 DEBUG ya_client::web] WebRequest.json(). method=GET url=http://0.0.0.0:17665/activity-api/v1/events?afterTimestamp=2022-03-25T14%3A59%3A48.807411311%2B00%3A00&appSessionId=witek.h-5601&timeout=3, resp='[{"activityId":"43416f3400eb43d29af023891d2e621f","agreementId":"caeb5959222c4e1b9a0feb5ba49940a2d6dfb011d6dfac08d69a539405b98c3d","eventType":{"CreateActivity":{}},"eventDate":"2022-03-25T14:59:57.096211338Z"},{"activityId":"43416f3400eb43d29af023891d2e621f","agreementId":"caeb5959222c4e1b9a0feb5ba49940a2d6dfb011d6dfac08d69a539405b98c3d","eventType":{"DestroyActivity":{}},"eventDate":"2022-03-25T15:00:02.099051972Z"}]'
2022-03-25 16:00:03 ya-provider [2022-03-25T16:00:03.116+0100 INFO  ya_provider::execution::task_runner] Collected 2 activity events. Processing...
2022-03-25 16:00:03 ya-provider [2022-03-25T16:00:03.116+0100 INFO  ya_provider::execution::task_runner] Destroying activity [43416f3400eb43d29af023891d2e621f].
2022-03-25 16:00:03 ya-provider [2022-03-25T16:00:03.120+0100 DEBUG ya_client::web] doing GET on http://0.0.0.0:17665/activity-api/v1/events?afterTimestamp=2022-03-25T15%3A00%3A02.099051972%2B00%3A00&appSessionId=witek.h-5601&timeout=3 
2022-03-25 16:00:03 yagna   [2022-03-25T16:00:03.102+0100 DEBUG ya_market::protocol::negotiation::provider] Negotiation API: Agreement [P-caeb5959222c4e1b9a0feb5ba49940a2d6dfb011d6dfac08d69a539405b98c3d] terminated by [0xee9b0706c981400d856611367c4f3d34984e0531].
2022-03-25 16:00:03 yagna   [2022-03-25T16:00:03.103+0100 DEBUG ya_market::db::dao::agreement_events] Event timestamp: 2022-03-25 14:59:57.027824970, type: Approved    
2022-03-25 16:00:03 yagna   [2022-03-25T16:00:03.103+0100 DEBUG ya_market::db::dao::agreement_events] Event timestamp: 2022-03-25 15:00:03.103500892, type: Terminated  
2022-03-25 16:00:03 yagna   [2022-03-25T16:00:03.104+0100 INFO  ya_market::negotiation::common] Received terminate Agreement [P-caeb5959222c4e1b9a0feb5ba49940a2d6dfb011d6dfac08d69a539405b98c3d] from [0xee9b0706c981400d856611367c4f3d34984e0531]. Reason: 'Work cancelled'
nieznanysprawiciel commented 2 years ago

Blocked because this problem doesn't appear