Logs do not appear in docker-compose

[drasko]

I am runnig openresty docker from docker-compose with other services, and only openresty do not print anything on stdout.

I have no idea where access.log and error.log are going, and if they are buffered or what - but they are no printed in the logs of docker-cmpose.

[drasko]

Also this:

content_by_lua '
   ngx.log(ngx.ERR, "Hello HTTP")
   ngx.log(ngx.ERR, ngx.var.ssl_client_cert)
';

is never printed on the screen.

[drasko]

Very strange, upon:

docker-compose -f docker/docker-compose.yml restart openresty

openresty spits all previous log on stdout and from there on starts sending access logs on stdout. Looks like something was cached previously. How to disable this caching?

Also, ony access.log is printed, i still does not print ngx.log(ngx.ERR, "Hello HTTP").

[drasko]

Indeed, docker-compose -f docker/docker-compose.yml restart openresty makes container dump all the logs on restart. I thought that these logs are outputed on stdout and never saved. If they are - where are these logs saved?

[neomantra]

The Usage section of the README says:

docker-openresty symlinks /usr/local/openresty/nginx/logs/access.log and error.log to /dev/stdout
and /dev/stderr respectively, so that Docker logging works correctly. If you change the log paths in
your nginx.conf, you should symlink those paths as well. This is not possible with the windows image.

This symlinking happens in the Dockerfile.

[drasko]

@neomantra yes, I am aware of this, and I saw that same technique is applied in official NginX Dockerfile.

However - NginX logs work like a charm, everything is printed on stdout and visible in docker-compose logs. But OpenResty logs are not, and they have this strange behavior - upon starting composition OpenResty container is silent. Then upon restart (restarting only this one container, while keeping other in composition running), it spits out all logs and from there on continues outputting access log on stdout.

What I am trying to do is to enable OpenResty for Mainflux IoT platform, and I just pushed the docker-compose.yml and nginx.conf on resty branch over there.

[drasko]

Is it possible that docker buffers stdout and not printing logs but saving them somewhere? because I can see that upon restart of this container all previous logs are spit on the screen...

And from this restart on logging works as it is supposed.

BTW, different engineers from our team thested this on different machines - same behaviour.

[neomantra]

What happens if you do docker logs on the raw container... meaning outside of your docker-compose run .

Edit: I mean, start with docker-compose and witness the buffering... then look at the raw containers with docker ps and try to docker logs the relevant one... do you see anything? Restart image as you say... then what's it look like?

[drasko]

Running container without docker-compose (and with without adding custom nginx.conf) logging works just fine:

drasko@Marx:~/go/src/github.com/mainflux/mainflux$ docker run -p 127.0.0.1:8000:80 openresty/openresty:alpine
172.17.0.1 - - [16/Mar/2019:15:44:32 +0000] "GET / HTTP/1.1" 200 649 "-" "curl/7.64.0"
172.17.0.1 - - [16/Mar/2019:15:44:35 +0000] "GET / HTTP/1.1" 200 649 "-" "curl/7.64.0"
172.17.0.1 - - [16/Mar/2019:15:44:35 +0000] "GET / HTTP/1.1" 200 649 "-" "curl/7.64.0"
172.17.0.1 - - [16/Mar/2019:15:44:36 +0000] "GET / HTTP/1.1" 200 649 "-" "curl/7.64.0"
172.17.0.1 - - [16/Mar/2019:15:44:37 +0000] "GET / HTTP/1.1" 200 649 "-" "curl/7.64.0"

Error is thus either in a custom nginx.conf or in docker-compose.

[neomantra]

I was Googling a bit and it seems there's some nuance or issues with docker-compose and buffering. If you think there's something with the image, I can try to help and point at things.

mainflux looks great btw.

[drasko]

I tried to use raw docker (without docker-compose) and custom ngin.conf - works like a charm:

