search

ExchangeUnion / xud

Exchange Union Daemon 🔁 ⚡️
https://exchangeunion.com
GNU Affero General Public License v3.0
115 stars 49 forks source link

Order stuck on-hold (arby exits with `Unrecoverable error`) #1835

Closed kilrau closed 4 years ago

kilrau commented 4 years ago 
020-08-02 11:43:58.5858 [OpenDEX] info: All OpenDEX orders have been removed
2020-08-02 11:43:59.5959 [Centralized] info: All CEX orders have been removed
2020-08-02 11:44:04.044 [Centralized] warn: Price feed lost. Retrying in 5000ms.
2020-08-02 11:44:04.044 [Centralized] trace: ETHBTC stream closed
2020-08-02 11:44:04.044 [OpenDEX] info: All OpenDEX orders have been removed
2020-08-02 11:44:04.044 [Centralized] info: All CEX orders have been removed
2020-08-02 11:44:09.099 [OpenDEX] trace: Base asset balance 0.13336819 (maxinbound: 90071992.54740991, maxoutbound: 0.13336819) and quote asset balance 0.01070385 (maxinbound: 0.00337293, maxoutbound: 0.01055893).
2020-08-02 11:44:09.099 [GLOBAL] info: Unrecoverable error. Cleaning up
2020-08-02 11:44:09.099 [Centralized] trace: ETHBTC stream closed
2020-08-02 11:44:09.099 [Centralized] warn: Failed to remove orders: binance GET https://api.binance.com/api/v3/openOrders?timestamp=1596368649941&recvWindow=5000&symbol=ETHBTC&signature=ef469f8cb63492195219968bfd8943830ded5a695710c78e697996fc927fa114 system request to https://api.binance.com/api/v3/openOrders?timestamp=1596368649941&recvWindow=5000&symbol=ETHBTC&signature=ef469f8cb63492195219968bfd8943830ded5a695710c78e697996fc927fa114 failed, reason: read ECONNRESET - retrying in 1000ms
2020-08-02 11:44:09.099 [OpenDEX] info: All OpenDEX orders have been removed
2020-08-02 11:44:11.1111 [Centralized] info: All CEX orders have been removed
Shutdown complete. Goodbye, Arby.
2020-08-02 11:44:44,460 INFO exited: arby (exit status 0; expected)

Full logs from 35 mins before crash: https://paste.ubuntu.com/p/kx6vbVDwPD/

kilrau commented 4 years ago

Interestingly, even after restarting arby, it can't connect to the price stream: https://paste.ubuntu.com/p/sssJG9wsRq/

kilrau commented 4 years ago

After debugging this:

Simnet (correct)

bash-5.0# cat supervisord.conf
[supervisord]
nodaemon=true
logfile=/app/supervisord.log
childlogdir=/app
user=root

[program:arby]
stdout_logfile=/dev/stdout
stdout_logfile_maxbytes=0
command=/app/entrypoint.sh
stopsignal=SIGINT
autorestart=true
bash-5.0# pwd
/etc/supervisor/conf.d

Mainnet (missing):

bash-5.0# cat supervisord.conf 
[supervisord]
nodaemon=true
logfile=/app/supervisord.log
childlogdir=/app
user=root

[program:arby]
stdout_logfile=/dev/stdout
stdout_logfile_maxbytes=0
command=/app/entrypoint.sh
stopsignal=SIGINT
reliveyy commented 4 years ago

@erkarl @kilrau I have manully built arby:1.1.0 through bot.

Mainnet is using arby:1.1.0 and Simnet is using arby:latest. The most recent PR updates images/arby folder content without modifying template.py in utils. So the old arby:1.1.0 image was untouched. And this is an expected behavior. TBH it's easy to forget updating existing image when you updated some image's build files.

kilrau commented 4 years ago

Arby was fine for about an hour, then it lost the binance price stream again and did shutdown with unrecoverable error again:

2020-08-03 08:50:53.5353 [OpenDEX] info: All OpenDEX orders have been removed
2020-08-03 08:50:53.5353 [Centralized] info: All CEX orders have been removed
2020-08-03 08:50:58.5858 [OpenDEX] trace: Base asset balance 0.13336819 (maxinbound: 90071992.54740991, maxoutbound: 0.13336819) and quote asset balance 0.01070385 (maxinbound: 0.00337293, maxoutbound: 0.01055893).
2020-08-03 08:51:01.011 [GLOBAL] info: Unrecoverable error. Cleaning up
2020-08-03 08:51:01.011 [Centralized] trace: ETHBTC stream closed
2020-08-03 08:51:01.011 [OpenDEX] info: All OpenDEX orders have been removed
2020-08-03 08:51:02.022 [Centralized] info: All CEX orders have been removed
Shutdown complete. Goodbye, Arby.
2020-08-03 08:51:02,207 INFO exited: arby (exit status 0; expected)

Restart fixed it immediately. So in my opinion there is still something wrong with how arby tries to recover the binance price stream since there are scenarios where it can't recover the price stream at run-time but can after restart.

kilrau commented 4 years ago

Didn't see this again. Closing.

kilrau commented 4 years ago

And this one is back again, arby is stuck in this loop:

2020-08-20 07:21:26.2626 [GLOBAL] info: Starting. Hello, Arby.
2020-08-20 07:21:26.2626 [GLOBAL] info: Running with config:
LIVE_CEX: false
LOG_LEVEL: trace
DATA_DIR: /root/.arby
OPENDEX_CERT_PATH: /root/.xud/tls.cert
OPENDEX_RPC_HOST: xud
OPENDEX_RPC_PORT: 28886
MARGIN: 0.03
BASEASSET: BTC
QUOTEASSET: USDT
TEST_CENTRALIZED_EXCHANGE_BASEASSET_BALANCE: 123
TEST_CENTRALIZED_EXCHANGE_QUOTEASSET_BALANCE: 321
2020-08-20 07:21:26.2626 [Centralized] info: Base asset balance 123 and quote asset balance 321
2020-08-20 07:21:27.2727 [OpenDEX] trace: Base asset balance 2.48309839 (maxinbound: 2.4668111, maxoutbound: 2.43309839) and quote asset balance 1016.435147 (maxinbound: 90071992.54740991, maxoutbound: 1016.435147).
2020-08-20 07:21:28.2828 [Centralized] trace: BTCUSDT established connection to wss://stream.binance.com:9443/ws/btcusdt@aggTrade
2020-08-20 07:21:28.2828 [Centralized] trace: heartbeat from BTCUSDT socket
2020-08-20 07:21:28.2828 [Centralized] trace: New price: 11740.52
2020-08-20 07:21:28.2828 [OpenDEX] trace: Starting to update OpenDEX orders
2020-08-20 07:21:28.2828 [OpenDEX] trace: Replacing BTC/USDT buy order with id arby-BTC/USDT-buy-order, quantity 0.08925254 and price 11388.3044
2020-08-20 07:21:28.2828 [OpenDEX] trace: Replacing BTC/USDT sell order with id arby-BTC/USDT-sell-order, quantity 0.0273412 and price 12092.7356
2020-08-20 07:21:28.2828 [Centralized] trace: New price: 11740.52
2020-08-20 07:21:28.2828 [GLOBAL] info: Unrecoverable error. Cleaning up.
2020-08-20 07:21:28.2828 [Centralized] info: Removing CEX orders
2020-08-20 07:21:28.2828 [Centralized] trace: BTCUSDT stream closed
2020-08-20 07:21:28.2828 [OpenDEX] info: All OpenDEX orders have been removed
2020-08-20 07:21:29.2929 [Centralized] info: Finished removing CEX orders
Shutdown complete. Goodbye, Arby.
2020-08-20 07:21:29,184 INFO exited: arby (exit status 0; expected)
2020-08-20 07:21:30,188 INFO spawned: 'arby' with pid 86

