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.

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

Requestor get agreement and start activity, then activity expires but final invoice is never accepted and payment never happens #3126

Open
averias opened this issue Mar 25, 2024 · 0 comments

Comments

@averias
Copy link

averias commented Mar 25, 2024

During the last 3 days, Requestor 0x6c9d01fcdb18c8Dd91F901580fEaCB4b2E24B4c7 started an activity for 2-3 hours by consuming all resources of my machine and reached the expiration date time of the agreement. When that happened, the invoice was generated but the requestor never accepted that invoice so the payment was never done. While the activity was executed, Debit Notes were accepted every time the cost was updated

For me, it's strange that this issue happens since in my understanding ya-payments should manage this situation, it's also strange since only happened with the same requestor, other requestors which consumed task expiration time, accepted the invoices and paid

Is that a bug? Is there any way of blocking this requestor or any advise to avoid this situation? otherwise, I'll stop using Golem network until the issue is solved.

Some logs from the last issue today:

Proposal + agreement + task creation. Debit notes are issued every 2 minutes and accepted by Node 0xe5e94b0634ebe16fe961183180a5280764b2b7b2

[2024-03-25T10:13:34.709+0100 INFO  ya_market::negotiation::provider] Agreement proposal [P-5822f584a23553e0f39d42de45fb1b38d5e7ac10182e7b37de2a8b29d3c6702a] received from [0x6c9d01fcdb18c8dd91f901580feacb4b2e24b4c7].
[2024-03-25T10:13:34.711+0100 INFO  ya_provider::market::provider_market] Got agreement [5822f584a23553e0f39d42de45fb1b38d5e7ac10182e7b37de2a8b29d3c6702a] from Requestor [0x6c9d01fcdb18c8dd91f901580feacb4b2e24b4c7] for subscription [vm].
[2024-03-25T10:13:34.713+0100 INFO  ya_provider::market::provider_market] Decided to ApproveAgreement [5822f584a23553e0f39d42de45fb1b38d5e7ac10182e7b37de2a8b29d3c6702a] for subscription [vm].
[2024-03-25T10:13:34.713+0100 INFO  ya_provider::market::provider_market] Got approved agreement [5822f584a23553e0f39d42de45fb1b38d5e7ac10182e7b37de2a8b29d3c6702a].
[2024-03-25T10:13:34.714+0100 INFO  ya_provider::tasks::task_manager] Agreement [5822f584a23553e0f39d42de45fb1b38d5e7ac10182e7b37de2a8b29d3c6702a] will be initialized in multi activity mode.
[2024-03-25T10:13:34.714+0100 INFO  ya_provider::payments::payments] Payments got signed agreement [5822f584a23553e0f39d42de45fb1b38d5e7ac10182e7b37de2a8b29d3c6702a]. Waiting for activities creation...
[2024-03-25T10:13:34.714+0100 INFO  ya_provider::payments::pricing] Creating LinearPricing payment model. Usage coefficients vector: [3.888888888888889e-6, 0.0, 0.0].
[2024-03-25T10:13:34.714+0100 INFO  ya_provider::payments::agreement] Requestor is expected to accept DebitNotes for Agreement [5822f584a23553e0f39d42de45fb1b38d5e7ac10182e7b37de2a8b29d3c6702a] in 4m
[2024-03-25T10:13:34.716+0100 INFO  ya_market::negotiation::provider] AppSession id [ya-provider-4366] set for Agreement [P-5822f584a23553e0f39d42de45fb1b38d5e7ac10182e7b37de2a8b29d3c6702a].
[2024-03-25T10:13:34.813+0100 INFO  ya_market::negotiation::provider] Provider 'golem-cli' [0xe5e94b0634ebe16fe961183180a5280764b2b7b2] approved Agreement [P-5822f584a23553e0f39d42de45fb1b38d5e7ac10182e7b37de2a8b29d3c6702a]. Waiting for commit from Requestor [0x6c9d01fcdb18c8dd91f901580feacb4b2e24b4c7].
[2024-03-25T10:13:34.815+0100 INFO  ya_market::negotiation::provider] Agreement [P-5822f584a23553e0f39d42de45fb1b38d5e7ac10182e7b37de2a8b29d3c6702a] approved (committed) by [0x6c9d01fcdb18c8dd91f901580feacb4b2e24b4c7].
[2024-03-25T10:13:36.248+0100 INFO  ya_provider::execution::task_runner] Collected 1 activity events. Processing...
[2024-03-25T10:13:36.267+0100 INFO  ya_provider::execution::task_runner] Creating task: agreement [5822f584a23553e0f39d42de45fb1b38d5e7ac10182e7b37de2a8b29d3c6702a], activity [a2c87fd8e5e54f8e938c7079466319f5] in directory: [/home/bewater/.local/share/ya-provider/exe-unit/work/5822f584a23553e0f39d42de45fb1b38d5e7ac10182e7b37de2a8b29d3c6702a/a2c87fd8e5e54f8e938c7079466319f5].
[2024-03-25T10:13:36.267+0100 INFO  ya_provider::execution::exeunit_instance] Spawning exeunit instance: vm
[2024-03-25T10:13:36.267+0100 INFO  ya_provider::execution::exeunit_instance] Exeunit log directory: /home/bewater/.local/share/ya-provider/exe-unit/work/5822f584a23553e0f39d42de45fb1b38d5e7ac10182e7b37de2a8b29d3c6702a/a2c87fd8e5e54f8e938c7079466319f5/logs
[2024-03-25T10:13:36.269+0100 INFO  ya_provider::execution::exeunit_instance] Exeunit process spawned, pid: 10271
[2024-03-25T10:13:36.270+0100 INFO  ya_provider::payments::payments] Payments - activity [a2c87fd8e5e54f8e938c7079466319f5] created. Start computing costs.
[2024-03-25T10:13:36.438+0100 INFO  ya_activity::provider::service] Requestor [0x6c9d01fcdb18c8dd91f901580feacb4b2e24b4c7] created Activity [a2c87fd8e5e54f8e938c7079466319f5] for Agreement [5822f584a23553e0f39d42de45fb1b38d5e7ac10182e7b37de2a8b29d3c6702a]
[2024-03-25T10:13:37.025+0100 INFO  ya_provider::execution::task_runner] ExeUnit initialized
[2024-03-25T10:15:34.636+0100 INFO  ya_provider::payments::payments] Updating cost for activity [a2c87fd8e5e54f8e938c7079466319f5]: 0.002866278329444444, usage [737.042999, 118.018211507].
[2024-03-25T10:15:34.663+0100 INFO  ya_payment::api::debit_notes] DebitNote [ca5c4ece-7cdc-4de0-b17d-ee129e8ec159] for Activity [a2c87fd8e5e54f8e938c7079466319f5] issued.
[2024-03-25T10:15:34.773+0100 INFO  ya_payment::api::debit_notes] DebitNote [ca5c4ece-7cdc-4de0-b17d-ee129e8ec159] for Activity [a2c87fd8e5e54f8e938c7079466319f5] sent to [0x6c9d01fcdb18c8dd91f901580feacb4b2e24b4c7].
[2024-03-25T10:15:34.774+0100 INFO  ya_provider::payments::payments] Debit note [ca5c4ece-7cdc-4de0-b17d-ee129e8ec159] for activity [a2c87fd8e5e54f8e938c7079466319f5] sent with due date: None.
[2024-03-25T10:15:35.121+0100 INFO  ya_payment::service::public] Node [0xe5e94b0634ebe16fe961183180a5280764b2b7b2] accepted DebitNote [ca5c4ece-7cdc-4de0-b17d-ee129e8ec159].
[2024-03-25T10:17:34.641+0100 INFO  ya_provider::payments::payments] Updating cost for activity [a2c87fd8e5e54f8e938c7079466319f5]: 0.005934611662777777, usage [1526.042999, 238.018813688].
[2024-03-25T10:17:34.646+0100 INFO  ya_payment::api::debit_notes] DebitNote [f98f7987-2928-4b70-81ac-8936437375ca] for Activity [a2c87fd8e5e54f8e938c7079466319f5] issued.
[2024-03-25T10:17:34.748+0100 INFO  ya_payment::api::debit_notes] DebitNote [f98f7987-2928-4b70-81ac-8936437375ca] for Activity [a2c87fd8e5e54f8e938c7079466319f5] sent to [0x6c9d01fcdb18c8dd91f901580feacb4b2e24b4c7].
[2024-03-25T10:17:34.748+0100 INFO  ya_provider::payments::payments] Debit note [f98f7987-2928-4b70-81ac-8936437375ca] for activity [a2c87fd8e5e54f8e938c7079466319f5] sent with due date: None.
[2024-03-25T10:17:35.587+0100 INFO  ya_payment::service::public] Node [0xe5e94b0634ebe16fe961183180a5280764b2b7b2] accepted DebitNote [f98f7987-2928-4b70-81ac-8936437375ca].

