search

lightninglabs / lightning-terminal

Lightning Terminal: Your Home for Lightning Liquidity
MIT License
508 stars 90 forks source link

LITD (remote mode) fails to start with "unable to resume account" with "transaction rejected: output already spent" #322

Closed deniv closed 2 years ago

deniv commented 2 years ago

Expected behavior

litd --uipassword=pwd with config in ~/.lit/lit.conf

Successfully starts LITD

Actual behavior LITD startup fails with:

2022-02-09 05:59:49.288 [INF] RPCS: Connected to lnd node NODE NAME with pubkey NODE PUB KEY
2022-02-09 05:59:49.652 [DBG] GRPC: [core] Subchannel Connectivity change to READY
2022-02-09 05:59:49.653 [DBG] GRPC: [core] pickfirstBalancer: UpdateSubConnState: 0xc000542250, {READY <nil>}
2022-02-09 05:59:49.653 [DBG] GRPC: [core] Channel Connectivity change to READY
2022-02-09 05:59:50.241 [INF] AUCT: Shutting down auctioneer client
2022-02-09 05:59:50.241 [DBG] GRPC: [core] Channel Connectivity change to SHUTDOWN
2022-02-09 05:59:50.241 [DBG] GRPC: [core] Subchannel Connectivity change to SHUTDOWN
2022-02-09 05:59:50.242 [ERR] LITD: Could not start subservers: unable to start account manager: unable to resume account ACCOUNT ID: rpc error: code = Unknown desc = transaction rejected: output already spent
2022-02-09 05:59:50.242 [INF] LOOPD: Stopping gRPC server
2022-02-09 05:59:50.242 [INF] LOOPD: Stopping REST server

To reproduce

System information

Standalone LITD connecting in remote mode to LND (lnd runs on the same host)

~/.lit/lit.conf

lit-dir=~/.lit remote.lit-debuglevel=debug lnd-mode=remote network=mainnet remote.lnd.rpcserver=127.0.0.1:10009 remote.lnd.macaroonpath=/home/USER/.lit/lnd/data/admin.macaroon remote.lnd.tlscertpath=/home/USER/.lnd/tls.cert loop.loopoutmaxparts=5 pool.newnodesonly=true faraday.min_monitored=48h faraday.connect_bitcoin=true

LITD Versions The issue above was reproduced with lightning-terminal-linux-amd64-v0.5.0-alpha.tar.gz binaries. Later on upgraded LITD to version compiled from v0.6.2-alpha tag but LITD keeps failing with the same error

Full startup log

