Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Agreement state inconsistency for Prov-Req daemons #847

Closed
tworec opened this issue Dec 4, 2020 · 3 comments
Closed

Agreement state inconsistency for Prov-Req daemons #847

tworec opened this issue Dec 4, 2020 · 3 comments

Comments

@tworec
Copy link
Contributor

tworec commented Dec 4, 2020 •
edited
Loading

Steps to reproduce:
inccur timeout when the provider is approving agreement (eg. via net brokeage)

[2020-12-04T04:47:34Z WARN  ya_provider::execution::task_runner] Can't destroy not existing activity [be899d80817f4b96ba116b1433f51032]
[2020-12-04T04:47:34Z INFO  ya_provider::execution::task_runner] Destroying activity [be899d80817f4b96ba116b1433f51032].
[2020-12-04T04:47:34Z INFO  ya_provider::execution::task_runner] Collected 1 activity events. Processing...
[2020-12-04T04:47:30Z WARN  ya_provider::execution::task_runner] Can't create activity for not my agreement [CreateActivity { activity_id: "be899d80817f4b96ba116b1433f51032", agreement_id: "d3247d1b4a137108ec9beab8cb468ce0f2e18bf770d7a25e5dc7006dba9e1bcc", requestor_pub_key: None }].
[2020-12-04T04:47:30Z ERROR ya_provider::execution::task_runner] Activity created: Can't create activity for not my agreement [CreateActivity { activity_id: "be899d80817f4b96ba116b1433f51032", agreement_id: "d3247d1b4a137108ec9beab8cb468ce0f2e18bf770d7a25e5dc7006dba9e1bcc", requestor_pub_key: None }].
[2020-12-04T04:47:30Z INFO  ya_provider::execution::task_runner] Collected 1 activity events. Processing...
[2020-12-04T04:47:22Z INFO  ya_provider::market::provider_market] Subscribed offer. Subscription id [4d89506206204fd48abd38442fca2e51-b8153600f979c63958579e7e91aadbda34cbe57bc29f1d2463e5fa1b019e5fb1], preset [vm].
[2020-12-04T04:47:22Z INFO  ya_market::matcher] Subscribed new Offer: [4d89506206204fd48abd38442fca2e51-b8153600f979c63958579e7e91aadbda34cbe57bc29f1d2463e5fa1b019e5fb1] using identity: golem-cli [0x99c323074ceb0bab449f11145a0f02e5607a8a97]
[2020-12-04T04:47:22Z INFO  ya_provider::market::provider_market] Subscribed offer. Subscription id [825d37a5cd3346c78d3f4a61b33e1e19-0139f25eeae9916ffb25f1e83d1d378cbf56e3cf8553c7eeebe9a3068be62ed2], preset [wasmtime].
[2020-12-04T04:47:22Z INFO  ya_market::matcher] Subscribed new Offer: [825d37a5cd3346c78d3f4a61b33e1e19-0139f25eeae9916ffb25f1e83d1d378cbf56e3cf8553c7eeebe9a3068be62ed2] using identity: golem-cli [0x99c323074ceb0bab449f11145a0f02e5607a8a97]
[2020-12-04T04:47:22Z INFO  ya_market::matcher] Unsubscribed Offer: [e459344cd7c14950a2c22ae0f4021901-d217d9e8eba39acf03eeef2220939f60d835cbec608b6d33345fe3d6d9721ae8] using identity: golem-cli [0x99c323074ceb0bab449f11145a0f02e5607a8a97]
[2020-12-04T04:47:22Z INFO  ya_provider::market::provider_market] Unsubscribing: e459344cd7c14950a2c22ae0f4021901-d217d9e8eba39acf03eeef2220939f60d835cbec608b6d33345fe3d6d9721ae8
[2020-12-04T04:47:22Z INFO  ya_market::matcher] Unsubscribed Offer: [797e28ba9afc40e2b3a283b2bcc74229-2d13f79c9c09567b4a054a8536b4e9211ac038823c965873df67b01945669ad0] using identity: golem-cli [0x99c323074ceb0bab449f11145a0f02e5607a8a97]
[2020-12-04T04:47:22Z INFO  ya_provider::market::provider_market] Unsubscribing: 797e28ba9afc40e2b3a283b2bcc74229-2d13f79c9c09567b4a054a8536b4e9211ac038823c965873df67b01945669ad0
[2020-12-04T04:47:22Z ERROR ya_provider::market::provider_market] Error processing event: Failed to approve agreement [d3247d1b4a137108ec9beab8cb468ce0f2e18bf770d7a25e5dc7006dba9e1bcc]. Error: request for http://0.0.0.0:18795/market-api/v1/agreements/d3247d1b4a137108ec9beab8cb468ce0f2e18bf770d7a25e5dc7006dba9e1bcc/approve?timeout=10 resulted in HTTP status code: 500 Internal Server Error: Protocol error while approving: Timeout while sending approval of Agreement [P-d3247d1b4a137108ec9beab8cb468ce0f2e18bf770d7a25e5dc7006dba9e1bcc], subscription_id: e459344cd7c14950a2c22ae0f4021901-d217d9e8eba39acf03eeef2220939f60d835cbec608b6d33345fe3d6d9721ae8.

