User couldn't be authenticated, aborting call

Community Support
1

Hello .*,

I was seeing this error pop up in oned.log. To fix it I thought I would change serveradmin password, update dotfiles, restart oned and sunstone and be good to go.

This deployment runs OpenNebula 4.6 on Debian Wheezy 7.7.

$ dpkg -l | grep opennebula
ii  opennebula                         4.6.2-1                       amd64        controller which executes the OpenNebula cluster services

After doing the above operations I was still receiving the following errors in oned.log:

Wed Mar  4 10:37:09 2015 [AuM][E]: Auth Error: bad decrypt
Wed Mar  4 10:37:09 2015 [ReM][E]: Req:4352 UID:- DocumentPoolInfo result FAILURE [DocumentPoolInfo] User couldn't be authenticated, aborting call.
Wed Mar  4 10:37:34 2015 [ReM][E]: Req:2624 UID:- VirtualMachinePoolInfo result FAILURE [VirtualMachinePoolInfo] User couldn't be authenticated, aborting call.
Wed Mar  4 10:37:34 2015 [ReM][E]: Req:736 UID:- VirtualMachinePoolInfo result FAILURE [VirtualMachinePoolInfo] User couldn't be authenticated, aborting call.
Wed Mar  4 10:37:34 2015 [ReM][E]: Req:736 UID:- VirtualMachinePoolInfo result FAILURE [VirtualMachinePoolInfo] User couldn't be authenticated, aborting call.
Wed Mar  4 10:37:35 2015 [ReM][E]: Req:8304 UID:- VirtualMachinePoolInfo result FAILURE [VirtualMachinePoolInfo] User couldn't be authenticated, aborting call.

So I thought I could erase serveradmin, recreate it with server_cipher driver, update the auth files, restart daemons and be ok :). Well, that didn’t happen. I have executed the following as oneadmin user.

$ oneuser delete serveradmin
$ oneuser create serveradmin --driver server_cipher parola

Modified ~/.one/sunstone_auth with new password hash taken from oneuser list.

Javi suggested I look if the MySQL databases has the same hash as oneuser list
or echo -n parola | sha1sum.

So I did that, the strings are the same.

$ oneuser list | grep serveradmin

8 serveradmin     oneadmin             6f9d3382f361c2181997336f8be4483098ea6328 server_cipher

$ mysql -e 'select body from user_pool where uid = 8' opennebula_main | awk -F"<PASSWORD>" ' { print $2 } ' | awk -F"</PASSWORD>" ' { print $1 }'

6f9d3382f361c2181997336f8be4483098ea6328

I have also checked /etc/one/sunstone-server.conf for auth parameteres.

$ cat /etc/one/sunstone-server.conf | grep core_auth
:core_auth: cipher

I am still receiving the same error :|. Can someone please help me somehow.

Best,
Valentin

2

Hi Valentin,

Probably the problem is with the oneflow_auth file instead of sunstone_auth

Cheers

3

Hi Daniel,

I have checked all the auth files. Please take a look.

    $ for service in occi sunstone ec2 oneflow onegate
    do
    cat ${service}_auth
    done
    serveradmin:6f9d3382f361c2181997336f8be4483098ea6328
    serveradmin:6f9d3382f361c2181997336f8be4483098ea6328
    serveradmin:6f9d3382f361c2181997336f8be4483098ea6328
    serveradmin:6f9d3382f361c2181997336f8be4483098ea6328
    serveradmin:6f9d3382f361c2181997336f8be4483098ea6328

$ oneuser list | grep serveradmin
   8 serveradmin     oneadmin             6f9d3382f361c2181997336f8be4483098ea6328 server_cipher

When I restart the server I receive the following in the oned.log.

