[Solved] Sunstone authentication bad decrypt

Hello, after I upgrade my OpenNebula System from 5.0.2 to version 5.1.80 using CentOS/RHEL 7 repository, according Front-end Installation — OpenNebula 5.2.1 documentation

(yum -y update)

I’m getting the following errors when I tri authenticate by Sunstone:

Wed Oct 12 16:10:11 2016 [Z0][ReM][D]: Req:1520 UID:0 VirtualMachinePoolInfo invoked , -2, -1, -1, -1
Wed Oct 12 16:10:11 2016 [Z0][ReM][D]: Req:1520 UID:0 VirtualMachinePoolInfo result SUCCESS, “<VM_POOL>24<…”
Wed Oct 12 16:10:11 2016 [Z0][ReM][D]: Req:4560 UID:0 VirtualMachinePoolInfo invoked , -2, -1, -1, -1
Wed Oct 12 16:10:11 2016 [Z0][ReM][D]: Req:4560 UID:0 VirtualMachinePoolInfo result SUCCESS, “<VM_POOL>24<…”
Wed Oct 12 16:10:17 2016 [Z0][ReM][D]: Req:0 UID:2 UserInfo invoked , -1
Wed Oct 12 16:10:17 2016 [Z0][ReM][D]: Req:0 UID:2 UserInfo result SUCCESS, “2<GID…”
Wed Oct 12 16:10:17 2016 [Z0][AuM][D]: Message received: LOG I 2 Command execution fail: /var/lib/one/remotes/auth/server_cipher/authenticate serveradmin 15c7ae542d8de1ed95eaa87e03e1c61e4857298e ****

Wed Oct 12 16:10:17 2016 [Z0][AuM][I]: Command execution fail: /var/lib/one/remotes/auth/server_cipher/authenticate serveradmin 15c7ae542d8de1ed95eaa87e03e1c61e4857298e ****
Wed Oct 12 16:10:17 2016 [Z0][AuM][D]: Message received: LOG E 2 bad decrypt

Wed Oct 12 16:10:17 2016 [Z0][AuM][I]: bad decrypt
Wed Oct 12 16:10:17 2016 [Z0][AuM][D]: Message received: LOG I 2 ExitCode: 255

Wed Oct 12 16:10:17 2016 [Z0][AuM][I]: ExitCode: 255
Wed Oct 12 16:10:17 2016 [Z0][AuM][D]: Message received: AUTHENTICATE FAILURE 2 bad decrypt

