Throwing 502 for every package after following setup instructions

[axfelix]

Hi folks,

After following the documentation to setup fixity on a dedicate Archivematica Storage Service server, scanall is throwing a 502 for every AIP it tries to scan. Any idea what could be causing this?

[sevein]

It seems that fixity has reached the frontend webserver (Nginx?) but the request could not be routed to the Storage Service backend. This is probably happening because the Storage Service is down or Nginx can't establish a connection due to some network or configuration issue. I would start looking at the error log of Nginx.

[axfelix]

That's what I thought, but it didn't make sense, because fixity is just hitting it from localhost, and the site is fully functional otherwise.

Error logs have: 2017/11/07 10:44:24 [error] 1269#0: *21266 upstream prematurely closed connection while reading response header from upstream, client: 127.0.0.1, server: , request: "GET /api/v2/file/67cec07f-f638-487f-9325-b5ff96eb7bd4/check_fixity/?username=garnett&api_key=db9b46cd1b622d7f86e794bd63cdd6b1fcbc7c98 HTTP/1.1", upstream: "http://127.0.0.1:8001/api/v2/file/67cec07f-f638-487f-9325-b5ff96eb7bd4/check_fixity/?username=garnett&api_key=dadada", host: "localhost:8000"

[sevein]

So if it says that SS (upstream) prematurely closed the connection I guess that's because the backend process crashed or something went wrong like a particular view in SS couldn't complete. Anything interesting in the logs of the WSGI server (Gunicorn or mod_wsgi depending on the version of AM you're running) or in the SS logs?

[axfelix]

[2017-11-07 10:44:24 +0000] [64283] [ERROR] Socket error processing request.
Traceback (most recent call last):
File "/usr/share/python/archivematica-storage-service/lib/python2.7/site-packages/gunicorn/workers/sync.py", line 130, in handle
self.handle_request(listener, req, client, addr)
File "/usr/share/python/archivematica-storage-service/lib/python2.7/site-packages/gunicorn/workers/sync.py", line 187, in handle_request
six.reraise(exc_info[0], exc_info[1], exc_info[2])
File "/usr/share/python/archivematica-storage-service/lib/python2.7/site-packages/gunicorn/workers/sync.py", line 171, in handle_request
respiter = self.wsgi(environ, resp.start_response)
File "/usr/share/python/archivematica-storage-service/lib/python2.7/site-packages/django/core/handlers/wsgi.py", line 189, in call
response = self.get_response(request)
File "/usr/share/python/archivematica-storage-service/lib/python2.7/site-packages/django/core/handlers/base.py", line 218, in get_response
response = self.handle_uncaught_exception(request, resolver, sys.exc_info())
File "/usr/share/python/archivematica-storage-service/lib/python2.7/site-packages/django/core/handlers/base.py", line 256, in handle_uncaught_exception
'request': request
File "/usr/lib64/python2.7/logging/init.py", line 1175, in error
self._log(ERROR, msg, args, **kwargs)
File "/usr/lib64/python2.7/logging/init.py", line 1268, in _log
self.handle(record)
File "/usr/lib64/python2.7/logging/init.py", line 1278, in handle
self.callHandlers(record)
File "/usr/lib64/python2.7/logging/init.py", line 1318, in callHandlers
hdlr.handle(record)
File "/usr/lib64/python2.7/logging/init.py", line 749, in handle
self.emit(record)
File "/usr/share/python/archivematica-storage-service/lib/python2.7/site-packages/django/utils/log.py", line 129, in emit
self.send_mail(subject, message, fail_silently=True, html_message=html_message)
File "/usr/share/python/archivematica-storage-service/lib/python2.7/site-packages/django/utils/log.py", line 132, in send_mail
mail.mail_admins(subject, message, *args, connection=self.connection(), **kwargs)
File "/usr/share/python/archivematica-storage-service/lib/python2.7/site-packages/django/core/mail/init.py", line 98, in mail_admins
mail.send(fail_silently=fail_silently)
File "/usr/share/python/archivematica-storage-service/lib/python2.7/site-packages/django/core/mail/message.py", line 303, in send
return self.get_connection(fail_silently).send_messages([self])
File "/usr/share/python/archivematica-storage-service/lib/python2.7/site-packages/django/core/mail/backends/smtp.py", line 100, in send_messages
new_conn_created = self.open()
File "/usr/share/python/archivematica-storage-service/lib/python2.7/site-packages/django/core/mail/backends/smtp.py", line 58, in open
self.connection = connection_class(self.host, self.port, **connection_params)
File "/usr/lib64/python2.7/smtplib.py", line 255, in init
(code, msg) = self.connect(host, port)
File "/usr/lib64/python2.7/smtplib.py", line 315, in connect
self.sock = self._get_socket(host, port, self.timeout)
File "/usr/lib64/python2.7/smtplib.py", line 290, in _get_socket
return socket.create_connection((host, port), timeout)
File "/usr/lib64/python2.7/socket.py", line 571, in create_connection
raise err
error: [Errno 111] Connection refused

in Gunicorn logs, I got the most ample python traceback I've ever seen, which I'm pretty sure just amounts to "can't connect on localhost" ...

[sevein]

Ok from that I can understand that there was an uncontrolled exception in SS (something bad happened) and it was caught by the logger which triedto send you an email. The email report is actually sent to the people in the ADMINS list using these settings.

I think that the logging defaults in SS 0.10 are not great. You could tweak the settings linked above to get the email logging going or you could just delete remove mail_admins from the list of handlers here which is not going to stop the event from being logged in the filesystem so you'll still be able to figure out what's the actual problem.

[axfelix]

OK, so just to clarify -- a default SS deployment basically expects to be able to connect to an SMTP client, and this is the result of it not being able to do so, regardless of what the actual error was?

I got the same traceback after commenting out that part of base.py and restarting the storage service...

[sevein]

OK, so just to clarify -- a default SS deployment basically expects to be able to connect to an SMTP client, and this is the result of it not being able to do so, regardless of what the actual error was?

Yes, that's what I think. Excepting that SS would be the SMTP client. Ultimately the way you send email depends on the type of email backend - you can even email to the filesystem or to a service like Amazon SES that doesn't rely on SMTP at all.

I got the same traceback after commenting out that part of base.py and restarting the storage service...

I'm not sure why that would happen, sorry. Maybe try to redefine the email back-end as follows:

EMAIL_BACKEND = 'django.core.mail.backends.console.EmailBackend'

More here: https://docs.djangoproject.com/en/1.8/topics/email/#console-backend

[axfelix]

Hi Jesus,

EMAIL_BACKEND = 'django.core.mail.backends.console.EmailBackend' is already set in local.py...

[sevein]

That would only apply if your environment string DJANGO_SETTINGS_MODULE equals to storage_service.settings.local (used in development environments) but the default is storage_service.settings.production (for rpm/deb installations or ansible by default).

[axfelix]

Ah, OK. still getting the same smtp traceback after pasting that line into the end of base.py, though...

Should I just try to configure postfix or sendmail on here at this point? Would that actually be easier?

[sevein]

You'd need to edit production.py because it overrides whatever settings you define in base.py.

Should I just try to configure postfix or sendmail on here at this point? Would that actually be easier?

Well I personally think that changing a configuration file should be much easier than setting up a MTA but you may think differently.

[axfelix]

OK, making some progress -- thanks for clarifying config file override, I have no idea how that part works. Now gunicorn log just contains this:

[2017-11-08 10:38:52 +0000] [49275] [INFO] Handling signal: term
[2017-11-08 10:38:52 +0000] [49286] [INFO] Worker exiting (pid: 49286)
[2017-11-08 10:38:52 +0000] [49280] [INFO] Worker exiting (pid: 49280)
[2017-11-08 10:38:52 +0000] [49291] [INFO] Worker exiting (pid: 49291)
[2017-11-08 10:38:52 +0000] [49281] [INFO] Worker exiting (pid: 49281)
[2017-11-08 10:38:52 +0000] [49275] [INFO] Shutting down: Master
[2017-11-08 10:38:53 +0000] [53599] [INFO] Starting gunicorn 19.4.5
[2017-11-08 10:38:53 +0000] [53599] [INFO] Listening at: http://127.0.0.1:8001 (53599)
[2017-11-08 10:38:53 +0000] [53599] [INFO] Using worker: sync
[2017-11-08 10:38:53 +0000] [53604] [INFO] Booting worker with pid: 53604
[2017-11-08 10:38:53 +0000] [53605] [INFO] Booting worker with pid: 53605
[2017-11-08 10:38:53 +0000] [53614] [INFO] Booting worker with pid: 53614
[2017-11-08 10:38:53 +0000] [53615] [INFO] Booting worker with pid: 53615

What should I be checking now to investigate the 502s?

[sevein]

What should I be checking now to investigate the 502s?

I'm glad we're making progress! There are two loggers that can help:

'logfile': {
    'level': 'INFO',
    'class': 'logging.handlers.RotatingFileHandler',
    'filename': '/var/log/archivematica/storage-service/storage_service.log',
    'formatter': 'detailed',
    'backupCount': 5,
    'maxBytes': 20 * 1024 * 1024,  # 20 MiB
},
'verboselogfile': {
    'level': 'DEBUG',
    'class': 'logging.handlers.RotatingFileHandler',
    'filename': '/var/log/archivematica/storage-service/storage_service_debug.log',
    'formatter': 'detailed',
    'backupCount': 5,
    'maxBytes': 100 * 1024 * 1024,  # 100 MiB
},

So you can take a look at /var/log/archivematica/storage-service/storage_service.log or /var/log/archivematica/storage-service/storage_service_debug.log. The latter is more verbose but for an uncaught exception like the one we're dealing with both loggers should report what happened.

[axfelix]

Right now, those just contain a lot of

INFO 2017-11-08 10:40:53 locations.models.package:package:extract_file:537: Extracting file with: ['7z', 'x', '-bd', '-y', '-o/var/archivematica/storage_service/tmpTaXD9N', u'/data/alder/aips/a3fc/a0a6/20f9/442d/89f1/b89e/e17a/1986/ACN-2017-008_2001-02-a3fca0a6-20f9-442d-89f1-b89ee17a1986.7z'] to /var/archivematica/storage_service/tmpTaXD9N/ACN-2017-008_2001-02-a3fca0a6-20f9-442d-89f1-b89ee17a1986

no warnings or errors or anything like that. not super familiar with Django's logging, but do I need to add an additional entry to that json config for WARN and ERROR level logging?

[sevein]

Can you show me the LOGGING config that is in your base.py file, please?

[axfelix]

Sure thing!

########## LOGGING CONFIGURATION
# See: https://docs.djangoproject.com/en/dev/ref/settings/#logging
# A sample logging configuration. The only tangible logging
# performed by this configuration is to send an email to
# the site admins on every HTTP 500 error when DEBUG=False.
# See http://docs.djangoproject.com/en/dev/topics/logging for
# more details on how to customize your logging configuration.
LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
    'filters': {
        'require_debug_false': {
            '()': 'django.utils.log.RequireDebugFalse'
        }
    },
    'formatters': {
        'simple': {
            'format': '%(levelname)-8s  %(name)s.%(funcName)s:  %(message)s',
        },
        'detailed': {
            'format': '%(levelname)-8s  %(asctime)s  %(name)s:%(module)s:%(funcName)s:%(lineno)d:  %(message)s',
            'datefmt': '%Y-%m-%d %H:%M:%S'
        },
    },
    'handlers': {
        'null': {
            'level': 'DEBUG',
            'class': 'logging.NullHandler'
        },
        'console': {
            'level': 'DEBUG',
            'class': 'logging.StreamHandler',
            'formatter': 'simple',
        },
        'mail_admins': {
            'level': 'ERROR',
            'filters': ['require_debug_false'],
            'class': 'django.utils.log.AdminEmailHandler'
        },
        'logfile': {
            'level': 'INFO',
            'class': 'logging.handlers.RotatingFileHandler',
            'filename': '/var/log/archivematica/storage-service/storage_service.log',
            'formatter': 'detailed',
            'backupCount': 5,
            'maxBytes': 20 * 1024 * 1024,  # 20 MiB
        },
        'verboselogfile': {
            'level': 'DEBUG',
            'class': 'logging.handlers.RotatingFileHandler',
            'filename': '/var/log/archivematica/storage-service/storage_service_debug.log',
            'formatter': 'detailed',
            'backupCount': 5,
            'maxBytes': 100 * 1024 * 1024,  # 100 MiB
        },
    },
    'loggers': {
        #'django.request': {
        #    'handlers': ['mail_admins'],
        #    'level': 'ERROR',
        #    'propagate': True,
        #},
        'django.request.tastypie': {
            'level': 'ERROR',
        },
        'administration': {
            'level': 'DEBUG',
        },
        'common': {
            'level': 'DEBUG',
        },
        'locations': {
            'level': 'DEBUG',
        },
        'sword2': {
            'level': 'INFO',
        }
    },
    'root': {
        'handlers': ['logfile', 'verboselogfile'],
        'level': 'WARNING',
    },
}
########## END LOGGING CONFIGURATION