> market-maker-tools@1.1.5 start:arby /app
> npm run compile && node dist/arby.js

> market-maker-tools@1.1.5 compile /app
> npm run lint && tsc && cross-os postcompile

2020-08-20 07:21:31,511 INFO success: arby entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)

> market-maker-tools@1.1.5 lint /app
> eslint . --ext .js,.ts

2020-08-20 07:21:48.4848 [GLOBAL] info: Starting. Hello, Arby.
2020-08-20 07:21:48.4848 [GLOBAL] info: Running with config:
LIVE_CEX: false
LOG_LEVEL: trace
DATA_DIR: /root/.arby
OPENDEX_CERT_PATH: /root/.xud/tls.cert
OPENDEX_RPC_HOST: xud
OPENDEX_RPC_PORT: 28886
MARGIN: 0.03
BASEASSET: BTC
QUOTEASSET: USDT
TEST_CENTRALIZED_EXCHANGE_BASEASSET_BALANCE: 123
TEST_CENTRALIZED_EXCHANGE_QUOTEASSET_BALANCE: 321
2020-08-20 07:21:48.4848 [Centralized] info: Base asset balance 123 and quote asset balance 321
2020-08-20 07:21:48.4848 [OpenDEX] trace: Base asset balance 2.48309839 (maxinbound: 2.4668111, maxoutbound: 2.43309839) and quote asset balance 1016.435147 (maxinbound: 90071992.54740991, maxoutbound: 1016.435147).
2020-08-20 07:21:49.4949 [Centralized] trace: BTCUSDT established connection to wss://stream.binance.com:9443/ws/btcusdt@aggTrade
2020-08-20 07:21:49.4949 [Centralized] trace: heartbeat from BTCUSDT socket
2020-08-20 07:21:49.4949 [Centralized] trace: New price: 11741.72
2020-08-20 07:21:49.4949 [OpenDEX] trace: Starting to update OpenDEX orders
2020-08-20 07:21:49.4949 [OpenDEX] trace: Replacing BTC/USDT buy order with id arby-BTC/USDT-buy-order, quantity 0.08924342 and price 11389.4684
2020-08-20 07:21:49.4949 [OpenDEX] trace: Replacing BTC/USDT sell order with id arby-BTC/USDT-sell-order, quantity 0.02733841 and price 12093.9716
2020-08-20 07:21:49.4949 [GLOBAL] info: Unrecoverable error. Cleaning up.
2020-08-20 07:21:49.4949 [Centralized] info: Removing CEX orders
2020-08-20 07:21:49.4949 [Centralized] trace: BTCUSDT stream closed
2020-08-20 07:21:49.4949 [OpenDEX] info: All OpenDEX orders have been removed
2020-08-20 07:21:50.5050 [Centralized] info: Finished removing CEX orders
Shutdown complete. Goodbye, Arby.
2020-08-20 07:21:50,573 INFO exited: arby (exit status 0; expected)
2020-08-20 07:21:51,577 INFO spawned: 'arby' with pid 165

> market-maker-tools@1.1.5 start:arby /app
> npm run compile && node dist/arby.js
erkarl commented 4 years ago

And this one is back again, arby is stuck in this loop:

Could you please provide more context when this happened? xud was upgraded, right?

kilrau commented 4 years ago

Full CLI log: arby-cli.txt Full arby log: arby.log

You can see arby working fine (orders on both sides - buy/sell in btc/usdt), until suddenly I notice one stuck order on the sell side. Checking arby logs, it's stuck in above loop. If I had to guess it has to do with this one order still being up.

erkarl commented 4 years ago

Full CLI log: arby-cli.txt Full arby log: arby.log

You can see arby working fine (orders on both sides - buy/sell in btc/usdt), until suddenly I notice one stuck order on the sell side. Checking arby logs, it's stuck in above loop. If I had to guess it has to do with this one order still being up.

Fully down-ing the environment and then starting again solves the issue, right?

kilrau commented 4 years ago

Fully down-ing the environment and then starting again solves the issue, right?

Correct

erkarl commented 4 years ago

Fully down-ing the environment and then starting again solves the issue, right?

Correct

I have a feeling this is somehow related to the docker setup and internal DNS as I've not been able to reproduce this outside the docker setup. Mystery :thinking:

kilrau commented 4 years ago

Just hit this again: again with a previous arby order "stuck" in xud:

TEST_CENTRALIZED_EXCHANGE_BASEASSET_BALANCE: 123
TEST_CENTRALIZED_EXCHANGE_QUOTEASSET_BALANCE: 321
2020-08-21 11:21:29.2929 [Centralized] info: Base asset balance 123 and quote asset balance 321
2020-08-21 11:21:29.2929 [OpenDEX] trace: Base asset balance 10.501 (maxinbound: 90071992.54740991, maxoutbound: 10.501) and quote asset balance 2.48309839 (maxinbound: 2.4668111, maxoutbound: 2.43309839).
2020-08-21 11:21:30.3030 [Centralized] trace: ETHBTC established connection to wss://stream.binance.com:9443/ws/ethbtc@aggTrade
2020-08-21 11:21:30.3030 [Centralized] trace: heartbeat from ETHBTC socket
2020-08-21 11:21:30.3030 [Centralized] trace: New price: 0.0347
2020-08-21 11:21:30.3030 [OpenDEX] trace: Starting to update OpenDEX orders
2020-08-21 11:21:30.3030 [OpenDEX] trace: Replacing ETH/BTC buy order with id arby-ETH/BTC-buy-order, quantity 72.28671053 and price 0.033659
2020-08-21 11:21:30.3030 [OpenDEX] trace: Replacing ETH/BTC sell order with id arby-ETH/BTC-sell-order, quantity 10.501 and price 0.035741
2020-08-21 11:21:30.3030 [OpenDEX] trace: Creating ETH/BTC sell order with id arby-ETH/BTC-sell-order, quantity 10.501 and price 0.035741
2020-08-21 11:21:31.3131 [GLOBAL] info: Unrecoverable error. Cleaning up.
2020-08-21 11:21:31.3131 [Centralized] info: Removing CEX orders
2020-08-21 11:21:31.3131 [Centralized] trace: ETHBTC stream closed
2020-08-21 11:21:31.3131 [OpenDEX] info: All OpenDEX orders have been removed
2020-08-21 11:21:32.3232 [Centralized] info: Finished removing CEX orders
Shutdown complete. Goodbye, Arby.
2020-08-21 11:21:32,045 INFO exited: arby (exit status 0; expected)
2020-08-21 11:21:33,049 INFO spawned: 'arby' with pid 86

