9: Bad file descriptor

[niko]

I'm using Openresty 1.17.8.2 to stream data from Redis to clients. So there are long open connections to Redis using lua-resty-redis and long open connections to the clients. Lately I'm seeing these error messages:

2020/10/21 08:46:31 [emerg] 27167#3261: lua pipe child close() socket xx.xx.x.xx:443 failed (9: Bad file descriptor)

The unexpected thing: I increased the log level from warn to debug and the error messages disappear. Any idea how I can further debug the error?

This is how it actually looks in the logs (docker logs -f e0dfb6f130 | grep descriptor | uniq -c), the number at the beginning of the line being the number of occurrences of the very same line:

     30 2020/10/21 11:48:19 [emerg] 822#30882: lua pipe child close() socket xx.xx.x.xx:8080 failed (9: Bad file descriptor)
     30 2020/10/21 11:48:19 [emerg] 822#30882: lua pipe child close() socket 172.17.110.1:8080 failed (9: Bad file descriptor)
     30 2020/10/21 11:48:19 [emerg] 822#30882: lua pipe child close() socket xx.xx.x.xx:8443 failed (9: Bad file descriptor)

      1 2020/10/21 11:48:22 [emerg] 816#30887: lua pipe child close() socket xx.xx.x.xx:8080 failed (9: Bad file descriptor)
      1 2020/10/21 11:48:22 [emerg] 816#30887: lua pipe child close() socket 172.17.110.1:8080 failed (9: Bad file descriptor)
      1 2020/10/21 11:48:22 [emerg] 816#30887: lua pipe child close() socket xx.xx.x.xx:8443 failed (9: Bad file descriptor)
     30 2020/10/21 11:48:22 [emerg] 816#30887: lua pipe child close() socket xx.xx.x.xx:8080 failed (9: Bad file descriptor)
     30 2020/10/21 11:48:22 [emerg] 816#30887: lua pipe child close() socket 172.17.110.1:8080 failed (9: Bad file descriptor)
     30 2020/10/21 11:48:22 [emerg] 816#30887: lua pipe child close() socket xx.xx.x.xx:8443 failed (9: Bad file descriptor)

      1 2020/10/21 11:48:51 [emerg] 841#30972: lua pipe child close() socket xx.xx.x.xx:8080 failed (9: Bad file descriptor)
      1 2020/10/21 11:48:51 [emerg] 841#30972: lua pipe child close() socket 172.17.110.1:8080 failed (9: Bad file descriptor)
      1 2020/10/21 11:48:51 [emerg] 841#30972: lua pipe child close() socket xx.xx.x.xx:8443 failed (9: Bad file descriptor)
     30 2020/10/21 11:48:51 [emerg] 841#30972: lua pipe child close() socket xx.xx.x.xx:8080 failed (9: Bad file descriptor)
     30 2020/10/21 11:48:51 [emerg] 841#30972: lua pipe child close() socket 172.17.110.1:8080 failed (9: Bad file descriptor)
     30 2020/10/21 11:48:51 [emerg] 841#30972: lua pipe child close() socket xx.xx.x.xx:8443 failed (9: Bad file descriptor)

      1 2020/10/21 11:49:21 [emerg] 826#31034: lua pipe child close() socket xx.xx.x.xx:8080 failed (9: Bad file descriptor)
      1 2020/10/21 11:49:21 [emerg] 826#31034: lua pipe child close() socket 172.17.110.1:8080 failed (9: Bad file descriptor)
      1 2020/10/21 11:49:21 [emerg] 826#31034: lua pipe child close() socket xx.xx.x.xx:8443 failed (9: Bad file descriptor)
     30 2020/10/21 11:49:21 [emerg] 826#31034: lua pipe child close() socket xx.xx.x.xx:8080 failed (9: Bad file descriptor)
     30 2020/10/21 11:49:21 [emerg] 826#31034: lua pipe child close() socket 172.17.110.1:8080 failed (9: Bad file descriptor)
     30 2020/10/21 11:49:21 [emerg] 826#31034: lua pipe child close() socket xx.xx.x.xx:8443 failed (9: Bad file descriptor)

      1 2020/10/21 11:49:48 [emerg] 822#31161: lua pipe child close() socket xx.xx.x.xx:8080 failed (9: Bad file descriptor)
      1 2020/10/21 11:49:48 [emerg] 822#31161: lua pipe child close() socket 172.17.110.1:8080 failed (9: Bad file descriptor)
      1 2020/10/21 11:49:48 [emerg] 822#31161: lua pipe child close() socket xx.xx.x.xx:8443 failed (9: Bad file descriptor)
     30 2020/10/21 11:49:48 [emerg] 822#31161: lua pipe child close() socket xx.xx.x.xx:8080 failed (9: Bad file descriptor)
     30 2020/10/21 11:49:48 [emerg] 822#31161: lua pipe child close() socket 172.17.110.1:8080 failed (9: Bad file descriptor)
     30 2020/10/21 11:49:48 [emerg] 822#31161: lua pipe child close() socket xx.xx.x.xx:8443 failed (9: Bad file descriptor)

     31 2020/10/21 11:50:00 [emerg] 812#31162: lua pipe child close() socket xx.xx.x.xx:8080 failed (9: Bad file descriptor)
     31 2020/10/21 11:50:00 [emerg] 812#31162: lua pipe child close() socket 172.17.110.1:8080 failed (9: Bad file descriptor)
     31 2020/10/21 11:50:00 [emerg] 812#31162: lua pipe child close() socket xx.xx.x.xx:8443 failed (9: Bad file descriptor)

     31 2020/10/21 11:50:09 [emerg] 812#31207: lua pipe child close() socket xx.xx.x.xx:8080 failed (9: Bad file descriptor)
     31 2020/10/21 11:50:09 [emerg] 812#31207: lua pipe child close() socket 172.17.110.1:8080 failed (9: Bad file descriptor)
     31 2020/10/21 11:50:09 [emerg] 812#31207: lua pipe child close() socket xx.xx.x.xx:8443 failed (9: Bad file descriptor)

     31 2020/10/21 11:50:10 [emerg] 812#31215: lua pipe child close() socket xx.xx.x.xx:8080 failed (9: Bad file descriptor)
     31 2020/10/21 11:50:10 [emerg] 812#31215: lua pipe child close() socket 172.17.110.1:8080 failed (9: Bad file descriptor)
     31 2020/10/21 11:50:10 [emerg] 812#31215: lua pipe child close() socket xx.xx.x.xx:8443 failed (9: Bad file descriptor)

      1 2020/10/21 11:50:25 [emerg] 821#31279: lua pipe child close() socket xx.xx.x.xx:8080 failed (9: Bad file descriptor)
      1 2020/10/21 11:50:25 [emerg] 821#31279: lua pipe child close() socket 172.17.110.1:8080 failed (9: Bad file descriptor)
      1 2020/10/21 11:50:25 [emerg] 821#31279: lua pipe child close() socket xx.xx.x.xx:8443 failed (9: Bad file descriptor)
     30 2020/10/21 11:50:25 [emerg] 821#31279: lua pipe child close() socket xx.xx.x.xx:8080 failed (9: Bad file descriptor)
     30 2020/10/21 11:50:25 [emerg] 821#31279: lua pipe child close() socket 172.17.110.1:8080 failed (9: Bad file descriptor)
     30 2020/10/21 11:50:25 [emerg] 821#31279: lua pipe child close() socket xx.xx.x.xx:8443 failed (9: Bad file descriptor)

      1 2020/10/21 11:51:44 [emerg] 816#31537: lua pipe child close() socket xx.xx.x.xx:8080 failed (9: Bad file descriptor)
      1 2020/10/21 11:51:44 [emerg] 816#31537: lua pipe child close() socket 172.17.110.1:8080 failed (9: Bad file descriptor)
      1 2020/10/21 11:51:44 [emerg] 816#31537: lua pipe child close() socket xx.xx.x.xx:8443 failed (9: Bad file descriptor)
     30 2020/10/21 11:51:44 [emerg] 816#31537: lua pipe child close() socket xx.xx.x.xx:8080 failed (9: Bad file descriptor)
     30 2020/10/21 11:51:44 [emerg] 816#31537: lua pipe child close() socket 172.17.110.1:8080 failed (9: Bad file descriptor)
     30 2020/10/21 11:51:44 [emerg] 816#31537: lua pipe child close() socket xx.xx.x.xx:8443 failed (9: Bad file descriptor)