Wed Oct 12 16:10:17 2016 [Z0][AuM][E]: Auth Error: bad decrypt
Wed Oct 12 16:10:17 2016 [Z0][ReM][D]: Req:4000 UID:-1 UserInfo invoked , -1
Wed Oct 12 16:10:17 2016 [Z0][ReM][E]: Req:4000 UID:- UserInfo result FAILURE [UserInfo] User couldn’t be authenticated, aborting call.
Wed Oct 12 16:10:35 2016 [Z0][MKP][D]: Monitoring marketplace OpenNebula Public (0)
Wed Oct 12 16:10:35 2016 [Z0][MKP][D]: Marketplace OpenNebula Public (0) successfully monitored.
Wed Oct 12 16:10:41 2016 [Z0][ReM][D]: Req:4752 UID:0 VirtualMachinePoolInfo invoked , -2, -1, -1, -1
Wed Oct 12 16:10:41 2016 [Z0][ReM][D]: Req:4752 UID:0 VirtualMachinePoolInfo result SUCCESS, “<VM_POOL>24<…”
Wed Oct 12 16:10:41 2016 [Z0][ReM][D]: Req:5024 UID:0 VirtualMachinePoolInfo invoked , -2, -1, -1, -1
Wed Oct 12 16:10:41 2016 [Z0][ReM][D]: Req:5024 UID:0 VirtualMachinePoolInfo result SUCCESS, “<VM_POOL>24<…”
Wed Oct 12 16:11:01 2016 [Z0][InM][D]: Monitoring datastore default (1)
Wed Oct 12 16:11:01 2016 [Z0][InM][D]: Monitoring datastore files (2)
Wed Oct 12 16:11:01 2016 [Z0][InM][D]: Monitoring datastore datastore1 (100)
Wed Oct 12 16:11:01 2016 [Z0][ImM][D]: Datastore default (1) successfully monitored.
Wed Oct 12 16:11:01 2016 [Z0][ImM][D]: Datastore files (2) successfully monitored.
Wed Oct 12 16:11:01 2016 [Z0][ReM][D]: Req:9936 UID:0 HostPoolInfo invoked
Wed Oct 12 16:11:01 2016 [Z0][ReM][D]: Req:9936 UID:0 HostPoolInfo result SUCCESS, “<HOST_POOL><ID…”
Wed Oct 12 16:11:01 2016 [Z0][ReM][D]: Req:9136 UID:0 SystemConfig invoked
Wed Oct 12 16:11:01 2016 [Z0][ReM][D]: Req:9136 UID:0 SystemConfig result SUCCESS, “<AUTH_MAD>…”
Wed Oct 12 16:11:01 2016 [Z0][ReM][D]: Req:6224 UID:0 HostInfo invoked , 0
Wed Oct 12 16:11:01 2016 [Z0][ReM][D]: Req:6224 UID:0 HostInfo result SUCCESS, “0<NAM…”
Wed Oct 12 16:11:01 2016 [Z0][ImM][I]: Command execution fail: /var/lib/one/remotes/datastore/vcenter/monitor PERTX0RSSVZFUl9BQ1RJT05fREFUQT48REFUQVNUT1JFPjxJRD4xMDA8L0lEPjxVSUQ+MjwvVUlEPjxHSUQ+MDwvR0lEPjxVTkFNRT5DbG91ZEFkbWluPC9VTkFNRT48R05BTUU+b25lYWRtaW48L0dOQU1FPjxOQU1FPmRhdGFzdG9yZTE8L05BTUU+PFBFUk1JU1NJT05TPjxPV05FUl9VPjE8L09XTkVSX1U+PE9XTkVSX00+MTwvT1dORVJfTT48T1dORVJfQT4wPC9PV05FUl9BPjxHUk9VUF9VPjE8L0dST1VQX1U+PEdST1VQX00+MDwvR1JPVVBfTT48R1JPVVBfQT4wPC9HUk9VUF9BPjxPVEhFUl9VPjA8L09USEVSX1U+PE9USEVSX00+MDwvT1RIRVJfTT48T1RIRVJfQT4wPC9PVEhFUl9BPjwvUEVSTUlTU0lPTlM+PERTX01BRD48IVtDREFUQVt2Y2VudGVyXV0+PC9EU19NQUQ+PFRNX01BRD48IVtDREFUQVt2Y2VudGVyXV0+PC9UTV9NQUQ+PEJBU0VfUEFUSD48IVtDREFUQVsvdmFyL2xpYi9vbmUvL2RhdGFzdG9yZXMvMTAwXV0+PC9CQVNFX1BBVEg+PFRZUEU+MDwvVFlQRT48RElTS19UWVBFPjA8L0RJU0tfVFlQRT48U1RBVEU+MDwvU1RBVEU+PENMVVNURVJTPjxJRD4wPC9JRD48L0NMVVNURVJTPjxUT1RBTF9NQj4yNzc1MDQ8L1RPVEFMX01CPjxGUkVFX01CPjY4MDUyPC9GUkVFX01CPjxVU0VEX01CPjIwOTQ1MjwvVVNFRF9NQj48SU1BR0VTPjwvSU1BR0VTPjxURU1QTEFURT48Q0xPTkVfVEFSR0VUPjwhW0NEQVRBW05PTkVdXT48L0NMT05FX1RBUkdFVD48RElTS19UWVBFPjwhW0NEQVRBW0ZJTEVdXT48L0RJU0tfVFlQRT48RFNfTUFEPjwhW0NEQVRBW3ZjZW50ZXJdXT48L0RTX01BRD48TE5fVEFSR0VUPjwhW0NEQVRBW05PTkVdXT48L0xOX1RBUkdFVD48UkVTVFJJQ1RFRF9ESVJTPjwhW0NEQVRBWy9dXT48L1JFU1RSSUNURURfRElSUz48U0FGRV9ESVJTPjwhW0NEQVRBWy92YXIvdG1wXV0+PC9TQUZFX0RJUlM+PFRNX01BRD48IVtDREFUQVt2Y2VudGVyXV0+PC9UTV9NQUQ+PFZDRU5URVJfQ0xVU1RFUj48IVtDREFUQVtDbHVzdGVyQ2xvdWRdXT48L1ZDRU5URVJfQ0xVU1RFUj48L1RFTVBMQVRFPjwvREFUQVNUT1JFPjwvRFNfRFJJVkVSX0FDVElPTl9EQVRBPg== 100
Wed Oct 12 16:11:01 2016 [Z0][ImM][I]: Error monitoring datastore1. Reason: Error decrypting vCenter password
Wed Oct 12 16:11:01 2016 [Z0][ImM][I]: ExitCode: 255
Wed Oct 12 16:11:01 2016 [Z0][ImM][E]: Error monitoring datastore 100: LQ==. Decoded info: -