> market-maker-tools@1.1.5 start:arby /app
> npm run compile && node dist/arby.js

> market-maker-tools@1.1.5 compile /app
> npm run lint && tsc && cross-os postcompile

2020-08-21 11:21:34,175 INFO success: arby entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)

> market-maker-tools@1.1.5 lint /app
> eslint . --ext .js,.ts

simnet > listorders

Trading pair: BTC/USDT
┌────────────────────────────────────────────────┬────────────────────────────────────────────────┐
│ Buy                                            │ Sell                                           │
├───────────────┬─────────────┬──────────────────┼───────────────┬─────────────┬──────────────────┤
│ Quantity      │ Price       │ Alias            │ Quantity      │ Price       │ Alias            │
└───────────────┴─────────────┴──────────────────┴───────────────┴─────────────┴──────────────────┘

Trading pair: ETH/BTC
┌────────────────────────────────────────────────┬────────────────────────────────────────────────┐
│ Buy                                            │ Sell                                           │
├───────────────┬─────────────┬──────────────────┼───────────────┬─────────────┬──────────────────┤
│ Quantity      │ Price       │ Alias            │ Quantity      │ Price       │ Alias            │
├───────────────┼─────────────┼──────────────────┼───────────────┼─────────────┼──────────────────┤
│ 72.24923254   │ 0.03367646  │ SheriffSolution  │               │             │                  │
└───────────────┴─────────────┴──────────────────┴───────────────┴─────────────┴──────────────────┘
kilrau commented 4 years ago

Just had this again and I found that the arby order "stuck" in xud seems to be on-hold. That probably causes arby to fail replacing this order.

Alice trying to fill Bob's stuck arby order:

simnet > sell 0.1 eth/btc mkt
matched 0.1 ETH @ 0.03357364 with peer SheriffSolution order 0dfb7860-e3a3-11ea-8bd1-2d84ece41194, attempting swap...
failed to swap 0.1 ETH due to OrderOnHold with peer order 0dfb7860-e3a3-11ea-8bd1-2d84ece41194, continuing with matching routine...
no more matches found, 0.1 qty will be discarded

Bob trying to remove the stuck arby order:

simnet > listorders -j
{
  "ordersMap": [
    [
      "BTC/USDT",
      {
        "buyOrdersList": [],
        "sellOrdersList": []
      }
    ],
    [
      "ETH/BTC",
      {
        "buyOrdersList": [
          {
            "price": 0.03357364,
            "quantity": 7237045938,
            "pairId": "ETH/BTC",
            "id": "0dfb7860-e3a3-11ea-8bd1-2d84ece41194",
            "nodeIdentifier": {
              "nodePubKey": "03df4f36fa35bd242263e8d09d6b422108dab1f08d91237bb3aa2dad957cf08a71",
              "alias": "SheriffSolution"
            },
            "localId": "arby-ETH/BTC-buy-order",
            "createdAt": 1598010004198,
            "side": 0,
            "isOwnOrder": true,
            "hold": 7237045938
          }
        ],
        "sellOrdersList": []
      }
    ],
    [
      "LTC/BTC",
      {
        "buyOrdersList": [],
        "sellOrdersList": []
      }
    ],
    [
      "LTC/USDT",
      {
        "buyOrdersList": [],
        "sellOrdersList": []
      }
    ]
  ]
}
simnet > removeorder 0dfb7860-e3a3-11ea-8bd1-2d84ece41194
Error: 5 NOT_FOUND: order with local id 0dfb7860-e3a3-11ea-8bd1-2d84ece41194 does not exist

It might be a bug on xud after all. Thoughts? @erkarl @sangaman

erkarl commented 4 years ago

Just had this again and I found that the arby order "stuck" in xud seems to be on-hold. That probably causes arby to fail replacing this order.

Alice trying to fill Bob's stuck arby order:

simnet > sell 0.1 eth/btc mkt
matched 0.1 ETH @ 0.03357364 with peer SheriffSolution order 0dfb7860-e3a3-11ea-8bd1-2d84ece41194, attempting swap...
failed to swap 0.1 ETH due to OrderOnHold with peer order 0dfb7860-e3a3-11ea-8bd1-2d84ece41194, continuing with matching routine...
no more matches found, 0.1 qty will be discarded

Bob trying to remove the stuck arby order:

simnet > listorders -j
{
  "ordersMap": [
    [
      "BTC/USDT",
      {
        "buyOrdersList": [],
        "sellOrdersList": []
      }
    ],
    [
      "ETH/BTC",
      {
        "buyOrdersList": [
          {
            "price": 0.03357364,
            "quantity": 7237045938,
            "pairId": "ETH/BTC",
            "id": "0dfb7860-e3a3-11ea-8bd1-2d84ece41194",
            "nodeIdentifier": {
              "nodePubKey": "03df4f36fa35bd242263e8d09d6b422108dab1f08d91237bb3aa2dad957cf08a71",
              "alias": "SheriffSolution"
            },
            "localId": "arby-ETH/BTC-buy-order",
            "createdAt": 1598010004198,
            "side": 0,
            "isOwnOrder": true,
            "hold": 7237045938
          }
        ],
        "sellOrdersList": []
      }
    ],
    [
      "LTC/BTC",
      {
        "buyOrdersList": [],
        "sellOrdersList": []
      }
    ],
    [
      "LTC/USDT",
      {
        "buyOrdersList": [],
        "sellOrdersList": []
      }
    ]
  ]
}
simnet > removeorder 0dfb7860-e3a3-11ea-8bd1-2d84ece41194
Error: 5 NOT_FOUND: order with local id 0dfb7860-e3a3-11ea-8bd1-2d84ece41194 does not exist

It might be a bug on xud after all. Thoughts? @erkarl @sangaman

For removing the order you'll need to use the localId of the order arby-ETH/BTC-buy-order

kilrau commented 4 years ago

And again I have a stuck order and arby is in a restart loop due to Unrecoverable error. This time I used local id correctly trying to remove the order and it gave me an Error: 2 UNKNOWN: quantityToRemove cannot be 0 or negative

