'NoneType' object has no attribute 'append_message' and other Debian (post-setup) trouble


#1

I created a new worker and a new project (project execution was tested with the tutorial worker as well, so it's not the worker's fault). The project script is incredibly simple. I commented out all the things except an echo statement after it didn't work.

It could just be me not understanding how these scripts should work so I'd appreciate advice on how to get the desired effect, but it seems to me the script won't work no matter what I do.

#!/bin/bash

echo "About to pull code from Github."

# cd /home/me/project
# git pull

## This probably won't work though.
# echo "Switching to Node 10."
# nvm use 10

# echo "Time to build ..."
# npm run build

# echo "All done."

And thanks again for all your work and replies and stuff, and sorry for the spam, I'm just very excited about this. :)


#2

Hey totally not spam at all... all good!

Can you include the full traceback? This should be in the worker logs ('/var/log/vespene') and is probably a super easy fix.

I use build scripts like that all the time though so I'm a little puzzled as to what specifically happened but if I get the line number I can probably figure it out really quick.

(edit: I'm not going to be around a computer much tomorrow, so quick may like be tomorrow night or this weekend).


#3

Also, once you have the traceback can you please file a ticket for this on github and link it here? Thanks!


#4

Here you go, I hope this is what you need: https://github.com/vespene-io/vespene/issues/66


#5

This was one of those "error while printing an error" type things - by favorite class of bug!

I have pushed new code for this and commented on the ticket.

Thanks!


#6

I'm continuing this thread because the error I get is still the same, albeit at a different point. :) I have now graduated from the previous errors to one that happens after vespene pulls from Github and tries to chmod -R 777 the folder. It keeps crashing. I tried logging more things, at first I thought it might be a user issue, so I added execute_command("id") to some scripts and logged the output. It's always the vespene user.

After that I ls -lsa the /opt/vespene directory. And the directory itself was owned by root. In a desperate attempt I ran sudo chown vespene.vespene . which didn't do anything. I am out of ideas, here is my worker log.

==> /var/log/vespene/worker_djnd-pool.log <==
2018-11-02 10:59:04,553 - vespene - DEBUG - building: 39, project: stanovanja-build
2018-11-02 10:59:04,625 - vespene - DEBUG - executing: mkdir -p 39
2018-11-02 10:59:04,649 - vespene - DEBUG - executing: id
2018-11-02 10:59:04,710 - vespene - DEBUG - uid=1001(vespene) gid=1001(vespene) groups=1001(vespene)

2018-11-02 10:59:04,711 - vespene - DEBUG - executing: chmod 770 39
2018-11-02 10:59:04,759 - vespene - DEBUG - adding SSH key with passphrase!
2018-11-02 10:59:04,761 - vespene - DEBUG - /tmp/tmpmhsiymvi
2018-11-02 10:59:04,761 - vespene - DEBUG - /tmp/tmp8spqe89a
2018-11-02 10:59:04,762 - vespene - DEBUG - executing: /usr/bin/expect -f /tmp/tmpmhsiymvi
2018-11-02 10:59:04,862 - vespene - DEBUG - executing: timeout 600 git clone -b master --single-branch git@github.com:danesjenovdan/stanovanja.git 39 -v
2018-11-02 10:59:07,989 - vespene - DEBUG - Warning: Permanently added 'github.com,192.30.253.113' (RSA) to the list of known hosts.

2018-11-02 10:59:07,990 - vespene - DEBUG - executing: (cd 39; git --no-pager log -n 1 --abbrev-commit --format='%aE')
2018-11-02 10:59:08,037 - vespene - DEBUG - executing: (cd 39; git rev-parse --short HEAD)
2018-11-02 10:59:08,118 - vespene - DEBUG - executing: id
2018-11-02 10:59:08,128 - vespene - DEBUG - uid=1001(vespene) gid=1001(vespene) groups=1001(vespene)

2018-11-02 10:59:08,129 - vespene - DEBUG - executing: chmod -R 777 39
2018-11-02 10:59:08,137 - vespene - ERROR - an error occurred
Traceback (most recent call last):
  File "/opt/vespene/vespene/workers/builder.py", line 160, in go
    self.main()
  File "/opt/vespene/vespene/workers/builder.py", line 69, in main
    self.run_build_script()
  File "/opt/vespene/vespene/workers/builder.py", line 91, in run_build_script
    self.isolation_manager.execute()
  File "/opt/vespene/vespene/workers/isolation.py", line 55, in execute
    return self.provider.execute()
  File "/opt/vespene/vespene/plugins/isolation/sudo.py", line 89, in execute
    commands.execute_command(None, "chmod -R %s %s" % (self.chmod, self.build.working_dir), output_log=False, message_log=True)
  File "/opt/vespene/vespene/workers/commands.py", line 128, in execute_command
    build.append_message("build failed with exit code %s" % process.returncode)
AttributeError: 'NoneType' object has no attribute 'append_message'
2018-11-02 10:59:08,139 - vespene - DEBUG - flagging build as failure
2018-11-02 10:59:08,170 - vespene - DEBUG - flagging build as done

What might be worth noting is, that if I restart the service and start the build process I get an extra error in the logs. It looks like this, but this only happens the first time I run the project after service restart (it almost looks like it's trying to do the thing twice):


==> /var/log/vespene/worker_djnd-pool.log <==
2018-11-02 11:00:39,620 - vespene - DEBUG - building: 40, project: stanovanja-build
2018-11-02 11:00:39,644 - vespene - DEBUG - building: 40, project: stanovanja-build
2018-11-02 11:00:39,886 - vespene - DEBUG - executing: mkdir -p 40
2018-11-02 11:00:39,913 - vespene - DEBUG - executing: id
2018-11-02 11:00:39,948 - vespene - DEBUG - executing: mkdir -p 40
2018-11-02 11:00:39,960 - vespene - DEBUG - uid=1001(vespene) gid=1001(vespene) groups=1001(vespene)

2018-11-02 11:00:39,962 - vespene - DEBUG - executing: chmod 770 40
2018-11-02 11:00:39,980 - vespene - DEBUG - executing: id
2018-11-02 11:00:40,018 - vespene - DEBUG - adding SSH key with passphrase!
2018-11-02 11:00:40,021 - vespene - DEBUG - /tmp/tmpigu6p0au
2018-11-02 11:00:40,022 - vespene - DEBUG - /tmp/tmpu0cln9ps
2018-11-02 11:00:40,023 - vespene - DEBUG - executing: /usr/bin/expect -f /tmp/tmpigu6p0au
2018-11-02 11:00:40,029 - vespene - DEBUG - uid=1001(vespene) gid=1001(vespene) groups=1001(vespene)

2018-11-02 11:00:40,030 - vespene - DEBUG - executing: chmod 770 40
2018-11-02 11:00:40,084 - vespene - DEBUG - adding SSH key with passphrase!
2018-11-02 11:00:40,086 - vespene - DEBUG - /tmp/tmpxic_ej_w
2018-11-02 11:00:40,086 - vespene - DEBUG - /tmp/tmpfuyx_ib4
2018-11-02 11:00:40,086 - vespene - DEBUG - executing: /usr/bin/expect -f /tmp/tmpxic_ej_w
2018-11-02 11:00:40,135 - vespene - DEBUG - executing: timeout 600 git clone -b master --single-branch git@github.com:danesjenovdan/stanovanja.git 40 -v
2018-11-02 11:00:40,223 - vespene - DEBUG - executing: timeout 600 git clone -b master --single-branch git@github.com:danesjenovdan/stanovanja.git 40 -v
2018-11-02 11:00:40,303 - vespene - ERROR - an error occurred
Traceback (most recent call last):
  File "/opt/vespene/vespene/workers/builder.py", line 160, in go
    self.main()
  File "/opt/vespene/vespene/workers/builder.py", line 67, in main
    self.checkout_and_record_scm_info()
  File "/opt/vespene/vespene/workers/builder.py", line 77, in checkout_and_record_scm_info
    output = self.scm_manager.checkout()
  File "/opt/vespene/vespene/workers/scm.py", line 46, in checkout
    self.provider.checkout()
  File "/opt/vespene/vespene/plugins/scm/git.py", line 84, in checkout
    output = commands.execute_command(self.build, cmd, output_log=False, message_log=True, timeout=600, env=key_mgmt)
  File "/opt/vespene/vespene/workers/commands.py", line 132, in execute_command
    raise Exception("Failed")
Exception: Failed
2018-11-02 11:00:40,306 - vespene - DEBUG - flagging build as failure
2018-11-02 11:00:40,337 - vespene - DEBUG - flagging build as done
2018-11-02 11:00:41,762 - vespene - DEBUG - Warning: Permanently added 'github.com,192.30.253.113' (RSA) to the list of known hosts.

2018-11-02 11:00:41,763 - vespene - DEBUG - executing: (cd 40; git --no-pager log -n 1 --abbrev-commit --format='%aE')
2018-11-02 11:00:41,837 - vespene - DEBUG - executing: (cd 40; git rev-parse --short HEAD)
2018-11-02 11:00:41,915 - vespene - DEBUG - executing: id
2018-11-02 11:00:41,925 - vespene - DEBUG - uid=1001(vespene) gid=1001(vespene) groups=1001(vespene)

2018-11-02 11:00:41,925 - vespene - DEBUG - executing: chmod -R 777 40
2018-11-02 11:00:41,933 - vespene - ERROR - an error occurred
Traceback (most recent call last):
  File "/opt/vespene/vespene/workers/builder.py", line 160, in go
    self.main()
  File "/opt/vespene/vespene/workers/builder.py", line 69, in main
    self.run_build_script()
  File "/opt/vespene/vespene/workers/builder.py", line 91, in run_build_script
    self.isolation_manager.execute()
  File "/opt/vespene/vespene/workers/isolation.py", line 55, in execute
    return self.provider.execute()
  File "/opt/vespene/vespene/plugins/isolation/sudo.py", line 89, in execute
    commands.execute_command(None, "chmod -R %s %s" % (self.chmod, self.build.working_dir), output_log=False, message_log=True)
  File "/opt/vespene/vespene/workers/commands.py", line 128, in execute_command
    build.append_message("build failed with exit code %s" % process.returncode)
AttributeError: 'NoneType' object has no attribute 'append_message'
2018-11-02 11:00:41,936 - vespene - DEBUG - flagging build as failure
2018-11-02 11:00:41,968 - vespene - DEBUG - flagging build as done

#7
commands.execute_command(None, "chmod -R %s %s" % (self.chmod, self.build.working_dir), output_log=False, message_log=True)

Ok, looks like here's another instance of passing None to the execute_command method. I'll dig in.


#8

Ok, (as I think you were trying to get this to work on Debian with modified scripts), what's happening here is your platform is probably seriously empty of much of the commands you need to run Vespene.

The code WAS wrong in that it is not passing self.build to log that error, but that is normally something that will only happen when commands fail that pretty much shouldn't ever fail (still my fault, and not good). I've pushed fixes for that error handling. This is still "error down the error path" code.

It seems you are missing commands such as "ssh-add" and your build directory does not exist or chmod isn't in path.

Until this is resolved I would highly recommend using one of the platforms that the install scripts have been written for, like Ubuntu LTS or CentOS.

That being said, I really want to get Debian supported, but a very minimal Debian distribution is going to need to make sure the installer has installed everything.

I think there are some obvious error message checks that should exist here of course, such as a missing build root.

And we can do some more checks up front to make sure all the required tools are in path. I'll open a ticket on this.

What I've just pushed makes sure there are no remaining calls to self.execute_command where the build is None (that's the result of a change last week or so to make sure all failures fail the build itself), so that class of error is gone, but you will still see failures because those commands are in fact failing.

The question is finding out why.

I suspect you do have timeout, because the code is written to only use "timeout" if it is installed if you have it, but if there's some chance you have something else in your path named "timeout" that could be the reason for the return code.

The full output of the command will be in the build tab for the build number and would be useful to see.

Apologies for the trouble but this is kind of what adding a new platform to Vespene is like, but once done it is pretty stable :)


