Conflicting SysLogHandler in ocrd_logging.conf

[markusweigelt]

Following error occurs when running make test

--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.8/logging/handlers.py", line 934, in emit
    self.socket.send(msg)
OSError: [Errno 9] Bad file descriptor

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3.8/logging/handlers.py", line 855, in _connect_unixsocket
    self.socket.connect(address)
FileNotFoundError: [Errno 2] No such file or directory

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3.8/logging/handlers.py", line 937, in emit
    self._connect_unixsocket(self.address)
  File "/usr/lib/python3.8/logging/handlers.py", line 866, in _connect_unixsocket
    self.socket.connect(address)
FileNotFoundError: [Errno 2] No such file or directory
Call stack:
  File "/usr/local/bin/ocrd", line 8, in <module>
    sys.exit(cli())
  File "/usr/local/lib/python3.8/site-packages/click/core.py", line 1157, in __call__
    return self.main(*args, **kwargs)
  File "/usr/local/lib/python3.8/site-packages/click/core.py", line 1078, in main
    rv = self.invoke(ctx)
  File "/usr/local/lib/python3.8/site-packages/click/core.py", line 1688, in invoke
    return _process_result(sub_ctx.command.invoke(sub_ctx))
  File "/usr/local/lib/python3.8/site-packages/click/core.py", line 1685, in invoke
    super().invoke(ctx)
  File "/usr/local/lib/python3.8/site-packages/click/core.py", line 1434, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "/usr/local/lib/python3.8/site-packages/click/core.py", line 783, in invoke
    return __callback(*args, **kwargs)
  File "/usr/local/lib/python3.8/site-packages/click/decorators.py", line 33, in new_func
    return f(get_current_context(), *args, **kwargs)
  File "/usr/local/lib/python3.8/site-packages/ocrd/cli/workspace.py", line 61, in workspace_cli
    initLogging()
  File "/usr/local/lib/python3.8/site-packages/ocrd_utils/logging.py", line 112, in initLogging
    logging.getLogger('').critical('initLogging was called multiple times. Source of latest call:')
Message: 'initLogging was called multiple times. Source of latest call:'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.8/logging/handlers.py", line 934, in emit
    self.socket.send(msg)
OSError: [Errno 9] Bad file descriptor

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3.8/logging/handlers.py", line 855, in _connect_unixsocket
    self.socket.connect(address)
FileNotFoundError: [Errno 2] No such file or directory

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3.8/logging/handlers.py", line 937, in emit
    self._connect_unixsocket(self.address)
  File "/usr/lib/python3.8/logging/handlers.py", line 866, in _connect_unixsocket
    self.socket.connect(address)
FileNotFoundError: [Errno 2] No such file or directory
Call stack:
  File "/usr/local/bin/ocrd", line 8, in <module>
    sys.exit(cli())
  File "/usr/local/lib/python3.8/site-packages/click/core.py", line 1157, in __call__
    return self.main(*args, **kwargs)
  File "/usr/local/lib/python3.8/site-packages/click/core.py", line 1078, in main
    rv = self.invoke(ctx)
  File "/usr/local/lib/python3.8/site-packages/click/core.py", line 1688, in invoke
    return _process_result(sub_ctx.command.invoke(sub_ctx))
  File "/usr/local/lib/python3.8/site-packages/click/core.py", line 1685, in invoke
    super().invoke(ctx)
  File "/usr/local/lib/python3.8/site-packages/click/core.py", line 1434, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "/usr/local/lib/python3.8/site-packages/click/core.py", line 783, in invoke
    return __callback(*args, **kwargs)
  File "/usr/local/lib/python3.8/site-packages/click/decorators.py", line 33, in new_func
    return f(get_current_context(), *args, **kwargs)
  File "/usr/local/lib/python3.8/site-packages/ocrd/cli/workspace.py", line 61, in workspace_cli
    initLogging()
  File "/usr/local/lib/python3.8/site-packages/ocrd_utils/logging.py", line 114, in initLogging
    logging.getLogger('').critical(line)