> market-maker-tools@1.1.5 start:arby /app
> npm run compile && node dist/arby.js

2020-08-25 08:46:12,241 INFO success: arby entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)

> market-maker-tools@1.1.5 compile /app
> npm run lint && tsc && cross-os postcompile

> market-maker-tools@1.1.5 lint /app
> eslint . --ext .js,.ts

2020-08-25 08:46:36.3636 [GLOBAL] info: Starting. Hello, Arby.
2020-08-25 08:46:36.3636 [GLOBAL] info: Running with config:
LIVE_CEX: false
LOG_LEVEL: trace
DATA_DIR: /root/.arby
OPENDEX_CERT_PATH: /root/.xud/tls.cert
OPENDEX_RPC_HOST: xud
OPENDEX_RPC_PORT: 18886
MARGIN: 0.03
BASEASSET: ETH
QUOTEASSET: BTC
TEST_CENTRALIZED_EXCHANGE_BASEASSET_BALANCE: 123
TEST_CENTRALIZED_EXCHANGE_QUOTEASSET_BALANCE: 321
2020-08-25 08:46:36.3636 [Centralized] info: Base asset balance 123 and quote asset balance 321
2020-08-25 08:46:36.3636 [OpenDEX] trace: Base asset balance 2.79963 (maxinbound: 90071992.54740991, maxoutbound: 2.79963) and quote asset balance 0.1 (maxinbound: 0.03199818, maxoutbound: 0.09866667).
2020-08-25 08:46:37.3737 [Centralized] trace: ETHBTC established connection to wss://stream.binance.com:9443/ws/ethbtc@aggTrade
2020-08-25 08:46:37.3737 [Centralized] trace: heartbeat from ETHBTC socket
2020-08-25 08:46:38.3838 [Centralized] trace: New price: 0.03404
2020-08-25 08:46:38.3838 [OpenDEX] trace: Starting to update OpenDEX orders
2020-08-25 08:46:38.3838 [OpenDEX] trace: Replacing ETH/BTC buy order with id arby-ETH/BTC-buy-order, quantity 2.98819672 and price 0.0330188
2020-08-25 08:46:38.3838 [OpenDEX] trace: Replacing ETH/BTC sell order with id arby-ETH/BTC-sell-order, quantity 0.9126379 and price 0.0350612
2020-08-25 08:46:38.3838 [OpenDEX] trace: Creating ETH/BTC sell order with id arby-ETH/BTC-sell-order, quantity 0.9126379 and price 0.0350612
2020-08-25 08:46:38.3838 [GLOBAL] info: Unrecoverable error. Cleaning up.
2020-08-25 08:46:38.3838 [Centralized] info: Removing CEX orders
2020-08-25 08:46:38.3838 [Centralized] trace: ETHBTC stream closed
2020-08-25 08:46:38.3838 [OpenDEX] info: All OpenDEX orders have been removed
2020-08-25 08:46:39.3939 [Centralized] info: Finished removing CEX orders
Shutdown complete. Goodbye, Arby.
2020-08-25 08:46:39,816 INFO exited: arby (exit status 0; expected)
2020-08-25 08:46:40,821 INFO spawned: 'arby' with pid 1144805

> market-maker-tools@1.1.5 start:arby /app
> npm run compile && node dist/arby.js

> market-maker-tools@1.1.5 compile /app
> npm run lint && tsc && cross-os postcompile

2020-08-25 08:46:42,699 INFO success: arby entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)

> market-maker-tools@1.1.5 lint /app
> eslint . --ext .js,.ts

testnet > listorders -j
{
  "ordersMap": [
    [
      "ETH/BTC",
      {
        "buyOrdersList": [
          {
            "price": 0.0333195,
            "quantity": 296122901,
            "pairId": "ETH/BTC",
            "id": "ac747ba0-e618-11ea-94fc-2dc3e300e2b6",
            "nodeIdentifier": {
              "nodePubKey": "02799dff47d38da549c9f9e3dcd94388e3a9fe05b4ea50ea0636562b4ba2b4ca4a",
              "alias": "AttitudeErase"
            },
            "localId": "arby-ETH/BTC-buy-order",
            "createdAt": 1598280423514,
            "side": 0,
            "isOwnOrder": true,
            "hold": 296122901
          }
        ],
        "sellOrdersList": []
      }
    ],
    [
      "ETH/LTC",
      {
        "buyOrdersList": [],
        "sellOrdersList": []
      }
    ],
    [
      "LTC/BTC",
      {
        "buyOrdersList": [],
        "sellOrdersList": []
      }
    ]
  ]
}
testnet > removeorder arby-ETH/BTC-buy-order
Error: 2 UNKNOWN: quantityToRemove cannot be 0 or negative
testnet > listorders

Trading pair: ETH/BTC
┌────────────────────────────────────────────────┬────────────────────────────────────────────────┐
│ Buy                                            │ Sell                                           │
├───────────────┬─────────────┬──────────────────┼───────────────┬─────────────┬──────────────────┤
│ Quantity      │ Price       │ Alias            │ Quantity      │ Price       │ Alias            │
├───────────────┼─────────────┼──────────────────┼───────────────┼─────────────┼──────────────────┤
│ 2.96122901    │ 0.0333195   │ AttitudeErase    │               │             │                  │
└───────────────┴─────────────┴──────────────────┴───────────────┴─────────────┴──────────────────┘

Restarting xud fixed it and arby issued orders again.

In conclusion: I think this order ends up being stuck on-hold (see peer output in above comment signifying that the order is on-hold), thus the order is irremovable and arby errors. Very much looks like an xud issue. Thoughts? @sangaman @erkarl

erkarl commented 4 years ago

And again I have a stuck order and arby is in a restart loop due to Unrecoverable error. This time I used local id correctly trying to remove the order and it gave me an Error: 2 UNKNOWN: quantityToRemove cannot be 0 or negative

> market-maker-tools@1.1.5 start:arby /app
> npm run compile && node dist/arby.js

2020-08-25 08:46:12,241 INFO success: arby entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)

> market-maker-tools@1.1.5 compile /app
> npm run lint && tsc && cross-os postcompile

> market-maker-tools@1.1.5 lint /app
> eslint . --ext .js,.ts