#9

Cross reference: https://github.com/vespene-io/vespene/issues/68


#10

Another possibility here on the chown is that for some reason you don't have permission to run chown on that file.

This shouldn't happen at all, but ... could it?

What's the permission/ownership situation with the build directory?


#11

I was AFK but am now back in action for the next few hours. I really want to make this work on Debian and if it's all right with you I'd keep patiently chucking away at the problems that present themselves. I'll pull fresh code and post a status update momentarily, until then:

The permission/ownership of the build directory:

djnd@scw-17e805:~$ ls -la /opt/vespene/
total 180
drwxr-xr-x 36 vespene vespene  4096 Nov  2 11:00 .
drwxr-xr-x  3 root    root     4096 Nov  1 20:47 ..
drwxrwx---  2 vespene vespene  4096 Nov  1 22:02 1
drwxrwx---  2 vespene vespene  4096 Nov  1 23:29 10
drwxrwx---  2 vespene vespene  4096 Nov  1 23:54 11
drwxrwx---  2 vespene vespene  4096 Nov  2 06:51 12
[...]
drwxrwx---  2 vespene vespene  4096 Nov  1 23:12 8
drwxrwx---  2 vespene vespene  4096 Nov  1 23:27 9
drwxr-xr-x  3 vespene djnd     4096 Nov  1 20:32 docs
drwxr-xr-x  2 vespene djnd     4096 Nov  1 22:36 setup
drwxr-xr-x 14 vespene djnd     4096 Nov  1 20:32 vespene
-rw-r--r--  1 vespene djnd      383 Nov  1 22:35 CONTRIBUTING.md
-rw-r--r--  1 vespene djnd    11366 Nov  1 20:32 LICENSE.md
-rw-r--r--  1 vespene djnd     1819 Nov  1 20:32 Makefile
-rwxr-xr-x  1 vespene djnd      634 Nov  1 20:32 manage.py
-rw-r--r--  1 vespene djnd       79 Nov  1 20:32 NOTICE
-rw-r--r--  1 vespene djnd     3454 Nov  1 22:35 README.md
-rw-r--r--  1 vespene djnd      301 Nov  1 20:32 requirements.txt

