resh-collect ERROR: 2020/07/01 20:46:23 resh-daemon is not running - try restarting this terminal

[samuelhwilliams]

In the last few weeks, I've constantly found myself getting hit with this error: resh-collect ERROR: 2020/07/01 20:46:23 resh-daemon is not running - try restarting this terminal

It doesn't seem to be caused by anything particular that I can nail down. Not sure where log files are but happy to share them if you can point me in the right direction. It's pretty frustrating.

[curusarn]

Hi, thanks for the report.

Logs for the daemon are located in ~/.resh/daemon.log. I will be more than happy to look into this if you post the log here. (If the issue happened recently you could run e.g. tail -n 100 ~/.resh/daemon.log to get recent logs.)

[samuelhwilliams]

20560 3390 | 2020/07/01 20:46:03 /record -  python37  - part 1
20561 3390 | 2020/07/01 20:46:03 sesshist: got record to add - python37
20562 3390 | 2020/07/01 20:46:03 sesshist: Adding a record, RLocking main lock ...
20563 3390 | 2020/07/01 20:46:03 sesshist: Getting a session ...
20564 3390 | 2020/07/01 20:46:03 sesshist: RUnlocking main lock ...
20565 3390 | 2020/07/01 20:46:03 sesshist: RLocking session lock (w/ defer) ...
20566 3390 | 2020/07/01 20:46:03 sesshist: record: python37 ; added to session: 812cdf00-847f-402a-a257-98fe9ac47205 ; session len: 616 ; session len (records): 66
20567 3390 | 2020/07/01 20:46:03 /record -  python37  - part 2
20568 3390 | 2020/07/01 20:46:12 signalhandler: Got signal interrupt
20569 3390 | 2020/07/01 20:46:12 signalhandler: Sending signals to Subscribers
20570 3390 | 2020/07/01 20:46:12 histfile: Got signal interrupt
20571 3390 | 2020/07/01 20:46:12 histfile DEBUG: Unlocked mutex
20572 3390 | 2020/07/01 20:46:12 histfile DEBUG: Shutdown success
20573 3390 | 2020/07/01 20:46:12 signalhandler: All boxes shut down successfully
20574 3390 | 2020/07/01 20:46:12 signalhandler: Shutting down the server
20575 3390 | 2020/07/01 20:46:12 main: Removing pidfile ...
20576 3390 | 2020/07/01 20:46:12 main: Shutdown - bye
20577 9030 | 2020/07/01 20:47:56 Error while checking daemon status - it's probably not running! Get http://localhost:2627/status: dial tcp [::1]:2627: connect: connection refused
20578 9030 | 2020/07/01 20:47:56 Error while checking if the daemon is runnnig Get http://localhost:2627/status: dial tcp [::1]:2627: connect: connection refused
20579 9030 | 2020/07/01 20:47:56 histfile: Checking if resh_history is large enough ...
20580 9030 | 2020/07/01 20:47:56 histfile: Loading resh history from file ...
20581 9030 | 2020/07/01 20:47:56 histfile: resh history loaded - cmdLine count: 616
20582 9030 | 2020/07/01 20:47:56 /record -  source ~/.bash_profile  - part 2
20583 9030 | 2020/07/01 20:47:56 sesswatch WARN: start watching NEW session (based on /record) ~ pid: 812cdf00-847f-402a-a257-98fe9ac47205 ~ 0
20584 9030 | 2020/07/01 20:47:56 sesshist: initializing session - 812cdf00-847f-402a-a257-98fe9ac47205
20585 9030 | 2020/07/01 20:47:56 sesshist: loading history to populate session - 812cdf00-847f-402a-a257-98fe9ac47205

Based on the log, what I think is happening is that, when I run a command and ctrl-C it, sometimes that interrupt is being handled by resh - causing it to shut down. I ctrl-C relatively aggressively, it seems. I'm not sure what a workaround/fix for this might be, though ... but it is a tad annoying. Often I can bring everything back online by just sourcing my bash profile again - but sometimes that seems not to work. I'll add a log if I can reproduce that again.

[curusarn]

That's a spot on analysis.

Here's a bit more in-depth explanation of what is happening.

The resh daemon is launched whenever you open a new terminal but only if it's not running already. When you run your first terminal after booting up the resh daemon is launched by that terminal.

Every process that is launched from a terminal belongs to the same process group. When you press CTRL+C and there is nothing running in the foreground the signal is sent to all the processes in the group.

When you press CTRL+C on an empty shell prompt in the first terminal you launched after booting up the signal is sent to the resh daemon and kills it.

This is obviously something we don't want to happen. On Linux I have found a way to take the resh daemon process out of the process group so it doesn't receive the signals from the terminal. On MacOS I couldn't find a simple way to do this. There is definitely a way I just didn't have time to find it at the time.

To make things worse, when the daemon gets killed and it is relaunched by the next new terminal the issue can happen again.

How to avoid the issue

Since the daemon is only "bound" to one terminal you can prevent the issue by closing the first terminal you open after booting up.

I'm not saying this is a good solution. I want to properly solve this issue but in the meantime this might make your experience with resh more consistent.