2020-08-25 08:46:36.3636 [GLOBAL] info: Starting. Hello, Arby.
2020-08-25 08:46:36.3636 [GLOBAL] info: Running with config:
LIVE_CEX: false
LOG_LEVEL: trace
DATA_DIR: /root/.arby
OPENDEX_CERT_PATH: /root/.xud/tls.cert
OPENDEX_RPC_HOST: xud
OPENDEX_RPC_PORT: 18886
MARGIN: 0.03
BASEASSET: ETH
QUOTEASSET: BTC
TEST_CENTRALIZED_EXCHANGE_BASEASSET_BALANCE: 123
TEST_CENTRALIZED_EXCHANGE_QUOTEASSET_BALANCE: 321
2020-08-25 08:46:36.3636 [Centralized] info: Base asset balance 123 and quote asset balance 321
2020-08-25 08:46:36.3636 [OpenDEX] trace: Base asset balance 2.79963 (maxinbound: 90071992.54740991, maxoutbound: 2.79963) and quote asset balance 0.1 (maxinbound: 0.03199818, maxoutbound: 0.09866667).
2020-08-25 08:46:37.3737 [Centralized] trace: ETHBTC established connection to wss://stream.binance.com:9443/ws/ethbtc@aggTrade
2020-08-25 08:46:37.3737 [Centralized] trace: heartbeat from ETHBTC socket
2020-08-25 08:46:38.3838 [Centralized] trace: New price: 0.03404
2020-08-25 08:46:38.3838 [OpenDEX] trace: Starting to update OpenDEX orders
2020-08-25 08:46:38.3838 [OpenDEX] trace: Replacing ETH/BTC buy order with id arby-ETH/BTC-buy-order, quantity 2.98819672 and price 0.0330188
2020-08-25 08:46:38.3838 [OpenDEX] trace: Replacing ETH/BTC sell order with id arby-ETH/BTC-sell-order, quantity 0.9126379 and price 0.0350612
2020-08-25 08:46:38.3838 [OpenDEX] trace: Creating ETH/BTC sell order with id arby-ETH/BTC-sell-order, quantity 0.9126379 and price 0.0350612
2020-08-25 08:46:38.3838 [GLOBAL] info: Unrecoverable error. Cleaning up.
2020-08-25 08:46:38.3838 [Centralized] info: Removing CEX orders
2020-08-25 08:46:38.3838 [Centralized] trace: ETHBTC stream closed
2020-08-25 08:46:38.3838 [OpenDEX] info: All OpenDEX orders have been removed
2020-08-25 08:46:39.3939 [Centralized] info: Finished removing CEX orders
Shutdown complete. Goodbye, Arby.
2020-08-25 08:46:39,816 INFO exited: arby (exit status 0; expected)
2020-08-25 08:46:40,821 INFO spawned: 'arby' with pid 1144805

> market-maker-tools@1.1.5 start:arby /app
> npm run compile && node dist/arby.js

> market-maker-tools@1.1.5 compile /app
> npm run lint && tsc && cross-os postcompile

2020-08-25 08:46:42,699 INFO success: arby entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)

> market-maker-tools@1.1.5 lint /app
> eslint . --ext .js,.ts

testnet > listorders -j
{
  "ordersMap": [
    [
      "ETH/BTC",
      {
        "buyOrdersList": [
          {
            "price": 0.0333195,
            "quantity": 296122901,
            "pairId": "ETH/BTC",
            "id": "ac747ba0-e618-11ea-94fc-2dc3e300e2b6",
            "nodeIdentifier": {
              "nodePubKey": "02799dff47d38da549c9f9e3dcd94388e3a9fe05b4ea50ea0636562b4ba2b4ca4a",
              "alias": "AttitudeErase"
            },
            "localId": "arby-ETH/BTC-buy-order",
            "createdAt": 1598280423514,
            "side": 0,
            "isOwnOrder": true,
            "hold": 296122901
          }
        ],
        "sellOrdersList": []
      }
    ],
    [
      "ETH/LTC",
      {
        "buyOrdersList": [],
        "sellOrdersList": []
      }
    ],
    [
      "LTC/BTC",
      {
        "buyOrdersList": [],
        "sellOrdersList": []
      }
    ]
  ]
}
testnet > removeorder arby-ETH/BTC-buy-order
Error: 2 UNKNOWN: quantityToRemove cannot be 0 or negative
testnet > listorders

Trading pair: ETH/BTC
┌────────────────────────────────────────────────┬────────────────────────────────────────────────┐
│ Buy                                            │ Sell                                           │
├───────────────┬─────────────┬──────────────────┼───────────────┬─────────────┬──────────────────┤
│ Quantity      │ Price       │ Alias            │ Quantity      │ Price       │ Alias            │
├───────────────┼─────────────┼──────────────────┼───────────────┼─────────────┼──────────────────┤
│ 2.96122901    │ 0.0333195   │ AttitudeErase    │               │             │                  │
└───────────────┴─────────────┴──────────────────┴───────────────┴─────────────┴──────────────────┘

In conclusion: somehow I think this order ends up being stuck on hold (see peer output in above comment signifying that the order is on hold), thus the order is irremovable and arby errors. Looks like an xud issue. Thoughts? @sangaman @erkarl

Super weird. I'm wondering what triggered xud to put that order on hold? @sangaman

kilrau commented 4 years ago

Super weird. I'm wondering what triggered xud to put that order on hold? @sangaman

And also why it's in the orderbook and visible to others while on-hold.

Here full xud container logs: xud.log

kilrau commented 4 years ago

And again. Again one order stuck.