It used to look like this though until I ran chown vespene.vespene . in desperation on the /opt/vespene/ directory:

djnd@scw-17e805:~$ ls -la /opt/vespene/
total 180
drwxr-xr-x 36 vespene root  4096 Nov  2 11:00 .
[...]
[ EVERYTHING ELSE SAME AS ABOVE UNTIL THE END]
[...]
-rw-r--r--  1 vespene djnd      301 Nov  1 20:32 requirements.txt

djnd is the sudo user here, the one that I entered in the web interface. I haven't messed with the vespene user by hand at all so I'm not sure what the situation is there.

Also if I go sudo su vespene and then try to chown the build folder it works when I do it by hand. For some reason the script can't handle it though.


#12

Yeah please go ahead that would be awesome - thanks!


#13

So I pulled and still got the same error. I think you might have missed lines 84 and 85 here: https://github.com/vespene-io/vespene/blob/master/vespene/plugins/isolation/sudo.py#L84

I changed None to self.build seeing as that's what you've done to the others and here's what I get right now:

2018-11-02 16:58:40,794 - vespene - DEBUG - building: 45, project: stanovanja-build
2018-11-02 16:58:40,857 - vespene - DEBUG - executing: mkdir -p 45
2018-11-02 16:58:40,880 - vespene - DEBUG - executing: id
2018-11-02 16:58:40,929 - vespene - DEBUG - uid=1001(vespene) gid=1001(vespene) groups=1001(vespene)

