Bug 901936 - uwsgi fails to start with provided systemd service file.
Summary: uwsgi fails to start with provided systemd service file.
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: Fedora
Classification: Fedora
Component: uwsgi
Version: 18
Hardware: x86_64
OS: Linux
unspecified
high
Target Milestone: ---
Assignee: Jorge Gallegos
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2013-01-20 02:56 UTC by Jason Nelson
Modified: 2013-02-14 19:03 UTC (History)
1 user (show)

Fixed In Version:
Clone Of:
Environment:
Last Closed: 2013-02-14 04:55:46 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)

Description Jason Nelson 2013-01-20 02:56:34 UTC
Description of problem:

Provided systemd start script will not start uwsgi.

Version-Release number of selected component (if applicable):

uwsgi-1.2.6-5.fc18.x86_64


How reproducible:

Everytime

Steps to Reproduce:
1. yum install uwsgi
2. systemctl enable uwsgi
3. systemctl start uwsgi
  
Actual results:

Jan 19 20:36:04 TRS80 uwsgi[4512]: open("/etc/uwsgi.ini;"): No such file or directory [utils.c line 2581]


Expected results:

uwsgi should start in daemon mode, or if there are errors within the uwsgi.ini file, to echo those errors to the systemd journal/status

Additional info:

Putting a space in between the ini and ; in /etc/systemd/system/multi-user.target.wants/uwsgi.service so it appears as such:

ExecStart=/usr/sbin/uwsgi --ini /etc/uwsgi.ini ; [ $? -eq 30 ]

Eliminates the error, however uwsgi still will not start nor report the error:

[root@TRS80 uwsgi]# systemctl status uwsgi
uwsgi.service - uWSGI Emperor Service
	  Loaded: loaded (/usr/lib/systemd/system/uwsgi.service; enabled)
	  Active: failed (Result: start-limit) since Sat, 2013-01-19 20:37:13 CST; 8s ago
	 Process: 4627 ExecStart=/usr/sbin/uwsgi --ini /etc/uwsgi.ini (code=exited, status=0/SUCCESS)
	 Process: 4624 ExecStartPre=/bin/chown uwsgi:uwsgi /run/uwsgi (code=exited, status=0/SUCCESS)
	 Process: 4621 ExecStartPre=/bin/mkdir -p /run/uwsgi (code=exited, status=0/SUCCESS)
	  CGroup: name=systemd:/system/uwsgi.service

Jan 19 20:37:13 TRS80 systemd[1]: Started uWSGI Emperor Service.
Jan 19 20:37:13 TRS80 systemd[1]: Stopping uWSGI Emperor Service...
Jan 19 20:37:13 TRS80 systemd[1]: Starting uWSGI Emperor Service...
Jan 19 20:37:13 TRS80 systemd[1]: Failed to start uWSGI Emperor Service.
Jan 19 20:37:13 TRS80 systemd[1]: Unit uwsgi.service entered failed state

[root@TRS80 uwsgi]# journalctl -n
-- Logs begin at Sat, 2013-01-19 16:24:32 CST, end at Sat, 2013-01-19 17:50:46 CST. --
Jan 19 20:37:13 TRS80 systemd[1]: Stopping uWSGI Emperor Service...
Jan 19 20:37:13 TRS80 systemd[1]: Starting uWSGI Emperor Service...
Jan 19 20:37:13 TRS80 uwsgi[4627]: [uWSGI] getting INI configuration from /etc/uwsgi.ini
Jan 19 20:37:13 TRS80 systemd[1]: Started uWSGI Emperor Service.
Jan 19 20:37:13 TRS80 systemd[1]: uwsgi.service holdoff time over, scheduling restart.
Jan 19 20:37:13 TRS80 systemd[1]: Stopping uWSGI Emperor Service...
Jan 19 20:37:13 TRS80 systemd[1]: Starting uWSGI Emperor Service...
Jan 19 20:37:13 TRS80 systemd[1]: uwsgi.service start request repeated too quickly, refusing to start.
Jan 19 20:37:13 TRS80 systemd[1]: Failed to start uWSGI Emperor Service.
Jan 19 20:37:13 TRS80 systemd[1]: Unit uwsgi.service entered failed state

However, I am able to start the daemon at the command line with:

[root@TRS80 uwsgi]# uwsgi --ini /etc/uwsgi.ini
[uWSGI] getting INI configuration from /etc/uwsgi.ini

Given the config of:

[root@TRS80 uwsgi]# cat /etc/uwsgi.ini
[uwsgi]
uid = uwsgi
gid = uwsgi
socket = 127.0.0.1:3031
master = true
daemonize = true
pidfile = /run/uwsgi/uwsgi.pid