2022-02-09 06:49:44.586 [INF] SESS: Checking for schema update: latest_version=0, db_version=0
2022-02-09 06:49:44.588 [INF] LITD: Dialing lnd gRPC server at 127.0.0.1:10009
2022-02-09 06:49:44.588 [DBG] GRPC: [core] parsed scheme: ""
2022-02-09 06:49:44.588 [DBG] GRPC: [core] scheme "" not registered, fallback to default scheme
2022-02-09 06:49:44.589 [DBG] GRPC: [core] ccResolverWrapper: sending update to cc: {[{127.0.0.1:10009  <nil> 0 <nil>}] <nil> <nil>}
2022-02-09 06:49:44.589 [DBG] GRPC: [core] ClientConn switching balancer to "pick_first"
2022-02-09 06:49:44.589 [DBG] GRPC: [core] Channel switches to new LB policy "pick_first"
2022-02-09 06:49:44.589 [DBG] GRPC: [core] Subchannel Connectivity change to CONNECTING
2022-02-09 06:49:44.590 [DBG] GRPC: [core] Subchannel picks a new address "127.0.0.1:10009" to connect
2022-02-09 06:49:44.591 [DBG] GRPC: [core] pickfirstBalancer: UpdateSubConnState: 0xc000235540, {CONNECTING <nil>}
2022-02-09 06:49:44.592 [DBG] GRPC: [core] Channel Connectivity change to CONNECTING
2022-02-09 06:49:44.616 [INF] LITD: Listening for http_tls on: 127.0.0.1:9443
2022-02-09 06:49:44.617 [DBG] GRPC: [core] Subchannel Connectivity change to READY
2022-02-09 06:49:44.618 [DBG] GRPC: [core] pickfirstBalancer: UpdateSubConnState: 0xc000235540, {READY <nil>}
2022-02-09 06:49:44.618 [DBG] GRPC: [core] Channel Connectivity change to READY
2022-02-09 06:49:44.617 [DBG] GRPC: [core] parsed scheme: ""
2022-02-09 06:49:44.618 [DBG] GRPC: [core] scheme "" not registered, fallback to default scheme
2022-02-09 06:49:44.618 [DBG] GRPC: [core] ccResolverWrapper: sending update to cc: {[{127.0.0.1:10009  <nil> 0 <nil>}] <nil> <nil>}
2022-02-09 06:49:44.618 [DBG] GRPC: [core] ClientConn switching balancer to "pick_first"
2022-02-09 06:49:44.619 [DBG] GRPC: [core] Channel switches to new LB policy "pick_first"
2022-02-09 06:49:44.619 [DBG] GRPC: [core] Subchannel Connectivity change to CONNECTING
2022-02-09 06:49:44.619 [DBG] GRPC: [core] blockingPicker: the picked transport is not ready, loop back to repick
2022-02-09 06:49:44.619 [DBG] GRPC: [core] pickfirstBalancer: UpdateSubConnState: 0xc000235d40, {CONNECTING <nil>}
2022-02-09 06:49:44.619 [DBG] GRPC: [core] Channel Connectivity change to CONNECTING
2022-02-09 06:49:44.619 [DBG] GRPC: [core] Subchannel picks a new address "127.0.0.1:10009" to connect
2022-02-09 06:49:44.628 [DBG] GRPC: [core] Subchannel Connectivity change to READY
2022-02-09 06:49:44.629 [DBG] GRPC: [core] pickfirstBalancer: UpdateSubConnState: 0xc000235d40, {READY <nil>}
2022-02-09 06:49:44.629 [DBG] GRPC: [core] Channel Connectivity change to READY
----------------------------------------------------------
 Lightning Terminal (LiT) by Lightning Labs               

 Operating mode      remote                                   
 Node status         online                                   
 Alias               <node alias>                                   
 Version             0.13.3-beta commit=v0.13.3-beta                                   
 Web interface       127.0.0.1:9443 (open https://127.0.0.1:9443 in your browser)         
----------------------------------------------------------
2022-02-09 06:49:44.914 [DBG] GRPC: [core] parsed scheme: ""
2022-02-09 06:49:44.914 [DBG] GRPC: [core] scheme "" not registered, fallback to default scheme
2022-02-09 06:49:44.914 [DBG] GRPC: [core] ccResolverWrapper: sending update to cc: {[{127.0.0.1:10009  <nil> 0 <nil>}] <nil> <nil>}
2022-02-09 06:49:44.914 [DBG] GRPC: [core] ClientConn switching balancer to "pick_first"
2022-02-09 06:49:44.914 [DBG] GRPC: [core] Channel switches to new LB policy "pick_first"
2022-02-09 06:49:44.915 [DBG] GRPC: [core] Subchannel Connectivity change to CONNECTING
2022-02-09 06:49:44.915 [INF] LNDC: Creating lnd connection to 127.0.0.1:10009
2022-02-09 06:49:44.915 [DBG] GRPC: [core] pickfirstBalancer: UpdateSubConnState: 0xc000157510, {CONNECTING <nil>}
2022-02-09 06:49:44.916 [DBG] GRPC: [core] parsed scheme: ""
2022-02-09 06:49:44.916 [DBG] GRPC: [core] Subchannel picks a new address "127.0.0.1:10009" to connect
2022-02-09 06:49:44.916 [DBG] GRPC: [core] Channel Connectivity change to CONNECTING
2022-02-09 06:49:44.916 [DBG] GRPC: [core] scheme "" not registered, fallback to default scheme
2022-02-09 06:49:44.917 [DBG] GRPC: [core] ccResolverWrapper: sending update to cc: {[{127.0.0.1:10009  <nil> 0 <nil>}] <nil> <nil>}
2022-02-09 06:49:44.917 [DBG] GRPC: [core] ClientConn switching balancer to "pick_first"
2022-02-09 06:49:44.917 [DBG] GRPC: [core] Channel switches to new LB policy "pick_first"
2022-02-09 06:49:44.917 [DBG] GRPC: [core] Subchannel Connectivity change to CONNECTING
2022-02-09 06:49:44.917 [INF] LNDC: Connected to lnd
2022-02-09 06:49:44.921 [DBG] GRPC: [core] pickfirstBalancer: UpdateSubConnState: 0xc000157da0, {CONNECTING <nil>}
2022-02-09 06:49:44.921 [DBG] GRPC: [core] Channel Connectivity change to CONNECTING
2022-02-09 06:49:44.921 [DBG] GRPC: [core] Subchannel picks a new address "127.0.0.1:10009" to connect
2022-02-09 06:49:44.929 [DBG] GRPC: [core] Subchannel Connectivity change to READY
2022-02-09 06:49:44.929 [DBG] GRPC: [core] pickfirstBalancer: UpdateSubConnState: 0xc000157510, {READY <nil>}
2022-02-09 06:49:44.930 [DBG] GRPC: [core] Channel Connectivity change to READY
2022-02-09 06:49:44.931 [DBG] GRPC: [core] Subchannel Connectivity change to READY
2022-02-09 06:49:44.931 [DBG] GRPC: [core] pickfirstBalancer: UpdateSubConnState: 0xc000157da0, {READY <nil>}
2022-02-09 06:49:44.931 [DBG] GRPC: [core] Channel Connectivity change to READY
2022-02-09 06:49:44.932 [INF] LNDC: Waiting for lnd to unlock
2022-02-09 06:49:44.934 [INF] LNDC: Wallet state of lnd is now: Lnd RPC server is ready for requests
2022-02-09 06:49:44.996 [INF] LNDC: lnd version: v0.13.3-beta, build tags 'monitoring,autopilotrpc,signrpc,walletrpc,chainrpc,invoicesrpc,routerrpc,watchtowerrpc'
2022-02-09 06:49:44.997 [INF] LNDC: Using network mainnet
2022-02-09 06:49:44.997 [INF] LNDC: Waiting for lnd to be fully synced to its chain backend, this might take a while
2022-02-09 06:49:45.059 [INF] LNDC: lnd is now fully synced to its chain backend
2022-02-09 06:49:45.691 [INF] LOOPD: Swap server address: swap.lightning.today:11010
2022-02-09 06:49:45.732 [INF] STORE: Checking for schema update: latest_version=4, db_version=4
2022-02-09 06:49:45.733 [DBG] GRPC: [core] parsed scheme: ""
2022-02-09 06:49:45.733 [DBG] GRPC: [core] scheme "" not registered, fallback to default scheme
2022-02-09 06:49:45.733 [DBG] GRPC: [core] ccResolverWrapper: sending update to cc: {[{swap.lightning.today:11010  <nil> 0 <nil>}] <nil> <nil>}
2022-02-09 06:49:45.733 [DBG] GRPC: [core] ClientConn switching balancer to "pick_first"
2022-02-09 06:49:45.733 [DBG] GRPC: [core] Channel switches to new LB policy "pick_first"
2022-02-09 06:49:45.734 [DBG] GRPC: [core] Subchannel Connectivity change to CONNECTING
2022-02-09 06:49:45.734 [DBG] GRPC: [core] Subchannel picks a new address "swap.lightning.today:11010" to connect
2022-02-09 06:49:45.734 [DBG] GRPC: [core] pickfirstBalancer: UpdateSubConnState: 0xc000594470, {CONNECTING <nil>}
2022-02-09 06:49:45.735 [DBG] GRPC: [core] Channel Connectivity change to CONNECTING
2022-02-09 06:49:45.941 [INF] POOL: Version: 0.5.4-alpha commit=v0.5.4-alpha.0.20220114202858-525fe156d240
2022-02-09 06:49:45.941 [INF] LOOPD: Starting swap client
2022-02-09 06:49:45.942 [INF] LOOP: Connected to lnd node '<NODE ALIAS' with pubkey <NODE PUB KEY> (version v0.13.3-beta, build tags 'monitoring,autopilotrpc,signrpc,walletrpc,chainrpc,invoicesrpc,routerrpc,watchtowerrpc')
2022-02-09 06:49:45.945 [INF] LOOP: Wait for first block ntfn
2022-02-09 06:49:45.945 [INF] LOOPD: Starting liquidity manager
2022-02-09 06:49:45.945 [INF] LOOPD: Waiting for updates
2022-02-09 06:49:45.953 [INF] LOOP: Starting event loop at height 722404
2022-02-09 06:49:46.128 [INF] POOL: Auction server address: pool.lightning.finance:12010
2022-02-09 06:49:46.157 [INF] CLDB: Checking for schema update: latest_version=1, db_version=1
2022-02-09 06:49:46.158 [DBG] GRPC: [core] parsed scheme: ""
2022-02-09 06:49:46.158 [DBG] GRPC: [core] scheme "" not registered, fallback to default scheme
2022-02-09 06:49:46.158 [DBG] GRPC: [core] ccResolverWrapper: sending update to cc: {[{pool.lightning.finance:12010  <nil> 0 <nil>}] <nil> <nil>}
2022-02-09 06:49:46.158 [DBG] GRPC: [core] ClientConn switching balancer to "pick_first"
2022-02-09 06:49:46.159 [DBG] GRPC: [core] Channel switches to new LB policy "pick_first"
2022-02-09 06:49:46.159 [DBG] GRPC: [core] Subchannel Connectivity change to CONNECTING
2022-02-09 06:49:46.159 [INF] RPCS: Starting trader server
2022-02-09 06:49:46.160 [DBG] GRPC: [core] Subchannel picks a new address "pool.lightning.finance:12010" to connect
2022-02-09 06:49:46.161 [DBG] GRPC: [core] pickfirstBalancer: UpdateSubConnState: 0xc000594800, {CONNECTING <nil>}
2022-02-09 06:49:46.163 [DBG] GRPC: [core] Channel Connectivity change to CONNECTING
2022-02-09 06:49:46.220 [INF] RPCS: Connected to lnd node <NODE ALIAS> with pubkey <NODE PUB KEY>
2022-022022-02-09 06:49:44.586 [INF] SESS: Checking for schema update: latest_version=0, db_version=0
2022-02-09 06:49:44.588 [INF] LITD: Dialing lnd gRPC server at 127.0.0.1:10009
2022-02-09 06:49:44.588 [DBG] GRPC: [core] parsed scheme: ""
2022-02-09 06:49:44.588 [DBG] GRPC: [core] scheme "" not registered, fallback to default scheme
2022-02-09 06:49:44.589 [DBG] GRPC: [core] ccResolverWrapper: sending update to cc: {[{127.0.0.1:10009  <nil> 0 <nil>}] <nil> <nil>}
2022-02-09 06:49:44.589 [DBG] GRPC: [core] ClientConn switching balancer to "pick_first"
2022-02-09 06:49:44.589 [DBG] GRPC: [core] Channel switches to new LB policy "pick_first"
2022-02-09 06:49:44.589 [DBG] GRPC: [core] Subchannel Connectivity change to CONNECTING
2022-02-09 06:49:44.590 [DBG] GRPC: [core] Subchannel picks a new address "127.0.0.1:10009" to connect
2022-02-09 06:49:44.591 [DBG] GRPC: [core] pickfirstBalancer: UpdateSubConnState: 0xc000235540, {CONNECTING <nil>}
2022-02-09 06:49:44.592 [DBG] GRPC: [core] Channel Connectivity change to CONNECTING
2022-02-09 06:49:44.616 [INF] LITD: Listening for http_tls on: 127.0.0.1:9443
2022-02-09 06:49:44.617 [DBG] GRPC: [core] Subchannel Connectivity change to READY
2022-02-09 06:49:44.618 [DBG] GRPC: [core] pickfirstBalancer: UpdateSubConnState: 0xc000235540, {READY <nil>}
2022-02-09 06:49:44.618 [DBG] GRPC: [core] Channel Connectivity change to READY
2022-02-09 06:49:44.617 [DBG] GRPC: [core] parsed scheme: ""
2022-02-09 06:49:44.618 [DBG] GRPC: [core] scheme "" not registered, fallback to default scheme
2022-02-09 06:49:44.618 [DBG] GRPC: [core] ccResolverWrapper: sending update to cc: {[{127.0.0.1:10009  <nil> 0 <nil>}] <nil> <nil>}
2022-02-09 06:49:44.618 [DBG] GRPC: [core] ClientConn switching balancer to "pick_first"
2022-02-09 06:49:44.619 [DBG] GRPC: [core] Channel switches to new LB policy "pick_first"
2022-02-09 06:49:44.619 [DBG] GRPC: [core] Subchannel Connectivity change to CONNECTING
2022-02-09 06:49:44.619 [DBG] GRPC: [core] blockingPicker: the picked transport is not ready, loop back to repick
2022-02-09 06:49:44.619 [DBG] GRPC: [core] pickfirstBalancer: UpdateSubConnState: 0xc000235d40, {CONNECTING <nil>}
2022-02-09 06:49:44.619 [DBG] GRPC: [core] Channel Connectivity change to CONNECTING
2022-02-09 06:49:44.619 [DBG] GRPC: [core] Subchannel picks a new address "127.0.0.1:10009" to connect
2022-02-09 06:49:44.628 [DBG] GRPC: [core] Subchannel Connectivity change to READY
2022-02-09 06:49:44.629 [DBG] GRPC: [core] pickfirstBalancer: UpdateSubConnState: 0xc000235d40, {READY <nil>}
2022-02-09 06:49:44.629 [DBG] GRPC: [core] Channel Connectivity change to READY
----------------------------------------------------------
 Lightning Terminal (LiT) by Lightning Labs               

 Operating mode      remote                                   
 Node status         online                                   
 Alias               <node alias>                                   
 Version             0.13.3-beta commit=v0.13.3-beta                                   
 Web interface       127.0.0.1:9443 (open https://127.0.0.1:9443 in your browser)         
----------------------------------------------------------
2022-02-09 06:49:44.914 [DBG] GRPC: [core] parsed scheme: ""
2022-02-09 06:49:44.914 [DBG] GRPC: [core] scheme "" not registered, fallback to default scheme
2022-02-09 06:49:44.914 [DBG] GRPC: [core] ccResolverWrapper: sending update to cc: {[{127.0.0.1:10009  <nil> 0 <nil>}] <nil> <nil>}
2022-02-09 06:49:44.914 [DBG] GRPC: [core] ClientConn switching balancer to "pick_first"
2022-02-09 06:49:44.914 [DBG] GRPC: [core] Channel switches to new LB policy "pick_first"
2022-02-09 06:49:44.915 [DBG] GRPC: [core] Subchannel Connectivity change to CONNECTING
2022-02-09 06:49:44.915 [INF] LNDC: Creating lnd connection to 127.0.0.1:10009
2022-02-09 06:49:44.915 [DBG] GRPC: [core] pickfirstBalancer: UpdateSubConnState: 0xc000157510, {CONNECTING <nil>}
2022-02-09 06:49:44.916 [DBG] GRPC: [core] parsed scheme: ""
2022-02-09 06:49:44.916 [DBG] GRPC: [core] Subchannel picks a new address "127.0.0.1:10009" to connect
2022-02-09 06:49:44.916 [DBG] GRPC: [core] Channel Connectivity change to CONNECTING
2022-02-09 06:49:44.916 [DBG] GRPC: [core] scheme "" not registered, fallback to default scheme
2022-02-09 06:49:44.917 [DBG] GRPC: [core] ccResolverWrapper: sending update to cc: {[{127.0.0.1:10009  <nil> 0 <nil>}] <nil> <nil>}
2022-02-09 06:49:44.917 [DBG] GRPC: [core] ClientConn switching balancer to "pick_first"
2022-02-09 06:49:44.917 [DBG] GRPC: [core] Channel switches to new LB policy "pick_first"
2022-02-09 06:49:44.917 [DBG] GRPC: [core] Subchannel Connectivity change to CONNECTING
2022-02-09 06:49:44.917 [INF] LNDC: Connected to lnd
2022-02-09 06:49:44.921 [DBG] GRPC: [core] pickfirstBalancer: UpdateSubConnState: 0xc000157da0, {CONNECTING <nil>}
2022-02-09 06:49:44.921 [DBG] GRPC: [core] Channel Connectivity change to CONNECTING
2022-02-09 06:49:44.921 [DBG] GRPC: [core] Subchannel picks a new address "127.0.0.1:10009" to connect
2022-02-09 06:49:44.929 [DBG] GRPC: [core] Subchannel Connectivity change to READY
2022-02-09 06:49:44.929 [DBG] GRPC: [core] pickfirstBalancer: UpdateSubConnState: 0xc000157510, {READY <nil>}
2022-02-09 06:49:44.930 [DBG] GRPC: [core] Channel Connectivity change to READY
2022-02-09 06:49:44.931 [DBG] GRPC: [core] Subchannel Connectivity change to READY
2022-02-09 06:49:44.931 [DBG] GRPC: [core] pickfirstBalancer: UpdateSubConnState: 0xc000157da0, {READY <nil>}
2022-02-09 06:49:44.931 [DBG] GRPC: [core] Channel Connectivity change to READY
2022-02-09 06:49:44.932 [INF] LNDC: Waiting for lnd to unlock
2022-02-09 06:49:44.934 [INF] LNDC: Wallet state of lnd is now: Lnd RPC server is ready for requests
2022-02-09 06:49:44.996 [INF] LNDC: lnd version: v0.13.3-beta, build tags 'monitoring,autopilotrpc,signrpc,walletrpc,chainrpc,invoicesrpc,routerrpc,watchtowerrpc'
2022-02-09 06:49:44.997 [INF] LNDC: Using network mainnet
2022-02-09 06:49:44.997 [INF] LNDC: Waiting for lnd to be fully synced to its chain backend, this might take a while
2022-02-09 06:49:45.059 [INF] LNDC: lnd is now fully synced to its chain backend
2022-02-09 06:49:45.691 [INF] LOOPD: Swap server address: swap.lightning.today:11010
2022-02-09 06:49:45.732 [INF] STORE: Checking for schema update: latest_version=4, db_version=4
2022-02-09 06:49:45.733 [DBG] GRPC: [core] parsed scheme: ""
2022-02-09 06:49:45.733 [DBG] GRPC: [core] scheme "" not registered, fallback to default scheme
2022-02-09 06:49:45.733 [DBG] GRPC: [core] ccResolverWrapper: sending update to cc: {[{swap.lightning.today:11010  <nil> 0 <nil>}] <nil> <nil>}
2022-02-09 06:49:45.733 [DBG] GRPC: [core] ClientConn switching balancer to "pick_first"
2022-02-09 06:49:45.733 [DBG] GRPC: [core] Channel switches to new LB policy "pick_first"
2022-02-09 06:49:45.734 [DBG] GRPC: [core] Subchannel Connectivity change to CONNECTING
2022-02-09 06:49:45.734 [DBG] GRPC: [core] Subchannel picks a new address "swap.lightning.today:11010" to connect
2022-02-09 06:49:45.734 [DBG] GRPC: [core] pickfirstBalancer: UpdateSubConnState: 0xc000594470, {CONNECTING <nil>}
2022-02-09 06:49:45.735 [DBG] GRPC: [core] Channel Connectivity change to CONNECTING
2022-02-09 06:49:45.941 [INF] POOL: Version: 0.5.4-alpha commit=v0.5.4-alpha.0.20220114202858-525fe156d240
2022-02-09 06:49:45.941 [INF] LOOPD: Starting swap client
2022-02-09 06:49:45.942 [INF] LOOP: Connected to lnd node '<NODE ALIAS' with pubkey <NODE PUB KEY> (version v0.13.3-beta, build tags 'monitoring,autopilotrpc,signrpc,walletrpc,chainrpc,invoicesrpc,routerrpc,watchtowerrpc')
2022-02-09 06:49:45.945 [INF] LOOP: Wait for first block ntfn
2022-02-09 06:49:45.945 [INF] LOOPD: Starting liquidity manager
2022-02-09 06:49:45.945 [INF] LOOPD: Waiting for updates
2022-02-09 06:49:45.953 [INF] LOOP: Starting event loop at height 722404
2022-02-09 06:49:46.128 [INF] POOL: Auction server address: pool.lightning.finance:12010
2022-02-09 06:49:46.157 [INF] CLDB: Checking for schema update: latest_version=1, db_version=1
2022-02-09 06:49:46.158 [DBG] GRPC: [core] parsed scheme: ""
2022-02-09 06:49:46.158 [DBG] GRPC: [core] scheme "" not registered, fallback to default scheme
2022-02-09 06:49:46.158 [DBG] GRPC: [core] ccResolverWrapper: sending update to cc: {[{pool.lightning.finance:12010  <nil> 0 <nil>}] <nil> <nil>}
2022-02-09 06:49:46.158 [DBG] GRPC: [core] ClientConn switching balancer to "pick_first"
2022-02-09 06:49:46.159 [DBG] GRPC: [core] Channel switches to new LB policy "pick_first"
2022-02-09 06:49:46.159 [DBG] GRPC: [core] Subchannel Connectivity change to CONNECTING
2022-02-09 06:49:46.159 [INF] RPCS: Starting trader server
2022-02-09 06:49:46.160 [DBG] GRPC: [core] Subchannel picks a new address "pool.lightning.finance:12010" to connect
2022-02-09 06:49:46.161 [DBG] GRPC: [core] pickfirstBalancer: UpdateSubConnState: 0xc000594800, {CONNECTING <nil>}
2022-02-09 06:49:46.163 [DBG] GRPC: [core] Channel Connectivity change to CONNECTING
2022-02-09 06:49:46.220 [INF] RPCS: Connected to lnd node <NODE ALIAS> with pubkey <NODE PUB KEY>
2022-02-09 06:49:46.654 [DBG] GRPC: [core] Subchannel Connectivity change to READY
2022-02-09 06:49:46.655 [DBG] GRPC: [core] pickfirstBalancer: UpdateSubConnState: 0xc000594800, {READY <nil>}
2022-02-09 06:49:46.655 [DBG] GRPC: [core] Channel Connectivity change to READY
2022-02-09 06:49:46.884 [INF] AUCT: Shutting down auctioneer client
2022-02-09 06:49:46.885 [DBG] GRPC: [core] Channel Connectivity change to SHUTDOWN
2022-02-09 06:49:46.885 [DBG] GRPC: [core] Subchannel Connectivity change to SHUTDOWN
2022-02-09 06:49:46.886 [ERR] LITD: Could not start subservers: unable to start account manager: unable to resume account ACCOUNT: rpc error: code = Unknown desc = transaction rejected: output already spent
2022-02-09 06:49:46.886 [INF] LOOPD: Stopping gRPC server
2022-02-09 06:49:46.886 [INF] LOOPD: Stopping REST server
2022-02-09 06:49:46.886 [INF] LOOPD: Liquidity manager stopped
2022-02-09 06:49:46.886 [INF] LOOP: Swap client terminating
2022-02-09 06:49:46.886 [DBG] LOOP: Wait for executor to finish
2022-02-09 06:49:46.887 [DBG] LOOP: Wait for goroutines to finish
2022-02-09 06:49:46.887 [INF] LOOP: Swap client terminated
2022-02-09 06:49:46.886 [DBG] GRPC: [transport] transport: loopyWriter.run returning. connection error: desc = "transport is closing"
2022-02-09 06:49:46.886 [DBG] LNDC: Closing lnd connection
2022-02-09 06:49:46.887 [DBG] GRPC: [core] Channel Connectivity change to SHUTDOWN
2022-02-09 06:49:46.887 [DBG] GRPC: [core] Subchannel Connectivity change to SHUTDOWN
2022-02-09 06:49:46.887 [DBG] LNDC: Wait for client to finish
2022-02-09 06:49:46.888 [ERR] ACCT: Unable to receive block notification: rpc error: code = Canceled desc = grpc: the client connection is closing
2022-02-09 06:49:46.888 [DBG] LNDC: Wait for chain notifier to finish
2022-02-09 06:49:46.888 [DBG] LNDC: Wait for invoices to finish
2022-02-09 06:49:46.888 [DBG] LNDC: Wait for router to finish
2022-02-09 06:49:46.888 [DBG] LNDC: Lnd services finished
2022-02-09 06:49:46.888 [DBG] LNDC: Lnd services finished
2022-02-09 06:49:46.888 [DBG] GRPC: [core] Channel Connectivity change to SHUTDOWN
2022-02-09 06:49:46.888 [DBG] GRPC: [core] Subchannel Connectivity change to SHUTDOWN
2022-02-09 06:49:46.887 [INF] LOOPD: Swap client stopped
2022-02-09 06:49:46.889 [INF] LOOPD: Daemon exited
2022-02-09 06:49:46.888 [DBG] GRPC: [transport] transport: loopyWriter.run returning. connection error: desc = "transport is closing"
2022-02-09 06:49:46.889 [WRN] GRPC: [core] grpc: addrConn.createTransport failed to connect to {swap.lightning.today:11010 swap.lightning.today:11010 <nil> 0 <nil>}. Err: connection error: desc = "transport: Error while dialing dial tcp: operation was canceled". Reconnecting...
2022-02-09 06:49:46.889 [DBG] LNDC: Closing lnd connection
2022-02-09 06:49:46.890 [ERR] LNDC: Error closing lnd connection: rpc error: code = Canceled desc = grpc: the client connection is closing
2022-02-09 06:49:46.890 [DBG] LNDC: Wait for client to finish
2022-02-09 06:49:46.890 [DBG] LNDC: Wait for chain notifier to finish
2022-02-09 06:49:46.891 [DBG] LNDC: Wait for invoices to finish
2022-02-09 06:49:46.891 [DBG] LNDC: Wait for router to finish
2022-02-09 06:49:46.891 [DBG] LNDC: Lnd services finished
2022-02-09 06:49:46.891 [DBG] LNDC: Lnd services finished
2022-02-09 06:49:46.891 [DBG] GRPC: [core] Channel Connectivity change to SHUTDOWN
2022-02-09 06:49:46.891 [DBG] GRPC: [core] Subchannel Connectivity change to SHUTDOWN
2022-02-09 06:49:46.892 [DBG] GRPC: [transport] transport: loopyWriter.run returning. connection error: desc = "transport is closing"
unable to start account manager: unable to resume account ACCOUNT: rpc error: code = Unknown desc = transaction rejected: output already spent-09 06:49:46.654 [DBG] GRPC: [core] Subchannel Connectivity change to READY
2022-02-09 06:49:46.655 [DBG] GRPC: [core] pickfirstBalancer: UpdateSubConnState: 0xc000594800, {READY <nil>}
2022-02-09 06:49:46.655 [DBG] GRPC: [core] Channel Connectivity change to READY
2022-02-09 06:49:46.884 [INF] AUCT: Shutting down auctioneer client
2022-02-09 06:49:46.885 [DBG] GRPC: [core] Channel Connectivity change to SHUTDOWN
2022-02-09 06:49:46.885 [DBG] GRPC: [core] Subchannel Connectivity change to SHUTDOWN
2022-02-09 06:49:46.886 [ERR] LITD: Could not start subservers: unable to start account manager: unable to resume account ACCOUNT: rpc error: code = Unknown desc = transaction rejected: output already spent
2022-02-09 06:49:46.886 [INF] LOOPD: Stopping gRPC server
2022-02-09 06:49:46.886 [INF] LOOPD: Stopping REST server
2022-02-09 06:49:46.886 [INF] LOOPD: Liquidity manager stopped
2022-02-09 06:49:46.886 [INF] LOOP: Swap client terminating
2022-02-09 06:49:46.886 [DBG] LOOP: Wait for executor to finish
2022-02-09 06:49:46.887 [DBG] LOOP: Wait for goroutines to finish
2022-02-09 06:49:46.887 [INF] LOOP: Swap client terminated
2022-02-09 06:49:46.886 [DBG] GRPC: [transport] transport: loopyWriter.run returning. connection error: desc = "transport is closing"
2022-02-09 06:49:46.886 [DBG] LNDC: Closing lnd connection
2022-02-09 06:49:46.887 [DBG] GRPC: [core] Channel Connectivity change to SHUTDOWN
2022-02-09 06:49:46.887 [DBG] GRPC: [core] Subchannel Connectivity change to SHUTDOWN
2022-02-09 06:49:46.887 [DBG] LNDC: Wait for client to finish
2022-02-09 06:49:46.888 [ERR] ACCT: Unable to receive block notification: rpc error: code = Canceled desc = grpc: the client connection is closing
2022-02-09 06:49:46.888 [DBG] LNDC: Wait for chain notifier to finish
2022-02-09 06:49:46.888 [DBG] LNDC: Wait for invoices to finish
2022-02-09 06:49:46.888 [DBG] LNDC: Wait for router to finish
2022-02-09 06:49:46.888 [DBG] LNDC: Lnd services finished
2022-02-09 06:49:46.888 [DBG] LNDC: Lnd services finished
2022-02-09 06:49:46.888 [DBG] GRPC: [core] Channel Connectivity change to SHUTDOWN
2022-02-09 06:49:46.888 [DBG] GRPC: [core] Subchannel Connectivity change to SHUTDOWN
2022-02-09 06:49:46.887 [INF] LOOPD: Swap client stopped
2022-02-09 06:49:46.889 [INF] LOOPD: Daemon exited
2022-02-09 06:49:46.888 [DBG] GRPC: [transport] transport: loopyWriter.run returning. connection error: desc = "transport is closing"
2022-02-09 06:49:46.889 [WRN] GRPC: [core] grpc: addrConn.createTransport failed to connect to {swap.lightning.today:11010 swap.lightning.today:11010 <nil> 0 <nil>}. Err: connection error: desc = "transport: Error while dialing dial tcp: operation was canceled". Reconnecting...
2022-02-09 06:49:46.889 [DBG] LNDC: Closing lnd connection
2022-02-09 06:49:46.890 [ERR] LNDC: Error closing lnd connection: rpc error: code = Canceled desc = grpc: the client connection is closing
2022-02-09 06:49:46.890 [DBG] LNDC: Wait for client to finish
2022-02-09 06:49:46.890 [DBG] LNDC: Wait for chain notifier to finish
2022-02-09 06:49:46.891 [DBG] LNDC: Wait for invoices to finish
2022-02-09 06:49:46.891 [DBG] LNDC: Wait for router to finish
2022-02-09 06:49:46.891 [DBG] LNDC: Lnd services finished
2022-02-09 06:49:46.891 [DBG] LNDC: Lnd services finished
2022-02-09 06:49:46.891 [DBG] GRPC: [core] Channel Connectivity change to SHUTDOWN
2022-02-09 06:49:46.891 [DBG] GRPC: [core] Subchannel Connectivity change to SHUTDOWN
2022-02-09 06:49:46.892 [DBG] GRPC: [transport] transport: loopyWriter.run returning. connection error: desc = "transport is closing"
unable to start account manager: unable to resume account ACCOUNT: rpc error: code = Unknown desc = transaction rejected: output already spent
guggero commented 2 years ago

It sounds like your Pool account got de-synced somehow. Can you please try the following:

  1. Make sure LiT is fully stopped (and not in a restart loop)
  2. Rename (or remove) the /home/USER/.pool/mainnet/pool.db file (don't touch any other files, especially not the lsat.token).
  3. Start LiT (it should now start successfully)
  4. Run pool accounts recover to get your account(s) back. See https://github.com/lightninglabs/lightning-terminal/blob/master/doc/config-lnd-remote.md#example-pool-command to find out what flags you need to use for the pool account (adjust to your system's paths obviously).
  5. Close the account or continue using it.

This will cancel any active orders. But you can re-create them after the recovery and continue using Pool if you wish.

deniv commented 2 years ago

Thank you, this has fixed the issue for me!

guggero commented 2 years ago

Cool! Thanks for the feedback, closing the issue.