2018-11-02 16:58:40,929 - vespene - DEBUG - executing: chmod 770 45
2018-11-02 16:58:40,973 - vespene - DEBUG - adding SSH key with passphrase!
2018-11-02 16:58:40,975 - vespene - DEBUG - /tmp/tmp78eaxsie
2018-11-02 16:58:40,975 - vespene - DEBUG - /tmp/tmpsne8zs5x
2018-11-02 16:58:40,976 - vespene - DEBUG - executing: /usr/bin/expect -f /tmp/tmp78eaxsie
2018-11-02 16:58:41,061 - vespene - DEBUG - executing: timeout 600 git clone -b master --single-branch git@github.com:danesjenovdan/stanovanja.git 45 -v
2018-11-02 16:58:42,693 - vespene - DEBUG - Warning: Permanently added 'github.com,192.30.253.112' (RSA) to the list of known hosts.

2018-11-02 16:58:42,693 - vespene - DEBUG - executing: (cd 45; git --no-pager log -n 1 --abbrev-commit --format='%aE')
2018-11-02 16:58:42,752 - vespene - DEBUG - executing: (cd 45; git rev-parse --short HEAD)
2018-11-02 16:58:42,827 - vespene - DEBUG - executing: id
2018-11-02 16:58:42,840 - vespene - DEBUG - uid=1001(vespene) gid=1001(vespene) groups=1001(vespene)

