Stellar often returns [op_over_source_max] despite return ratio > 1

[Reidmcc]

Describe the bug When the bot finds a trade opportunity meeting the minimum ratio parameter and submits the path payment, Stellar will often, in fact usually, return [op_over_source_max]. This error means that the requested path would cost more than the maximum specified in the operation, but that shouldn't be the case when the ratios line up.

To Reproduce

1. Run Rockfish with a profitable minimum ratio, e.g. MIN_RATIO=1.0005. Setting the payment at a losing rate works fine, so the transactions are valid
2. Wait for a trade opportunity to trigger
3. Check the log; either the payment goes through or [op_over_source_max] is returned as the error.

Expected behavior I expect the payments to mostly go through. It's possible that the orders enabling the path are taken before my transaction hits the network, but it seems like that shouldn't be the most common outcome.

Notes I've checked the ratio math; that's not the problem. Next step is probably to run at a higher ratio and see if the additional padding takes care of it, or run at a larger amount to preclude rounding errors as a possible cause.

Version

  version: min-value:93c410c2-dirty
  git branch: min-value
  git hash: 93c410c2c644ed4e47c9dbcdd3f70c6f14f24cd5-dirty
  build date: 20190130T025818Z
  GOOS: linux
  GOARCH: amd64

[Reidmcc]

Experimented with asking the network for payment paths and amounts. That was much slower, presumably due to Horizon checking a ton of paths, and didn't work any better.

[Reidmcc]

Tried increasing the cycle amount, which did not resolve the issue but does sometimes get payments through at ratios as low as 1.00013. Will run at this setting longer and see what the trend is.

[Reidmcc]

This issue may be fixed in Horizon release 0.16.0, see the change "Fixed effects ingestion of circular payments". The fix looks to have been merged by stellar/go PR #807.

Leaving this issue open pending results after the deployment of 0.16.0 to the Horizon servers I use.

[ghost]

Hey there @Reidmcc

I'm not sure why, but it keeps saying op_over_source_max, even though now horizon's version is 0.16.0-cffdea30514f951136e7dbd947dbc6c013c50868.