Wed Mar  4 12:03:04 2015 [ReM][E]: Req:8800 UID:- SystemConfig result FAILURE [SystemConfig] User couldn't be authenticated, aborting call.
Wed Mar  4 12:03:22 2015 [AuM][E]: Auth Error: bad decrypt
Wed Mar  4 12:03:22 2015 [ReM][E]: Req:5936 UID:- DocumentPoolInfo result FAILURE [DocumentPoolInfo] User couldn't be authenticated, aborting call.
Wed Mar  4 12:03:22 2015 [ReM][E]: Req:1600 UID:- VirtualMachinePoolInfo result FAILURE [VirtualMachinePoolInfo] User couldn't be authenticated, aborting call.
Wed Mar  4 12:03:23 2015 [ReM][E]: Req:1600 UID:- VirtualMachinePoolInfo result FAILURE [VirtualMachinePoolInfo] User couldn't be authenticated, aborting call.
Wed Mar  4 12:03:33 2015 [ReM][E]: Req:9264 UID:- VirtualMachinePoolInfo result FAILURE [VirtualMachinePoolInfo] User couldn't be authenticated, aborting call.
Wed Mar  4 12:03:33 2015 [ReM][E]: Req:9264 UID:- VirtualMachinePoolInfo result FAILURE [VirtualMachinePoolInfo] User couldn't be authenticated, aborting call.

What else should I check or look for? Thanks.

Best,
Valentin

4

Now the problem is you are using the hashed version of the password in the files, instead of the plain password.

5

Hi Dani,

I have changed the auth files with clear text password of serveradmin.

$ oneuser passwd serveradmin xxxxYYY
$ for service in occi sunstone ec2 oneflow onegate
do
cat ${service}_auth
done
serveradmin:xxxxYYY
serveradmin:xxxxYYY
serveradmin:xxxxYYY
serveradmin:xxxxYYY
serveradmin:xxxxYYY

Restarted opennebula and opennebula-sunstone. Now I receive the following error.

Wed Mar  4 14:54:23 2015 [ReM][E]: Req:6592 UID:- SystemConfig result FAILURE [SystemConfig] User couldn't be authenticated, aborting call.
Wed Mar  4 14:54:29 2015 [ReM][E]: Req:8240 UID:- VirtualMachinePoolInfo result FAILURE [VirtualMachinePoolInfo] User couldn't be authenticated, aborting call.
Wed Mar  4 14:54:29 2015 [ReM][E]: Req:8240 UID:- VirtualMachinePoolInfo result FAILURE [VirtualMachinePoolInfo] User couldn't be authenticated, aborting call.
Wed Mar  4 14:54:49 2015 [AuM][E]: Auth Error: key length too short
Wed Mar  4 14:54:49 2015 [ReM][E]: Req:2160 UID:- DocumentPoolInfo result FAILURE [DocumentPoolInfo] User couldn't be authenticated, aborting call.
Wed Mar  4 14:54:52 2015 [ReM][E]: Req:1760 UID:- VirtualMachinePoolInfo result FAILURE [VirtualMachinePoolInfo] User couldn't be authenticated, aborting call.
Wed Mar  4 14:54:52 2015 [ReM][E]: Req:1760 UID:- VirtualMachinePoolInfo result FAILURE [VirtualMachinePoolInfo] User couldn't be authenticated, aborting call.
Wed Mar  4 14:54:59 2015 [ReM][E]: Req:9856 UID:- VirtualMachinePoolInfo result FAILURE [VirtualMachinePoolInfo] User couldn't be authenticated, aborting call.
Wed Mar  4 14:54:59 2015 [ReM][E]: Req:128 UID:- VirtualMachinePoolInfo result FAILURE [VirtualMachinePoolInfo] User couldn't be authenticated, aborting call.
Wed Mar  4 14:55:19 2015 [AuM][E]: Auth Error: key length too short

I would also mention that I have commented out the oneflow route from sunstone-server.conf as I don’t use it.

Thanks. Best,
Valentin

6

This command will store the plain password in the database :smile:

You have to add the --sha1 option to the command or specify the driver --driver server_cipher

7

Ok :smile: . Follows the entire sequence of commands.

$ oneuser passwd --sha1 serveradmin xxxxYYY

$ oneuser list | grep serveradmin
   8 serveradmin     oneadmin             b24ba600cbe18b40534af559e9895351bac267ca server_cipher

mysql -e 'select body from user_pool where uid = 8' opennebula_main | awk -F"<PASSWORD>" ' { print $2 } ' | awk -F"</PASSWORD>" ' { print $1 }'

b24ba600cbe18b40534af559e9895351bac267ca

$ for service in occi sunstone ec2 oneflow onegate
do
cat ${service}_auth
done
serveradmin:xxxxYYY
serveradmin:xxxxYYY
serveradmin:xxxxYYY
serveradmin:xxxxYYY
serveradmin:xxxxYYY

# /etc/init.d/opennebula stop ; /etc/init.d/opennebula-sunstone stop

# /etc/init.d/opennebula start ; /etc/init.d/opennebula-sunstone start
VNC proxy started
sunstone-server started

And the follows is what I find in the logs.

Wed Mar  4 15:33:55 2015 [ReM][E]: Req:5200 UID:- SystemConfig result FAILURE [SystemConfig] User couldn't be authenticated, aborting call.
Wed Mar  4 15:33:59 2015 [ReM][E]: Req:2448 UID:- VirtualMachinePoolInfo result FAILURE [VirtualMachinePoolInfo] User couldn't be authenticated, aborting call.
Wed Mar  4 15:33:59 2015 [ReM][E]: Req:2448 UID:- VirtualMachinePoolInfo result FAILURE [VirtualMachinePoolInfo] User couldn't be authenticated, aborting call.

Thanks. Best,
Valentin

8

I have also tried to set the serveradmin passwd using --driver server_cipher.

$ oneuser passwd --sha1 --driver server_cipher serveradmin xxxxYYY

Something changed in the logs, it says bad decrypt now.

Wed Mar  4 15:36:23 2015 [ReM][E]: Req:7808 UID:- SystemConfig result FAILURE [SystemConfig] User couldn't be authenticated, aborting call.
Wed Mar  4 15:36:25 2015 [AuM][E]: Auth Error: bad decrypt
Wed Mar  4 15:36:25 2015 [ReM][E]: Req:1504 UID:- DocumentPoolInfo result FAILURE [DocumentPoolInfo] User couldn't be authenticated, aborting call.
Wed Mar  4 15:36:26 2015 [ReM][E]: Req:2640 UID:- VirtualMachinePoolInfo result FAILURE [VirtualMachinePoolInfo] User couldn't be authenticated, aborting call.
Wed Mar  4 15:36:26 2015 [ReM][E]: Req:7920 UID:- VirtualMachinePoolInfo result FAILURE [VirtualMachinePoolInfo] User couldn't be authenticated, aborting call.
9

Thought the following would be useful to help in debugging.

$ ruby --version
ruby 1.9.3p194 (2012-04-20 revision 35410) [x86_64-linux]

$ gem list
amazon-ec2 (0.9.17)
aws-sdk (1.38.0)
builder (3.2.2)
curb (0.8.5)
daemons (1.1.9)
eventmachine (1.0.3)
json (1.8.1)
mini_portile (0.5.3)
mysql (2.9.1)
net-ldap (0.6.1)
nokogiri (1.6.1)
parse-cron (0.1.4)
polyglot (0.3.4)
rack (1.5.2)
rack-protection (1.5.3)
sequel (4.9.0)
sinatra (1.4.5)
sqlite3 (1.3.9)
thin (1.6.2)
tilt (1.4.1)
treetop (1.5.3)
trollop (2.0)
uuidtools (2.1.4)
xml-simple (1.1.3)
10

In your first message you received the following error:

Is this error in the logs?