Message: '  File "/usr/local/lib/python3.8/site-packages/ocrd/cli/workspace.py", line 61, in workspace_cli'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "/usr/lib/python3.8/logging/handlers.py", line 934, in emit
    self.socket.send(msg)
OSError: [Errno 9] Bad file descriptor

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3.8/logging/handlers.py", line 855, in _connect_unixsocket
    self.socket.connect(address)
FileNotFoundError: [Errno 2] No such file or directory

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3.8/logging/handlers.py", line 937, in emit
    self._connect_unixsocket(self.address)
  File "/usr/lib/python3.8/logging/handlers.py", line 866, in _connect_unixsocket
    self.socket.connect(address)
FileNotFoundError: [Errno 2] No such file or directory
Call stack:
  File "/usr/local/bin/ocrd", line 8, in <module>
    sys.exit(cli())
  File "/usr/local/lib/python3.8/site-packages/click/core.py", line 1157, in __call__
    return self.main(*args, **kwargs)
  File "/usr/local/lib/python3.8/site-packages/click/core.py", line 1078, in main
    rv = self.invoke(ctx)
  File "/usr/local/lib/python3.8/site-packages/click/core.py", line 1688, in invoke
    return _process_result(sub_ctx.command.invoke(sub_ctx))
  File "/usr/local/lib/python3.8/site-packages/click/core.py", line 1685, in invoke
    super().invoke(ctx)
  File "/usr/local/lib/python3.8/site-packages/click/core.py", line 1434, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "/usr/local/lib/python3.8/site-packages/click/core.py", line 783, in invoke
    return __callback(*args, **kwargs)
  File "/usr/local/lib/python3.8/site-packages/click/decorators.py", line 33, in new_func
    return f(get_current_context(), *args, **kwargs)
  File "/usr/local/lib/python3.8/site-packages/ocrd/cli/workspace.py", line 61, in workspace_cli
    initLogging()
  File "/usr/local/lib/python3.8/site-packages/ocrd_utils/logging.py", line 114, in initLogging
    logging.getLogger('').critical(line)
Message: '    initLogging()'
Arguments: ()

The temporary solution was to replace the handler with a NullHandler.

ocrd_manager/ocrd_logging.conf

Lines 95 to 102 in df6cec1

	[handler_consoleHandler]
	#class=StreamHandler
	#class=logging.handlers.SysLogHandler
	class=logging.NullHandler
	formatter=defaultFormatter
	#args=(sys.stderr,)
	#args=('/dev/log', 'user')
	args=()

[bertsky]

Following error occurs when running make test
...

Sounds like we got a problem with rsyslog not providing /dev/log anymore.

The temporary solution was to replace the handler with a NullHandler.

We do need logging though, I'll revert and try to get the true problem fixed...

[bertsky]

Ok, so the reason for this error is quite simple: you ran some OCR-D command before starting the syslog service (rsyslogd creates /dev/log). Do you still remember in what context you called make test?

[markusweigelt]

Do you still remember in what context you called make test?

Yes the context was calling make test of makefile-ci workflow in ocrd_kitodo repository.

[bertsky]

Yes the context was calling make test of makefile-ci workflow in ocrd_kitodo repository.

Strange! It should rely on a rully initialised Manager (i.e. after having run startup.sh, which does up rsyslogd).

Do you remember how the test identifies its Manager instance, does it echo using ocrd@localhost or using ocrd_kitodo-ocrd-manager-1?

[markusweigelt]

As far as I can see (

ocrd_manager/Makefile

Line 93 in e8c06e0

ifeq ($(NETWORK),bridge)

and

ocrd_manager/Makefile

Line 109 in e8c06e0

ifeq ($(NETWORK),bridge)

), the test depends on checking the network, so I assume it's running under ocrd@localhost.

[bertsky]

the test depends on checking the network, so I assume it's running under ocrd@localhost.

yes, and as per ocrd_kitodo's make test, this will be the one controlled by Docker Compose. So it tries to log into the existing SSH servers instead of docker execing into the container. But in either case, the container should have a running rsyslog... still puzzled!