Problem: amclient does not use log file location specified by `--log-file` about automation-tools

[hakamine]

BTW this problem also affects transfers.py, when transfers.py is run it tries to create a log file in path (os.path.join(THIS_DIR, 'amclient.log'))

[ross-spencer]

@hakamine I have created a new issue here that we can use to attach more substantial refactoring work to.

Before then, are you happy to try the changes in this branch for me? https://github.com/artefactual/automation-tools/tree/dev/issue-51-fix-utils-log-responsibilities - I have created a small but useful workaround which should see the behaviour you require re-implemented. I tested it on my machine and it looks good, but I'm keen to know if it works in your configuration. If it's okay, I'll then submit it for code review. 👍

[hakamine]

Hi @ross-spencer , I tried the code in the new branch, but still having the same problem:

# sudo -u archivematica /etc/archivematica/automation-tools/amclient-close-completed-transfers.sh
Traceback (most recent call last):
  File "/usr/lib/python2.7/runpy.py", line 174, in _run_module_as_main
    "__main__", fname, loader, pkg_name)
  File "/usr/lib/python2.7/runpy.py", line 72, in _run_code
    exec code in run_globals
  File "/opt/archivematica/automation-tools/transfers/amclient.py", line 41, in <module>
    LOGGER = get_logger(defaults.AMCLIENT_LOG_FILE, defaults.DEFAULT_LOG_LEVEL)
  File "/opt/archivematica/automation-tools/transfers/amclient.py", line 37, in get_logger
    return loggingconfig.setup(log_level, log_file_name, "amclient")
  File "transfers/loggingconfig.py", line 54, in setup
    logging.config.dictConfig(CONFIG)
  File "/usr/lib/python2.7/logging/config.py", line 794, in dictConfig
    dictConfigClass(config).configure()
  File "/usr/lib/python2.7/logging/config.py", line 576, in configure
    '%r: %s' % (name, e))
ValueError: Unable to configure handler 'file': [Errno 13] Permission denied: '/opt/archivematica/automation-tools/transfers/amclient.log'

I was wondering why I seem to get different results compared to your environment, do you invoke the script differently ?

[ross-spencer]

hi @hakamine :)

The good news is that the issue is happening at a different place now, so one step closer:

From this:

  File "/opt/archivematica/automation-tools/transfers/amclient.py", line 33, in <module>
    from transfers import utils
  File "transfers/utils.py", line 17, in <module>
    LOGGER = get_logger(defaults.AMCLIENT_LOG_FILE, defaults.DEFAULT_LOG_LEVEL)

to:

File "/opt/archivematica/automation-tools/transfers/amclient.py", line 41, in <module>
    LOGGER = get_logger(defaults.AMCLIENT_LOG_FILE, defaults.DEFAULT_LOG_LEVEL)
  File "/opt/archivematica/automation-tools/transfers/amclient.py", line 37, in get_logger
    return loggingconfig.setup(log_level, log_file_name, "amclient")

I'm pretty sure I've missed something in testing, so will try and mirror your setup more closely. It might be something to do with the entry-point via the bash script vs. standalone.

[ross-spencer]

@hakamine I am looking at this now but I'm not seeing anything obvious. I can create the error if I try writing to somewhere without permission or that doesn't exist.

Just some obvious things while I think about other causes:

• Can you modify --log-file /var/log/archivematica/automation-tools/amclient.log to something like --log-file /var/log/archivematica/automation-tools/amclient_newname.log and we can make sure the script is somehow still using the default variable.
• Can you confirm the symlink is still active?
• Can you confirm the user permissions on the folder that you're trying to write to?

I'll keep probing away at this one.

[hakamine]

@ross-spencer In the server where I had the error, I had checked all of these items (changing log file name, checking symlink, ) and they were ok , also when reverting the commit for PR #48 in the automation tools code, the error didn't occur (so I inferred this was related with this PR).
However, I just set up automation tools in a different server using the code for PR #48, and the problem with the log file location does not happen (however now getting a different unrelated error). Both servers ubuntu 16.04 VMs. I am puzzled why supposedly similar environments produce different outcomes.
@ross-spencer could you please share details of the environment in which the script is working for you? Could you please provide an example of the script invocation?

[ross-spencer]