There is one more case to be investigated:
[2020-12-04T15:16:29Z ERROR ya_provider::market::provider_market] Error processing event: Failed to approve agreement [9315ada127d81384cba933d01f0c538941d3c9cbd5f206e6e9f0e3ad4a17ce85]. Error: request for http://0.0.0.0:18595/market-api/v1/agreements/9315ada127d81384cba933d01f0c538941d3c9cbd5f206e6e9f0e3ad4a17ce85/approve?timeout=10 resulted in HTTP status code: 500 Internal Server Error: Protocol error while approving: Remote Approve: Agreement [R-9315ada127d81384cba933d01f0c538941d3c9cbd5f206e6e9f0e3ad4a17ce85] in state Proposal, can't be approved., subscription_id: f8d4ecfb758846a7bc8eed4c8a5f6f69-4c7971835eaf18451f0d09d7db8e99a4a2a6be9fcc266d31bee6c433e81143a5.
@tworec tworec changed the title possible inconsistent Agreement states between Prov-Req daemons Agreement state inconsistency for Prov-Req daemons Dec 4, 2020
@tworec tworec added the t-mkt label Dec 4, 2020
@tworec tworec mentioned this issue Dec 4, 2020
Merged
@etam
Copy link
Contributor

etam commented Jan 22, 2021 

[2021-01-21T16:31:03Z INFO  ya_market::negotiation::provider] Agreement proposal [P-9e40599941c3fd50618ba098d14c13dd7435c8e450357ee4005e6403babe4d35] received from [0x6d0de4941fd926b1660196ae6993ff6fa9d8a384].
[2021-01-21T16:31:03Z INFO  ya_provider::market::provider_market] Got agreement [9e40599941c3fd50618ba098d14c13dd7435c8e450357ee4005e6403babe4d35] from Requestor [0x6d0de4941fd926b1660196ae6993ff6fa9d8a384] for subscription [vm].
[2021-01-21T16:31:03Z INFO  ya_provider::market::provider_market] Decided to ApproveAgreement agreement [9e40599941c3fd50618ba098d14c13dd7435c8e450357ee4005e6403babe4d35] for subscription [vm].
[2021-01-21T16:31:04Z INFO  ya_provider::execution::task_runner] Collected 1 activity events. Processing...
[2021-01-21T16:31:04Z ERROR ya_provider::execution::task_runner] Activity created: Can't create activity for not my agreement [CreateActivity { activity_id: "e50de91f5df748c78f32da58da117f56", agreement_id: "9e40599941c3fd50618ba098d14c13dd7435c8e450357ee4005e6403babe4d35", requestor_pub_key: None }].
[2021-01-21T16:31:04Z WARN  ya_provider::execution::task_runner] Can't create activity for not my agreement [CreateActivity { activity_id: "e50de91f5df748c78f32da58da117f56", agreement_id: "9e40599941c3fd50618ba098d14c13dd7435c8e450357ee4005e6403babe4d35", requestor_pub_key: None }].
[2021-01-21T16:31:04Z INFO  ya_market::negotiation::provider] Provider 'golem-cli' [0x89c0851462e4bd87a60c20fbba86f8cb3bff29a5] approved Agreement [P-9e40599941c3fd50618ba098d14c13dd7435c8e450357ee4005e6403babe4d35].
[2021-01-21T16:31:04Z INFO  ya_provider::market::provider_market] Got approved agreement [9e40599941c3fd50618ba098d14c13dd7435c8e450357ee4005e6403babe4d35].
[2021-01-21T16:31:04Z INFO  ya_provider::payments::payments] Payments got signed agreement [9e40599941c3fd50618ba098d14c13dd7435c8e450357ee4005e6403babe4d35]. Waiting for activities creation...
[2021-01-21T16:31:04Z INFO  ya_provider::payments::pricing] Creating LinearPricing payment model. Usage coefficients vector: [0.001, 0.002, 0.0].
[2021-01-21T16:31:06Z INFO  ya_provider::execution::task_runner] Collected 1 activity events. Processing...
[2021-01-21T16:31:06Z INFO  ya_provider::execution::task_runner] Destroying activity [e50de91f5df748c78f32da58da117f56].
[2021-01-21T16:31:06Z WARN  ya_provider::execution::task_runner] Can't destroy not existing activity [e50de91f5df748c78f32da58da117f56]
[2021-01-21T16:31:59Z ERROR r2d2] database is locked
[2021-01-21T16:32:34Z WARN  ya_provider::task_manager] Breaking agreement [9e40599941c3fd50618ba098d14c13dd7435c8e450357ee4005e6403babe4d35], reason: No activity created within 90s from Agreement Approval.
[2021-01-21T16:32:34Z INFO  ya_provider::market::mock_negotiator] Negotiator: 1 free slot(s) for agreements.
[2021-01-21T16:32:34Z INFO  ya_provider::market::provider_market] Re-subscribing all active offers to get fresh proposals from the Market
[2021-01-21T16:32:34Z INFO  ya_provider::market::provider_market] Unsubscribing: 42c5d7845e9d42008c3e578855b27230-25906282b594587be3f5801ccc896dc21e4a7a8ee2e9f6919b59c79b55d4b188
[2021-01-21T16:32:34Z INFO  ya_provider::payments::payments] Payments - agreement [9e40599941c3fd50618ba098d14c13dd7435c8e450357ee4005e6403babe4d35] closed. Computing cost summary...
[2021-01-21T16:32:34Z INFO  ya_provider::payments::payments] Final cost for agreement [9e40599941c3fd50618ba098d14c13dd7435c8e450357ee4005e6403babe4d35]: 0, usage [0.0, 0.0].

full log: collossus.3.zip

@tworec
Copy link
Contributor Author

tworec commented Jan 27, 2021

loosly related to #921

@nieznanysprawiciel
Copy link
Contributor

Should be fixed after: #1014 and #1015

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@etam @nieznanysprawiciel @tworec