[root@TRS80 uwsgi]# ps -ef | grep uwsgi
uwsgi     4667     1  0 20:52 ?        00:00:00 uwsgi --ini /etc/uwsgi.ini
uwsgi     4668  4667  0 20:52 ?        00:00:00 uwsgi --ini /etc/uwsgi.ini
root      4678  3039  0 20:53 pts/0    00:00:00 grep --color=auto uwsgi

[root@TRS80 uwsgi]# netstat -lntp | grep 3031
tcp        0      0 127.0.0.1:3031          0.0.0.0:*               LISTEN      4667/uwsgi

Comment 1 Jorge Gallegos 2013-01-21 21:29:39 UTC
Hi,

This is partly a duplicate (sort of) of BZ 873382. It is sort of a duplicate because that bug is to get uwsgi to get rid of that hacky call in the systemd file. I pushed a build to stable just today, should arrive in -updates shortly, but if you want to try it before that happens here's the build:

http://koji.fedoraproject.org/koji/buildinfo?buildID=375043

Please let me know if this fixes the issue with uwsgi respawning.


Cheers

Comment 2 Jason Nelson 2013-01-26 03:17:27 UTC
Alright, updated, currently not starting, however, also not running a default config (but a fairly standard config).

First error was:

Jan 25 09:37:47 TRS80 systemd[1]: Starting uWSGI Emperor Service...
Jan 25 09:37:47 TRS80 uwsgi[2421]: [uWSGI] getting INI configuration from /etc/uwsgi.ini
Jan 25 09:37:47 TRS80 uwsgi[2421]: *** Starting uWSGI 1.2.6 (64bit) on [Fri Jan 25 09:37:47 2013] ***
Jan 25 09:37:47 TRS80 uwsgi[2421]: compiled with version: 4.7.2 20121109 (Red Hat 4.7.2-8) on 27 December 2012 02:3
5:22
Jan 25 09:37:47 TRS80 uwsgi[2421]: detected number of CPU cores: 2
Jan 25 09:37:47 TRS80 uwsgi[2421]: current working directory: /
Jan 25 09:37:47 TRS80 uwsgi[2421]: writing pidfile to /run/uwsgi/uwsgi.pid
Jan 25 09:37:47 TRS80 uwsgi[2421]: detected binary path: /usr/sbin/uwsgi
Jan 25 09:37:47 TRS80 uwsgi[2421]: setgid() to 988
Jan 25 09:37:47 TRS80 uwsgi[2421]: setuid() to 991
Jan 25 09:37:47 TRS80 uwsgi[2421]: *** WARNING: you are running uWSGI without its master process manager ***
Jan 25 09:37:47 TRS80 uwsgi[2421]: your memory page size is 4096 bytes
Jan 25 09:37:47 TRS80 uwsgi[2421]: detected max file descriptor number: 1024
Jan 25 09:37:47 TRS80 uwsgi[2421]: lock engine: pthread robust mutexes
Jan 25 09:37:47 TRS80 uwsgi[2421]: *** starting uWSGI Emperor ***
Jan 25 09:37:47 TRS80 uwsgi[2421]: uwsgi socket 0 bound to UNIX address /run/uwsgi/uwsgi.socket fd 4
Jan 25 09:37:47 TRS80 uwsgi[2421]: your server socket listen backlog is limited to 100 connections
Jan 25 09:37:47 TRS80 uwsgi[2421]: *** Operational MODE: single process ***
Jan 25 09:37:47 TRS80 uwsgi[2421]: *** no app loaded. going in full dynamic mode ***
Jan 25 09:37:47 TRS80 uwsgi[2421]: *** uWSGI is running in multiple interpreter mode ***
Jan 25 09:37:47 TRS80 uwsgi[2421]: spawned uWSGI worker 1 (and the only) (pid: 2421, cores: 1)
Jan 25 09:37:48 TRS80 uwsgi[2421]: [emperor-tyrant] invalid permissions for file test.ini
Jan 25 09:37:52 TRS80 uwsgi[2421]: [emperor-tyrant] invalid permissions for file test.ini


Easy enough, chown uwsgi:uwsgi /etc/uwsgi.d/test.ini

Now, I receive:

Jan 25 10:59:56 TRS80 uwsgi[3900]: [emperor-tyrant] dropping privileges to 991 988 for instance test.ini
Jan 25 10:59:56 TRS80 uwsgi[3900]: setgroups(): Operation not permitted [emperor.c line 277]
Jan 25 10:59:56 TRS80 uwsgi[3900]: removed uwsgi instance test.ini