25/08/2020 09:51:19.854 [ORDERBOOK] debug: placed entire order 869a46d0-e6b8-11ea-a5a1-ef5663efc665 on hold
25/08/2020 09:51:19.855 [ORDERBOOK] debug: removed entire hold on order 869a46d0-e6b8-11ea-a5a1-ef5663efc665
Aug 25 09:51:20.000 [notice] Closed 1 streams for service [scrubbed].onion for reason resolve failed. Fetch status: No more HSDir available to query.
25/08/2020 09:51:20.308 [P2P] debug: Connection attempt ExchangeUnion/market-maker-tools#7 to 03dfd2e2c21614fe824f53851af259f02a67bf87c8d51f8a363ebfa8781cae5bd0@uqcvn7c3sx5yhxkxamohjclegl75o2pkuykkzjgxg2b345fiih6moxqd.onion:28885 failed: Socks5 proxy rejected connection - HostUnreachable. retrying in 300 sec...
25/08/2020 09:51:20.688 [LND-BTC] debug: new channel maximum outbound capacity: 0
25/08/2020 09:51:20.688 [LND-BTC] debug: new channel inbound capacity: 0
25/08/2020 09:51:20.688 [LND-BTC] debug: new channel total outbound capacity: 0
25/08/2020 09:51:20.778 [ORDERBOOK] debug: placed entire order 86d21fb0-e6b8-11ea-a5a1-ef5663efc665 on hold
25/08/2020 09:51:20.780 [RPC] error: call /xudrpc.Xud/PlaceOrderSync errored with code 9: BTC outbound balance of 0 is not sufficient for order amount of 283938972
25/08/2020 09:51:20.781 [ORDERBOOK] debug: placed entire order 86d294e0-e6b8-11ea-a5a1-ef5663efc665 on hold
25/08/2020 09:51:20.781 [ORDERBOOK] debug: removed entire hold on order 86d294e0-e6b8-11ea-a5a1-ef5663efc665
Aug 25 09:51:23.000 [notice] Closed 1 streams for service [scrubbed].onion for reason resolve failed. Fetch status: No more HSDir available to query.
25/08/2020 09:51:23.978 [P2P] debug: Connection attempt ExchangeUnion/market-maker-tools#7 to 023c6212381a34202e8eacb726844582014e57b33a9fcfc86e8ed67f12dfdb8ea0@k6wygpw6pyia3ojxyhxh7n7dwq7rfxbkl4qmwaqfjtoxzeumft3v73qd.onion:28885 failed: Socks5 proxy rejected connection - HostUnreachable. retrying in 300 sec...
25/08/2020 09:52:26.014 [LND-BTC] debug: new channel maximum outbound capacity: 283938972
25/08/2020 09:52:26.015 [LND-BTC] debug: new channel inbound capacity: 206051977
25/08/2020 09:52:26.015 [LND-BTC] debug: new channel total outbound capacity: 283938972
25/08/2020 09:52:26.200 [RPC] error: call /xudrpc.Xud/PlaceOrderSync errored with code 3: order with local id arby-BTC/USDT-sell-order has a quantity of 283938972 on hold
25/08/2020 09:52:26.201 [ORDERBOOK] debug: placed entire order 875fe0c0-e6b8-11ea-a5a1-ef5663efc665 on hold
25/08/2020 09:52:26.202 [ORDERBOOK] debug: removed entire hold on order 875fe0c0-e6b8-11ea-a5a1-ef5663efc665
25/08/2020 09:52:26.521 [P2P] debug: Connection attempt ExchangeUnion/market-maker-tools#7 to 03baccdf0197d9d1246b653cbf7c3ac3c40c48e290f6402eacdb1873853d26ad28@w7aiabs7jbwovnpzzsfkbf5zu6acd7npcmqdvllhqungq4ygor5rdhqd.onion:28885 failed: Proxy connection timed out. retrying in 300 sec...
25/08/2020 09:52:51.076 [RPC] error: call /xudrpc.Xud/PlaceOrderSync errored with code 3: order with local id arby-BTC/USDT-sell-order has a quantity of 283938972 on hold
25/08/2020 09:52:51.077 [RPC] error: call /xudrpc.Xud/PlaceOrderSync errored with code 5: order with id arby-BTC/USDT-buy-order could not be found
25/08/2020 09:53:10.348 [RPC] error: call /xudrpc.Xud/PlaceOrderSync errored with code 3: order with local id arby-BTC/USDT-sell-order has a quantity of 283938972 on hold
25/08/2020 09:53:10.349 [RPC] error: call /xudrpc.Xud/PlaceOrderSync errored with code 5: order with id arby-BTC/USDT-buy-order could not be found
kilrau commented 4 years ago

Also, when restarting xud after above, it says it did shutdown gracefully but then just hangs there and waits for docker to be killed:

25/08/2020 09:53:10.349 [RPC] error: call /xudrpc.Xud/PlaceOrderSync errored with code 5: order with id arby-BTC/USDT-buy-order could not be found
25/08/2020 09:53:35.525 [RPC] error: call /xudrpc.Xud/PlaceOrderSync errored with code 3: order with local id arby-BTC/USDT-sell-order has a quantity of 283938972 on hold
25/08/2020 09:53:35.526 [RPC] error: call /xudrpc.Xud/PlaceOrderSync errored with code 5: order with id arby-BTC/USDT-buy-order could not be found
25/08/2020 09:53:55.165 [RPC] error: call /xudrpc.Xud/PlaceOrderSync errored with code 3: order with local id arby-BTC/USDT-sell-order has a quantity of 283938972 on hold
25/08/2020 09:53:55.166 [RPC] error: call /xudrpc.Xud/PlaceOrderSync errored with code 5: order with id arby-BTC/USDT-buy-order could not be found
25/08/2020 09:54:18.248 [RPC] error: call /xudrpc.Xud/PlaceOrderSync errored with code 3: order with local id arby-BTC/USDT-sell-order has a quantity of 283938972 on hold
25/08/2020 09:54:18.249 [RPC] error: call /xudrpc.Xud/PlaceOrderSync errored with code 5: order with id arby-BTC/USDT-buy-order could not be found
25/08/2020 09:54:38.470 [RPC] error: call /xudrpc.Xud/PlaceOrderSync errored with code 3: order with local id arby-BTC/USDT-sell-order has a quantity of 283938972 on hold
25/08/2020 09:54:38.470 [RPC] error: call /xudrpc.Xud/PlaceOrderSync errored with code 5: order with id arby-BTC/USDT-buy-order could not be found
25/08/2020 09:55:01.670 [RPC] error: call /xudrpc.Xud/PlaceOrderSync errored with code 3: order with local id arby-BTC/USDT-sell-order has a quantity of 283938972 on hold
25/08/2020 09:55:01.671 [RPC] error: call /xudrpc.Xud/PlaceOrderSync errored with code 5: order with id arby-BTC/USDT-buy-order could not be found
25/08/2020 09:55:07.399 [GLOBAL] info: XUD is shutting down
25/08/2020 09:55:07.400 [LND-BTC] info: new status: Disconnected
25/08/2020 09:55:07.401 [LND-LTC] info: new status: Disconnected
25/08/2020 09:55:07.402 [CONNEXT] info: new status: Disconnected
25/08/2020 09:55:07.405 [HTTP] info: http server has closed
25/08/2020 09:55:07.407 [P2P] debug: Peer 03ece33a30db1dbce4b62fa96a5e9541138a24997ef5672eebed2d332270e39542 (OzoneYellow): closing socket. reason: Shutdown
25/08/2020 09:55:07.409 [P2P] debug: Peer 02e98d38585e5d3221984c2a944eb004b4c1db22b3bb8f5327b27776b8c88dec80 (NeckSchool): closing socket. reason: Shutdown
25/08/2020 09:55:07.410 [P2P] debug: Peer 03ad8a98151caa68e41412359b9b9c1e1467f1ed88b4bd3e70d8fad4ab795b3095 (NeglectAcoustic): closing socket. reason: Shutdown
25/08/2020 09:55:07.411 [P2P] debug: Peer 021f6ad8ce59d547e9f194786b915b7e45f97cd2663d9a4dc70c4935a4b179e92b (TheoryFederal): closing socket. reason: Shutdown
25/08/2020 09:55:07.412 [RPC] info: gRPC server completed shutdown
25/08/2020 09:55:07.416 [ORDERBOOK] debug: removed all orders for peer 03ece33a30db1dbce4b62fa96a5e9541138a24997ef5672eebed2d332270e39542 (OzoneYellow)
25/08/2020 09:55:07.423 [ORDERBOOK] debug: removed all orders for peer 02e98d38585e5d3221984c2a944eb004b4c1db22b3bb8f5327b27776b8c88dec80 (NeckSchool)
25/08/2020 09:55:07.424 [ORDERBOOK] debug: removed all orders for peer 03ad8a98151caa68e41412359b9b9c1e1467f1ed88b4bd3e70d8fad4ab795b3095 (NeglectAcoustic)
25/08/2020 09:55:07.426 [ORDERBOOK] debug: removed all orders for peer 021f6ad8ce59d547e9f194786b915b7e45f97cd2663d9a4dc70c4935a4b179e92b (TheoryFederal)
25/08/2020 09:55:07.430 [GLOBAL] info: XUD shutdown gracefully
kilrau commented 4 years ago