@hakamine I was hoping to see the error with the changed log name to see what the location in the error said.

Sorry, not trying to suggest you haven't done any or all of this, just following the avenues, and looking for clues as I go.

Will grab my script and post it here.

Can you post the other error from the other server as well?

[ross-spencer]

@hakamine my symlink is setup as follows:

ross-spencer@artefactual:/tmp/mylink:$ ls -la
total 16
drwxr-xr-x  2 ross-spencer ross-spencer  4096 Mar 14 23:59 .
drwxrwxrwt 19 root         root         12288 Mar 14 23:58 ..
lrwxrwxrwx  1 ross-spencer ross-spencer    46 Mar 14 23:59 folder -> /home/ross-spencer/Desktop/Artefactual/py/auto

And the script I am using is as follows (I've set additional logging up using set:

#!/bin/bash

# additional logging when the script runs or fails
set -eux 

cd /home/ross-spencer/git/artefactual/automation-tools
TEST=/tmp/mylink/folder
python2 -m transfers.amclient --log-file "$TEST/py2_autoamclient_custom.log" close-completed-transfers --am-user-name test test
python3 -m transfers.amclient --log-file "$TEST/py3_autoamclient_custom.log" close-completed-transfers --am-user-name test test

And I'm on the following branch:

ross-spencer@artefactual:~/git/artefactual/automation-tools:$ git branch
  dev/client-reingest-compressed
  dev/issue-10180-reingest-aip
* dev/issue-51-fix-utils-log-responsibilities
  master

The following plays out if I run the code:

ross-spencer@artefactual:~/Desktop/Artefactual/py/auto:$ pwd
/home/ross-spencer/Desktop/Artefactual/py/auto
ross-spencer@artefactual:~/Desktop/Artefactual/py/auto:$ ls -la
total 12
drwxr-xr-x 2 ross-spencer ross-spencer 4096 Mar 15 00:08 .
drwxrwxr-x 5 ross-spencer ross-spencer 4096 Mar 15 00:08 ..
-rwxr-xr-x 1 ross-spencer ross-spencer  410 Mar 15 00:03 autotools-script.sh
ross-spencer@artefactual:~/Desktop/Artefactual/py/auto:$ ./autotools-script.sh 
+ cd /home/ross-spencer/git/artefactual/automation-tools
+ TEST=/tmp/mylink/folder
+ python2 -m transfers.amclient --log-file /tmp/mylink/folder/py2_autoamclient_custom.log close-completed-transfers --am-user-name test test
{}
+ python3 -m transfers.amclient --log-file /tmp/mylink/folder/py3_autoamclient_custom.log close-completed-transfers --am-user-name test test
{}
ross-spencer@artefactual:~/Desktop/Artefactual/py/auto:$ ls -la
total 12
drwxr-xr-x 2 ross-spencer ross-spencer 4096 Mar 15 00:08 .
drwxrwxr-x 5 ross-spencer ross-spencer 4096 Mar 15 00:08 ..
-rwxr-xr-x 1 ross-spencer ross-spencer  410 Mar 15 00:03 autotools-script.sh
-rw-r--r-- 1 ross-spencer ross-spencer    0 Mar 15 00:08 py2_autoamclient_custom.log
-rw-r--r-- 1 ross-spencer ross-spencer    0 Mar 15 00:08 py3_autoamclient_custom.log

I did find some issues when I was using a symlink in the same folder and to python it looked like a relative path. This happens because of the cd but, that wouldn't be happening here because we begin at /var/....

Let me know if you see anything strange or different about what I'm doing here and that might provide some more clues.

If you can give me access to the VM that is causing the issue then that might help me too. This seems like it should be so simple so we can't be far!

NB. I did some exploration of the way we're working with paths in the script to see if we're mangling the path somehow, but I didn't see anything odd there. I also rolled back to 1cb44a7cfd224965469585bf84cb1da09af3c6fc but I didn't see any change in behaviour, i.e. it worked.

[hakamine]

Thank you @ross-spencer , I will try to reproduce the problem again if possible, and add more information here.

[ross-spencer]

No worries @hakamine. That new branch will be good to merge at some point alongside this issue because the logging script should be more self contained and that first trace wasn't good. We've pushed it on there. I hope we can get to the bottom of the rest, but let me know.