Last cost updating and final cost calculated, agreement is broken because of expiration time, the invoice is sent but never accepted

[2024-03-25T13:03:34.635+0100 INFO  ya_provider::payments::payments] Updating cost for activity [a2c87fd8e5e54f8e938c7079466319f5]: 0.2458635005516666, usage [63222.042999, 10198.019573627].
[2024-03-25T13:03:34.639+0100 INFO  ya_payment::api::debit_notes] DebitNote [67ee9b0d-62ae-48d3-afee-cf26cbddb51f] for Activity [a2c87fd8e5e54f8e938c7079466319f5] issued.
[2024-03-25T13:03:34.740+0100 INFO  ya_payment::api::debit_notes] DebitNote [67ee9b0d-62ae-48d3-afee-cf26cbddb51f] for Activity [a2c87fd8e5e54f8e938c7079466319f5] sent to [0x6c9d01fcdb18c8dd91f901580feacb4b2e24b4c7].
[2024-03-25T13:03:34.740+0100 INFO  ya_provider::payments::payments] Debit note [67ee9b0d-62ae-48d3-afee-cf26cbddb51f] for activity [a2c87fd8e5e54f8e938c7079466319f5] sent with due date: None.
[2024-03-25T13:03:35.286+0100 WARN  ya_provider::tasks::task_manager] Breaking agreement [5822f584a23553e0f39d42de45fb1b38d5e7ac10182e7b37de2a8b29d3c6702a], reason: Agreement expired @ 2024-03-25 12:03:35.286 UTC.
[2024-03-25T13:03:35.293+0100 WARN  ya_provider::execution::task_runner] Activity [a2c87fd8e5e54f8e938c7079466319f5] will be destroyed, because of terminated agreement [5822f584a23553e0f39d42de45fb1b38d5e7ac10182e7b37de2a8b29d3c6702a].
[2024-03-25T13:03:35.293+0100 INFO  ya_provider::execution::task_runner] Destroying activity [a2c87fd8e5e54f8e938c7079466319f5].
[2024-03-25T13:03:35.293+0100 INFO  ya_provider::execution::exeunit_instance] Terminating ExeUnit [vm]... pid: 10271
[2024-03-25T13:03:35.426+0100 INFO  ya_provider::execution::task_runner] ExeUnit process exited with status Finished - exit status: 0, agreement [5822f584a23553e0f39d42de45fb1b38d5e7ac10182e7b37de2a8b29d3c6702a], activity [a2c87fd8e5e54f8e938c7079466319f5].
[2024-03-25T13:03:35.426+0100 INFO  ya_provider::execution::task_runner] ExeUnit for activity terminated: [a2c87fd8e5e54f8e938c7079466319f5].
[2024-03-25T13:03:35.427+0100 INFO  ya_provider::payments::payments] Payments - agreement [5822f584a23553e0f39d42de45fb1b38d5e7ac10182e7b37de2a8b29d3c6702a] closed. Computing cost summary...
[2024-03-25T13:03:35.427+0100 INFO  ya_provider::market::negotiator::builtin::max_agreements] Negotiator: 1 free slot(s) for agreements.
[2024-03-25T13:03:35.427+0100 INFO  ya_provider::market::provider_market] Re-negotiating all demands
[2024-03-25T13:03:35.427+0100 INFO  ya_provider::market::provider_market] Terminating agreement [5822f584a23553e0f39d42de45fb1b38d5e7ac10182e7b37de2a8b29d3c6702a]. Reason: [Expired] Agreement expired @ 2024-03-25 12:03:35.286 UTC