2019/02/19 15:11:33 logging to file: ./log/log_20190219T151133-03.log
2019/02/19 15:11:33 Starting Rockfish in Arbitrage Cycle mode: master:84185981-dirty [84185981b10182fd7036eeafc2657924175324bb-dirty]
2019/02/19 15:11:33 will run unbounded iterations
2019/02/19 15:11:33 configs:
2019/02/19 15:11:33      TRADING_SECRET_SEED: [secret key to account GBQCL655S76TSFG45WPLLCDTPOJWUOMZCWKAIBT7GFRWHMYSJLQMT4EQ]
2019/02/19 15:11:33      SOURCE_SECRET_SEED: 
2019/02/19 15:11:33      TICK_INTERVAL_SECONDS: 1
2019/02/19 15:11:33      HORIZON_URL: https://horizon.stellar.org
2019/02/19 15:11:33 
2019/02/19 15:11:33 configs:
2019/02/19 15:11:33      HOLD_ASSET_CODE: XLM
2019/02/19 15:11:33      HOLD_ASSET_ISSUER: 
2019/02/19 15:11:33      MIN_RATIO: 1.0001
2019/02/19 15:11:33      USE_BALANCE: true
2019/02/19 15:11:33      STATIC_AMOUNT: 0
2019/02/19 15:11:33      MIN_AMOUNT: 1
2019/02/19 15:11:33      ASSETS: [{CODE:BTC ISSUER:GBSTRH4QOTWNSVA6E4HFERETX4ZLSR3CIUBLK7AXYII277PFJC4BBYOG GROUP:1} {CODE:ETH ISSUER:GBSTRH4QOTWNSVA6E4HFERETX4ZLSR3CIUBLK7AXYII277PFJC4BBYOG GROUP:1} {CODE:BTC ISSUER:GBSTRH4QOTWNSVA6E4HFERETX4ZLSR3CIUBLK7AXYII277PFJC4BBYOG GROUP:2} {CODE:USD ISSUER:GBSTRUSD7IRX73RQZBL3RQUH6KS3O4NYFY3QCALDLZD77XMZOPWAVTUK GROUP:2} {CODE:ETH ISSUER:GBSTRH4QOTWNSVA6E4HFERETX4ZLSR3CIUBLK7AXYII277PFJC4BBYOG GROUP:3} {CODE:USD ISSUER:GBSTRUSD7IRX73RQZBL3RQUH6KS3O4NYFY3QCALDLZD77XMZOPWAVTUK GROUP:3} {CODE:ETH ISSUER:GBETHKBL5TCUTQ3JPDIYOZ5RDARTMHMEKIO2QZQ7IOZ4YC5XV3C2IKYU GROUP:4} {CODE:CNY ISSUER:GAREELUB43IRHWEASCFBLKHURCGMHE5IF6XSE7EXDLACYHGRHM43RFOX GROUP:4} {CODE:CNY ISSUER:GAREELUB43IRHWEASCFBLKHURCGMHE5IF6XSE7EXDLACYHGRHM43RFOX GROUP:5} {CODE:XCN ISSUER:GCNY5OXYSY4FKHOPT2SPOQZAOEIGXB5LBYW3HVU3OWSTQITS65M5RCNY GROUP:5} {CODE:BTC ISSUER:GCNSGHUCG5VMGLT5RIYYZSO7VQULQKAJ62QA33DBC5PPBSO57LFWVV6P GROUP:6} {CODE:LTC ISSUER:GCNSGHUCG5VMGLT5RIYYZSO7VQULQKAJ62QA33DBC5PPBSO57LFWVV6P GROUP:6}]
2019/02/19 15:11:33 No Source Account Set
2019/02/19 15:11:33 generating path list: 
2019/02/19 15:11:33 added path: XLM -> BTC | GBSTRH4QOTWNSVA6E4HFERETX4ZLSR3CIUBLK7AXYII277PFJC4BBYOG -> ETH | GBSTRH4QOTWNSVA6E4HFERETX4ZLSR3CIUBLK7AXYII277PFJC4BBYOG -> XLM
2019/02/19 15:11:33 added path: XLM -> ETH | GBSTRH4QOTWNSVA6E4HFERETX4ZLSR3CIUBLK7AXYII277PFJC4BBYOG -> BTC | GBSTRH4QOTWNSVA6E4HFERETX4ZLSR3CIUBLK7AXYII277PFJC4BBYOG -> XLM
2019/02/19 15:11:33 added path: XLM -> BTC | GBSTRH4QOTWNSVA6E4HFERETX4ZLSR3CIUBLK7AXYII277PFJC4BBYOG -> USD | GBSTRUSD7IRX73RQZBL3RQUH6KS3O4NYFY3QCALDLZD77XMZOPWAVTUK -> XLM
2019/02/19 15:11:33 added path: XLM -> USD | GBSTRUSD7IRX73RQZBL3RQUH6KS3O4NYFY3QCALDLZD77XMZOPWAVTUK -> BTC | GBSTRH4QOTWNSVA6E4HFERETX4ZLSR3CIUBLK7AXYII277PFJC4BBYOG -> XLM
2019/02/19 15:11:33 added path: XLM -> ETH | GBSTRH4QOTWNSVA6E4HFERETX4ZLSR3CIUBLK7AXYII277PFJC4BBYOG -> USD | GBSTRUSD7IRX73RQZBL3RQUH6KS3O4NYFY3QCALDLZD77XMZOPWAVTUK -> XLM
2019/02/19 15:11:33 added path: XLM -> USD | GBSTRUSD7IRX73RQZBL3RQUH6KS3O4NYFY3QCALDLZD77XMZOPWAVTUK -> ETH | GBSTRH4QOTWNSVA6E4HFERETX4ZLSR3CIUBLK7AXYII277PFJC4BBYOG -> XLM
2019/02/19 15:11:33 added path: XLM -> ETH | GBETHKBL5TCUTQ3JPDIYOZ5RDARTMHMEKIO2QZQ7IOZ4YC5XV3C2IKYU -> CNY | GAREELUB43IRHWEASCFBLKHURCGMHE5IF6XSE7EXDLACYHGRHM43RFOX -> XLM
2019/02/19 15:11:33 added path: XLM -> CNY | GAREELUB43IRHWEASCFBLKHURCGMHE5IF6XSE7EXDLACYHGRHM43RFOX -> ETH | GBETHKBL5TCUTQ3JPDIYOZ5RDARTMHMEKIO2QZQ7IOZ4YC5XV3C2IKYU -> XLM
2019/02/19 15:11:33 added path: XLM -> CNY | GAREELUB43IRHWEASCFBLKHURCGMHE5IF6XSE7EXDLACYHGRHM43RFOX -> XCN | GCNY5OXYSY4FKHOPT2SPOQZAOEIGXB5LBYW3HVU3OWSTQITS65M5RCNY -> XLM
2019/02/19 15:11:33 added path: XLM -> XCN | GCNY5OXYSY4FKHOPT2SPOQZAOEIGXB5LBYW3HVU3OWSTQITS65M5RCNY -> CNY | GAREELUB43IRHWEASCFBLKHURCGMHE5IF6XSE7EXDLACYHGRHM43RFOX -> XLM
2019/02/19 15:11:33 added path: XLM -> BTC | GCNSGHUCG5VMGLT5RIYYZSO7VQULQKAJ62QA33DBC5PPBSO57LFWVV6P -> LTC | GCNSGHUCG5VMGLT5RIYYZSO7VQULQKAJ62QA33DBC5PPBSO57LFWVV6P -> XLM
2019/02/19 15:11:33 added path: XLM -> LTC | GCNSGHUCG5VMGLT5RIYYZSO7VQULQKAJ62QA33DBC5PPBSO57LFWVV6P -> BTC | GCNSGHUCG5VMGLT5RIYYZSO7VQULQKAJ62QA33DBC5PPBSO57LFWVV6P -> XLM
2019/02/19 15:11:33 Starting the trader bot...
2019/02/19 15:11:33 ----------------------------------------------------------------------------------------------------
2019/02/19 15:11:34 Going into the cycle XLM balance was 32.5845301
2019/02/19 15:11:35 Return ratio | Cycle amount for path XLM -> BTC - > ETH -> XLM was 1.0003229 | 115.7554585
2019/02/19 15:11:35 
2019/02/19 15:11:35 ***** Minimum profit ratio was met, proceeding to payment! *****
2019/02/19 15:11:35 
2019/02/19 15:11:35 
2019/02/19 15:11:35 Best path was XLM -> BTC - > ETH XLM -> with return ratio of 1.0003229
2019/02/19 15:11:35 balance return to payWithBalance received amount of: 32.5845301
2019/02/19 15:11:35 after checking for lower maxAmount, payAmount set to: 32.5845301
2019/02/19 15:11:35 receiveAmount string set to: 32.5845301
2019/02/19 15:11:35 maxPayAmount string set to: 32.5845201
2019/02/19 15:11:35 Raw build.PayWith set to: {{  %!s(bool=true)} 32.5845201 [{BTC GBSTRH4QOTWNSVA6E4HFERETX4ZLSR3CIUBLK7AXYII277PFJC4BBYOG %!s(bool=false)} {ETH GBSTRH4QOTWNSVA6E4HFERETX4ZLSR3CIUBLK7AXYII277PFJC4BBYOG %!s(bool=false)}]}
2019/02/19 15:11:35 reloading sequence number
2019/02/19 15:11:36 Pre-XDR raw was: &{%!s(*xdr.Transaction=&{{0 0xc00031a500} 100 96886946004992037 <nil> {0 <nil> <nil> <nil> <nil>} [{<nil> {2 <nil> <nil> 0xc0003a8000 <nil> <nil> <nil> <nil> <nil> <nil> <nil> <nil>}}] {0}}) Public Global Stellar Network ; September 2015 %!s(uint64=100)}
2019/02/19 15:11:36 tx XDR: AAAAAGAl+72X/TkU3O2etYhze5NqOZkVlAQGfzFjY7MSSuDJAAAAZAFYNioAAAAlAAAAAAAAAAAAAAABAAAAAAAAAAIAAAAAAAAAABNsANEAAAAAYCX7vZf9ORTc7Z61iHN7k2o5mRWUBAZ/MWNjsxJK4MkAAAAAAAAAABNsATUAAAACAAAAAUJUQwAAAAAAZTifkHTs2VQeJw5SRJO/MrlHYkUCtXwXwhGv/eVIuBAAAAABRVRIAAAAAABlOJ+QdOzZVB4nDlJEk78yuUdiRQK1fBfCEa/95Ui4EAAAAAAAAAABEkrgyQAAAEDAoNF8qP2RVM2hy+9NHKF2Cc/7DtTb+WekYG4+P9HFz5lSruYyBgvKoppwLcNoomiGq3TDcWRlFkNSDHNifLUG
2019/02/19 15:11:36 submitting tx XDR to network (async)
2019/02/19 15:11:38 (async) error: result code details: tx code =%!(EXTRA string=tx_failed, string=, opcodes =, []string=[op_over_source_max])

