Bench update works, but can't load after all

Install / Update
1

Hi,

I’m facing an issue for the past four days, and after read a lot, and try a lot, still can’t recover my site.

I tried to update my develop v12 version, and got a lot of problems… (in a try to fix, I’ve tried to change the branch to production… and get back to develop) So, I’ve, with your tremendous help, could fix a lot of them… Now, I can do bench update, but can’t load bench start.

When I see my worker.error.log, I see this error:

return callback(*args, **kwargs)
File “/home/frappe/frappe-bench/apps/frappe/frappe/commands/scheduler.py”, line 158, in start_worker
start_worker(queue, quiet = quiet)
File “/home/frappe/frappe-bench/apps/frappe/frappe/utils/background_jobs.py”, line 147, in start_worker
Worker(queues, name=get_worker_name(queue)).work(logging_level = logging_level)
File “/home/frappe/frappe-bench/env/local/lib/python2.7/site-packages/rq/worker.py”, line 466, in work
self.register_birth()
File “/home/frappe/frappe-bench/env/local/lib/python2.7/site-packages/rq/worker.py”, line 273, in register_birth
if self.connection.exists(self.key) and
File “/home/frappe/frappe-bench/env/local/lib/python2.7/site-packages/redis/client.py”, line 951, in exists
return self.execute_command(‘EXISTS’, name)
File “/home/frappe/frappe-bench/env/local/lib/python2.7/site-packages/redis/client.py”, line 673, in execute_command
connection.send_command(*args)
File “/home/frappe/frappe-bench/env/local/lib/python2.7/site-packages/redis/connection.py”, line 610, in send_command
self.send_packed_command(self.pack_command(*args))
File “/home/frappe/frappe-bench/env/local/lib/python2.7/site-packages/redis/connection.py”, line 585, in send_packed_command
self.connect()
File “/home/frappe/frappe-bench/env/local/lib/python2.7/site-packages/redis/connection.py”, line 489, in connect
raise ConnectionError(self._error_message(e))
redis.exceptions.ConnectionError: Error 111 connecting to localhost:11000. Connection refused.

when i look into the redis-cache.log, I see:

12643:M 12 Jul 12:06:29.025 # Current maximum open files is 4096. maxclients has been reduced to 4064 to compensate for low ulimit. If$
12643:M 12 Jul 12:06:29.025 # Creating Server TCP listening socket 127.0.0.1:13000: bind: Address already in use

bench.log:

2019-07-12 12:12:17,537 INFO git pull upstream develop

I tried a lot of things, and don’t know what I can do to fix it.

Please, I need some help!

2

If you have switched to production, then it’s possible your redis or supervisor subsystems are not happy.

sudo supervisorctl restart all

The bind address in use indicates that it has started already. Maybe check and kill those processes. Check what’s listening like so…

netstat -tnlp | grep -i listen

3

Trentmu, you always are helping us!! Thanks!

Unfortunately, it still messy.

Tonight, I did bench start, and, got this issue:

05:11:17 redis_queue.1 | 2797:M 13 Jul 05:11:17.391 * The server is now ready to accept connections on port 11000
05:12:06 socketio.1 | listening on *: 9000
05:15:05 web.1 | * Running on http://0.0.0.0:8000/ (Press CTRL+C to quit)
05:15:06 web.1 | * Restarting with inotify reloader
05:15:07 watch.1 | yarn run v1.12.3
05:15:08 watch.1 | $ node rollup/watch.js
05:15:09 web.1 | * Debugger is active!
05:15:09 web.1 | * Debugger PIN: 426-180-966
05:15:13 watch.1 |
05:15:13 watch.1 | Rollup Watcher Started
05:15:13 watch.1 |
05:15:13 watch.1 | Watching…
05:15:16 watch.1 | Rebuilding frappe-web.css
05:15:31 watch.1 | Rebuilding frappe-web-b4.css
05:15:33 watch.1 | Rebuilding chat.js
05:16:39 watch.1 | Rebuilding frappe-recorder.min.js
05:18:44 watch.1 | Rebuilding frappe-web.min.js
05:19:48 watch.1 | Rebuilding bootstrap-4-web.min.js
05:20:27 watch.1 | Rebuilding control.min.js
05:22:05 watch.1 | Rebuilding dialog.min.js
05:22:39 watch.1 | Rebuilding desk.min.css
05:22:41 watch.1 | Rebuilding frappe-rtl.css
05:22:42 watch.1 | Rebuilding printview.css
05:22:43 watch.1 | Rebuilding desk.min.js
05:26:28 watch.1 | Rebuilding module.min.css
05:26:28 watch.1 | Rebuilding form.min.css
05:26:28 watch.1 | Rebuilding form.min.js
05:27:59 watch.1 | Rebuilding list.min.css
05:27:59 watch.1 | Rebuilding list.min.js
05:30:08 watch.1 | Rebuilding report.min.css
05:30:08 watch.1 | Rebuilding report.min.js
05:30:15 watch.1 | Rebuilding web_form.min.js
05:30:20 watch.1 | Rebuilding web_form.css
05:30:21 watch.1 | Rebuilding email.css
05:30:21 watch.1 | Rebuilding social.min.js
05:30:58 watch.1 | Rebuilding modules.min.js
05:31:07 watch.1 | Rebuilding erpnext.css
05:31:10 watch.1 | Rebuilding marketplace.css
05:31:10 watch.1 | Rebuilding erpnext-web.min.js
05:31:13 watch.1 | Rebuilding erpnext-web.css
05:31:13 watch.1 | Rebuilding marketplace.min.js
05:39:57 watch.1 | Rebuilding erpnext.min.js
05:45:09 watch.1 | Rebuilding item-dashboard.min.js
06:02:32 worker_short.1 | fatal: Needed a single revision
06:02:33 worker_short.1 | fatal: Needed a single revision
07:00:46 worker_short.1 | fatal: Needed a single revision
07:00:46 worker_short.1 | fatal: Needed a single revision
08:00:51 worker_short.1 | fatal: Needed a single revision
08:00:51 worker_short.1 | fatal: Needed a single revision
09:00:57 worker_short.1 | fatal: Needed a single revision
09:00:57 worker_short.1 | fatal: Needed a single revision
10:00:02 worker_short.1 | fatal: Needed a single revision
10:00:02 worker_short.1 | fatal: Needed a single revision
11:00:07 worker_short.1 | fatal: Needed a single revision
11:00:07 worker_short.1 | fatal: Needed a single revision
12:00:14 worker_short.1 | fatal: Needed a single revision
12:00:14 worker_short.1 | fatal: Needed a single revision
13:00:18 worker_short.1 | fatal: Needed a single revision
13:00:18 worker_short.1 | fatal: Needed a single revision
14:00:24 worker_short.1 | fatal: Needed a single revision
14:00:24 worker_short.1 | fatal: Needed a single revision
15:00:29 worker_short.1 | fatal: Needed a single revision
15:00:29 worker_short.1 | fatal: Needed a single revision
16:00:35 worker_short.1 | fatal: Needed a single revision
16:00:35 worker_short.1 | fatal: Needed a single revision
17:00:40 worker_short.1 | fatal: Needed a single revision
17:00:40 worker_short.1 | fatal: Needed a single revision
^C17:28:37 system | SIGINT received
17:28:37 system | sending SIGTERM to redis_socketio.1 (pid 2755)
17:28:37 system | sending SIGTERM to worker_long.1 (pid 2767)
17:28:37 system | sending SIGTERM to watch.1 (pid 2754)
17:28:37 system | sending SIGTERM to redis_queue.1 (pid 2780)
17:28:37 system | sending SIGTERM to web.1 (pid 2762)
17:28:37 system | sending SIGTERM to schedule.1 (pid 2763)
17:28:37 system | sending SIGTERM to worker_default.1 (pid 2778)
17:28:37 system | sending SIGTERM to socketio.1 (pid 2783)
17:28:37 system | sending SIGTERM to redis_cache.1 (pid 2784)
17:28:37 system | sending SIGTERM to worker_short.1 (pid 2773)
17:28:37 worker_short.1 | 17:28:37 Warm shut down requested
17:28:38 redis_queue.1 | 2797:signal-handler (1563038917) Received SIGTERM scheduling shutdown…
17:28:38 redis_queue.1 | 2797:M 13 Jul 17:28:38.004 # User requested shutdown…
17:28:38 redis_queue.1 | 2797:M 13 Jul 17:28:38.004 # Redis is now ready to exit, bye bye…
17:28:38 redis_socketio.1 | 2757:signal-handler (1563038917) Received SIGTERM scheduling shutdown…
17:28:38 redis_socketio.1 | 2757:M 13 Jul 17:28:38.004 # User requested shutdown…
17:28:38 redis_socketio.1 | 2757:M 13 Jul 17:28:38.005 # Redis is now ready to exit, bye bye…
17:28:38 system | redis_socketio.1 stopped (rc=-15)
17:28:38 system | schedule.1 stopped (rc=-15)
17:28:38 redis_cache.1 | 2795:signal-handler (1563038917) Received SIGTERM scheduling shutdown…
17:28:38 redis_cache.1 | 2795:M 13 Jul 17:28:38.005 # User requested shutdown…
17:28:38 redis_cache.1 | 2795:M 13 Jul 17:28:38.005 # Redis is now ready to exit, bye bye…
17:28:38 system | redis_cache.1 stopped (rc=-15)
17:28:38 system | socketio.1 stopped (rc=-15)
17:28:38 system | redis_queue.1 stopped (rc=-15)
17:28:39 worker_long.1 | 17:28:38 Warm shut down requested
17:28:40 worker_long.1 | Traceback (most recent call last):
17:28:40 worker_long.1 | File “/usr/lib/python2.7/runpy.py”, line 174, in _run_module_as_main
17:28:40 worker_long.1 | “main”, fname, loader, pkg_name)
17:28:40 worker_long.1 | File “/usr/lib/python2.7/runpy.py”, line 72, in _run_code
17:28:40 worker_long.1 | exec code in run_globals
17:28:40 worker_long.1 | File “/home/frappe/frappe-bench/apps/frappe/frappe/utils/bench_helper.py”, line 97, in
17:28:40 worker_long.1 | main()
17:28:40 worker_long.1 | File “/home/frappe/frappe-bench/apps/frappe/frappe/utils/bench_helper.py”, line 18, in main
17:28:40 worker_long.1 | click.Group(commands=commands)(prog_name=‘bench’)
17:28:40 worker_long.1 | File “/home/frappe/frappe-bench/env/local/lib/python2.7/site-packages/click/core.py”, line 764, in call
17:28:40 worker_long.1 | return self.main(*args, **kwargs)
17:28:40 worker_long.1 | File “/home/frappe/frappe-bench/env/local/lib/python2.7/site-packages/click/core.py”, line 717, in main
17:28:40 worker_long.1 | rv = self.invoke(ctx)
17:28:40 worker_long.1 | File “/home/frappe/frappe-bench/env/local/lib/python2.7/site-packages/click/core.py”, line 1137, in invoke
17:28:40 worker_long.1 | return _process_result(sub_ctx.command.invoke(sub_ctx))
17:28:40 worker_long.1 | File “/home/frappe/frappe-bench/env/local/lib/python2.7/site-packages/click/core.py”, line 1137, in invoke
17:28:40 worker_long.1 | return _process_result(sub_ctx.command.invoke(sub_ctx))
17:28:40 worker_long.1 | File “/home/frappe/frappe-bench/env/local/lib/python2.7/site-packages/click/core.py”, line 956, in invoke
17:28:40 worker_long.1 | return ctx.invoke(self.callback, **ctx.params)
17:28:40 worker_long.1 | File “/home/frappe/frappe-bench/env/local/lib/python2.7/site-packages/click/core.py”, line 555, in invoke
17:28:40 worker_long.1 | return callback(*args, **kwargs)
17:28:40 worker_long.1 | File “/home/frappe/frappe-bench/apps/frappe/frappe/commands/scheduler.py”, line 158, in start_worker
17:28:40 worker_long.1 | start_worker(queue, quiet = quiet)
17:28:40 worker_long.1 | File “/home/frappe/frappe-bench/apps/frappe/frappe/utils/background_jobs.py”, line 147, in start_worker
17:28:40 worker_long.1 | Worker(queues, name=get_worker_name(queue)).work(logging_level = logging_level)
17:28:40 worker_long.1 | File “/home/frappe/frappe-bench/env/local/lib/python2.7/site-packages/rq/worker.py”, line 502, in work
17:28:40 worker_long.1 | self.register_death()
17:28:40 worker_long.1 | File “/home/frappe/frappe-bench/env/local/lib/python2.7/site-packages/rq/worker.py”, line 300, in register_death
17:28:40 worker_long.1 | p.execute()
17:28:40 worker_long.1 | File “/home/frappe/frappe-bench/env/local/lib/python2.7/site-packages/redis/client.py”, line 2894, in execute
17:28:40 worker_long.1 | return execute(conn, stack, raise_on_error)
17:28:40 worker_long.1 | File “/home/frappe/frappe-bench/env/local/lib/python2.7/site-packages/redis/client.py”, line 2749, in _execute_transaction
17:28:40 worker_long.1 | connection.send_packed_command(all_cmds)
17:28:40 worker_long.1 | File “/home/frappe/frappe-bench/env/local/lib/python2.7/site-packages/redis/connection.py”, line 585, in send_packed_command
17:28:40 worker_long.1 | self.connect()
17:28:40 worker_long.1 | File “/home/frappe/frappe-bench/env/local/lib/python2.7/site-packages/redis/connection.py”, line 489, in connect
17:28:40 worker_long.1 | raise ConnectionError(self._error_message(e))
17:28:40 worker_long.1 | redis.exceptions.ConnectionError: Error 111 connecting to localhost:11000. Connection refused.
17:28:39 worker_default.1 | 17:28:38 Warm shut down requested
17:28:40 worker_default.1 | Traceback (most recent call last):
17:28:40 worker_default.1 | File “/usr/lib/python2.7/runpy.py”, line 174, in _run_module_as_main
17:28:40 worker_default.1 | “main”, fname, loader, pkg_name)
17:28:40 worker_default.1 | File “/usr/lib/python2.7/runpy.py”, line 72, in _run_code
17:28:40 worker_default.1 | exec code in run_globals
17:28:40 worker_default.1 | File “/home/frappe/frappe-bench/apps/frappe/frappe/utils/bench_helper.py”, line 97, in
17:28:40 worker_default.1 | main()
17:28:40 worker_default.1 | File “/home/frappe/frappe-bench/apps/frappe/frappe/utils/bench_helper.py”, line 18, in main
17:28:40 worker_default.1 | click.Group(commands=commands)(prog_name=‘bench’)
17:28:40 worker_default.1 | File “/home/frappe/frappe-bench/env/local/lib/python2.7/site-packages/click/core.py”, line 764, in call
17:28:40 worker_default.1 | return self.main(*args, **kwargs)
17:28:40 worker_default.1 | File “/home/frappe/frappe-bench/env/local/lib/python2.7/site-packages/click/core.py”, line 717, in main
17:28:40 worker_default.1 | rv = self.invoke(ctx)
17:28:40 worker_default.1 | File “/home/frappe/frappe-bench/env/local/lib/python2.7/site-packages/click/core.py”, line 1137, in invoke
17:28:40 worker_default.1 | return _process_result(sub_ctx.command.invoke(sub_ctx))
17:28:40 worker_default.1 | File “/home/frappe/frappe-bench/env/local/lib/python2.7/site-packages/click/core.py”, line 1137, in invoke
17:28:40 worker_default.1 | return _process_result(sub_ctx.command.invoke(sub_ctx))
17:28:40 worker_default.1 | File “/home/frappe/frappe-bench/env/local/lib/python2.7/site-packages/click/core.py”, line 956, in invoke
17:28:40 worker_default.1 | return ctx.invoke(self.callback, **ctx.params)
17:28:40 worker_default.1 | File “/home/frappe/frappe-bench/env/local/lib/python2.7/site-packages/click/core.py”, line 555, in invoke
17:28:40 worker_default.1 | return callback(*args, **kwargs)
17:28:40 worker_default.1 | File “/home/frappe/frappe-bench/apps/frappe/frappe/commands/scheduler.py”, line 158, in start_worker
17:28:40 worker_default.1 | start_worker(queue, quiet = quiet)
17:28:40 worker_default.1 | File “/home/frappe/frappe-bench/apps/frappe/frappe/utils/background_jobs.py”, line 147, in start_worker
17:28:40 worker_default.1 | Worker(queues, name=get_worker_name(queue)).work(logging_level = logging_level)
17:28:40 worker_default.1 | File “/home/frappe/frappe-bench/env/local/lib/python2.7/site-packages/rq/worker.py”, line 502, in work
17:28:40 worker_default.1 | self.register_death()
17:28:40 worker_default.1 | File “/home/frappe/frappe-bench/env/local/lib/python2.7/site-packages/rq/worker.py”, line 300, in register_death
17:28:40 worker_default.1 | p.execute()
17:28:40 worker_default.1 | File “/home/frappe/frappe-bench/env/local/lib/python2.7/site-packages/redis/client.py”, line 2894, in execute
17:28:40 worker_default.1 | return execute(conn, stack, raise_on_error)
17:28:40 worker_default.1 | File “/home/frappe/frappe-bench/env/local/lib/python2.7/site-packages/redis/client.py”, line 2749, in _execute_transaction
17:28:40 worker_default.1 | connection.send_packed_command(all_cmds)
17:28:40 worker_default.1 | File “/home/frappe/frappe-bench/env/local/lib/python2.7/site-packages/redis/connection.py”, line 585, in send_packed_command
17:28:40 worker_default.1 | self.connect()
17:28:40 worker_default.1 | File “/home/frappe/frappe-bench/env/local/lib/python2.7/site-packages/redis/connection.py”, line 489, in connect
17:28:40 worker_default.1 | raise ConnectionError(self._error_message(e))
17:28:40 worker_default.1 | redis.exceptions.ConnectionError: Error 111 connecting to localhost:11000. Connection refused.
17:28:40 watch.1 | error Command failed with signal “SIGTERM”.
17:28:40 watch.1 | info Visit yarn run | Yarn for documentation about this command.
17:28:41 system | watch.1 stopped (rc=-15)
17:28:43 system | sending SIGKILL to worker_long.1 (pid 2767)
17:28:43 system | sending SIGKILL to web.1 (pid 2762)
17:28:43 system | sending SIGKILL to worker_default.1 (pid 2778)
17:28:43 system | sending SIGKILL to worker_short.1 (pid 2773)
17:28:43 system | worker_default.1 stopped (rc=-15)
17:28:43 system | sending SIGKILL to worker_long.1 (pid 2767)
17:28:43 system | sending SIGKILL to web.1 (pid 2762)
17:28:43 system | sending SIGKILL to worker_short.1 (pid 2773)
17:28:43 system | worker_long.1 stopped (rc=-15)
17:28:43 system | sending SIGKILL to web.1 (pid 2762)
17:28:43 system | sending SIGKILL to worker_short.1 (pid 2773)
17:28:43 system | worker_short.1 stopped (rc=-15)
17:28:43 system | sending SIGKILL to web.1 (pid 2762)
17:28:43 system | web.1 stopped (rc=-15)