Currently the system are running these packages versions:

opennebula-sunstone-5.1.80-1.x86_64
opennebula-common-5.1.80-1.x86_64
opennebula-5.1.80-1.x86_64
opennebula-server-5.1.80-1.x86_64
opennebula-ruby-5.1.80-1.x86_64
opennebula-flow-5.1.80-1.x86_64

Using CLI i can run the one* commands without problem.

There are any procedure to fix it? I did not found nothing in official documentation.

Thanks in advance

-Carlos

Additional info:

[root@localhost one]# oneuser show 1 -x

<USER>
  <ID>1</ID>
  <GID>0</GID>
  <GROUPS>
    <ID>0</ID>
  </GROUPS>
  <GNAME>oneadmin</GNAME>
  <NAME>serveradmin</NAME>
  <PASSWORD><![CDATA[5baa61e4c9b93f3f0682250b6cf8331b7ee68fd8]]></PASSWORD>
  <AUTH_DRIVER><![CDATA[server_cipher]]></AUTH_DRIVER>
  <ENABLED>1</ENABLED>
  <TEMPLATE>
    <TOKEN_PASSWORD><![CDATA[942b3ba171f538aae6c180e358a26aa827e278c6]]></TOKEN_PASSWORD>
  </TEMPLATE>
  <DATASTORE_QUOTA/>
  <NETWORK_QUOTA/>
  <VM_QUOTA>
    <VM>
      <CPU><![CDATA[-1]]></CPU>
      <CPU_USED><![CDATA[0]]></CPU_USED>
      <MEMORY><![CDATA[-1]]></MEMORY>
      <MEMORY_USED><![CDATA[0]]></MEMORY_USED>
      <SYSTEM_DISK_SIZE><![CDATA[-1]]></SYSTEM_DISK_SIZE>
      <SYSTEM_DISK_SIZE_USED><![CDATA[0]]></SYSTEM_DISK_SIZE_USED>
      <VMS><![CDATA[-1]]></VMS>
      <VMS_USED><![CDATA[0]]></VMS_USED>
    </VM>
  </VM_QUOTA>
  <IMAGE_QUOTA/>
  <DEFAULT_USER_QUOTAS>
    <DATASTORE_QUOTA/>
    <NETWORK_QUOTA/>
    <VM_QUOTA/>
    <IMAGE_QUOTA/>
  </DEFAULT_USER_QUOTAS>
</USER>


