Wrong GNT amount reserved for a subtask of a blender task

[ederenn]

Description

Golem Version: 0.21.0+dev122.g9a56168

Golem-Messages version (leave empty if unsure): golem_messages Version: 3.13.0

Electron version (if used): 0.2.3

OS [e.g. Windows 10 Pro]: Linux

Branch (if launched from source): develop

Mainnet/Testnet: mainnet

Priority label is set to the lowest by default. To setup higher priority please change the label
P0 label is set for Severity-Critical/Effort-easy
P1 label is set for Severity-Critical/Effort-hard
P2 label is set for Severity-Low/ Effort-easy
P3 label is set for Severity-Low/Effort-hard

Description of the issue:

In blender task reserved GNT amount is several times higher than the correct value.

Actual result:

Reserved GNT amount for subtasks is several times higher than it should be payed, as a result value shown in wallet is on minus. Too big numbers shown in requestor's transactions history in awaiting state, on provider's side transaction history looks correct.

2019-10-18 14:41:18 INFO     golem.task.taskmanager              Creating task. type=<class 'apps.blender.task.blenderrendertask.BlenderRenderTask'>, id=94a63580-f1a4-11e9-9df6-2f67ff27ad1e
2019-10-18 14:41:18 INFO     golem.ethereum.fundslocker          Locking funds for task: '94a63580-f1a4-11e9-9df6-2f67ff27ad1e' price: 0.017 GNTB num: 4
2019-10-18 14:41:18 INFO     golem.ethereum.transactionsystem    Locking 0.067 GNTB and 0.00089840 ETH for 4 payments

019-10-18 14:43:30 INFO     golem.verifier.blender_verifier     Verification completed. Subtask_id: a245f802-f1a4-11e9-8345-2f67ff27ad1e. Verification verdict: positive. 
2019-10-18 14:43:30 INFO     apps.core.verification_queue        Finished verification of subtask 'a245f802-f1a4-11e9-8345-2f67ff27ad1e'
2019-10-18 14:43:30 INFO     golem.ethereum.paymentprocessor     Adding payment for a245f802-f1a4-11e9-8345-2f67ff27ad1e to 0xe1D92383296F093515643ff8Fc5Cd128Fc038559 (60.00000000 GNTB)
2019-10-18 14:43:30 INFO     golem.ethereum.paymentprocessor     Reserved 60.000 GNTB
2019-10-18 14:43:30 INFO     golem.ethereum.fundslocker          Removing subtask lock for task '94a63580-f1a4-11e9-9df6-2f67ff27ad1e'
2019-10-18 14:43:30 INFO     golem.ethereum.transactionsystem    Unlocking 0.017 GNTB for 1 payments

Screenshots:

requestor's side:

provider's side:

Steps To Reproduce

Short description of steps to reproduce the behavior:
e.g.

1. Launch Golem on two nodes, provider and requestor
2. Start a short task, Small shark, resolution and samples from file, 2 frames, 4 subtasks, bid 0.1, task time 10 min for a task, 5 min for a subtask
3. Wait for task to finish
4. Check wallet and history of payments.
5. Chek amounts for subtasks in golem.log

Expected behavior

(What is the expected behavior and/or result in this scenario)

Logs and any additional context

golem.log

task dump:

tasks show 94a63580-f1a4-11e9-9df6-2f67ff27ad1e
---
id: 94a63580-f1a4-11e9-9df6-2f67ff27ad1e
status: Finished
time_remaining: 0.0
subtasks_count: 4
progress: 1.0
cost: ~
fee: ~
estimated_cost: "66666666666666668"
estimated_fee: "358400000000000"
compute_on: cpu
options:
  frame_count: 2
  output_path: /home/ederenn/Documents/small_shark100_2019-10-18_14-41-18
  format: PNG
  resolution:
    - 400
    - 400
  frames: 1-2
  compositing: false
  samples: 1000
bid: 0.1
timeout: "0:30:00"
preview: /home/ederenn/.local/share/golem/default/mainnet/ComputerRes/94a63580-f1a4-11e9-9df6-2f67ff27ad1e/tmp/current_task_preview1.PNG
type: Blender
name: small_shark100
last_updated: 1571402892.375528
subtask_timeout: "0:10:00"
resources:
  - /home/ederenn/Desktop/Host_Share_Folder/test files/small_shark100.blend
concent_enabled: false
status_message: ~
time_started: 1571402478.2504884
>> 

2019-10-18 16:28:24 INFO     golem_sci.implementation            Detected event <BatchTransferEvent tx: 0x51e4ed83fc106dc8803111909ef539403e157c78f2fb15f5079fe96b7fda0736 sender: 0x04DbBA54eA78E9D919d359836f374c0b28C82386 receiver: 0x2C9287402aA1797e6c32cAC433130cB63C72ac2F amount: 0.05833333333333334 closure_time: 1568380331>
2019-10-18 16:28:24 INFO     golem_sci.implementation            Detected event <BatchTransferEvent tx: 0x086de533efaf607ad0159f5010b0670fc090680a82efe1f781309004411b3f4e sender: 0xd8055fD4086Cc37bDB04f143a587209C31642Ada receiver: 0x2C9287402aA1797e6c32cAC433130cB63C72ac2F amount: 0.04166666666666667 closure_time: 1568385097>
2019-10-18 16:28:24 INFO     golem_sci.implementation            Detected event <BatchTransferEvent tx: 0x79315d4f58341c724f4e1244d104c56433d1f9d0ac0a27cff83ca8cdc6c606ef sender: 0xd8055fD4086Cc37bDB04f143a587209C31642Ada receiver: 0x2C9287402aA1797e6c32cAC433130cB63C72ac2F amount: 0.08333333333333334 closure_time: 1568645438>
2019-10-18 16:28:24 INFO     golem_sci.implementation            Detected event <BatchTransferEvent tx: 0xfec157b0447e6f904916582e26e7d715bcb0c2efeb43b38f681e9d18a6276ac9 sender: 0x04DbBA54eA78E9D919d359836f374c0b28C82386 receiver: 0x2C9287402aA1797e6c32cAC433130cB63C72ac2F amount: 0.025 closure_time: 1568646081>

Proposed Solution?

(Optional: What could be a solution for that issue)

[ederenn]

subtasks in this task

>> tasks subtasks list 94a63580-f1a4-11e9-9df6-2f67ff27ad1e
┌────────┬────────────────────────────────────────┬────────────┬────────────┐
│  node  │  subtask id                            │  status    │  progress  │
├────────┼────────────────────────────────────────┼────────────┼────────────┤
│  vm s  │  a245f802-f1a4-11e9-8345-2f67ff27ad1e  │  Finished  │  100.0 %   │
│  vm s  │  ef2d7aa4-f1a4-11e9-968a-2f67ff27ad1e  │  Finished  │  100.0 %   │
│  vm s  │  1ebcde02-f1a5-11e9-b45b-2f67ff27ad1e  │  Finished  │  100.0 %   │
│  vm s  │  652cabf6-f1a5-11e9-8880-2f67ff27ad1e  │  Finished  │  100.0 %   │
└────────┴────────────────────────────────────────┴────────────┴────────────┘
>> 

[ederenn]

same happens on testnet, issue repeats with blender tasks, same for newly requested tasks and for restarted ones.