And one more case leading to this. Arby logs:

2020-08-25 11:39:22.2222 [Centralized] info: Base asset balance 123 and quote asset balance 321
2020-08-25 11:39:22.2222 [OpenDEX] trace: Base asset balance 2.79963 (maxinbound: 90071992.54740991, maxoutbound: 2.79963) and quote asset balance 0.1 (maxinbound: 0.03199818, maxoutbound: 0.09866667).
2020-08-25 11:39:23.2323 [Centralized] trace: ETHBTC established connection to wss://stream.binance.com:9443/ws/ethbtc@aggTrade
2020-08-25 11:39:23.2323 [Centralized] trace: heartbeat from ETHBTC socket
2020-08-25 11:39:24.2424 [Centralized] trace: New price: 0.034059
2020-08-25 11:39:24.2424 [OpenDEX] trace: Starting to update OpenDEX orders
2020-08-25 11:39:24.2424 [OpenDEX] trace: Replacing ETH/BTC buy order with id arby-ETH/BTC-buy-order, quantity 2.98652974 and price 0.03303723
2020-08-25 11:39:24.2424 [OpenDEX] trace: Replacing ETH/BTC sell order with id arby-ETH/BTC-sell-order, quantity 0.91212878 and price 0.03508077
2020-08-25 11:39:24.2424 [OpenDEX] trace: Creating ETH/BTC sell order with id arby-ETH/BTC-sell-order, quantity 0.91212878 and price 0.03508077
2020-08-25 11:39:25.2525 [OpenDEX] trace: Creating ETH/BTC buy order with id arby-ETH/BTC-buy-order, quantity 2.98652974 and price 0.03303723
2020-08-25 11:39:25.2525 [Centralized] trace: New price: 0.034052
2020-08-25 11:39:25.2525 [OpenDEX] trace: Order arby-ETH/BTC-sell-order created
2020-08-25 11:39:25.2525 [OpenDEX] trace: Order arby-ETH/BTC-buy-order created
2020-08-25 11:39:25.2525 [OpenDEX] trace: OpenDEX orders updated
2020-08-25 11:39:26.2626 [Centralized] trace: New price: 0.034052
2020-08-25 11:39:28.2828 [Centralized] trace: New price: 0.034056
2020-08-25 11:39:28.2828 [OpenDEX] trace: Starting to update OpenDEX orders
2020-08-25 11:39:28.2828 [OpenDEX] trace: Replacing ETH/BTC buy order with id arby-ETH/BTC-buy-order, quantity 2.98679282 and price 0.03303432
2020-08-25 11:39:28.2828 [OpenDEX] trace: Replacing ETH/BTC sell order with id arby-ETH/BTC-sell-order, quantity 0.91220913 and price 0.03507768
2020-08-25 11:39:28.2828 [OpenDEX] trace: Order arby-ETH/BTC-sell-order created
2020-08-25 11:39:28.2828 [OpenDEX] trace: Order arby-ETH/BTC-buy-order created
2020-08-25 11:39:28.2828 [OpenDEX] trace: OpenDEX orders updated
2020-08-25 11:39:29.2929 [Centralized] trace: New price: 0.034057
2020-08-25 11:39:29.2929 [OpenDEX] trace: Starting to update OpenDEX orders
2020-08-25 11:39:29.2929 [OpenDEX] trace: Replacing ETH/BTC buy order with id arby-ETH/BTC-buy-order, quantity 2.98670512 and price 0.03303529
2020-08-25 11:39:29.2929 [OpenDEX] trace: Replacing ETH/BTC sell order with id arby-ETH/BTC-sell-order, quantity 0.91218234 and price 0.03507871
2020-08-25 11:39:29.2929 [OpenDEX] trace: Order arby-ETH/BTC-sell-order created
2020-08-25 11:39:29.2929 [OpenDEX] trace: Order arby-ETH/BTC-buy-order created
2020-08-25 11:39:29.2929 [OpenDEX] trace: OpenDEX orders updated
2020-08-25 11:39:30.3030 [Centralized] trace: New price: 0.034057
2020-08-25 11:39:30.3030 [Centralized] trace: New price: 0.034057
2020-08-25 11:39:31.3131 [Centralized] trace: New price: 0.034059
2020-08-25 11:39:31.3131 [OpenDEX] trace: Starting to update OpenDEX orders
2020-08-25 11:39:31.3131 [OpenDEX] trace: Replacing ETH/BTC buy order with id arby-ETH/BTC-buy-order, quantity 2.98652974 and price 0.03303723
2020-08-25 11:39:31.3131 [OpenDEX] trace: Replacing ETH/BTC sell order with id arby-ETH/BTC-sell-order, quantity 0.91212878 and price 0.03508077
2020-08-25 11:39:32.3232 [Centralized] trace: New price: 0.03406
2020-08-25 11:39:32.3232 [Centralized] trace: New price: 0.034058
2020-08-25 11:39:32.3232 [OpenDEX] trace: Order arby-ETH/BTC-sell-order created
2020-08-25 11:39:32.3232 [OpenDEX] trace: Order arby-ETH/BTC-buy-order created
2020-08-25 11:39:32.3232 [OpenDEX] trace: OpenDEX orders updated
2020-08-25 11:39:33.3333 [Centralized] trace: heartbeat from ETHBTC socket
2020-08-25 11:39:39.3939 [Centralized] trace: New price: 0.034055
2020-08-25 11:39:39.3939 [OpenDEX] trace: Starting to update OpenDEX orders
2020-08-25 11:39:39.3939 [OpenDEX] trace: Replacing ETH/BTC buy order with id arby-ETH/BTC-buy-order, quantity 2.98688053 and price 0.03303335
2020-08-25 11:39:39.3939 [OpenDEX] trace: Replacing ETH/BTC sell order with id arby-ETH/BTC-sell-order, quantity 0.91223591 and price 0.03507665
2020-08-25 11:39:39.3939 [OpenDEX] trace: Order arby-ETH/BTC-sell-order created
2020-08-25 11:39:39.3939 [OpenDEX] trace: Order arby-ETH/BTC-buy-order created
2020-08-25 11:39:39.3939 [OpenDEX] trace: OpenDEX orders updated
2020-08-25 11:39:42.4242 [Centralized] trace: New price: 0.034054
2020-08-25 11:39:42.4242 [OpenDEX] trace: Starting to update OpenDEX orders
2020-08-25 11:39:42.4242 [OpenDEX] trace: Replacing ETH/BTC buy order with id arby-ETH/BTC-buy-order, quantity 2.98696824 and price 0.03303238
2020-08-25 11:39:42.4242 [OpenDEX] trace: Replacing ETH/BTC sell order with id arby-ETH/BTC-sell-order, quantity 0.9122627 and price 0.03507562
2020-08-25 11:39:42.4242 [OpenDEX] trace: Order arby-ETH/BTC-sell-order created
2020-08-25 11:39:42.4242 [OpenDEX] warn: 9 FAILED_PRECONDITION: BTC outbound balance of 0 is not sufficient for order amount of 9866667. Retrying in 5000ms.
2020-08-25 11:39:47.4747 [Centralized] info: Base asset balance 123 and quote asset balance 321
2020-08-25 11:39:47.4747 [OpenDEX] trace: Base asset balance 2.79963 (maxinbound: 90071992.54740991, maxoutbound: 2.79963) and quote asset balance 0.1 (maxinbound: 0.03199818, maxoutbound: 0.09866667).
2020-08-25 11:39:48.4848 [Centralized] trace: New price: 0.034054
2020-08-25 11:39:48.4848 [OpenDEX] trace: Starting to update OpenDEX orders
2020-08-25 11:39:48.4848 [OpenDEX] trace: Replacing ETH/BTC buy order with id arby-ETH/BTC-buy-order, quantity 2.98696824 and price 0.03303238
2020-08-25 11:39:48.4848 [OpenDEX] trace: Replacing ETH/BTC sell order with id arby-ETH/BTC-sell-order, quantity 0.9122627 and price 0.03507562
2020-08-25 11:39:48.4848 [Centralized] trace: New price: 0.034055
2020-08-25 11:39:48.4848 [OpenDEX] trace: Order arby-ETH/BTC-sell-order created
2020-08-25 11:39:48.4848 [GLOBAL] info: Unrecoverable error. Cleaning up.
2020-08-25 11:39:48.4848 [Centralized] info: Removing CEX orders
2020-08-25 11:39:48.4848 [Centralized] trace: ETHBTC stream closed
2020-08-25 11:39:48.4848 [OpenDEX] info: All OpenDEX orders have been removed
2020-08-25 11:39:49.4949 [Centralized] info: Finished removing CEX orders
Shutdown complete. Goodbye, Arby.
2020-08-25 11:39:50,581 INFO exited: arby (exit status 0; expected)
2020-08-25 11:39:51,586 INFO spawned: 'arby' with pid 86
2020-08-25 11:39:52,589 INFO success: arby entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
raladev commented 4 years ago

