version 3.1.1 seems to incorrectly close the log file fd.

[dbaxa]

After updating to django celery from v3.0.23 to v3.1.1, I get the following output and IOError on start up:

python manage.py celery worker -B -f /home/example/django_app/scheduler.log -l INFO


 -------------- celery@example-box v3.1.1 (Cipater)
---- **** -----
--- * ***  * -- Linux-3.11.6
-- * - **** ---
- ** ---------- [config]
- ** ---------- .> broker:      amqp://guest@localhost:5672//
- ** ---------- .> app:         default:0x3282490 (djcelery.loaders.DjangoLoader)
- ** ---------- .> concurrency: 16 (prefork)
- *** --- * --- .> events:      ON
-- ******* ----
--- ***** ----- [queues]
 -------------- .> celery           exchange=celery(direct) key=celery


[tasks]
  . django_app.celery_tasks.check_if_repositories_are_dead
  . django_app.celery_tasks.code_change_monitor


Traceback (most recent call last):
  File "/usr/lib/python2.7/logging/__init__.py", line 875, in emit
    self.flush()
  File "/usr/lib/python2.7/logging/__init__.py", line 835, in flush
    self.stream.flush()
IOError: [Errno 9] Bad file descriptor
Logged from file beat.py, line 432
Traceback (most recent call last):
  File "/usr/lib/python2.7/logging/__init__.py", line 875, in emit
    self.flush()
  File "/usr/lib/python2.7/logging/__init__.py", line 835, in flush
    self.stream.flush()
IOError: [Errno 32] Broken pipe
Logged from file beat.py, line 198

Here are some of my celery settings:

CELERYD_LOG_FORMAT = "%(processName)s/%(name)s %(process)d %(levelname)s[%(asctime)s]: %(message)s"
CELERYD_TASK_LOG_FORMAT = CELERYD_LOG_FORMAT
CELERY_IGNORE_RESULT = True
CELERYD_MAX_TASKS_PER_CHILD = 2
CELERY_SEND_EVENTS = True
CELERY_REDIRECT_STDOUTS = False

Log file output:

MainProcess/celery.worker.consumer 65300 INFO[2013-11-12 10:34:08,231]: Connected to amqp://guest@127.0.0.1:5672//
MainProcess/celery.worker.consumer 65300 INFO[2013-11-12 10:34:08,259]: mingle: searching for neighbors
MainProcess/celery.worker.consumer 65300 INFO[2013-11-12 10:34:09,271]: mingle: all alone

MainProcess/celery.beat 65300 INFO[2013-11-12 10:34:12,419]: beat: Shutting down...

---

I am guessing that in 3.1.1 a log handler's fd is being closed, whereas in 3.0.23 it was not. I am using django 1.5.5.

[ask]

Thanks! I was looking into this yesterday and even made a fix:
celery/celery@b1e2744

There still weren't any output though, so it must be some other fd than what's in logger.handlers

[ask]

Well, doh, it seems I was cheating off the wrong person, so to speak,
I was looking at a section in multiprocessing for an example that used:

# keep all files except for r
os.closerange(0, r)
os.closerange(r + 1, maxfd)

but the high argument is inclusive, so that should be os.closerange(0, r + 1).

Seems I can fix two bugs in one with this

[dbaxa]

Awesome.

[ask]

Seems I'm a bit tired, closerange was correct, the problem was that Logger.manager.LoggerDict does not include the root logger.

[dbaxa]

@ask could it also be that I am redirecting stdout and since celery/celery@3614c15 you have closed it after forking?

[ask]

No, it's just that I was searching for fds to keep in logging.logger.manager.LoggerDict, but that contains all the loggers registered in the process, except for the root logger object.

celery/celery@8015da0 fixes the problem,
I've tested it here and logging works with -B after this change.

[dbaxa]

@ask cool I'll try it out :-)

[dbaxa]

Yep fixed :-)