When I did sudo supervisorctl restart all, and after sudo netstat -tnlp | grep -i listen, i got:

tcp 0 0 127.0.0.1:3306 0.0.0.0:* LISTEN 1868/mysqld
tcp 0 0 0.0.0.0:53 0.0.0.0:* LISTEN 1386/dnsmasq
tcp 0 0 0.0.0.0:22 0.0.0.0:* LISTEN 1326/sshd
tcp 0 0 0.0.0.0:25 0.0.0.0:* LISTEN 2259/master
tcp6 0 0 :::53 :::* LISTEN 1386/dnsmasq
tcp6 0 0 :::22 :::* LISTEN 1326/sshd
tcp6 0 0 :::25 :::* LISTEN 2259/master

I did sudo service nginx status:

● nginx.service - A high performance web server and a reverse proxy server
Loaded: loaded (/lib/systemd/system/nginx.service; enabled; vendor preset: enabled)
Active: active (running) since Sat 2019-07-13 05:04:20 UTC; 12h ago
Process: 2657 ExecReload=/usr/sbin/nginx -g daemon on; master_process on; -s reload (code=exited, status=0/SUCCESS)
Process: 1377 ExecStart=/usr/sbin/nginx -g daemon on; master_process on; (code=exited, status=0/SUCCESS)
Process: 1226 ExecStartPre=/usr/sbin/nginx -t -q -g daemon on; master_process on; (code=exited, status=0/SUCCESS)
Main PID: 1449 (nginx)
Tasks: 3
Memory: 280.0K
CPU: 732ms
CGroup: /system.slice/nginx.service
├─1449 nginx: master process /usr/sbin/nginx -g daemon on; master_process on
├─2661 nginx: worker process
└─2662 nginx: cache manager process