Got it too: arby2_log_stuck.log xud_arby_stuck.log

sangaman commented 4 years ago

Bob trying to remove the stuck arby order:

simnet > listorders -j
{
  "ordersMap": [
    [
      "BTC/USDT",
      {
        "buyOrdersList": [],
        "sellOrdersList": []
      }
    ],
    [
      "ETH/BTC",
      {
        "buyOrdersList": [
          {
            "price": 0.03357364,
            "quantity": 7237045938,
            "pairId": "ETH/BTC",
            "id": "0dfb7860-e3a3-11ea-8bd1-2d84ece41194",
            "nodeIdentifier": {
              "nodePubKey": "03df4f36fa35bd242263e8d09d6b422108dab1f08d91237bb3aa2dad957cf08a71",
              "alias": "SheriffSolution"
            },
            "localId": "arby-ETH/BTC-buy-order",
            "createdAt": 1598010004198,
            "side": 0,
            "isOwnOrder": true,
            "hold": 7237045938
          }
        ],
        "sellOrdersList": []
      }
    ],
    [
      "LTC/BTC",
      {
        "buyOrdersList": [],
        "sellOrdersList": []
      }
    ],
    [
      "LTC/USDT",
      {
        "buyOrdersList": [],
        "sellOrdersList": []
      }
    ]
  ]
}
simnet > removeorder 0dfb7860-e3a3-11ea-8bd1-2d84ece41194
Error: 5 NOT_FOUND: order with local id 0dfb7860-e3a3-11ea-8bd1-2d84ece41194 does not exist

It might be a bug on xud after all. Thoughts? @erkarl @sangaman

Just a note here that attempting to remove the order by the global id won't work, it's expecting the local id (arby-ETH/BTC-buy-order in this case).

kilrau commented 4 years ago

Just a note here that attempting to remove the order by the global id won't work, it's expecting the local id (arby-ETH/BTC-buy-order in this case).

That is clear and was an oversight on my end, but in https://github.com/ExchangeUnion/xud/issues/1835#issuecomment-679894767 below you can see the error it gave me when I used the local id correctly.

kilrau commented 4 years ago

Just encountered this again with latest xud master.

  1. I noticed arby errored with Unrecoverable error again, just like before.
  2. xud logs show failure to place order: 
    01/09/2020 12:02:54.478 [RPC] error: call /xudrpc.Xud/PlaceOrderSync errored with code 3: order with local id arby-ETH/BTC-sell-order has a quantity of 10000 on hold
01/09/2020 12:02:54.479 [RPC] error: call /xudrpc.Xud/PlaceOrderSync errored with code 5: order with id arby-ETH/BTC-buy-order could not be found
  3. and indeed there is an order on hold that shouldn't be: 
    "ordersMap": [
[
  "ETH/BTC",
  {
    "buyOrdersList": [],
    "sellOrdersList": [
      {
        "price": 0.0406026,
        "quantity": 10000,
        "pairId": "ETH/BTC",
        "id": "254925e0-ec49-11ea-9ff0-dd2aa9506f54",
        "nodeIdentifier": {
          "nodePubKey": "02799dff47d38da549c9f9e3dcd94388e3a9fe05b4ea50ea0636562b4ba2b4ca4a",
          "alias": "AttitudeErase"
        },
        "localId": "arby-ETH/BTC-sell-order",
        "createdAt": 1598960949054,
        "side": 1,
        "isOwnOrder": true,
        "hold": 10000
      }
    ]
  }
],

Since I have one machine where this can be reproduced very reliably (testnet), I'll run reproduce this with xud in log level trace once more and attach logs here.

sangaman commented 4 years ago

I'm closing this again because the issue above was not caused by the original issue here, where replacing orders could leave orders stuck on hold forever, but rather because of a hold caused by a "pending" connext payment due to #1850.