payments: time component overflow

[zolia]

Consumer disconnects at very first invoice. Upper bound is not reached, but ignored.

Ver: fc0fc64 (latest master)

provider to test with: 0x2bc8193504a60c1d9746006a9eb3ade5d6b7f51b

consumer:

2020-03-29T12:48:15.890 DBG communication/nats/receiver.go:54        > Message "86ddc481-b700-4e73-b2cd-3bd706842f6d.session-invoice" received: {"payload":{"invoice":{"AgreementID":12462307641529119526,"AgreementTotal":14757395258967640064,"TransactorFee":0,"Hashlock":"3f919839628b5cfcab01990f0932158852caf138bb353a1c628aed3c170e3347","Provider":"0x2bc8193504a60c1d9746006a9eb3ade5d6b7f51b"}},"signature":"djWL6ijdfsY8Ysi0uA5YZJFXTCZarLVLg5q8fRqSxx0i1Kw3say6uS607O/8xWR8Y9fsTMbB4IkoCkLE9zJPpQE="}
2020-03-29T12:48:15.891 DBG session/pingpong/invoice_payer.go:148    > Invoice received: {12462307641529119526 14757395258967640064 0 3f919839628b5cfcab01990f0932158852caf138bb353a1c628aed3c170e3347 0x2bc8193504a60c1d9746006a9eb3ade5d6b7f51b}
2020-03-29T12:48:15.891 DBG session/pingpong/price_calculator.go:66  > Calculated price 137354. Time component: 635, data component: 136719
2020-03-29T12:48:15.891 DBG session/pingpong/invoice_payer.go:234    > Estimated tolerance 3, upper bound 412062
2020-03-29T12:48:15.891 WRN session/pingpong/invoice_payer.go:237    > Provider trying to overcharge
2020-03-29T12:48:15.892 ERR core/connection/manager.go:585           > Payment error error="invoice not valid: provider is overcharging"
2020-03-29T12:48:15.892 INF core/connection/manager.go:552           > Connection state: Connecting → Disconnecting
2020-03-29T12:48:15.892 TRC core/connection/manager.go:326           > Connection cleaning up: (2/2)
2020-03-29T12:48:15.892 TRC core/connection/manager.go:313           > Cleaning: payments
2020-03-29T12:48:15.892 DBG session/pingpong/invoice_payer.go:313    > Stopping...
2020-03-29T12:48:15.892 TRC core/connection/manager.go:316           > Cleaning: payments DONE
2020-03-29T12:48:15.892 TRC core/connection/manager.go:326           > Connection cleaning up: (1/2)
2020-03-29T12:48:15.893 TRC core/connection/manager.go:479           > Cleaning: publishing session ended status

provider:

2020-03-29T12:48:20.014 DBG communication/nats/receiver.go:142       > Request "86ddc481-b700-4e73-b2cd-3bd706842f6d.session-create" response: {"payload":{"success":true,"message":"","session":{"id":"889c4c5f-08ed-4abe-8a24-a8dd48c05b7f","config":{"local_port":0,"remote_port":0,"ports":null,"provider":{"public_key":"Ghf5YUn49pS/0SPFZVJ8pVUULbKIp5YrQ7C4PbLk9m4=","endpoint":"88.119.191.24:49343"},"consumer":{"ip_address":"10.182.0.2/24","dns_ips":"10.182.0.1","connect_delay":2000}}},"paymentInfo":{"supported":"v3"}},"signature":"sO0h8EK1S4lS9fGSIjBRtTcC+NLlrW/3G2UDye0ZUz4f4MlXQMQX417Og8Zd9oDxjVK4GBwHSTQrthxlohrPsAE="}
2020-03-29T12:48:21.457 DBG session/pingpong/price_calculator.go:66  > Calculated price 18446744073709549250. Time component: 18446744073709549246, data component: 4
2020-03-29T12:48:21.459 DBG session/pingpong/invoice_tracker.go:472  > Being lenient for the first payment, asking for 14757395258967640064
2020-03-29T12:48:21.487 DBG communication/nats/sender.go:56          > Message "86ddc481-b700-4e73-b2cd-3bd706842f6d.session-invoice" sending: {"payload":{"invoice":{"AgreementID":12462307641529119526,"AgreementTotal":14757395258967640064,"TransactorFee":0,"Hashlock":"3f919839628b5cfcab01990f0932158852caf138bb353a1c628aed3c170e3347","Provider":"0x2bc8193504a60c1d9746006a9eb3ade5d6b7f51b"}},"signature":"djWL6ijdfsY8Ysi0uA5YZJFXTCZarLVLg5q8fRqSxx0i1Kw3say6uS607O/8xWR8Y9fsTMbB4IkoCkLE9zJPpQE="}
2020-03-29T12:49:11.489 INF session/pingpong/invoice_tracker.go:504  > did not get paid for invoice with hashlock 3f919839628b5cfcab01990f0932158852caf138bb353a1c628aed3c170e3347, incrementing failure count
2020-03-29T12:49:21.544 DBG session/pingpong/price_calculator.go:66  > Calculated price 6971. Time component: 18446744073709549210, data component: 9377