[root@localhost .one]# for file in $(ls); do echo $file; cat $file; echo -----; done
ec2_auth
serveradmin:5baa61e4c9b93f3f0682250b6cf8331b7ee68fd8
-----
occi_auth
serveradmin:5baa61e4c9b93f3f0682250b6cf8331b7ee68fd8
-----
one_auth
oneadmin:password
-----
oneflow_auth
serveradmin:5baa61e4c9b93f3f0682250b6cf8331b7ee68fd8
-----
onegate_auth
serveradmin:5baa61e4c9b93f3f0682250b6cf8331b7ee68fd8
-----
one_key
5baa61e4c9b93f3f0682250b6cf8331b7ee68fd8
-----
sunstone_auth
serveradmin:5baa61e4c9b93f3f0682250b6cf8331b7ee68fd8
-----

Any tip folks?

Best regards,

-Carlos

Somehow, the password for opennebula services has been changed, this should
not happen during an upgrade.Can you confirm that you did not change them?

Reset serveradmin password:

  1. Change it in oned, note that passwd is hashed
oneuser passwd --sha1 serveradmin  <new_passwd>
  1. Update auth files wit passwd in plain text
echo "serveradmin:<new_passwd>" > sunstone_auth

Cheers

Hello @ruben,

Thank you by your answer!

Yes, I did not change none. I did not touched in none config. Only using yum tool.

Even following your suggests, the problem persist.

[root@localhost ~]# oneuser passwd --sha1 serveradmin password
[root@localhost ~]# echo "serveradmin:password" > /var/lib/one/.one/sunstone_auth 
[root@localhost ~]# systemctl restart opennebula.service
[root@localhost ~]# systemctl restart opennebula-sunstone.service
[root@localhost ~]# oneuser list
  ID NAME            GROUP      AUTH           VMS            MEMORY         CPU
   0 oneadmin        oneadmin   core             -                 -           -
   1 serveradmin     oneadmin   server_c   0 /   -      0M /       -   0.0 /   -
   2 demo            demo       core       0 /   5      0M /    4.9G   0.0 / 6.0
[root@localhost ~]# 

The log result:

Thu Oct 13 12:33:22 2016 [Z0][ReM][D]: Req:1120 UID:3 UserInfo invoked , -1
Thu Oct 13 12:33:22 2016 [Z0][ReM][D]: Req:1120 UID:3 UserInfo result SUCCESS, “3<GID…”
Thu Oct 13 12:33:22 2016 [Z0][AuM][D]: Message received: LOG I 4 Command execution fail: /var/lib/one/remotes/auth/server_cipher/authenticate serveradmin 5baa61e4c9b93f3f0682250b6cf8331b7ee68fd8 ****

Thu Oct 13 12:33:22 2016 [Z0][AuM][I]: Command execution fail: /var/lib/one/remotes/auth/server_cipher/authenticate serveradmin 5baa61e4c9b93f3f0682250b6cf8331b7ee68fd8 ****
Thu Oct 13 12:33:22 2016 [Z0][AuM][D]: Message received: LOG E 4 bad decrypt

Thu Oct 13 12:33:22 2016 [Z0][AuM][I]: bad decrypt
Thu Oct 13 12:33:22 2016 [Z0][AuM][D]: Message received: LOG I 4 ExitCode: 255

Thu Oct 13 12:33:22 2016 [Z0][AuM][I]: ExitCode: 255
Thu Oct 13 12:33:22 2016 [Z0][AuM][D]: Message received: AUTHENTICATE FAILURE 4 bad decrypt

Thu Oct 13 12:33:22 2016 [Z0][AuM][E]: Auth Error: bad decrypt
Thu Oct 13 12:33:22 2016 [Z0][ReM][D]: Req:8240 UID:-1 UserInfo invoked , -1
Thu Oct 13 12:33:22 2016 [Z0][ReM][E]: Req:8240 UID:- UserInfo result FAILURE [UserInfo] User couldn’t be authenticated, aborting call.

Any other tip?

Best regards,

-Carlos

Sorry, I cannot reproduce it. Your fisrt setup was wrong because the
password in OpenNebula and sunstone_auth were the same; and OpenNebula
stores a hash of the password. try to restart again sunstone, (make sure it
is not running)…

Also make sure that you updated the right files, as they are read by
Sunstone server /var/lib/one/.one/sunstone.auth