as far as I know that's stock from an Artefactual deployment.

[sevein]

Excepting that the django.request logger is commented out. Do you want to uncomment it and try again? I would expect the error to be captured in /var/log/archivematica/storage-service/* but also in /var/log/upstart/archivematica-storage-service.log (or sudo journalctl -u archivematica-storage-service in systemd) because that's where the standard streams are captured (and the console email backend sends the email to the standard streams).

[axfelix]

ah, here we go, some actual output!

INFO      2017-11-08 14:05:57  locations.models.package:package:extract_file:537:  Extracting file with: ['7z', 'x', '-bd', '-y', '-o/var/archivematica/storage_service/tmpb1Qzzx', u'/data/alder/aips/a3fc/a0a6/20f9/442d/89f1/b89e/e17a/1986/ACN-2017-008_2001-02-a3fca0a6-20f9-442d-89f1-b89ee17a1986.7z'] to /var/archivematica/storage_service/tmpb1Qzzx/ACN-2017-008_2001-02-a3fca0a6-20f9-442d-89f1-b89ee17a1986
ERROR     2017-11-08 14:05:57  django.request.tastypie:resources:_handle_500:301:  Internal Server Error: /api/v2/file/a3fca0a6-20f9-442d-89f1-b89ee17a1986/check_fixity/
Traceback (most recent call last):
  File "/usr/share/python/archivematica-storage-service/lib/python2.7/site-packages/tastypie/resources.py", line 220, in wrapper
    response = callback(request, *args, **kwargs)
  File "/usr/lib/archivematica/storage-service/locations/api/resources.py", line 91, in wrapper
    result = func(resource, request, bundle, **kwargs)
  File "/usr/lib/archivematica/storage-service/locations/api/resources.py", line 713, in check_fixity_request
    success, failures, message, timestamp = bundle.obj.check_fixity(force_local=force_local)
  File "/usr/lib/archivematica/storage-service/locations/models/package.py", line 843, in check_fixity
    path, temp_dir = self.extract_file()
  File "/usr/lib/archivematica/storage-service/locations/models/package.py", line 538, in extract_file
    rc = subprocess.call(command)
  File "/usr/lib64/python2.7/subprocess.py", line 524, in call
    return Popen(*popenargs, **kwargs).wait()
  File "/usr/lib64/python2.7/subprocess.py", line 711, in __init__
    errread, errwrite)
  File "/usr/lib64/python2.7/subprocess.py", line 1327, in _execute_child
    raise child_exception
OSError: [Errno 2] No such file or directory

Unfortunately it suggests that the storage service can't find any packages when being called in this way?

[sevein]

👏 👏 👏 👏 👏 👏

It looks like 7z is not installed in the machine where SS is running perhaps?

[axfelix]

Hah. That did it.

FYI, I'm not sure there's a 7z binary available for RHEL-based distros; I just installed p7zip from rpmforge and symlinked /usr/bin/7za to /usr/bin/7z.

Thanks! Might want to list that as a requirement on the readme...

[sevein]

Thanks @axfelix, I'll talk to @scollazo about that and make sure it's installed. He's working on the AM17 packaging as we speak.

[sevein]

@axfelix is your installation using the official packages or the Ansible role? Which version of SS are you running?

[axfelix]

It's:

Version: 0.10.0
Git commit: 43a01dc74a8d9637898fee20f77b36fff7b77cdb

Deployed by Artefacutal for SFU, not sure about Ansible.

[sevein]

@axfelix I've just talked to @scollazo. Apparently this is a known issue. It's documented in the installation instructions (see https://www.archivematica.org/en/docs/archivematica-1.6/admin-manual/installation/installation/#installation).

I've filed a bug anyways: artefactual/archivematica-storage-service#260.

[axfelix]

Aha! Well, whoever set up this VM didn't follow them :)