sudo service supervisor status:

● supervisor.service - Supervisor process control system for UNIX
Loaded: loaded (/lib/systemd/system/supervisor.service; enabled; vendor preset: enabled)
Active: active (running) since Sat 2019-07-13 05:04:14 UTC; 12h ago
Docs: http://supervisord.org
Main PID: 1278 (supervisord)
Tasks: 1
Memory: 6.2M
CPU: 1min 44.234s
CGroup: /system.slice/supervisor.service
└─1278 /usr/bin/python /usr/bin/supervisord -n -c /etc/supervisor/supervisord.conf

Jul 13 05:08:44 ip-172-31-86-84 supervisord[1278]: 2019-07-13 05:08:44,761 INFO waiting for frappe-bench-redis-cache to stop
Jul 13 05:08:44 ip-172-31-86-84 supervisord[1278]: 2019-07-13 05:08:44,798 INFO waiting for frappe-bench-redis-socketio to stop
Jul 13 05:08:44 ip-172-31-86-84 supervisord[1278]: 2019-07-13 05:08:44,839 INFO stopped: frappe-bench-redis-queue (exit status 0)
Jul 13 05:08:44 ip-172-31-86-84 supervisord[1278]: 2019-07-13 05:08:44,840 INFO stopped: frappe-bench-redis-cache (exit status 0)
Jul 13 05:08:44 ip-172-31-86-84 supervisord[1278]: 2019-07-13 05:08:44,840 INFO stopped: frappe-bench-redis-socketio (exit status 0)
Jul 13 17:46:36 ip-172-31-86-84 supervisord[1278]: 2019-07-13 17:46:36,800 CRIT Supervisor running as root (no user in config file)
Jul 13 17:46:36 ip-172-31-86-84 supervisord[1278]: 2019-07-13 17:46:36,804 WARN No file matches via include "/etc/supervisor/conf.d/*.c
Jul 13 17:46:36 ip-172-31-86-84 supervisord[1278]: 2019-07-13 17:46:36,821 INFO RPC interface ‘supervisor’ initialized
Jul 13 17:46:36 ip-172-31-86-84 supervisord[1278]: 2019-07-13 17:46:36,825 CRIT Server ‘unix_http_server’ running without any HTTP auth
Jul 13 17:46:36 ip-172-31-86-84 supervisord[1278]: 2019-07-13 17:46:36,828 INFO supervisord started with pid 1278