2018-11-02 16:58:42,840 - vespene - DEBUG - executing: chmod -R 777 45
2018-11-02 16:58:42,922 - vespene - ERROR - an error occurred
Traceback (most recent call last):
  File "/opt/vespene/vespene/workers/builder.py", line 160, in go
    self.main()
  File "/opt/vespene/vespene/workers/builder.py", line 69, in main
    self.run_build_script()
  File "/opt/vespene/vespene/workers/builder.py", line 91, in run_build_script
    self.isolation_manager.execute()
  File "/opt/vespene/vespene/workers/isolation.py", line 55, in execute
    return self.provider.execute()
  File "/opt/vespene/vespene/plugins/isolation/sudo.py", line 89, in execute
    commands.execute_command(self.build, "chmod -R %s %s" % (self.chmod, self.build.working_dir), output_log=False, message_log=True)
  File "/opt/vespene/vespene/workers/commands.py", line 132, in execute_command
    raise Exception("Failed")
Exception: Failed
2018-11-02 16:58:42,924 - vespene - DEBUG - flagging build as failure
2018-11-02 16:58:42,954 - vespene - DEBUG - flagging build as done

Any ideas on how I could make this more helpful? It tries to chmod as the user vespene which I can totally do by hand, so I really have no idea what could be bothering it. It also chmodded to 770 successfully before. It could have something to do with changing users when connecting to git? A friend of mine suggested I use https://github.com/danesjenovdan/stanovanja.git since it's a read only situation when I described the issue. But that won't work since vespene wants the git@git form.

So I can see two options:

  1. Ideas on how to make the logging more verbose or what extra stuff to log out there in the script.
  2. Delete the whole installation and start from scratch with the Debian-updated installers, although I don't think that will make a difference tbh.

#14

I have an update @mpdehaan - it still fails, however now the UI gives the error no such file or directory while there obviously is a directory with the appropriate name. I just ran build 48 and I can see the directory if I ls /opt/vespene

If I sudo su vespene && ls /opt/vespene/48 it looks like it successfully pulled stuff from git and there are some extra vespene* files in there. Even if I chmod -R 777 /opt/vespene/48 it works. Proof:

djnd@scw-17e805:~$ sudo su vespene
vespene@scw-17e805:/home/djnd$ ls /opt/vespene/48/
babel.config.js  package.json  package-lock.json  public  src  vespene.json  vespene_launch.sh  vue.config.js
vespene@scw-17e805:/home/djnd$ chmod -R 777 /opt/vespene/48

Is it possible we've got some kind of race condition on our hands?

Edit: here's the Messages output from the UI:


    0.00m | mkdir -p 48
    0.00m | id
    0.00m | chmod 770 48
    0.00m | /usr/bin/expect -f /tmp/tmpuk5nfg1s
    0.01m | ----------
Pre hooks...
    0.01m | ----------
Cloning repository...
    0.01m | timeout 600 git clone -b master --single-branch git@github.com:danesjenovdan/stanovanja.git 48 -v
    0.01m | Cloning into '48'...

    0.01m | Warning: Permanently added 'github.com,192.30.253.113' (RSA) to the list of known hosts.

    0.03m | (cd 48; git --no-pager log -n 1 --abbrev-commit --format='%aE')
    0.03m | mato@zgajner.com

    0.03m | (cd 48; git rev-parse --short HEAD)
    0.03m | 064f402

    0.03m | running build asunder user: djnd
    0.04m | ----------
Building...
    0.04m | chmod -R 777 48
    0.04m | chmod: cannot access '48': No such file or directory

    0.04m | build failed with exit code 1
    0.04m | ----------
Post hooks...

Another edit: I just noticed the Messages say running build asunder user djnd -> could this be the problem since vespene owns the directory djnd can't chown it. It would have to use sudo to be able to do that ...


#15

So the “48” is telling - it should be like /tmp/vespene_build/48

Is the build dir somehow set to empty string?

I agree I need to add some better messages (next week) in case things get confused but that seems to be it. All of that stuff like “configured build root is empty” would be easy additions.

I’ll check to see if that self.build stuff didn’t get pushed later, thought it did, posting on phone at the moment.

Anyway should be easy to get a hold of this, thanks for helping with this and for your patience on it!


#16

Probably a non issue but since you were on Debian stable what version of python is this?


#17

If it helps, the 48 folder is created in /opt/vespene/.

The Python version is: Python 3.5.3 for python3 and Python 2.7.13 for python but I assume you use python3 all around since the scripts install it.

Edit: there are no /tmp/vespene* folders or files.


#18

You should have the build root somewhere else - in fact if the sudo user can read /etc/vespene or write to anything other than the build dir that’s a security concern.

Can you check your settings and share what you have?

The choice of 48 without a full path seems to imply that base build dir setting is blank to me.


#19

Also check to see if the build root if configured actually exists.

If that is the problem this is a super easy change for me to raise an error in that case.

Python version should be fine, that is not too old, just wanted to check to see if there were any bugs with that version if I couldn’t figure it out.

Thanks!


#20

You are absolutely correct. The build root is an empty string. What do you suggest I should set it to?

djnd@scw-17e805:/etc/vespene/settings.d$ cat workers.py 
BUILD_ROOT=""
# FILESERVING_ENABLED = True
# FILESERVING_PORT = 8000
# FILESERVING_HOSTNAME = "this-server.example.com"
djnd@scw-17e805:/etc/vespene/settings.d$ cat interface.py 
BUILDROOT_WEB_LINK=""
djnd@scw-17e805:/etc/vespene/settings.d$ cat database.py 
DATABASES = {
        'default': {
            'ENGINE': 'django.db.backends.postgresql',
            'NAME': 'namenamesomename',
            'USER': 'userusersomeuser',
            'PASSWORD' : 'passwordpasswordsomepassword',
            'HOST': '127.0.0.1',
            'ATOMIC_REQUESTS': True
        }
}
djnd@scw-17e805:/etc/vespene/settings.d$ cat secrets.py 

DJANGO_SECRET_KEY = "secretsecretsomedjangosecret"

SYMETRIC_SECRET_KEY = b'secretsecretsomesymetricsecret'