[niko]

I found out more.

I'm using the OpenResty Alpine Docker image. The error occurs only with the latest version of OpenResty, 1.17.8.2. When downgrading to 1.15.8.1 (the previous version in the openresty:alpine image) it's gone.

The remaining question seems to be:

• does 1.17.8.x introduce an error or
• does my code have an error which isn't logged by 1.15.8.x?

[niko]

I found the place where the log gets created:

lua-nginx-module/src/ngx_http_lua_pipe.c

Lines 692 to 694 in a4d63f7

	ngx_log_error(NGX_LOG_EMERG, ngx_cycle->log, ngx_socket_errno,
	"lua pipe child " ngx_close_socket_n
	" %V failed", &ls[i].addr_text);

This has been there since the beginning of the pipe c-api as far as I can tell. Now trying to find the exact lua-nginx-module version that introduced those log lines for me.

[niko]

I can now confirm that the exact version where the logs start to appear is 1.17.8.1 The version 1.15.8.3 does not show this error message.

The only entries in the Changelog related to any socket errors seem to be

bugfix: ngx.pipe: ensured reading while a process died returns the "closed" error. Thanks @thibaultcha for the patch.
bugfix: added missing arguments to an ngx_log_error call in ngx_http_lua_pipe.c. Thanks @thibaultcha for the patch.

I honestly have no clue if those changes have anything to do with my issue. I'd be very thankful if anyone could help me pinpointing this issue.

[yorkane]

any update on this issue
I have encountered the same problem...

[thibaultcha]

The close unused fds patch introduced in 1.17.8.1 is probably already closing these fds causing the ngx.pipe codepath to try and close fds that aren't anymore, hence the EBADF error. Most likely.

Note that the error shouldn't impact any behavior in your OpenResty app. Arguably, it hardly deserves an emerg severity to me.

[niko]

I found the exact place in my code that is triggering this: It's a ngx.req.socket:send() when the connection is broken by a ctlr-c-ed or hanging client. Is there any way to check if a downstream tcp socket is still functional?