``` {"level":"info","time":"2020-03-26T13:16:45+01:00","message":"Loaded state for provider {\"test\"}: balance 1000009000000, available balance 1000009000000, unsettled balance 0"} {"level":"debug","time":"2020-03-26T13:16:45+01:00","message":"Published topic=\"earnings_change\" event={Identity:{Address:test} Previous:{Channel:{Beneficiary:[0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0] Balance:<nil> Settled:<nil> Loan:<nil> LastUsedNonce:<nil> Timelock:<nil>} LastPromise:{ChannelID:[] Amount:0 Fee:0 Hashlock:[] R:[] Signature:[]} settleInProgress:false registered:false} Current:{Channel:{Beneficiary:[0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0] Balance:+1000000000000 Settled:+9000000 Loan:+12312323 LastUsedNonce:<nil> Timelock:<nil>} LastPromise:{ChannelID:[] Amount:0 Fee:0 Hashlock:[] R:[] Signature:[]} settleInProgress:false registered:true}}"} {"level":"info","time":"2020-03-26T13:16:45+01:00","message":"Loaded state for provider {\"test\"}: balance 1000002000000, available balance 1000009000000, unsettled balance 0"} {"level":"debug","time":"2020-03-26T13:16:45+01:00","message":"Published topic=\"earnings_change\" event={Identity:{Address:test} Previous:{Channel:{Beneficiary:[0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0] Balance:<nil> Settled:<nil> Loan:<nil> LastUsedNonce:<nil> Timelock:<nil>} LastPromise:{ChannelID:[] Amount:0 Fee:0 Hashlock:[] R:[] Signature:[]} settleInProgress:false registered:false} Current:{Channel:{Beneficiary:[0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0] Balance:+1000000000000 Settled:+9000000 Loan:+12312323 LastUsedNonce:<nil> Timelock:<nil>} LastPromise:{ChannelID:[] Amount:7000000 Fee:0 Hashlock:[] R:[] Signature:[]} settleInProgress:false registered:true}}"} {"level":"info","time":"2020-03-26T13:16:45+01:00","message":"State for {test} already loaded, skipping"} {"level":"info","time":"2020-03-26T13:16:45+01:00","message":"Provider {test} not registered, skipping"} {"level":"info","time":"2020-03-26T13:16:45+01:00","message":"Loaded state for provider {\"test\"}: balance 1000009000000, available balance 1000009000000, unsettled balance 0"} {"level":"debug","time":"2020-03-26T13:16:45+01:00","message":"Published topic=\"earnings_change\" event={Identity:{Address:test} Previous:{Channel:{Beneficiary:[0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0] Balance:<nil> Settled:<nil> Loan:<nil> LastUsedNonce:<nil> Timelock:<nil>} LastPromise:{ChannelID:[] Amount:0 Fee:0 Hashlock:[] R:[] Signature:[]} settleInProgress:false registered:false} Current:{Channel:{Beneficiary:[0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0] Balance:+1000000000000 Settled:+9000000 Loan:+12312323 LastUsedNonce:<nil> Timelock:<nil>} LastPromise:{ChannelID:[] Amount:0 Fee:0 Hashlock:[] R:[] Signature:[]} settleInProgress:false registered:true}}"} {"level":"debug","time":"2020-03-26T13:16:45+01:00","message":"Ignoring service event with status Starting"} {"level":"debug","time":"2020-03-26T13:16:45+01:00","message":"Ignoring service event with status NotRunning"} {"level":"info","time":"2020-03-26T13:16:45+01:00","message":"Loaded state for provider {\"test\"}: balance 1000009000000, available balance 1000009000000, unsettled balance 0"} {"level":"debug","time":"2020-03-26T13:16:45+01:00","message":"Published topic=\"earnings_change\" event={Identity:{Address:test} Previous:{Channel:{Beneficiary:[0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0] Balance:<nil> Settled:<nil> Loan:<nil> LastUsedNonce:<nil> Timelock:<nil>} LastPromise:{ChannelID:[] Amount:0 Fee:0 Hashlock:[] R:[] Signature:[]} settleInProgress:false registered:false} Current:{Channel:{Beneficiary:[0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0] Balance:+1000000000000 Settled:+9000000 Loan:+12312323 LastUsedNonce:<nil> Timelock:<nil>} LastPromise:{ChannelID:[] Amount:0 Fee:0 Hashlock:[] R:[] Signature:[]} settleInProgress:false registered:true}}"} {"level":"debug","time":"2020-03-26T13:16:45+01:00","message":"Ignoring event RegisteredConsumer for provider {\"test\"}"} {"level":"debug","time":"2020-03-26T13:16:45+01:00","message":"Ignoring event Unregistered for provider {\"test\"}"} {"level":"debug","time":"2020-03-26T13:16:45+01:00","message":"Ignoring event InProgress for provider {\"test\"}"} {"level":"debug","time":"2020-03-26T13:16:45+01:00","message":"Ignoring event Promoting for provider {\"test\"}"} {"level":"debug","time":"2020-03-26T13:16:45+01:00","message":"Ignoring event RegistrationError for provider {\"test\"}"} {"level":"info","time":"2020-03-26T13:16:45+01:00","message":"Identity registration event received for provider {\"test\"}"} {"level":"info","time":"2020-03-26T13:16:45+01:00","message":"Loaded state for provider {\"test\"}: balance 1000009000000, available balance 1000009000000, unsettled balance 0"} {"level":"info","time":"2020-03-26T13:16:45+01:00","message":"Identity registration event handled for provider {\"test\"}"} {"level":"info","time":"2020-03-26T13:16:45+01:00","message":"Received accountant promise for {\"test\"}"} {"level":"error","time":"2020-03-26T13:16:45+01:00","message":"Have no info on provider {\"test\"}, skipping"} {"level":"debug","time":"2020-03-26T13:16:45+01:00","message":"Published topic=\"earnings_change\" event={Identity:{Address:test} Previous:{Channel:{Beneficiary:[0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0] Balance:<nil> Settled:<nil> Loan:<nil> LastUsedNonce:<nil> Timelock:<nil>} LastPromise:{ChannelID:[] Amount:0 Fee:0 Hashlock:[] R:[] Signature:[]} settleInProgress:false registered:false} Current:{Channel:{Beneficiary:[0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0] Balance:+1000000000000 Settled:+9000000 Loan:+12312323 LastUsedNonce:<nil> Timelock:<nil>} LastPromise:{ChannelID:[] Amount:0 Fee:0 Hashlock:[] R:[] Signature:[]} settleInProgress:false registered:true}}"} {"level":"info","time":"2020-03-26T13:16:45+01:00","message":"Received accountant promise for {\"test\"}"} {"level":"error","time":"2020-03-26T13:16:45+01:00","message":"provider {\"test\"} not registered, skipping"} {"level":"info","time":"2020-03-26T13:16:45+01:00","message":"Received accountant promise for {\"test\"}"} {"level":"info","time":"2020-03-26T13:16:45+01:00","message":"Accountant promise state updated for provider {\"test\"}"} {"level":"info","time":"2020-03-26T13:16:45+01:00","message":"Received accountant promise for {\"test\"}"} {"level":"info","time":"2020-03-26T13:16:45+01:00","message":"Accountant promise state updated for provider {\"test\"}"} --- FAIL: TestPromiseSettler_handleAccountantPromiseReceived (0.01s) {"level":"debug","time":"2020-03-26T13:16:45+01:00","message":"Published topic=\"earnings_change\" event={Identity:{Address:test} Previous:{Channel:{Beneficiary:[0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0] Balance:+10 Settled:<nil> Loan:<nil> LastUsedNonce:<nil> Timelock:<nil>} LastPromise:{ChannelID:[] Amount:100000 Fee:0 Hashlock:[] R:[] Signature:[]} settleInProgress:false registered:true} Current:{Channel:{Beneficiary:[0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0] Balance:+10 Settled:<nil> Loan:<nil> LastUsedNonce:<nil> Timelock:<nil>} LastPromise:{ChannelID:[] Amount:110000 Fee:0 Hashlock:[] R:[] Signature:[]} settleInProgress:false registered:true}}"} accountant_promise_settler_test.go:343: Error Trace: accountant_promise_settler_test.go:343 accountant_promise_settler_test.go:336 Error: did not expect to receive from settled queue Test: TestPromiseSettler_handleAccountantPromiseReceived {"level":"debug","time":"2020-03-26T13:16:45+01:00","message":"Published topic=\"earnings_change\" event={Identity:{Address:test} Previous:{Channel:{Beneficiary:[0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0] Balance:+10000 Settled:<nil> Loan:<nil> LastUsedNonce:<nil> Timelock:<nil>} LastPromise:{ChannelID:[] Amount:8999 Fee:0 Hashlock:[] R:[] Signature:[]} settleInProgress:false registered:true} Current:{Channel:{Beneficiary:[0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0] Balance:+10000 Settled:<nil> Loan:<nil> LastUsedNonce:<nil> Timelock:<nil>} LastPromise:{ChannelID:[] Amount:9000 Fee:0 Hashlock:[] R:[] Signature:[]} settleInProgress:false registered:true}}"} {"level":"info","time":"2020-03-26T13:16:50+01:00","message":"Listening for settlement events"} {"level":"info","time":"2020-03-26T13:16:50+01:00","message":"Loaded state for provider {\"0xffaedd9c60b2f01d158c12e465d7f1d8f9c3c3e6\"}: balance 1000009000000, available balance 1000009000000, unsettled balance 0"} {"level":"info","time":"2020-03-26T13:16:50+01:00","message":"Provider {0x4a78fbe1a6275bc628a2f382e4bfc77b7cd71012} not registered, skipping"} {"level":"debug","time":"2020-03-26T13:16:50+01:00","message":"Published topic=\"earnings_change\" event={Identity:{Address:0xffaedd9c60b2f01d158c12e465d7f1d8f9c3c3e6} Previous:{Channel:{Beneficiary:[0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0] Balance:<nil> Settled:<nil> Loan:<nil> LastUsedNonce:<nil> Timelock:<nil>} LastPromise:{ChannelID:[] Amount:0 Fee:0 Hashlock:[] R:[] Signature:[]} settleInProgress:false registered:false} Current:{Channel:{Beneficiary:[0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0] Balance:+1000000000000 Settled:+9000000 Loan:+12312323 LastUsedNonce:<nil> Timelock:<nil>} LastPromise:{ChannelID:[] Amount:0 Fee:0 Hashlock:[] R:[] Signature:[]} settleInProgress:false registered:true}}"} {"level":"debug","time":"2020-03-26T13:16:57+01:00","message":"Published topic=\"registration_event_topic\" event={ID:{Address:0x000000001} Status:RegisteredProvider}"} {"level":"debug","time":"2020-03-26T13:16:57+01:00","message":"Published topic=\"registration_event_topic\" event={ID:{Address:0x000000002} Status:RegistrationError}"} {"level":"debug","time":"2020-03-26T13:16:57+01:00","message":"Published topic=\"balance_change\" event={Identity:{Address:0x000000001} Previous:0 Current:100000000}"} {"level":"debug","time":"2020-03-26T13:16:57+01:00","message":"Published topic=\"identity-unlocked\" event=0x000000002"} {"level":"debug","time":"2020-03-26T13:16:57+01:00","message":"Published topic=\"balance_change\" event={Identity:{Address:0x000000002} Previous:0 Current:100000000}"} {"level":"debug","time":"2020-03-26T13:16:57+01:00","message":"Published topic=\"exchange_message_topic\" event={Identity:{Address:0x000000001} AmountPromised:100}"} {"level":"debug","time":"2020-03-26T13:16:57+01:00","message":"Published topic=\"balance_change\" event={Identity:{Address:0x000000001} Previous:100000000 Current:99999900}"} {"level":"debug","time":"2020-03-26T13:16:57+01:00","message":"Published topic=\"balance_change\" event={Identity:{Address:test} Previous:0 Current:100}"} {"level":"debug","time":"2020-03-26T13:16:57+01:00","message":"Published topic=\"balance_change\" event={Identity:{Address:test} Previous:1010 Current:1090}"} {"level":"debug","time":"2020-03-26T13:16:57+01:00","message":"Published topic=\"balance_change\" event={Identity:{Address:test} Previous:1010 Current:990}"} {"level":"error","error":"explosions","time":"2020-03-26T13:16:57+01:00","message":"could not get accountant balance"} {"level":"debug","time":"2020-03-26T13:16:57+01:00","message":"Published topic=\"balance_change\" event={Identity:{Address:test} Previous:0 Current:100000}"} {"level":"debug","time":"2020-03-26T13:16:57+01:00","message":"Published topic=\"balance_change\" event={Identity:{Address:test} Previous:200000 Current:200000}"} {"level":"debug","time":"2020-03-26T13:16:57+01:00","message":"Using lightweight keystore"} {"level":"debug","time":"2020-03-26T13:16:59+01:00","message":"Starting..."} {"level":"debug","time":"2020-03-26T13:16:59+01:00","message":"Loaded accountant state: already promised: 0"} {"level":"debug","time":"2020-03-26T13:16:59+01:00","message":"Stopping..."} {"level":"debug","time":"2020-03-26T13:16:59+01:00","message":"Using lightweight keystore"} {"level":"debug","time":"2020-03-26T13:17:05+01:00","message":"Starting..."} {"level":"debug","time":"2020-03-26T13:17:05+01:00","message":"Loaded accountant state: already promised: 10"} {"level":"debug","time":"2020-03-26T13:17:05+01:00","message":"Invoice received: {1 0 0 0x441Da57A51e42DAB7Daf55909Af93A9b00eEF23C 0x441da57a51e42dab7daf55909af93a9b00eef23c}"} {"level":"debug","time":"2020-03-26T13:17:05+01:00","message":"Calculated price 0. Time component: 0, data component: 0 "} {"level":"debug","time":"2020-03-26T13:17:05+01:00","message":"Estimated tolerance 3, upper bound 0"} {"level":"debug","time":"2020-03-26T13:17:05+01:00","message":"Loaded previous state: already promised: 10"} {"level":"debug","time":"2020-03-26T13:17:05+01:00","message":"Incrementing promised amount by 0"} {"level":"debug","time":"2020-03-26T13:17:05+01:00","message":"Stopping..."} {"level":"debug","time":"2020-03-26T13:17:05+01:00","message":"Using lightweight keystore"} {"level":"debug","time":"2020-03-26T13:17:12+01:00","message":"Starting..."} {"level":"debug","time":"2020-03-26T13:17:12+01:00","message":"Loaded accountant state: already promised: 0"} {"level":"debug","time":"2020-03-26T13:17:12+01:00","message":"Invoice received: {1 0 0 0x441Da57A51e42DAB7Daf55909Af93A9b00eEF23C 0x441da57a51e42dab7daf55909af93a9b00eef23c}"} {"level":"debug","time":"2020-03-26T13:17:12+01:00","message":"Estimated tolerance 3, upper bound 0"} {"level":"debug","time":"2020-03-26T13:17:12+01:00","message":"Loaded previous state: already promised: 0"} {"level":"debug","time":"2020-03-26T13:17:12+01:00","message":"Incrementing promised amount by 0"} {"level":"debug","time":"2020-03-26T13:17:12+01:00","message":"Stopping..."} {"level":"debug","time":"2020-03-26T13:17:12+01:00","message":"Using lightweight keystore"} {"level":"debug","time":"2020-03-26T13:17:14+01:00","message":"Starting..."} {"level":"debug","time":"2020-03-26T13:17:14+01:00","message":"Loaded accountant state: already promised: 0"} {"level":"debug","time":"2020-03-26T13:17:14+01:00","message":"Invoice received: {0 0 0 }"} {"level":"debug","time":"2020-03-26T13:17:14+01:00","message":"Stopping..."} {"level":"debug","time":"2020-03-26T13:17:14+01:00","message":"Calculated price 100000. Time component: 100000, data component: 0 "} {"level":"debug","time":"2020-03-26T13:17:14+01:00","message":"Estimated tolerance 1.611, upper bound 161097"} {"level":"debug","time":"2020-03-26T13:17:14+01:00","message":"No previous invoice grand total, assuming zero"} {"level":"debug","time":"2020-03-26T13:17:14+01:00","message":"Loaded previous state: already promised: 0"} {"level":"debug","time":"2020-03-26T13:17:14+01:00","message":"Incrementing promised amount by 10"} {"level":"debug","time":"2020-03-26T13:17:14+01:00","message":"Loaded previous state: already promised: 100"} {"level":"debug","time":"2020-03-26T13:17:14+01:00","message":"Incrementing promised amount by 10"} {"level":"debug","time":"2020-03-26T13:17:14+01:00","message":"Loaded previous state: already promised: 100"} {"level":"debug","time":"2020-03-26T13:17:14+01:00","message":"Incrementing promised amount by 9"} {"level":"debug","time":"2020-03-26T13:17:14+01:00","message":"Using lightweight keystore"} {"level":"debug","time":"2020-03-26T13:17:21+01:00","message":"Loaded previous state: already promised: 0"} {"level":"debug","time":"2020-03-26T13:17:21+01:00","message":"Incrementing promised amount by 5"} {"level":"debug","time":"2020-03-26T13:17:21+01:00","message":"Using lightweight keystore"} {"level":"debug","time":"2020-03-26T13:17:28+01:00","message":"Loaded previous state: already promised: 0"} {"level":"debug","time":"2020-03-26T13:17:28+01:00","message":"Incrementing promised amount by 0"} {"level":"debug","time":"2020-03-26T13:17:28+01:00","message":"Loaded previous state: already promised: 0"} {"level":"debug","time":"2020-03-26T13:17:28+01:00","message":"Incrementing promised amount by 0"} {"level":"warn","error":"explosions everywhere","time":"2020-03-26T13:17:28+01:00","message":"Failed to send exchange message"} {"level":"debug","time":"2020-03-26T13:17:28+01:00","message":"Loaded previous state: already promised: 0"} {"level":"debug","time":"2020-03-26T13:17:28+01:00","message":"Incrementing promised amount by 15"} {"level":"debug","time":"2020-03-26T13:17:30+01:00","message":"Starting..."} {"level":"debug","time":"2020-03-26T13:17:30+01:00","message":"Stopping..."} {"level":"debug","time":"2020-03-26T13:17:32+01:00","message":"Starting..."} {"level":"debug","time":"2020-03-26T13:17:32+01:00","message":"Stopping..."} {"level":"debug","time":"2020-03-26T13:17:34+01:00","message":"Starting..."} {"level":"debug","time":"2020-03-26T13:17:34+01:00","message":"Stopping..."} {"level":"debug","time":"2020-03-26T13:17:37+01:00","message":"Starting..."} {"level":"debug","time":"2020-03-26T13:17:37+01:00","message":"Stopping..."} {"level":"error","time":"2020-03-26T13:17:37+01:00","message":"Accountant fee too large, asking for 1501 where 1500 is the limit"} {"level":"debug","time":"2020-03-26T13:17:39+01:00","message":"Starting..."} {"level":"debug","time":"2020-03-26T13:17:39+01:00","message":"Stopping..."} {"level":"debug","time":"2020-03-26T13:17:41+01:00","message":"Starting..."} {"level":"debug","time":"2020-03-26T13:17:41+01:00","message":"Calculated price 0. Time component: 0, data component: 0 "} {"level":"debug","time":"2020-03-26T13:17:41+01:00","message":"Being lenient for the first payment, asking for 0"} {"level":"debug","time":"2020-03-26T13:17:41+01:00","message":"Stopping..."} {"level":"debug","time":"2020-03-26T13:17:43+01:00","message":"Starting..."} {"level":"debug","time":"2020-03-26T13:17:43+01:00","message":"Calculated price 5073100. Time component: 5073100, data component: 0 "} {"level":"debug","time":"2020-03-26T13:17:43+01:00","message":"Being lenient for the first payment, asking for 4058480"} {"level":"debug","time":"2020-03-26T13:17:43+01:00","message":"Stopping..."} {"level":"debug","time":"2020-03-26T13:17:45+01:00","message":"Starting..."} {"level":"debug","time":"2020-03-26T13:17:45+01:00","message":"Being lenient for the first payment, asking for 0"} {"level":"debug","time":"2020-03-26T13:17:45+01:00","message":"Stopping..."} {"level":"debug","time":"2020-03-26T13:17:55+01:00","message":"consumer sent exchange message with missing expired hashlock , skipping"} {"level":"debug","time":"2020-03-26T13:17:55+01:00","message":"consumer sent exchange message with missing expired hashlock , skipping"} {"level":"debug","time":"2020-03-26T13:17:55+01:00","message":"consumer sent exchange message with missing expired hashlock , skipping"} {"level":"trace","time":"2020-03-26T13:17:55+01:00","message":"accountant error count 1/0"} {"level":"error","error":"pita bread: internal error","time":"2020-03-26T13:17:55+01:00","message":"unknown accountant error encountered"} {"level":"trace","time":"2020-03-26T13:17:55+01:00","message":"accountant error count 1/0"} {"level":"trace","time":"2020-03-26T13:17:55+01:00","message":"accountant error count 1/1"} {"level":"warn","error":"internal error","time":"2020-03-26T13:17:55+01:00","message":"accountant error, will retry"} {"level":"trace","time":"2020-03-26T13:17:55+01:00","message":"accountant error count 1/0"} {"level":"trace","time":"2020-03-26T13:17:55+01:00","message":"accountant error count 1/1"} {"level":"warn","error":"hashlock missmatch","time":"2020-03-26T13:17:55+01:00","message":"accountant error, will retry"} {"level":"error","error":"unknown error","time":"2020-03-26T13:17:55+01:00","message":"unknown accountant error encountered"} {"level":"info","time":"2020-03-26T13:17:55+01:00","message":"Recovering R..."} {"level":"info","time":"2020-03-26T13:17:55+01:00","message":"R recovered, will reveal..."} {"level":"info","time":"2020-03-26T13:17:55+01:00","message":"R recovered successfully"} {"level":"info","time":"2020-03-26T13:17:55+01:00","message":"Recovering R..."} {"level":"info","time":"2020-03-26T13:17:55+01:00","message":"R recovered, will reveal..."} {"level":"info","time":"2020-03-26T13:17:55+01:00","message":"Recovering R..."} {"level":"debug","time":"2020-03-26T13:17:55+01:00","message":"Calculated price 3000000. Time component: 3000000, data component: 0 "} {"level":"debug","time":"2020-03-26T13:17:55+01:00","message":"Calculated price 180000000. Time component: 180000000, data component: 0 "} {"level":"debug","time":"2020-03-26T13:17:55+01:00","message":"Calculated price 7000000. Time component: 0, data component: 7000000 "} {"level":"debug","time":"2020-03-26T13:17:55+01:00","message":"Calculated price 10000000. Time component: 3000000, data component: 7000000 "} FAIL coverage: 54.3% of statements FAIL github.com/mysteriumnetwork/node/session/pingpong 70.053s ```
