1. Jordan Lee Avatar Jordan Lee
  2. Untitled project
  3. NuBotTrading
  4. Issues

Stopping the bot via GUI stop button : "no active session"

Issue #589 resolved
Desrever Nu created an issue

The shutdown sequence looks ok looking at the console, and also monitoring the session file being created and destroyed.

17:38:03.765 [qtp979231439-23 - //localhost:4567/startstop] INFO  - bot start/stop  >> stop [com.nubits.nubot.webui.BotController:73]
17:38:03.765 [qtp979231439-23 - //localhost:4567/startstop] INFO  - try interrupt bot [com.nubits.nubot.webui.BotController:117]
17:38:03.766 [qtp979231439-23 - //localhost:4567/startstop] INFO  - Bot shutting down sequence started. [com.nubits.nubot.bot.NuBotBase:293]
17:38:03.767 [qtp979231439-23 - //localhost:4567/startstop] INFO  - after 0 hours 0 minutes 33 seconds uptime on bitcoincoid [nbt_btc] [com.nubits.nubot.bot.NuBotBase:302]
17:38:04.304 [qtp979231439-23 - //localhost:4567/startstop] INFO  - try to shutdown all tasks [com.nubits.nubot.bot.NuBotBase:310]
17:38:04.305 [qtp979231439-23 - //localhost:4567/startstop] INFO  - Stopping all BotTasks.  [com.nubits.nubot.tasks.TaskManager:141]
17:38:04.305 [qtp979231439-23 - //localhost:4567/startstop] DEBUG - Shutting down checkConnection [com.nubits.nubot.tasks.TaskManager:147]
17:38:04.305 [qtp979231439-23 - //localhost:4567/startstop] DEBUG - Shutting down sendLiquidity [com.nubits.nubot.tasks.TaskManager:147]
17:38:04.305 [qtp979231439-23 - //localhost:4567/startstop] DEBUG - Shutting down Strategy Fiat Task [com.nubits.nubot.tasks.TaskManager:147]
17:38:04.306 [qtp979231439-23 - //localhost:4567/startstop] DEBUG - Shutting down Strategy Crypto Task [com.nubits.nubot.tasks.TaskManager:147]
17:38:04.306 [qtp979231439-23 - //localhost:4567/startstop] DEBUG - Shutting down priceTriggerTask [com.nubits.nubot.tasks.TaskManager:147]
17:38:04.306 [qtp979231439-23 - //localhost:4567/startstop] INFO  - BotTasks stopped.  [com.nubits.nubot.tasks.TaskManager:155]
17:38:04.307 [qtp979231439-23 - //localhost:4567/startstop] INFO  - Clearing out active orders ...  [com.nubits.nubot.bot.NuBotBase:321]
17:38:10.259 [qtp979231439-28 - //localhost:4567/info] DEBUG - activeorders BUY 1 [com.nubits.nubot.strategy.OrderManager:267]
17:38:10.259 [qtp979231439-28 - //localhost:4567/info] DEBUG - buy orders: 1 [com.nubits.nubot.strategy.OrderManager:283]
17:38:10.381 [qtp979231439-23 - //localhost:4567/startstop] INFO  - Order clear request successful [com.nubits.nubot.bot.NuBotBase:328]
17:38:10.382 [qtp979231439-23 - //localhost:4567/startstop] INFO  - Logs of this session saved in logs/session_1429717043980 [com.nubits.nubot.bot.NuBotBase:361]
17:38:10.382 [qtp979231439-23 - //localhost:4567/startstop] INFO  - ** end of the session ** [com.nubits.nubot.bot.NuBotBase:365]
17:38:10.385 [qtp979231439-45 - //localhost:4567/startstop] INFO  - bot start/stop  >> stop [com.nubits.nubot.webui.BotController:73]
17:38:10.385 [qtp979231439-45 - //localhost:4567/startstop] INFO  - no session running [com.nubits.nubot.webui.BotController:132]
17:38:10.552 [qtp979231439-28 - //localhost:4567/info] DEBUG - activeorders SELL 0 [com.nubits.nubot.strategy.OrderManager:267]
17:38:10.553 [qtp979231439-28 - //localhost:4567/info] DEBUG - sell orders: 0 [com.nubits.nubot.strategy.OrderManager:284]
17:38:10.853 [qtp979231439-28 - //localhost:4567/info] DEBUG - activeorders BUY 0 [com.nubits.nubot.strategy.OrderManager:267]
17:38:11.144 [qtp979231439-28 - //localhost:4567/info] DEBUG - activeorders SELL 0 [com.nubits.nubot.strategy.OrderManager:267]
17:38:11.144 [qtp979231439-28 - //localhost:4567/info] DEBUG - buys: 0 [com.nubits.nubot.webui.LogController:66]
17:38:11.144 [qtp979231439-28 - //localhost:4567/info] DEBUG - sells: 0 [com.nubits.nubot.webui.LogController:67]

Comments (18)

  1. Benjamin Cordes

    this is a race condition ... session ended and then query reaches. with a change in shutdown this will go away.

  2. Desrever Nu reporter

    happened again The first time start and then stop worked perfectly. Then I re started the bot, and when I stopped I had a "no session running" popup.

    The bot stopped correctly apparently : 

    11:54:15.718 [qtp1144461211-22 - //localhost:4567/startstop] INFO  - bot start/stop  >> stop [com.nubits.nubot.webui.BotController:67]
11:54:15.719 [qtp1144461211-22 - //localhost:4567/startstop] INFO  - try interrupt bot [com.nubits.nubot.webui.BotController:111]
11:54:15.719 [qtp1144461211-22 - //localhost:4567/startstop] INFO  - Bot shutting down sequence started. [com.nubits.nubot.bot.NuBotBase:293]
11:54:15.719 [qtp1144461211-22 - //localhost:4567/startstop] INFO  - after 0 hours 0 minutes 42 seconds uptime on ccedk [nbt_btc] [com.nubits.nubot.bot.NuBotBase:302]
11:54:16.788 [qtp1144461211-22 - //localhost:4567/startstop] INFO  - try to shutdown all tasks [com.nubits.nubot.bot.NuBotBase:310]
11:54:16.789 [qtp1144461211-22 - //localhost:4567/startstop] INFO  - Stopping all BotTasks.  [com.nubits.nubot.tasks.TaskManager:148]
11:54:16.789 [qtp1144461211-22 - //localhost:4567/startstop] INFO  - Stopped BotTask checkConnection [com.nubits.nubot.tasks.BotTask:74]
11:54:16.790 [qtp1144461211-22 - //localhost:4567/startstop] INFO  - Stopped BotTask sendLiquidity [com.nubits.nubot.tasks.BotTask:74]
11:54:16.790 [qtp1144461211-22 - //localhost:4567/startstop] INFO  - Stopped BotTask Strategy Fiat Task [com.nubits.nubot.tasks.BotTask:74]
11:54:16.791 [qtp1144461211-22 - //localhost:4567/startstop] INFO  - Stopped BotTask Strategy Crypto Task [com.nubits.nubot.tasks.BotTask:74]
11:54:16.791 [qtp1144461211-22 - //localhost:4567/startstop] INFO  - Stopped BotTask priceTriggerTask [com.nubits.nubot.tasks.BotTask:74]
11:54:16.792 [qtp1144461211-22 - //localhost:4567/startstop] INFO  - BotTasks stopped.  [com.nubits.nubot.tasks.TaskManager:162]
11:54:16.792 [qtp1144461211-22 - //localhost:4567/startstop] INFO  - Clearing out active orders ...  [com.nubits.nubot.bot.NuBotBase:321]
11:54:17.706 [qtp1144461211-22 - //localhost:4567/startstop] ERROR - Could not submit request to clear orders [c.n.n.b.NuBotBase:330]
11:54:17.706 [qtp1144461211-22 - //localhost:4567/startstop] INFO  - Logs of this session saved in logs/session_1430128292867 [com.nubits.nubot.bot.NuBotBase:361]
11:54:17.706 [qtp1144461211-22 - //localhost:4567/startstop] INFO  - ** end of the session ** [com.nubits.nubot.bot.NuBotBase:364]
11:54:17.710 [qtp1144461211-79 - //localhost:4567/startstop] INFO  - bot start/stop  >> stop [com.nubits.nubot.webui.BotController:67]
11:54:17.710 [qtp1144461211-79 - //localhost:4567/startstop] INFO  - no session running [com.nubits.nubot.webui.BotController:126]

    Will try to reproduce to see if I can identify patterns and provide verbose log

  6. Benjamin Cordes

    I could reproduce this issue once again. I think finally I know what the problem is. The client requests stop. then if things take too long, the browser somehow automatically re-tries and then gets this error.

    This could be fixed with issuing stop with a future. The client can't know immediately whether stop was successful or not. Alternatively in BotController we check whether things where recently halted and then return success. I'll try the second method since its easier.

  7. Benjamin Cordes

    here is my log. stop was issued twice.

    12:00:50.867 [qtp466121628-21 - //localhost:4567/startstop] INFO  - bot start/stop  >> stop [c.n.n.w.BotController:67]
12:00:50.868 [qtp466121628-21 - //localhost:4567/startstop] INFO  - try interrupt bot. set halting mode [c.n.n.w.BotController:112]
...
12:00:54.408 [qtp466121628-21 - //localhost:4567/startstop] INFO  - ** end of the session ** [c.n.n.b.NuBotBase:376]
12:00:54.408 [qtp466121628-21 - //localhost:4567/startstop] INFO  - session statistics [c.n.n.b.NuBotBase:294]
12:00:54.408 [qtp466121628-21 - //localhost:4567/startstop] INFO  - totalOrdersSubmitted 4 [c.n.n.b.NuBotBase:296]
12:00:54.409 [qtp466121628-21 - //localhost:4567/startstop] INFO  - after 0 hours 0 minutes 31 seconds uptime on Poloniex [nbt_btc] [c.n.n.b.NuBotBase:305]
12:00:55.007 [qtp466121628-21 - //localhost:4567/startstop] INFO  - startup time: 7541 [c.n.n.b.NuBotBase:308]
12:00:55.012 [qtp466121628-20 - //localhost:4567/startstop] DEBUG - /startstop called [c.n.n.w.BotController:52]
12:00:55.013 [qtp466121628-20 - //localhost:4567/startstop] INFO  - bot start/stop  >> stop [c.n.n.w.BotController:67]
12:00:55.014 [qtp466121628-20 - //localhost:4567/startstop] INFO  - no session running [c.n.n.w.BotController:127]
  8. Desrever Nu reporter

    Nice catch, we could also temporarily prevent the client from refreshing the status from the moment in which the user presses the "stop" button till the end of the "progress bar" animation (or another event) .

    With js is possible to stop an interval timer by knowing its id : http://stackoverflow.com/a/109091/4812573

  9. Desrever Nu reporter

    stop was issued twice.

    mmm are you telling me the client called the /startstop route twice? Can you paste the lines immediately above the one you already posted? from that snipped this line is only printed once : 

    12:00:55.012 [qtp466121628-20 - //localhost:4567/startstop] DEBUG - /startstop called [c.n.n.w.BotController:52]
  10. Benjamin Cordes 
    **12:00:50.866 c.n.n.w.BotController - /startstop called**
12:00:50.867 c.n.n.w.BotController - bot start/stop  >> stop
12:00:50.868 c.n.n.w.BotController - try interrupt bot. set halting mode
12:00:50.868 c.n.n.b.SessionManager - set mode to halting
12:00:50.868 c.n.n.b.NuBotBase - Bot shutting down sequence started.

12:00:54.408 c.n.n.b.NuBotBase - ** end of the session **
12:00:54.408 c.n.n.b.NuBotBase - session statistics
12:00:54.408 c.n.n.b.NuBotBase - totalOrdersSubmitted 4
12:00:54.409 c.n.n.b.NuBotBase - after 0 hours 0 minutes 31 seconds uptime on Poloniex [nbt_btc]
12:00:55.007 c.n.n.b.NuBotBase - startup time: 7541
**12:00:55.012 c.n.n.w.BotController - /startstop called**
12:00:55.013 c.n.n.w.BotController - bot start/stop  >> stop
12:00:55.014 c.n.n.w.BotController - no session running
12:08:22.438 c.n.n.bot.Global - global shutdownhook called
12:08:22.440 c.n.n.bot.Global - Exit main
  11. Benjamin Cordes

    call happened twice. I believe it's automatically. in the JS we call it only once, but since it timeouts it probably retries somehow

  13. Benjamin Cordes

    to reproduce this one should leave the session running for a bit. then shutdown takes longer. proposed fix

    if (SessionManager.lastStopped()<10000){
                    opmap.put("success", true);
                    json = new Gson().toJson(opmap);
                    return json;
                }
  14. Desrever Nu reporter

    the stopbot() js function is not in timeouts.

    This is the only place where it is called , and it requires a click on the button...

     $('#togglebot').click(function() {
          if (botRunning)
              stopBot();
          else
              startBot();
      });

    Maybe you clicked twice?

    And the click should be disabled when the animation is running. Which browser are you using?

    We can add another check for safety

  16. Benjamin Cordes

    I think this is internally. the above piece of code should fix it. we just ignore the second call, if the last stop was less then 10 sec ago.

  19. Log in to comment
Assignee
Type
bug
Priority
major
Status
resolved
Milestone
0.3.0 - UI
Version
–
Votes
0
Watchers
1
Jira: the preferred issue tracker for Bitbucket. Join the team!