And a restart every second.

So somewhere along the line, uwsgi lost the ability to do setgroups().

This happens when using both systemctl or starting from the command line.

So I tried blowing away the current configs, and reinstalling (disabling and re-enabling the service).  Put back my configs, and still the same issue.

Current configs:

uwsgi.ini:

[root@TRS80 uwsgi.d]# cat /etc/uwsgi.ini 
[uwsgi]
uid = uwsgi
gid = uwsgi
pidfile = /run/uwsgi/uwsgi.pid
emperor = /etc/uwsgi.d
emperor-tyrant = true
master = true

[root@TRS80 uwsgi.d]# cat /etc/uwsgi.d/test.ini 
[uwsgi]
plugin = python
pythonpath = /var/www/
mount = /=hello:application
socket = 0.0.0.0:3031
logto = /var/log/uwsgi/uwsgi.log

If I set emperor-tyrant to false, I can start fine from the command line, starting from systemctl starts the service, but I still receive the timeout 90 seconds later and it restarts uwsgi over.  Command line shows:

[root@TRS80 uwsgi.d]# systemctl start uwsgi
Job for uwsgi.service failed. See 'systemctl status uwsgi.service' and 'journalctl -xn' for details.

[root@TRS80 uwsgi.d]# systemctl status uwsgi.service 
uwsgi.service - uWSGI Emperor Service
	  Loaded: loaded (/usr/lib/systemd/system/uwsgi.service; enabled)
	  Active: activating (start) since Fri 2013-01-25 21:16:31 CST; 31s ago
	 Process: 13105 ExecStartPre=/bin/chown uwsgi:uwsgi /run/uwsgi (code=exited, status=0/SUCCESS)
	 Process: 13102 ExecStartPre=/bin/mkdir -p /run/uwsgi (code=exited, status=0/SUCCESS)
	Main PID: 13108 (uwsgi)
	  CGroup: name=systemd:/system/uwsgi.service
		  ├─13108 /usr/sbin/uwsgi --ini /etc/uwsgi.ini
		  ├─13109 /usr/sbin/uwsgi --ini /etc/uwsgi.ini
		  ├─13110 /usr/sbin/uwsgi --ini test.ini
		  └─13111 /usr/sbin/uwsgi --ini test.ini

Jan 25 21:16:31 TRS80 uwsgi[13108]: setgid() to 988
Jan 25 21:16:31 TRS80 uwsgi[13108]: setuid() to 991
Jan 25 21:16:31 TRS80 uwsgi[13108]: your memory page size is 4096 bytes
Jan 25 21:16:31 TRS80 uwsgi[13108]: detected max file descriptor number: 1024
Jan 25 21:16:31 TRS80 uwsgi[13108]: lock engine: pthread robust mutexes
Jan 25 21:16:31 TRS80 uwsgi[13108]: *** Operational MODE: no-workers ***
Jan 25 21:16:31 TRS80 uwsgi[13108]: spawned uWSGI master process (pid: 13108)
Jan 25 21:16:31 TRS80 uwsgi[13108]: *** starting uWSGI Emperor ***
Jan 25 21:16:32 TRS80 uwsgi[13108]: *** has_emperor mode detected (fd: 7) ***
Jan 25 21:16:32 TRS80 uwsgi[13108]: [uWSGI] getting INI configuration from test.ini


Let me know if you need more info.

Comment 3 Jorge Gallegos 2013-02-14 04:55:46 UTC
Thanks, this is useful... I don't think this is exactly related but a bug nonetheless. Let's close this one and track the setgroups() stuff in a different one, I'll poke the uwsgi mailing list for details.

Comment 4 Jorge Gallegos 2013-02-14 19:03:29 UTC
All right so there's probably no need for a new bug, I asked around, you can see the response here:

http://lists.unbit.it/pipermail/uwsgi/2013-February/005370.html

tl;dr I shouldn't be putting "emperor-tyrant" in the emperor.ini. I pushed https://admin.fedoraproject.org/updates/uwsgi-1.2.6-7.fc18 which only has that change... 

diff --git a/emperor.ini b/emperor.ini
index 562b57b..9dfecca 100644
--- a/emperor.ini
+++ b/emperor.ini
@@ -4,4 +4,3 @@ gid = uwsgi
 socket = /run/uwsgi/uwsgi.socket
 pidfile = /run/uwsgi/uwsgi.pid
 emperor = /etc/uwsgi.d
-emperor-tyrant = true

And try again.


Note You need to log in before you can comment on or make changes to this bug.