drasko@Marx:~/go/src/github.com/mainflux/mainflux$ docker run --volume `pwd`/docker/nginx.conf:/usr/local/openresty/nginx/conf/nginx.conf --volume `pwd`/docker/ssl/certs/mainflux-server.crt:/etc/ssl/certs/mainflux-server.crt --volume `pwd`/docker/ssl/certs/mainflux-server.key:/etc/ssl/private/mainflux-server.key --volume `pwd`/docker/ssl/certs/ca.crt:/etc/ssl/certs/ca.crt --volume `pwd`/docker/ssl/dhparam.pem:/etc/ssl/certs/dhparam.pem -p 127.0.0.1:443:443 openresty/openresty:alpine
2019/03/16 15:57:27 [error] 8#8: *1 [lua] content_by_lua(nginx.conf:130):2: Hello HTTP, client: 172.17.0.1, server: localhost, request: "POST /users HTTP/2.0", host: "localhost"
2019/03/16 15:57:27 [error] 8#8: *1 [lua] content_by_lua(nginx.conf:130):3: -----BEGIN CERTIFICATE-----
	MIIEPzCCAyegAwIBAgIUWiGAGgp81v+arKsrWTfcC1ftePYwDQYJKoZIhvcNAQEN
	BQAwVzESMBAGA1UEAwwJbG9jYWxob3N0MREwDwYDVQQKDAhNYWluZmx1eDEMMAoG
	A1UECwwDSW9UMSAwHgYJKoZIhvcNAQkBFhFpbmZvQG1haW5mbHV4LmNvbTAeFw0x
	OTAzMTUwMTQ5MTRaFw0zMjAzMTEwMTQ5MTRaMBoxGDAWBgNVBAMMD21haW5mbHV4
	LWNsaWVudDCCASIwDQYJKoZIhvcNAQEBBQADggEPADCCAQoCggEBAKeB9GyR8Gij
	t7otk+cPtvFmhq5o5ZaT08hMRNTk6gpFrIH/9qgSDmZ45upjrdT2+GkV5QvtjI7V
	/ooS/Rdy0JOUHPRTVxOonwo04Sxy2KD4NyofN9mylOTV4LPDvq4+aggW/6OqOZVV
	ZlbIKfuNeMTxpqwJrJhVLwzySX9aoU4RHLm130kXdvJg/9d1qWKikyx7nXt0rDyB
	qLdHd6adsApQpcjAkzoQQdy6EojpJlUmV+5p6QgAMoM0X4Jy2zkulvR0tSb9rFJ/
	Cm1iAX77BfYtx6quCW06xnua4a0tDw08lPzlyioXZEQhDFWyuyOFtRMUTwJAaWB8
	Zf93O9somwcCAwEAAaOCAT4wggE6MAwGA1UdEwEB/wQCMAAwCQYDVR0RBAIwADAR
	BglghkgBhvhCAQEEBAMCBaAwHQYDVR0lBBYwFAYIKwYBBQUHAwIGCCsGAQUFBwME
	MAsGA1UdDwQEAwIDqDAqBglghkgBhvhCAQ0EHRYbTWFpbmZsdXggQ2xpZW50IENl
	cnRpZmljYXRlMB0GA1UdDgQWBBRGHgljTWjgTGkdEcfao1ftbweprjCBlAYDVR0j
	BIGMMIGJgBQL5KQHaahMjqzJ7Qw+Pei5vcUX+qFbpFkwVzESMBAGA1UEAwwJbG9j
	YWxob3N0MREwDwYDVQQKDAhNYWluZmx1eDEMMAoGA1UECwwDSW9UMSAwHgYJKoZI
	hvcNAQkBFhFpbmZvQG1haW5mbHV4LmNvbYIUaWUcPgOJU9qDuLX+ocvK5yb7NVww
	DQYJKoZIhvcNAQENBQADggEBAIkz0So+uY83BwC3dAchOFhpVtc85kG64SYLr+yJ
	r4BACcTCP+v9wrxViYXk+gtZbGTqRhpuxks699Wub6htGlb4D7oazcVjkwBObAjl
	d9r3MZqH9SVgNdiLFKY67/EzTvGWPsuNAmVsppQRslGCfaBMBBG5gMwTxOxWObRA
	rvXRWOTTvsqsMu8tClkutC6iiB5CWpjdXe2RN3ZeOxPh5kjBmHEoRdEkBKgPWJmy
	7+2OwMzM6wLOXQOGMWLsx3VGbSDDlRuedcp3WNSOw8tH+P6cexGeicOEvh86qmX5
	/j/okK5WgFMB1UPQRpW8ZaFKdr7ZHCbCWhzslle7JUOwXk4=
	-----END CERTIFICATE-----, client: 172.17.0.1, server: localhost, request: "POST /users HTTP/2.0", host: "localhost"
172.17.0.1 - - [16/Mar/2019:15:57:27 +0000] "POST /users HTTP/2.0" 200 0 "-" "curl/7.64.0"