P.S. Sorry for my English, as my first language is Portuguese.

[Reidmcc]

Hi @dmcclccam. That's actually expected behavior for now. The [op_over_source_max] error's meaning is that the payment would cost more than you specified in your transaction, so if it processed the payment you would lose money. The normal reason for this is if someone else took one of the offers Rockfish is trying to use before your transaction gets there. I'm investigating whether there are other causes. The last paragraph of the walkthrough has more details.

However, you can trade through this. My Rockfish gets [op_over_source_max] on more than 90% of its attempts and I end up with 3-4 successful cycles a day.

I'm currently working on an upgrade that uses streaming to synchronize Rockfish's cycles with Stellar's ledger updates, and uses multi-threading to make the return ratio calculations much faster. I'm hoping to push the upgrade to master in the next couple of days. I'll be sure to let you know when it's up.

[ghost]

Thanks for the reply!

[Reidmcc]

@dmcclccam the streaming-synced upgrade is now live as version 0.3.0

[ghost]

Thank you for alerting me @Reidmcc It's working indeed! I wish I knew Go so I could help with the development...

[Reidmcc]

@dmcclccam just an fyi: Rockfish 0.3.0 has a bug that causes it to continuously use more CPU the longer it runs. I have a bug fix release, 0.3.1

[Reidmcc]