[vkuznecovas]

provider is obviously calculating something very wrong.

2020-03-29T12:48:21.457 DBG session/pingpong/price_calculator.go:66 > Calculated price 18446744073709549250. Time component: 18446744073709549246, data component: 4

[vkuznecovas]

could be related to time tracking?

[zolia]

This is related with older consumer identity at some point. Did test creating a new identity for consumer - everything works.

But can reproduce this old identity behaviour 100%.

[zolia]

Still getting good connects with old identity too:

2020-03-29T14:25:14.219 DBG session/pingpong/price_calculator.go:66  > Calculated price 1266. Time component: 1256, data component: 10
2020-03-29T14:25:14.221 DBG session/pingpong/invoice_tracker.go:472  > Being lenient for the first payment, asking for 1012
2020-03-29T14:25:14.236 DBG communication/nats/sender.go:56          > Message "e5fcf4c1-92d7-4d90-84bd-6d6c2379d51b.session-invoice" sending: {"payload":{"invoice":{"AgreementID":2818621502970843408,"AgreementTotal":1012,"TransactorFee":0,"Hashlock":"9bbcf0992e89449b9f82d5f9762a1e9e14af3bff8fc69412f700b1663fe4f77f","Provider":"0x2bc8193504a60c1d9746006a9eb3ade5d6b7f51b"}},"signature":"HMtxD7zUs8b93vj773bBXNaFtWg52JkyYgd1E7kmPK1c+8kLzzr4SN47LnKgETNMGCPgWg6+WRm3fGu17hcfdgA="}

[vkuznecovas]

this is related to the invoice being sent with maxuint according to your logs, not something else. The question is why this time component is recalculated like so.

[zolia]

we are till getting this, provider log:

2020-03-31T17:18:47.897 INF session/mbtime/mbtime_linux.go:27        > Getting nanotime
2020-03-31T17:18:47.927 ERR services/openvpn/service/proxy.go:54     > Failed to write/read a stream to/from natProxy error="read udp 127.0.0.1:52786->127.0.0.1:41819: read: connection refused"
2020-03-31T17:18:53.640 ERR services/openvpn/service/proxy.go:54     > Failed to write/read a stream to/from natProxy error="write udp 127.0.0.1:52786->127.0.0.1:41819: write: connection refused"
2020-03-31T17:18:56.818 INF session/mbtime/mbtime_linux.go:36        > nanotimeRes ts.Sec*1e9=-1755311616, ts.Nsec=%!(EXTRA int32=930493073)
2020-03-31T17:18:56.818 DBG services/openvpn/service/proxy.go:57     > Total bytes transferred from 78.157.70.161:47487 to 127.0.0.1:41819: 108
2020-03-31T17:18:56.818 DBG services/openvpn/service/proxy.go:57     > Total bytes transferred from 127.0.0.1:41819 to 78.157.70.161:47487: 0
2020-03-31T17:18:56.819 INF session/mbtime/mbtime.go:66              > Subbing: u.ns 1.710218588s
2020-03-31T17:18:56.820 INF session/mbtime/mbtime.go:67              > Subbing: t.s -824.818543ms
2020-03-31T17:18:56.822 INF session/mbtime/mbtime.go:69              > Subbing: d -2.535037131s
2020-03-31T17:18:56.830 INF session/pingpong/price_calculator.go:45  > calculating amount based on timePassed: -2.535037131s, bytesTransferred.Sum(), 0
2020-03-31T17:18:56.832 DBG session/pingpong/price_calculator.go:67  > Calculated price 18446744073709549503. Time component: 18446744073709549503, data component: 0
2020-03-31T17:18:56.834 DBG session/pingpong/invoice_tracker.go:472  > Being lenient for the first payment, asking for 14757395258967640064