I really don’t know what to do… I tried to initialize another instance with clean system, but can’t install it on ubuntu 16, using EC2 AWS.

Do you have any tip?

4

This line in your traceback stands out the most, but I don’t yet know the fix (I will look into it this morning).
It looks like a git versioning problem somewhere along the line, but I am not sure. The pieces I found refer to
“That error sounds like it’s coming from git rebase” - I also don’t know git very well either.

I think this post has the most sensible looking answers…



Several options:

    You are not on a branch (Detached head) or maybe you are trying to rebase or the wrong branch.
    Checkout the branch you want to rebase and try again.

    you don't have 8 commits in your history (you have 7 or less)

    try: git rebase -i --root

Here is the documentation for the --root flag and why it will work for you.

--root

Rebase all commits reachable from <branch>, instead of limiting them with
an <upstream>.This allows you to rebase the root commit(s) on a branch.  
When used with --onto, it will skip changes already contained in `<newbase>`   
(instead of `<upstream>`) whereas without --onto it will operate on every 
change. When used together with both --onto and --preserve-merges, all root 
commits will be rewritten to have `<newbase>` as parent instead.`

I don’t know ubuntu very well. I prefer to use Debian 9.x and have done a short post on my personal blog on that install.

5

Trentmu!! Thanks for your colaboration!!

I restored the backup in another v12 instance… It’s all working now…

This intance still useless… I’ll try to recover, just to understand the problem. I’ll look deep into the git possibilities.

Thanks!!

1 Like