Internal Server Error, Bench unresponsive

tkhamdan · December 17, 2015, 10:53pm

Was getting errors at login with v6.13.0 installed. Went to update to v6.13.1, was getting permission errors. Deleted /home/frappe/frappe-bench/logs/bench.log as per a few other posts with similar issues. Now: “Internal Server Error” in front end and unresponsiveness to all bench commands.

root@ERPNext:/# bench restart
Traceback (most recent call last):
File “/usr/local/bin/bench”, line 9, in
load_entry_point(‘bench==0.92’, ‘console_scripts’, ‘bench’)()
File “/home/frappe/bench-repo/bench/cli.py”, line 60, in cli
bench()
File “/usr/local/lib/python2.7/dist-packages/click/core.py”, line 716, in call
return self.main(*args, **kwargs)
File “/usr/local/lib/python2.7/dist-packages/click/core.py”, line 696, in main
rv = self.invoke(ctx)
File “/usr/local/lib/python2.7/dist-packages/click/core.py”, line 1057, in invoke
Command.invoke(self, ctx)
File “/usr/local/lib/python2.7/dist-packages/click/core.py”, line 889, in invoke
return ctx.invoke(self.callback, **ctx.params)
File “/usr/local/lib/python2.7/dist-packages/click/core.py”, line 534, in invoke
return callback(*args, **kwargs)
File “/home/frappe/bench-repo/bench/cli.py”, line 151, in bench
setup_logging(bench=bench)
File “/home/frappe/bench-repo/bench/utils.py”, line 237, in setup_logging
hdlr = logging.FileHandler(log_file)
File “/usr/lib/python2.7/logging/init.py”, line 903, in init
StreamHandler.init(self, self._open())
File “/usr/lib/python2.7/logging/init.py”, line 928, in _open
stream = open(self.baseFilename, self.mode)
IOError: [Errno 13] Permission denied: ‘/home/frappe/frappe-bench/logs/bench.log’

Any solutions?

rmehta · December 18, 2015, 7:20am

Can you just re-create the logs folder and make sure the user frappe has write permissions?

tkhamdan · December 18, 2015, 9:02am

I reinstalled Maria and was able to get the app to run dev with bench start, and back up all data and doctypes, but at some point I might have killed production. I can’t get anything in production to print status.