Especially if the issue just happened to you. You can open a terminal to launch the daemon and then close it to prevent any signals from being sent to the daemon.

I hope this helps a little bit. Definitely thank you for the report. This kind of feedback is essential when I'm deciding what issues and problems to focus on next.

[samuelhwilliams]

Thanks for the detailed explanation. I'll try the proposed workaround - if it's effective then I can adapt to just doing that relatively easily.

Great work 👍

[ruvkr]

In Kubuntu 20.04, first time opening terminal after boot I get the same error. Every time I had to restart terminal.

1380 | 2020/07/10 10:20:22 Error while checking if the daemon is runnnig Get http://localhost:2627/status: dial tcp 127.0.0.1:2627: connect: connection refused
1380 | 2020/07/10 10:20:22 Pidfile exists
1380 | 2020/07/10 10:20:22 6474
1380 | 2020/07/10 10:20:22 Command finished with error: exit status 1
1380 | 2020/07/10 10:20:22 Error while killing daemon exit status 1
1380 | 2020/07/10 10:20:22 histfile: Checking if resh_history is large enough ...
1380 | 2020/07/10 10:20:22 histfile: Loading resh history from file ...
1380 | 2020/07/10 10:20:23 histfile: resh history loaded - cmdLine count: 475
1380 | 2020/07/10 10:22:14 /record -  reshctl status  - part 1
1380 | 2020/07/10 10:22:14 sesswatch WARN: start watching NEW session (based on /record) ~ pid: f1ac7234-009d-4037-b613-0a77c988c508 ~ 1234
1380 | 2020/07/10 10:22:14 sesshist: got record to add - reshctl status
1380 | 2020/07/10 10:22:14 sesshist: Adding a record, RLocking main lock ...
1380 | 2020/07/10 10:22:14 sesshist: Getting a session ...
1380 | 2020/07/10 10:22:14 sesshist: RUnlocking main lock ...
1380 | 2020/07/10 10:22:14 sesshist ERROR: addRecentRecord(): No session history for SessionID f1ac7234-009d-4037-b613-0a77c988c508 - creating session history.
1380 | 2020/07/10 10:22:14 sesshist: initializing session - f1ac7234-009d-4037-b613-0a77c988c508
1380 | 2020/07/10 10:22:14 sesshist: loading history to populate session - f1ac7234-009d-4037-b613-0a77c988c508
1380 | 2020/07/10 10:22:14 histfile: History requested ...
1380 | 2020/07/10 10:22:14 histfile: history copied (zsh) - cmdLine count: 475
1380 | 2020/07/10 10:22:14 sesshist: session init done - f1ac7234-009d-4037-b613-0a77c988c508
1380 | 2020/07/10 10:22:14 sesshist: Adding a record, RLocking main lock ...
1380 | 2020/07/10 10:22:14 sesshist: Getting a session ...
1380 | 2020/07/10 10:22:14 sesshist: RUnlocking main lock ...
1380 | 2020/07/10 10:22:14 sesshist: RLocking session lock (w/ defer) ...
1380 | 2020/07/10 10:22:14 sesshist: record: reshctl status ; added to session: f1ac7234-009d-4037-b613-0a77c988c508 ; session len: 476 ; session len (records): 1
1380 | 2020/07/10 10:22:14 /status START
1380 | 2020/07/10 10:22:14 /status END
1380 | 2020/07/10 10:22:14 /record -  reshctl status  - part 2
1380 | 2020/07/10 10:24:14 sesswatch: Dropping session ~ pid: f1ac7234-009d-4037-b613-0a77c988c508 ~ 1234
1380 | 2020/07/10 10:24:14 sesswatch: sending 'drop session' message ...
1380 | 2020/07/10 10:24:14 sesswatch: sending 'drop session' message DONE
1380 | 2020/07/10 10:24:14 sesswatch: sending 'drop session' message ...
1380 | 2020/07/10 10:24:14 sesswatch: sending 'drop session' message DONE
1380 | 2020/07/10 10:24:14 histfile: got session to drop f1ac7234-009d-4037-b613-0a77c988c508
1380 | 2020/07/10 10:24:14 histfile: No hanging parts for session: f1ac7234-009d-4037-b613-0a77c988c508
1380 | 2020/07/10 10:24:14 sesshist: got session to drop - f1ac7234-009d-4037-b613-0a77c988c508```

[curusarn]

@RrajibB Can you create a new issue because it seems like your issue is different than this one?Also can you please run tail -n 100 ~/.resh/daemon.log right after the issue happens - what you pasted seems to be normal log output from a properly running resh-daemon.

[stan-sack]

I hit this all the time and its honestly pretty frustrating. If you source ~/.zshrc manually that will fix it. This is a great project and makes my life a lot easier but this issue is a PITA.

[curusarn]

This issue should be fixed in version 2.8.0. Could somebody on macOS test that the issue is actually gone.

[curusarn]

@tivvit confirmed that the daemon is no longer getting killed by Ctrl+C key presses. Feel free to reopen if the issue persists for you.