28 June 2016, 12:05

Hi guys,

Suddenly out of the blue we are unable to log on from Moodle to Mahara using SSO.  We have had this running smoothly for over 7 years.  No changes have been made to the configuration, the first identification of a problem was last Friday.  Error being received when attempting to SSO:

Unable to sign in via SSO.
We were unable to authenticate you at this time. Possible reasons might be:

* Your SSO session might have expired. Go back to the other application and click the link to sign into Mahara again.
* You may not be allowed to SSO to Mahara. Please check with your administrator if you think you should be allowed to.

URL seems incomplete in address bar: http://www.mydomain.co.uk/mahara/auth/xmlrpc/land.php?token=*******************&idp=http://www.mydomain.co.uk/moodle&wantsurl=
(NOTE: I removed the token and domain)

 public_html/mahara/auth/xmlrpc/error_log shows:

[28-Jun-2016 00:43:02 Europe/London] [DBG] 75 (auth/user.php:1557) Destroying user with un-committed changes
[28-Jun-2016 00:43:02 Europe/London] [WAR] 75 (api/xmlrpc/client.php:109) Undefined variable: payload
[28-Jun-2016 00:43:02 Europe/London] Call stack (most recent first):
[28-Jun-2016 00:43:02 Europe/London] * log_message("Undefined variable: payload", 8, true, true, "/home/username/public_html/mahara/api/xmlrpc...", 109) at /home/username/public_html/mahara/lib/errors.php:441
[28-Jun-2016 00:43:02 Europe/London] * error(8, "Undefined variable: payload", "/home/username/public_html/mahara/api/xmlrpc...", 109, array(size 12)) at /home/username/public_html/mahara/api/xmlrpc/client.php:109
[28-Jun-2016 00:43:02 Europe/London] * Client->send("http://www.mydomain.co.uk/moodle") at /home/username/public_html/mahara/auth/xmlrpc/lib.php:103
[28-Jun-2016 00:43:02 Europe/London] * AuthXmlrpc->request_user_authorise("*****************", "http://www.mydomain.co.uk/moodle") at /home/username/public_html/mahara/auth/xmlrpc/land.php:78

No errors show in Moodle error_log, so I am assuming this is a Mahara issue?

I have deleted both public keys, but Moodle does not seem to pick up the key from Mahara as it should.  Even if I copy and paste it in the SSO still doesn't work.  I have double checked all settings following the Mahoodle pdf guide.

I have been in contact with my host for most of the day trying to establish if they tweaked stuff their end and they have run out of ideas now.

I noted in the error_log (before the host restored an earlier backup) that new keys had been autogenerated on 21/6/16 and it was from this point that SSO failed.  I assumed that somehow the key was corrupt, but deleting and generating new keys should have resolved this.

The most similar problem I have found during research was this: https://mahara.org/interaction/forum/topic.php?id=3888 but this turned out to be a simple case of mismatched keys, which I have already addressed.

I have also tried these:

• Add the path to openssl.cnf to Moodle config.php, but I'm not entirely sure what the path is.  
• Confirmed matching keys in the database mnet_host table, however the Mahara entry has a last_connect_time of 1467054121, whereas the Moodle last_connect_time is empty (probably because I had previously added this manually because it wasn't picking it up from Mahara) 
• Confirmed that the ID for mdl_users and mdl_config matches mnet_localhost_id in mdl_mnet_host (https://moodle.org/mod/forum/discuss.php?d=176370#p790491 )

Has anyone got anything else I can try, running out of steam now :(

Thanks,

Stella

28 June 2016, 18:44

Hi Stella,

What versions of Moodle and Mahara are you running? And are you using Moodle as the identity provider, or Mahara?

Please also ask your web host whether the version of PHP and/or OpenSSL may have changed on the Moodle or Mahara web servers. (If you haven't already.)

Another thing you could check is whether the error logging level in Moodle has changed recently, which could be causing Moodle to print warning messages as part of its XML response. To test that out, go to "Administration -> Development -> Debugging", and set "Debug messages" to "NONE" and see if that helps.

That warning message that you saw in your logs... looking at the code I think that the "undefined variable 'payload'" message might happen if Mahara doesn't like the response it's getting from Moodle during the MNet handshake. Specifically, if the root XML element of the response is a <methodResponse> tag, rather than an <encryptedMessage> or <signedMessage> tag. So it does seem the problem has to do with the encryption between the two sites.

Good luck!

Aaron

28 June 2016, 23:18

Hi Aaron,

Many thanks for responding.

This is what we have at the moment:

• Moodle 2.9.2+ (Build: 20151014)
• Mahara version 15.10.0

Moodle is the identity provider.

I asked the host if they had made any changes, but I didn't ask them specifics, so I think I will do this now thanks.

I changed the error logging level in Moodle last night to try and get more information, but it hadn't been changed prior to this.

Regarding your last paragraph, what could cause this issue, have you seen it before?

Thanks again,

Stella

28 June 2016, 23:30

Hi again,

The host has responded to say that no changes to PHP or MySQL were made.

Stella

29 June 2016, 1:52

Hi,

I have found more errors logs in public_html/mahara/api/xmlrpc

[28-Jun-2016 12:46:00 Europe/London] [INF] 2b (api/xmlrpc/lib.php:1055) Signature verification for message from http://www.mydomain.co.uk/moodle failed, checking to see if they have a new signature for us
[28-Jun-2016 12:46:01 Europe/London] [WAR] 2b (api/xmlrpc/client.php:109) Undefined variable: payload
[28-Jun-2016 12:46:01 Europe/London] Call stack (most recent first):
[28-Jun-2016 12:46:01 Europe/London] * log_message("Undefined variable: payload", 8, true, true, "/home/username/public_html/mahara/api/xmlrpc...", 109) at /home/username/public_html/mahara/lib/errors.php:441
[28-Jun-2016 12:46:01 Europe/London] * error(8, "Undefined variable: payload", "/home/username/public_html/mahara/api/xmlrpc...", 109, array(size 12)) at /home/username/public_html/mahara/api/xmlrpc/client.php:109
[28-Jun-2016 12:46:01 Europe/London] * Client->send("http://www.mydomain.co.uk/moodle") at /home/username/public_html/mahara/api/xmlrpc/lib.php:1059
[28-Jun-2016 12:46:01 Europe/London] * xmldsig_envelope_strip(object(SimpleXMLElement)) at /home/username/public_html/mahara/api/xmlrpc/server.php:97
[28-Jun-2016 12:46:01 Europe/London]
[28-Jun-2016 12:46:01 Europe/London] [WAR] 2b (lib/errors.php:459) An exception was thrown of class MaharaException.
[28-Jun-2016 12:46:01 Europe/London] [WAR] 2b (lib/errors.php:459) THIS IS BAD and should be changed to something extending MaharaException,
[28-Jun-2016 12:46:01 Europe/London] [WAR] 2b (lib/errors.php:459) unless the exception is from a third party library.
[28-Jun-2016 12:46:01 Europe/London] [WAR] 2b (lib/errors.php:459) Original trace follows
[28-Jun-2016 12:46:01 Europe/London] [WAR] 2b (api/xmlrpc/lib.php:1076) An error occurred while trying to verify your message signature
[28-Jun-2016 12:46:01 Europe/London] Call stack (most recent first):
[28-Jun-2016 12:46:01 Europe/London] * xmldsig_envelope_strip(object(SimpleXMLElement)) at /home/username/public_html/mahara/api/xmlrpc/server.php:97

Stella

29 June 2016, 14:34

Hi Stella,

Well, I'm not too familiar with the inner workings of MNet, but looking at the Moodle side of things, it seems a message of this sort is probably Moodle trying to communicate an error response back to Mahara. It's a bit of a bug on the Mahara side that it has no way of logging this message...

You should be able to see it (along with perhaps too much additional detail) if you turn on the mnet debugging setting in your Moodle's config.php file:

$CFG->mnet_rpcdebug = 2;

Try adding that, then attempting to roam across, then remove it from your config.php. Then look in the PHP error logs for your Moodle site and you should see more about what's going on, on the Moodle side.

Another thing you could try, is updating the public keys directly in the Moodle and Mahara databases. In the Moodle database they're stored under "mdl_mnet_host.public_key', and in the Mahara database they're stored under "host.publickey". You'd also want to update the "publickeyexpires" date in the same tables, to sometime in the future.

Cheers,

Aaron

29 June 2016, 23:28

Hi Aaron,

I added the MNET debug line and this produced an error log entry in public_html/moodle/mnet/xmlrpc:

[29-Jun-2016 11:19:26 Europe/London] MNET DEBUG (server http://www.mydomain.co.uk/moodle) HTTP_RAW_POST_DATA
[29-Jun-2016 11:19:26 Europe/London] MNET DEBUG (server http://www.mydomain.co.uk/moodle) <?xml version="1.0" encoding="iso-8859-1"?>
<encryptedMessage>
<EncryptedData Id="ED" xmlns="http://www.w3.org/2001/04/xmlenc#">
<EncryptionMethod Algorithm="http://www.w3.org/2001/04/xmlenc#arcfour"/>
<ds:KeyInfo xmlns:ds="http://www.w3.org/2000/09/xmldsig#">
<ds:RetrievalMethod URI="#EK" Type="http://www.w3.org/2001/04/xmlenc#EncryptedKey"/>
<ds:KeyName>XMLENC</ds:KeyName>
</ds:KeyInfo>
<CipherData>
<CipherValue>***REMOVED***</CipherValue>
</CipherData>
</EncryptedData>
<EncryptedKey Id="EK" xmlns="http://www.w3.org/2001/04/xmlenc#">
<EncryptionMethod Algorithm="http://www.w3.org/2001/04/xmlenc#rsa-1_5"/>
<ds:KeyInfo xmlns:ds="http://www.w3.org/2000/09/xmldsig#">
<ds:KeyName>SSLKEY</ds:KeyName>
</ds:KeyInfo>
<CipherData>
<CipherValue>***REMOVED***</CipherValue>
</CipherData>
<ReferenceList>
<DataReference URI="#ED"/>
</ReferenceList>
<CarriedKeyName>XMLENC</CarriedKeyName>
</EncryptedKey>
<wwwroot>http://www.mydomain.co.uk/mahara</wwwroot>
<X1>nothing</X1>
</encryptedMessage>
[29-Jun-2016 11:19:26 Europe/London] MNET DEBUG (server http://www.mydomain.co.uk/moodle) encryption strip exception thrown: mnet/encryption-invalid
[29-Jun-2016 11:19:26 Europe/London] MNET DEBUG (server http://www.mydomain.co.uk/moodle) XMLRPC Error Response 7023: mnet/encryption-invalid

I deleted the public keys directly from the Moodle database in mdl_mnet_host.public_key.  Within Moodle admin I then deleted the key to trigger a new one and confirmed this entered into the database.  There are 2 hosts showing in the table, one for Moodle (key populated) one for Mahara (key blank).

I deleted the public key directly in the Mahara database in host.publickey.  Within Mahara admin I deleted the key to trigger a new one.  The key did not enter into host.publickey, but I found it in config.openssl_keypair

I decided to delete the Mahara host in Moodle (Manage Peers), but found it would not let me delete it cleanly (it saves the deleted version and doesn't let you create a fresh one.  So I decided to delete the host from the database mdl_mnet_host and try and create it again.

This time it picked up the key from Mahara! 

Tested SSO, now getting:

Mahara: Site unavailable

A nonrecoverable error occurred. This probably means you have encountered a bug in the system.

New error in public_html/mahara/auth/xmlrpc

29-Jun-2016 12:30:49 Europe/London] [DBG] 0d (auth/user.php:1557) Destroying user with un-committed changes
[29-Jun-2016 12:30:49 Europe/London] [WAR] 0d (api/xmlrpc/lib.php:1599) This is not a valid SSL certificate.
[29-Jun-2016 12:30:49 Europe/London] Call stack (most recent first):
[29-Jun-2016 12:30:49 Europe/London] * PublicKey->__construct("", "http://www.mydomain.co.uk/moodle") at /home/username/public_html/mahara/lib/peer.php:94
[29-Jun-2016 12:30:49 Europe/London] * Peer->findByWwwroot("http://www.mydomain.co.uk/moodle") at /home/username/public_html/mahara/api/xmlrpc/lib.php:1017
[29-Jun-2016 12:30:49 Europe/London] * get_peer("http://www.mydomain.co.uk/moodle") at /home/username/public_html/mahara/auth/xmlrpc/lib.php:93
[29-Jun-2016 12:30:49 Europe/London] * AuthXmlrpc->request_user_authorise("8e1e2c8eed727bf660a9d9b973121654f8e6a93f", "http://www.mydomain.co.uk/moodle") at /home/username/public_html/mahara/auth/xmlrpc/land.php:78

:(

30 June 2016, 19:13

Hi Stella,

Hm, from that MNet debug stuff from Moodle, it looks like what was happening was that Moodle didn't like the encryption on the message it received from Mahara, so it was trying to send back an (unencrypted) error response message to Mahara, which Mahara was not able to process.

That new error you're seeing, I think the crucial line is this: "(api/xmlrpc/lib.php:1599) This is not a valid SSL certificate."

From this, it seems that Mahara doesn't like the public key value that it has on file for your Moodle site. So it's either missing, or malformed. Normally Mahara would request Moodle's public key itself and automatically feed it into the host table, but that process seems to have gotten off track in your system.

(Just to clarify (and apologies if you already know this), MNet uses symmetric keys, which means Moodle has its own "private key" which it keeps secret, and a "public key" that it hands out to other sites. Other sites can then use Moodle's "public key" to encrypt messages that only Moodle can decrypt. Mahara likewise has its own private and public keys. Normally during Mnet, one of the first things that happens is that Moodle gets a copy of Mahara's public key, and Mahara gets a copy of Moodle's public key. It sounds like, from the current message, that Mahara is missing or has a bad copy of Moodle's public key.)

I hope that helps!

Aaron