Hold on, there were a bug with serveradmin auth in beta, and now I’m not
sure if the packages got that. can you check line 167 of one_auth_mad.rb,

timeout = arg.to_i

Hi @ruben,

I already restart several times the service and recheck the files.

In the line 167 of one_auth_mad.rb file I got this

[root@localhost one]# sed -n ‘167p’ /usr/lib/one/mads/one_auth_mad.rb
rc = LocalCommand.run(command, log_method(request_id))
[root@localhost one]#

best regards,

Carlos

Hi @ruben,

Only to report the procedure:

After remove all packs and reinstall (using yum) and restore database content, I’m able to login on Sunstone.
I needed to change the vCenter credentials, because I was getting error bad decrypt on vCenter monitoring.

But, even Sunstone are working, I still see these errors in log file.

Thu Oct 13 19:19:29 2016 [Z0][AuM][D]: Message received: LOG I 257 Command execution fail: /var/lib/one/remotes/auth/server_cipher/authenticate serveradmin 5baa61e4c9b93f3f0682250b6cf8331b7ee68fd8 ****

Thu Oct 13 19:19:29 2016 [Z0][AuM][I]: Command execution fail: /var/lib/one/remotes/auth/server_cipher/authenticate serveradmin 5baa61e4c9b93f3f0682250b6cf8331b7ee68fd8 ****
Thu Oct 13 19:19:29 2016 [Z0][AuM][D]: Message received: LOG D 257 authenticate: Authenticating serveradmin, with password 5baa61e4c9b93f3f0682250b6cf8331b7ee68fd8 (f1oj2j5DSlygv4b6iM2AiurwcRjcMCZQXJ7s8fVR598pcQO5XxNOodx1i3V/DyhV)

Thu Oct 13 19:19:29 2016 [Z0][AuM][I]: authenticate: Authenticating serveradmin, with password 5baa61e4c9b93f3f0682250b6cf8331b7ee68fd8 (f1oj2j5DSlygv4b6iM2AiurwcRjcMCZQXJ7s8fVR598pcQO5XxNOodx1i3V/DyhV)
Thu Oct 13 19:19:29 2016 [Z0][AuM][D]: Message received: LOG E 257 bad decrypt

Thu Oct 13 19:19:29 2016 [Z0][AuM][I]: bad decrypt
Thu Oct 13 19:19:29 2016 [Z0][AuM][D]: Message received: LOG I 257 ExitCode: 255

Thu Oct 13 19:19:29 2016 [Z0][AuM][I]: ExitCode: 255
Thu Oct 13 19:19:29 2016 [Z0][AuM][D]: Message received: AUTHENTICATE FAILURE 257 bad decrypt

Thu Oct 13 19:19:29 2016 [Z0][AuM][E]: Auth Error: bad decrypt
Thu Oct 13 19:19:29 2016 [Z0][ReM][D]: Req:6560 UID:-1 DocumentPoolInfo invoked , -2, -1, -1, 100
Thu Oct 13 19:19:29 2016 [Z0][ReM][E]: Req:6560 UID:- DocumentPoolInfo result FAILURE [DocumentPoolInfo] User couldn't be authenticated, aborting call.

But I don’t see errors in Sunstone GUI.

Any other tip!?

best regards,

-Carlos

This is probably from oneflow server, oneflow_auth not updated?

Hi @ruben,

All packs were updated.
Look

[root@localhost one]# rpm -qa | grep -i opennebul
opennebula-sunstone-5.1.80-1.x86_64
opennebula-common-5.1.80-1.x86_64
opennebula-5.1.80-1.x86_64
opennebula-server-5.1.80-1.x86_64
opennebula-ruby-5.1.80-1.x86_64
opennebula-flow-5.1.80-1.x86_64

Best regards,

-Carlos

Hi @ruben,

After update the /var/lib/one/.one/oneflow_auth file the log does not show errors

echo "serveradmin:<new_passwd>" > oneflow_auth

I will try investigate the root cause of this.

Thank you by your help!

-Carlos