Could you check if these requests are logged in sunstone.log?

This call is only performed by oneflow, could you check if the service is running?

11

Indeed, you are right, Flow, Gate and Econe were running. I have stopped them.

$ ps aux | grep ruby
oneadmin  5117  0.0  0.0  57308 14708 ?        Sl   Feb19   0:50 ruby /var/tmp/one/im/kvm.d/collectd-client.rb kvm /var/lib/one//datastores 4124 20 0 DellDx150-01
oneadmin 40675  0.1  0.0  39948  9680 ?        SNl  16:33   0:00 ruby /usr/lib/one/mads/one_vmm_exec.rb -t 15 -r 0 kvm
oneadmin 40758  0.0  0.0 102912  5612 ?        SNl  16:33   0:00 ruby /usr/lib/one/mads/one_im_exec.rb -r 3 -t 15 kvm
oneadmin 40774  0.0  0.0 101512  5712 ?        SNl  16:33   0:00 ruby /usr/lib/one/mads/one_tm.rb -t 15 -d dummy,lvm,shared,fs_lvm,qcow2,ssh,vmfs,ceph
oneadmin 40795  0.0  0.0 101264  5544 ?        SNl  16:33   0:00 ruby /usr/lib/one/mads/one_hm.rb
oneadmin 40815  0.2  0.0 110128  9904 ?        SNl  16:33   0:00 ruby /usr/lib/one/mads/one_datastore.rb -t 15 -d dummy,fs,vmfs,lvm,ceph
oneadmin 40839  0.0  0.0 103048  5848 ?        SNl  16:33   0:00 ruby /usr/lib/one/mads/one_auth_mad.rb --authn ssh,x509,ldap,server_cipher,server_x509
oneadmin 41440  1.7  0.0 276452 36176 ?        Sl   16:33   0:00 ruby /usr/lib/one/sunstone/sunstone-server.rb
oneadmin 42390  5.0  0.0  35844  8788 ?        Sl   16:33   0:01 ruby ../../vmm/kvm/poll --kvm -t
oneadmin 42478  4.9  0.0  35844  8792 ?        Rl   16:33   0:01 ruby ../../vmm/kvm/poll --kvm -t

Restarted daemons, Suntstone and OpenNebula. Now I get the following.

Wed Mar  4 16:33:06 2015 [ReM][E]: Req:6352 UID:- SystemConfig result FAILURE [SystemConfig] User couldn't be authenticated, aborting call.
Wed Mar  4 16:33:29 2015 [ReM][E]: Req:5808 UID:- VirtualMachinePoolInfo result FAILURE [VirtualMachinePoolInfo] User couldn't be authenticated, aborting call.
Wed Mar  4 16:33:29 2015 [ReM][E]: Req:5808 UID:- VirtualMachinePoolInfo result FAILURE [VirtualMachinePoolInfo] User couldn't be authenticated, aborting call.
Wed Mar  4 16:33:35 2015 [ReM][E]: Req:7808 UID:- VirtualMachinePoolInfo result FAILURE [VirtualMachinePoolInfo] User couldn't be authenticated, aborting call.
Wed Mar  4 16:33:35 2015 [ReM][E]: Req:7808 UID:- VirtualMachinePoolInfo result FAILURE [VirtualMachinePoolInfo] User couldn't be authenticated, aborting call.
Wed Mar  4 16:33:58 2015 [ReM][E]: Req:8640 UID:- VirtualMachinePoolInfo result FAILURE [VirtualMachinePoolInfo] User couldn't be authenticated, aborting call.

Thank you Dani for your help. Best.

12

These calls are probably coming from the scheduler, but the scheduler uses ONE_AUTH.

13

Hi Dani,

Thank you kindly for your patience and assistance :-). I have updated the OpenNebula DB with hash of oneadmin new password and things got back to normal. Honestly I don’t know what happened, I have just inherited this ONE deployment.