Does exactly what I need - logs all access and also logs Lua prints (which in this case print out received client certificate).

I can not obtain these logs and especially this printfs from Lua even after container restart in docker-compose. I.e. after container restart in docker-copose I have access log, that logs accessed HTTP URLs, but I still do not have these nice prits from Lua that I need.

[drasko]

@neomantra thanks - I would like to investigate and solve this, because we really want to use OpenResty in Mainflux and allow mTLS and full X.509 client-side cert support for MQTT and other protocols.

What is strange is that official NginX image which uses the same mechianism of symlinking in the Dockerfile works fine out of the box with the same docker-compose...

[drasko]

Fixed by mounting custom nginx.conf on default OpenResty location, as described in #90

[drasko]

I have to re-open this issue. It was actually not solved when I added proxy_pass directives in nginx.conf.

I have noticed that when openresty container starts before of other containers in composition, and does not find other containers from nginx.conf, it complains with something like:

mainflux-openresty | 2019/03/17 21:00:00 [emerg] 1#1: host not found in upstream "mqtt-adapter" in /usr/local/openresty/nginx/conf/nginx.conf:302
mainflux-openresty | nginx: [emerg] host not found in upstream "mqtt-adapter" in /usr/local/openresty/nginx/conf/nginx.conf:302

OpenResty is set to restart on failure in docker-compose: https://github.com/drasko/mainflux/blob/resty/docker/docker-compose.yml#L22

Maybe this restart or error in nginx.conf somehow makes problem for logging?

[drasko]

Maybe realted to this one: docker/compose#2700

I do not understand however why mainstream NginX works in the same setup (with restart).

[drasko]

Tried with latest docker-compose v1.24-rc1 - same behavior: no logs on start, then on restart logs appear.

[drasko]

@neomantra I think that this might finally be a OpenResty issue.

Here are the steps to recreate the issue:

• Write a simple docker-compose.yml with 2 services: 1) openresty and 2) your backend to which requests would be proxied (can be hello world, whatever)
• This docker-compose.yml must containrestart: on-failure stanza, so that services are automaticly restarted when they die.
• Write simple nginx.conf in which you use proxy_pass to your hello_world backend
• Using docker-compose start only openresty service (but no hello_world yet). OpenResty will see `proxy_pass in the conf and try to connect to the backend. Then it will see that backend is missing and will die. Docker-compose will automatically restart OpenResty (which will die again, and so on).
• Now fire you other service, `hello_world backend. this time OpenResty will eventually find the service and will stop restarting. Everything should work from now on.
• However - you will see no logs in OpenResty anymore!

In order to see logs again, you need to restart OpenResty once more, manually. Then logs will appear.

I do not know what the issue might be, but the same procedure works fine with original NginX docker, as I mentioned.

[Genzer]

Hi @drasko,

Has there been any update from your case?

I happened to get into the same issue. What I did was to build a Docker image from source following Building (DEB based) with the RESTY_DEB_FLAVOR="-debug".

With nginx.conf using

error_log logs/error.log debug;

I could see all the logs to /dev/stdout and /dev/stderr, even the ones using ngx.log().

[ghost]

I can confirm @Genzer 's solution works.
I also notice something interesting, when reloading openresty within container using /usr/bin/openresty -s reload, I get following output:

openresty    | nginx: [alert] could not open error log file: open() "/usr/local/openresty/nginx/logs/error.log" failed (13: Permission denied)

[rulatir]

Is there a definite known once-and-for-all workaround for this that doesn't require rebuilding openresty from sources?

[neomantra]

It's been hard to tell what the problem actually was.... also the various software (Docker runtimes, docker-compose, OpenResty) have evolved in the last 3 years. If you have something reproducible, I can try to help troubleshoot.

[renatosc]

Almost 2 yers later and I am seeing this problem also.

[renatosc]

@akuznetsov-novatus , I followed @Genzer suggestion above to use the DEB based Docker image with debug flag and could get the logs working.

[neomantra]

I think different people are seeing this problem for different reasons. I personally could never reproduce it. Various software has advanced since then and I am happy to look at a self-contained example again.

It is weird that debug level is needed. I thought that was just needed if one tries to change the log level to debug (which @Genzer does above).

Some good news is that there are now debug images on Docker Hub, so you can run with 1.27.1.1-bullseye-debug if you need to.