...

[2024-03-25T13:03:35.428+0100 INFO  ya_provider::payments::payments] Updating cost for activity [a2c87fd8e5e54f8e938c7079466319f5]: 0.2458868338850000, usage [63228.042999, 10199.021254722].

...

[2024-03-25T13:03:35.534+0100 INFO  ya_market::negotiation::common] Provider 'golem-cli' [0xe5e94b0634ebe16fe961183180a5280764b2b7b2] terminated Agreement [P-5822f584a23553e0f39d42de45fb1b38d5e7ac10182e7b37de2a8b29d3c6702a]. Reason: 'Agreement expired @ 2024-03-25 12:03:35.286 UTC'
[2024-03-25T13:03:35.535+0100 INFO  ya_provider::market::provider_market] Agreement [5822f584a23553e0f39d42de45fb1b38d5e7ac10182e7b37de2a8b29d3c6702a] terminated by Provider.
[2024-03-25T13:03:35.535+0100 INFO  ya_payment::api::debit_notes] DebitNote [41b64e7d-31f6-48e0-a85b-089391f14cc2] for Activity [a2c87fd8e5e54f8e938c7079466319f5] sent to [0x6c9d01fcdb18c8dd91f901580feacb4b2e24b4c7].
[2024-03-25T13:03:35.536+0100 INFO  ya_provider::payments::payments] Debit note [41b64e7d-31f6-48e0-a85b-089391f14cc2] for activity [a2c87fd8e5e54f8e938c7079466319f5] sent with due date: None.
[2024-03-25T13:03:35.536+0100 INFO  ya_provider::payments::payments] Final cost for activity [a2c87fd8e5e54f8e938c7079466319f5]: 0.2458868338850000.
[2024-03-25T13:03:35.536+0100 INFO  ya_provider::payments::payments] Activity [a2c87fd8e5e54f8e938c7079466319f5] finished.
[2024-03-25T13:03:35.536+0100 INFO  ya_provider::payments::payments] Final cost for agreement [5822f584a23553e0f39d42de45fb1b38d5e7ac10182e7b37de2a8b29d3c6702a]: 0.2458868338850000, usage [63228.042999, 10199.021254722].
[2024-03-25T13:03:35.543+0100 INFO  ya_payment::api::invoices] Invoice [535bd0e2-da88-498b-88ca-953b35ebe139] for Agreement [5822f584a23553e0f39d42de45fb1b38d5e7ac10182e7b37de2a8b29d3c6702a] issued.
[2024-03-25T13:03:35.544+0100 INFO  ya_provider::payments::payments] Invoice [535bd0e2-da88-498b-88ca-953b35ebe139] issued.
[2024-03-25T13:03:35.544+0100 INFO  ya_provider::tasks::task_manager] Agreement [5822f584a23553e0f39d42de45fb1b38d5e7ac10182e7b37de2a8b29d3c6702a] cleanup finished.
[2024-03-25T13:03:35.544+0100 INFO  ya_provider::payments::payments] Sending invoice [535bd0e2-da88-498b-88ca-953b35ebe139] to requestor...
[2024-03-25T13:03:35.631+0100 INFO  ya_provider::market::provider_market] Re-negotiating Proposal [P-f822fba58e8c6eaa4046b76e0f4d6416ed222bb8e5f2dd8a3498f1bc4df75bc6] with [0xdd329f6edf93637634e8862d34c3909d298a7055].
[2024-03-25T13:03:35.631+0100 INFO  ya_provider::market::provider_market] Got proposal [P-f822fba58e8c6eaa4046b76e0f4d6416ed222bb8e5f2dd8a3498f1bc4df75bc6] from Requestor [0xdd329f6edf93637634e8862d34c3909d298a7055] for subscription [vm].
[2024-03-25T13:03:35.633+0100 INFO  ya_provider::market::negotiator::component] Negotiator component 'PaymentTimeout' is still negotiating Proposal [P-f822fba58e8c6eaa4046b76e0f4d6416ed222bb8e5f2dd8a3498f1bc4df75bc6].
[2024-03-25T13:03:35.633+0100 INFO  ya_provider::market::negotiator::component] Negotiator component 'DebitNoteInterval' is still negotiating Proposal [P-f822fba58e8c6eaa4046b76e0f4d6416ed222bb8e5f2dd8a3498f1bc4df75bc6].
[2024-03-25T13:03:35.633+0100 INFO  ya_provider::market::provider_market] Decided to CounterProposal [P-f822fba58e8c6eaa4046b76e0f4d6416ed222bb8e5f2dd8a3498f1bc4df75bc6] for subscription [vm].
[2024-03-25T13:03:35.650+0100 INFO  ya_payment::api::invoices] Invoice [535bd0e2-da88-498b-88ca-953b35ebe139] for Agreement [5822f584a23553e0f39d42de45fb1b38d5e7ac10182e7b37de2a8b29d3c6702a] sent to [0x6c9d01fcdb18c8dd91f901580feacb4b2e24b4c7].
[2024-03-25T13:03:35.651+0100 INFO  ya_provider::payments::payments] Invoice [535bd0e2-da88-498b-88ca-953b35ebe139] sent.

@averias averias changed the title Requestor get agreement and start activity, then activity expires but final invoice is never accepted and payment nevers happens Requestor get agreement and start activity, then activity expires but final invoice is never accepted and payment never happens Mar 25, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

1 participant