root@KJ-ERPNext:/var/lib/redis# 03:31:17 system 03:31:17 system 03:31:17 system 03:31:17 system 03:31:17 system 03:31:17 redis_async_broker.1 03:31:17 redis_async_broker.1 | 03:31:17 redis_async_broker.1 | 03:31:17 redis_async_broker.1 | 03:31:17 redis_async_broker.1 | 03:31:17 redis_async_broker.1 | 03:31:17 redis_async_broker.1 | 03:31:17 redis_async_broker.1 | 03:31:17 redis_async_broker.1 |
03:31:17 redis_async_broker.1 03:31:17 redis_async_broker.1 03:31:17 redis_async_broker.1 03:31:17 system 03:31:17 redis_cache.1 03:31:17 redis_cache.1 03:31:17 redis_cache.1 03:31:17 redis_cache.1 03:31:17 redis_cache.1 03:31:17 redis_cache.1 03:31:17 redis_cache.1 03:31:17 redis_cache.1 03:31:17 redis_cache.1 |
03:31:17 redis_cache.1 03:31:17 redis_cache.1 03:31:17 redis_cache.1 03:31:18 workerbeat.1 03:31:19 workerbeat.1 03:31:19 workerbeat.1 03:31:19 workerbeat.1 03:31:19 workerbeat.1 03:31:19 workerbeat.1 03:31:19 workerbeat.1 03:31:19 workerbeat.1 03:31:19 workerbeat.1 03:31:19 workerbeat.1 03:31:19 workerbeat.1 03:31:19 worker.1 |
03:31:19 worker.1 03:31:19 worker.1 03:31:19 worker.1 03:31:19 worker.1 03:31:19 worker.1 03:31:19 worker.1 03:31:19 worker.1 03:31:19 worker.1 03:31:19 worker.1 03:31:19 worker.1 03:31:19 worker.1 03:31:19 worker.1 03:31:19 worker.1 |
03:31:19 worker.1 |
03:31:19 worker.1 03:31:19 worker.1 03:31:19 worker.1 |
03:31:19 socketio.1 03:31:19 web.1 03:31:19 web.1 03:31:21 workerbeat.1 03:31:21 worker.1 03:31:21 worker.1 03:31:21 worker.1 |
03:31:25 workerbeat.1 03:31:25 worker.1 03:31:25 worker.1 03:31:25 worker.1 |
03:31:31 workerbeat.1 03:31:31 worker.1 03:31:31 worker.1 03:31:31 worker.1 |
03:31:33 web.1 03:31:34 web.1 03:31:38 web.1 bench start
| web.1 started (pid=2368)
| worker.1 started (pid=2367)
| workerbeat.1 started (pid=2370)
| socketio.1 started (pid=2369)
| redis_async_broker.1 started (pid=2373)
| [2381] 18 Dec 03:31:17.672 # Unable to set the max number of files limit to 10032 (Operation not permitted), setting the max clients configuration to 3984.
.
.-__ ''-._ 03:31:17 redis_async_broker.1 | _.- . . ‘’-._ Redis 2.8.4 (00000000/0) 64 bit
.- .-```. ```\/ _.,_ ''-._ 03:31:17 redis_async_broker.1 | ( ' , .-` | `, ) Running in stand alone mode 03:31:17 redis_async_broker.1 | |`-._`-...-` __...-.-.|'_.-'| Port: 12311 03:31:17 redis_async_broker.1 | | -. ._ / _.-' | PID: 2381 03:31:17 redis_async_broker.1 | -._ -._ -./ .-’ .-’
|-._-. -.__.-' _.-'_.-'| 03:31:17 redis_async_broker.1 | | -.-._ _.-'_.-' | http://redis.io 03:31:17 redis_async_broker.1 | -._ -._-..-'.-’ .-’
|-._-. -.__.-' _.-'_.-'| 03:31:17 redis_async_broker.1 | | -.-._ _.-'_.-' | 03:31:17 redis_async_broker.1 | -._ -._-..-‘.-’ .-’
-._ -..-’ _.-’
-._ _.-' 03:31:17 redis_async_broker.1 | -..-’
| [2381] 18 Dec 03:31:17.673 # Server started, Redis version 2.8.4
| [2381] 18 Dec 03:31:17.673 # WARNING overcommit_memory is set to 0! Background save may fail under low memory condition. To fix this issue add ‘vm.overcommit_memory = 1’ to /etc/sysctl.conf and then reboot or run the command ‘sysctl vm.overcommit_memory=1’ for this to take effect.
| [2381] 18 Dec 03:31:17.673 * The server is now ready to accept connections on port 12311
| redis_cache.1 started (pid=2371)
| [2386] 18 Dec 03:31:17.698 # Unable to set the max number of files limit to 10032 (Operation not permitted), setting the max clients configuration to 3984.
| .
| .-__ ''-._ 03:31:17 redis_cache.1 | _.- . . ‘’-. Redis 2.8.4 (00000000/0) 64 bit
| .- .-```. ```\/ _.,_ ''-._ 03:31:17 redis_cache.1 | ( ' , .-` | `, ) Running in stand alone mode 03:31:17 redis_cache.1 | |`-._`-...-` __...-.-.|’_.-'| Port: 11311 03:31:17 redis_cache.1 | | -._ ._ / _.-' | PID: 2386 03:31:17 redis_cache.1 | -._ -._ -./ .-’ .-’
| |-._-. -.__.-' _.-'_.-'| 03:31:17 redis_cache.1 | | -.-._ _.-'_.-' | http://redis.io 03:31:17 redis_cache.1 | -._ -._-..-'.-’ .-’
| |-._-. -.__.-' _.-'_.-'| 03:31:17 redis_cache.1 | | -.-._ _.-'_.-' | 03:31:17 redis_cache.1 | -._ -._-..-‘_.-’ _.-’
| -._ -..-’ _.-’
| -._ _.-' 03:31:17 redis_cache.1 | -..-’
| [2386] 18 Dec 03:31:17.698 # Server started, Redis version 2.8.4
| [2386] 18 Dec 03:31:17.698 # WARNING overcommit_memory is set to 0! Background save may fail under low memory condition. To fix this issue add ‘vm.overcommit_memory = 1’ to /etc/sysctl.conf and then reboot or run the command ‘sysctl vm.overcommit_memory=1’ for this to take effect.
| [2386] 18 Dec 03:31:17.698 * The server is now ready to accept connections on port 11311
| celery beat v3.1.19 (Cipater) is starting.
| __ - … __ - _
| Configuration →
| . broker → redis://localhost:6379//
| . loader → celery.loaders.app.AppLoader
| . scheduler → celery.beat.PersistentScheduler
| . db → scheduler.schedule
| . logfile → [stderr]@%INFO
| . maxinterval → now (0s)
| [2015-12-18 03:31:19,264: INFO/MainProcess] beat: Starting…
| [2015-12-18 03:31:19,348: ERROR/MainProcess] beat: Connection error: Error 111 connecting to localhost:6379. Connection refused… Trying again in 2.0 seconds…
| -------------- celery@KJ-ERPNext v3.1.19 (Cipater)
| ---- **** -----
| — * *** * – Linux-3.13.0-57-generic-x86_64-with-Ubuntu-14.04-trusty
| – * - **** —
| - ** ---------- [config]
| - ** ---------- .> app: frappe:0x7fc2c19310d0
| - ** ---------- .> transport: redis://localhost:6379//
| - ** ---------- .> results: redis://localhost
| - *** — * — .> concurrency: 1 (prefork)
| – ******* ----
| — ***** ----- [queues]
| -------------- .> celery exchange=celery(direct) key=celery
| [2015-12-18 03:31:19,499: ERROR/MainProcess] consumer: Cannot connect to redis://localhost:6379//: Error 111 connecting to localhost:6379. Connection refused…
| Trying again in 2.00 seconds…
| listening on *:3000
| * Running on http://0.0.0.0:8000/ (Press CTRL+C to quit)
| * Restarting with inotify reloader
| [2015-12-18 03:31:21,353: ERROR/MainProcess] beat: Connection error: Error 111 connecting to localhost:6379. Connection refused… Trying again in 4.0 seconds…
| [2015-12-18 03:31:21,506: ERROR/MainProcess] consumer: Cannot connect to redis://localhost:6379//: Error 111 connecting to localhost:6379. Connection refused…
| Trying again in 4.00 seconds…
| [2015-12-18 03:31:25,360: ERROR/MainProcess] beat: Connection error: Error 111 connecting to localhost:6379. Connection refused… Trying again in 6.0 seconds…
| [2015-12-18 03:31:25,514: ERROR/MainProcess] consumer: Cannot connect to redis://localhost:6379//: Error 111 connecting to localhost:6379. Connection refused…
| Trying again in 6.00 seconds…
| [2015-12-18 03:31:31,369: ERROR/MainProcess] beat: Connection error: Error 111 connecting to localhost:6379. Connection refused… Trying again in 8.0 seconds…
| [2015-12-18 03:31:31,524: ERROR/MainProcess] consumer: Cannot connect to redis://localhost:6379//: Error 111 connecting to localhost:6379. Connection refused…
| Trying again in 8.00 seconds…
| 127.0.0.1 - - [18/Dec/2015 03:31:33] “GET /desk HTTP/1.0” 200 -
| 127.0.0.1 - - [18/Dec/2015 03:31:34] “GET /api/method/frappe.async.get_user_info HTTP/1.0” 200 -
| 127.0.0.1 - - [18/Dec/2015 03:31:38] “POST / HTTP/1.0” 200 -

rmehta · December 23, 2015, 3:17pm

Your redis installation also seems messed up.

tkhamdan · January 25, 2016, 7:46pm

I did a fresh install on a bare instance. Working well now.