closing this issue; this is probably not on Rockfish's end, but rather a correct message from Stellar that somone got the the trade first.

[dpblnt]

op_over_source_max still occurs But I think the assumption that the orders were taken by someone else is not correct, since here is 2 of my consecutive failed attempts:

AAAAALfVm+jT628T1XNDAdy4eQyeqUbx13x/GzP1XyLdA0OGAAAAZAJMPRgAAAAFAAAAAAAAAAAAAAABAAAAAAAAAAIAAAAAAAAAAANVEX0AAAAAt9Wb6NPrbxPVc0MB3Lh5DJ6pRvHXfH8bM/VfIt0DQ4YAAAAAAAAAAANVEX0AAAACAAAAAVVTREMAAAAAO5kROA7+mIugqJAOsc/kTzZvfb6Ua+0HckD39iTfFcUAAAABQlRDAAAAAADekC0cBlVKatzXqdspgJ+E3YExehEcR1hneTXow7O67QAAAAAAAAAB3QNDhgAAAEAID0DBaPRg0uWBPAO4RzYy6x87QcdhgHUTqgyH4M3iriOrSi3mg+Y9mRt9Aj3nkrvypzttUs7TMc41cT87CK4B

AAAAALfVm+jT628T1XNDAdy4eQyeqUbx13x/GzP1XyLdA0OGAAAAZAJMPRgAAAAGAAAAAAAAAAAAAAABAAAAAAAAAAIAAAAAAAAAAANVEX0AAAAAt9Wb6NPrbxPVc0MB3Lh5DJ6pRvHXfH8bM/VfIt0DQ4YAAAAAAAAAAANVEX0AAAACAAAAAVVTREMAAAAAO5kROA7+mIugqJAOsc/kTzZvfb6Ua+0HckD39iTfFcUAAAABQlRDAAAAAADekC0cBlVKatzXqdspgJ+E3YExehEcR1hneTXow7O67QAAAAAAAAAB3QNDhgAAAECzc1TYQpHrmbWfNOPvMpv30H4HUbQ6b9DFmfSOc/fNJW9rWnc1hkeF2oE4UJMabvmoNQ//+pZn1TVoRNHdgbwH

You can see the same orders are still there 7 seconds later.

From Horizon API Reference, OpOverSourceMax PATH_PAYMENT_STRICT_RECEIVE_OVER_SENDMAX The paths that could send destination amount of destination asset would exceed send max.

This might mean, that along the path we are trying to consume greater volume than there is order for. Just a guess.

It is possible that these guys solved it