Changing an existing question - Sorry, you don't have permission to see that

Hi there,

We've had Metabase working great for a while now but are seeing a new error when we try to edit the fields or conditions of existing questions, written in SQL (native query).

It seems pretty random, so for example if we have an existing query that selects * and we change that to select just one particular field, we see the error message "Sorry, you don’t have permission to see that.".

So for example this works:

SELECT *
FROM   personfile AS pf
WHERE  pf.type = 'employment-agreement'
AND    pf.`status` = 'in-review'
AND    pf.due BETWEEN CONVERT_TZ(DATE_ADD(DATE(CONVERT_TZ(NOW(), '+00:00', '+13:00')), INTERVAL 8 HOUR), '+13:00', '+00:00') AND CONVERT_TZ(DATE_ADD(DATE(CONVERT_TZ(NOW(), '+00:00', '+13:00')), INTERVAL 18 HOUR), '+13:00', '+00:00')
ORDER BY pf.due;

And changing SELECT * to SELECT pf.id like this doesn't work:

SELECT pf.id
FROM   personfile AS pf
WHERE  pf.type = 'employment-agreement'
AND    pf.`status` = 'in-review'
AND    pf.due BETWEEN CONVERT_TZ(DATE_ADD(DATE(CONVERT_TZ(NOW(), '+00:00', '+13:00')), INTERVAL 8 HOUR), '+13:00', '+00:00') AND CONVERT_TZ(DATE_ADD(DATE(CONVERT_TZ(NOW(), '+00:00', '+13:00')), INTERVAL 18 HOUR), '+13:00', '+00:00')
ORDER BY pf.due;

We thought this was a bit odd and maybe to do with the particular question so we tried editing another question by just adding in AND 1=1 as another condition in the WHERE statement and that is an edit but it shouldn't change the results. This also gives us the "Sorry, you don’t have permission to see that." message.

We've tried running the same SQL directly against the databases involved and that works fine so we don't think it's an issue with the queries themselves.

We are running v0.33.3 and are seeing the issue when logged in as an administrator user. As we had only recently upgraded to 0.33.3, we tested out our old v0.29.3 setup and it shows the same error. Our administrator users have the "unrestricted access" and "can write raw queries" permissions, as shown in this screenshot form our setup.
06%20AM

We've tried a few things like re-scanning the database schemas, restarting the Metabase service and restarting mysql, as well as granting all permissions on mysql to the Metabase user and none of this has helped.

Any help here would be greatly appreciated as we're a bit hamstrung at the moment.
Thanks

Hi @april
Can you post the Diagnostic Info located in Admin > Troubleshooting?
Which database and version are you using for internal metadata?
Do you see any other errors/warnings at the same time in the Metabase log?
So this problem only just started happening after the upgrade to 0.33.3?
And you can reproduce the problem on specific questions, while other Native questions without SELECT * ... just saves without any problems?

Hi @flamber,

Here is the diagnostic info:

{
  "browser-info": {
    "language": "en-US",
    "platform": "MacIntel",
    "userAgent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/77.0.3865.90 Safari/537.36",
    "vendor": "Google Inc."
  },
  "system-info": {
    "java.runtime.name": "OpenJDK Runtime Environment",
    "java.runtime.version": "1.8.0_222-8u222-b10-1ubuntu1~18.04.1-b10",
    "java.vendor": "Private Build",
    "java.vendor.url": "http://java.oracle.com/",
    "java.version": "1.8.0_222",
    "java.vm.name": "OpenJDK 64-Bit Server VM",
    "java.vm.version": "25.222-b10",
    "os.name": "Linux",
    "os.version": "4.15.0-65-generic",
    "user.language": "en",
    "user.timezone": "Etc/UTC"
  },
  "metabase-info": {
    "databases": [
      "mysql"
    ],
    "hosting-env": "unknown",
    "application-database": "mysql",
    "run-mode": "prod",
    "version": {
      "tag": "v0.33.3",
      "date": "2019-09-20",
      "branch": "release-0.33.x",
      "hash": "86d32bf"
    },
    "settings": {
      "report-timezone": "Pacific/Auckland"
    }
  }
}

We’re using MySQL 5.7.27 for our internal metadata db.

This is what we see in the Metabase logs at the same time as getting the error:

[6234cbc5-c879-4a2e-98c6-eceda734afb1] 2019-10-03T12:18:52+13:00 ERROR metabase.driver.sql-jdbc.execute Failed to set timezone:
SQLException:
Message: (conn=90) Unknown or incorrect time zone: 'Pacific/Auckland'
SQLState: HY000
Error Code: 1298

[6234cbc5-c879-4a2e-98c6-eceda734afb1] 2019-10-03T12:18:52+13:00 DEBUG metabase.middleware.log POST /api/dataset 200 [ASYNC: completed] 117.7 ms (9 DB calls) Jetty threads: 2/50 (4 idle, 0 queued) (85 total active threads) Queries in flight: 0
[6234cbc5-c879-4a2e-98c6-eceda734afb1] 2019-10-03T12:18:58+13:00 DEBUG metabase.middleware.log GET /api/database/2/autocomplete_suggestions 200 32.8 ms (6 DB calls) Jetty threads: 3/50 (4 idle, 0 queued) (85 total active threads) Queries in flight: 0
[6234cbc5-c879-4a2e-98c6-eceda734afb1] 2019-10-03T12:18:59+13:00 DEBUG metabase.middleware.log GET /api/database/2/autocomplete_suggestions 200 19.2 ms (6 DB calls) Jetty threads: 3/50 (4 idle, 0 queued) (85 total active threads) Queries in flight: 0
[6234cbc5-c879-4a2e-98c6-eceda734afb1] 2019-10-03T12:19:13+13:00 WARN metabase.util.encryption Cannot decrypt encrypted string. Have you changed or forgot to set MB_ENCRYPTION_SECRET_KEY? 0 > -32 ("java.util.Arrays.copyOfRange(Arrays.java:3519)"
"buddy.core.bytes$slice.invokeStatic(bytes.clj:47)"
"buddy.core.bytes$slice.invokePrim(bytes.clj)"
"buddy.core.crypto$fn__23094.invokeStatic(crypto.clj:485)"
"buddy.core.crypto$fn__23094.invoke(crypto.clj:478)"
"clojure.lang.MultiFn.invoke(MultiFn.java:229)"
"buddy.core.crypto$decrypt.invokeStatic(crypto.clj:572)"
"buddy.core.crypto$decrypt.invoke(crypto.clj:559)"
"--> util.encryption$decrypt.invokeStatic(encryption.clj:65)"
"util.encryption$decrypt.invoke(encryption.clj:57)"
"util.encryption$maybe_decrypt.invokeStatic(encryption.clj:108)"
"util.encryption$maybe_decrypt.doInvoke(encryption.clj:96)"
"models.setting.cache$restore_cache_BANG_.invokeStatic(cache.clj:122)"
"models.setting.cache$restore_cache_BANG_.invoke(cache.clj:118)"
"models.setting$fn__18970$set_string_BANG___18975$fn__18976.invoke(setting.clj:283)"
"models.setting$fn__18970$set_string_BANG___18975.invoke(setting.clj:268)"
"models.setting$set_timestamp_BANG_.invokeStatic(setting.clj:343)"
"models.setting$set_timestamp_BANG_.invoke(setting.clj:340)"
"models.setting$set_BANG_.invokeStatic(setting.clj:386)"
"models.setting$set_BANG_.invoke(setting.clj:374)"
"models.setting$setting_fn$fn__19016.invoke(setting.clj:459)"
"metabot.instance$update_last_checkin_BANG_.invokeStatic(instance.clj:63)"
"metabot.instance$update_last_checkin_BANG_.invoke(instance.clj:60)"
"metabot.instance$check_and_update_instance_status_BANG_.invokeStatic(instance.clj:117)"
"metabot.instance$check_and_update_instance_status_BANG_.invoke(instance.clj:108)"
"metabot.instance$start_instance_monitor_BANG_$fn__55191.invoke(instance.clj:132)")

This error did only start happening after we upgraded to v0.33, however that may just be a coincidence as we also have our old 0.29.3 environment running in parallel (so we could test out 0.33 before switching over) and we are also seeing the issue on 0.29.3.

I’ve just had another play with a few more of our questions and have found some that don’t use SELECT * that also exhibit the problem. For example, this question that selects some specific fields gives me the error if I try to add on more field to the SELECT statement:

SELECT m.company_name, p.first_name, p.last_name, DATE_FORMAT(pf.createdAt, '%a, %d-%b-%Y') AS agreement_created_date, job_title, department_name
FROM `personfile` pf
JOIN member m ON pf.member_id = m.id
JOIN person p ON pf.person_id = p.id
WHERE pf.`type` = 'employment-agreement'
AND pf.createdAt BETWEEN DATE_ADD(NOW(), INTERVAL -1 WEEK) AND NOW()
AND m.package_id <> 1
ORDER BY pf.member_id;

And sorry, I should have said that I see the error when I try to run the edited question even before saving.

Hopefully this info helps, let me know if there’s anything else I can provide you with.
Thanks

@april
Awesome with all the extra info. I’m fairly sure you’re experiencing the same issue as this, which we haven’t found the root cause of yet:
https://github.com/metabase/metabase/issues/10897
Check some of the comments, since moving some WHERE columns around seems to allow it to save sometimes. This is an extremely strange error and so far, the only similarities I can see are MySQL as metadata and 0.33.3

What differs on your log though is the Cannot decrypt encrypted string error. Have you ever used MB_ENCRYPTION_SECRET_KEY variable?

Hi @flamber

I’ve had a read of issue 10897 and it does sound very familiar. We too have managed to rewrite a where condition in a different way but to give us the same result set and we can manage to get one of the questions to then run without error.

We are definitely seeing the issue on 0.33.3 but also on our instance of 0.29.3, if that’s of any help with further diagnosing.

In answer to your question, yes, we used the MB_ENCRYPTION_SECRET_KEY variable when we were on v0.29.3 for encrypting our db connection details at rest. We still set this environment variable in our 0.33.3 environment so let us know if we need to make a change with regards to this.

Thanks again,
April

@april

Just to confirm. You are using different metadata databases for each version, right?
Metabase doesn’t handle downgrading, so using the same metadata with different versions will likely end up corrupting the metadata.

On your 0.29.3, have this problem always existed or did you just notice it now after doing some re-testing?

I’m not sure what’s going on with the encryption key - it seems like it’s not being set - strange.
Is the key a base64-encoded string of at least 16 characters? Example:
MB_ENCRYPTION_SECRET_KEY='dGVzdHRlc3R0ZXN0dGVzdHRlc3Q='

You’re running Metabase as JAR-file on Ubuntu, right?
Are you running it as a service, if yes, init.d or systemd? If no, then how?

@flamber

Yes, we have two separate servers, each running Ubuntu and MySQL 5.7 with their own metabase databases and one is running the 0.29.3 JAR file and the other is running the 0.33.3 JAR file. The JAR files are running as a service using systemd. This is our bash script for the service with some details obfuscated:

#!/bin/sh

MB_DB_TYPE=mysql \
MB_DB_DBNAME=metabase \
MB_DB_PORT=3306 \
MB_DB_USER=root \
MB_DB_PASS=<removed> \
MB_DB_HOST=localhost \
MB_PASSWORD_COMPLEXITY=strong \
MB_PASSWORD_LENGTH=10 \
MB_ENCRYPTION_SECRET_KEY=<removed> \
/usr/bin/java \
-Xmx512m \
-jar /usr/local/lib/metabase/metabase.jar

Our MB_ENCRYPTION_SECRET_KEY value is base64-encoded string of 56 characters.

We’ve been running 0.29.3 without issue for a long time and only saw the issue occur there after we saw it happen on 0.33.3 first and thought let’s test it out on 0.29.3 to see if we could narrow down the cause.

Is there a utility we could run to see if our metadata has become corrupt somehow?

Thanks,
April

@april

Great with all the details you provide. If you had corrupted metadata, then you would know it - either Metabase wouldn’t start or there would be a lot of errors.

It’s really strange that you’re also seeing this issue on 0.29.3, since I have never seen this issue reported until #10897 a couple of weeks ago.
Let’s see what Daniel (@flyingmachine on Github, @nonrecursive in the forum) knows, since he has been investigating the issue on Github.

As for the encrypted key error, I’m hoping @camsaul knows a debug method or can spot something that I have overlooked. EDIT: Seems like there’s a problem with the encrypted key - https://github.com/metabase/metabase/issues/11048

Hi! Sorry I’m late to the party :slight_smile: I’m looking into this. It’s been a very difficult bug to pin down in part because of what seems like the arbitrary nature of the bug occurrences. It seems like the main common factor so far is using MySQL for the MB database.

@april thank you very much for providing logs and info, it’s very helpful. The next step in the debugging process is for me to be able to reproduce the bug, and I’m hoping I’ll be able to do that soon.

Hi @nonrecursive

No problem at all :slight_smile:

It does seem super random and so we’ve done a few more things trying to narrow down what it might be related to. On the Ubuntu 18.04 server where we were trying out v0.33.3, we started with a fresh install of Metabase using 0.33.3 and let it use the default of H2 for the metadata and that exhibited the same problem.

So we then tried a fresh install of Metabase 0.33.3 not on our Ubuntu server but just locally on a development Mac and it did not show the issue.

This is making us think that it has something to do with our production environment so we’re going to try out running Metabase in a docker container there when we get a chance.

In the meantime, since we’re administrators we are able to (carefully) edit the SQL for native queries directly in the report_card table to make the edits we want. The questions will run correctly with those edits so that lets us move forward and also shows that it’s really just in the saving of the question and not the running of it that is when the error occurs.

Do let us know if there’s anything else we can provide you and if you manage to reproduce and we’ll let you know how we get on with our environment investigations.

Thanks,
April

Thank you so much @april! Would you by chance be able to share the logs for this?

Thank you thank you :slight_smile:

So this is what we see in the logs for the H2 metabase instance we have when we try to edit a question and run it and it gives us the error:

[2440e6a5-32ea-4403-9e22-6a71acf8247c] 2019-10-08T10:13:38+13:00 DEBUG metabase.middleware.log POST /api/session 200 92.0 ms (2 DB calls) Jetty threads: 3/50 (5 idle, 0 queued) (81 total active threads) Queries in flight: 0
[2440e6a5-32ea-4403-9e22-6a71acf8247c] 2019-10-08T10:13:38+13:00 DEBUG metabase.middleware.log GET /api/user/current 200 2.8 ms (3 DB calls) Jetty threads: 3/50 (5 idle, 0 queued) (81 total active threads) Queries in flight: 0
[2440e6a5-32ea-4403-9e22-6a71acf8247c] 2019-10-08T10:13:38+13:00 DEBUG metabase.middleware.log GET /api/database 200 4.4 ms (3 DB calls) Jetty threads: 3/50 (5 idle, 0 queued) (81 total active threads) Queries in flight: 0 

You’ll see there is no error and also there is no log of the POST /api/dataset call although we do see a failed 403 request in network in dev tools in the browser.

When we edit a question in a way that works, we see this:

[2440e6a5-32ea-4403-9e22-6a71acf8247c] 2019-10-08T10:13:38+13:00 DEBUG metabase.middleware.log GET /api/collection/root/items 200 3.3 ms (6 DB calls) Jetty threads: 3/50 (5 idle, 0 queued) (81 total active threads) Queries in flight: 0
[2440e6a5-32ea-4403-9e22-6a71acf8247c] 2019-10-08T10:13:38+13:00 DEBUG metabase.middleware.log GET /api/collection/root 200 3.3 ms (2 DB calls) Jetty threads: 3/50 (5 idle, 0 queued) (81 total active threads) Queries in flight: 0
[2440e6a5-32ea-4403-9e22-6a71acf8247c] 2019-10-08T10:13:39+13:00 DEBUG metabase.middleware.log GET /api/database 200 4.7 ms (3 DB calls) Jetty threads: 3/50 (5 idle, 0 queued) (81 total active threads) Queries in flight: 0
[2440e6a5-32ea-4403-9e22-6a71acf8247c] 2019-10-08T10:13:39+13:00 DEBUG metabase.middleware.log GET /api/automagic-dashboards/database/2/candidates 200 107.7 ms (6 DB calls) Jetty threads: 3/50 (5 idle, 0 queued) (81 total active threads) Queries in flight: 0
[2440e6a5-32ea-4403-9e22-6a71acf8247c] 2019-10-08T10:13:47+13:00 DEBUG metabase.middleware.log GET /api/database 200 12.3 ms (5 DB calls) Jetty threads: 3/50 (5 idle, 0 queued) (81 total active threads) Queries in flight: 0
[2440e6a5-32ea-4403-9e22-6a71acf8247c] 2019-10-08T10:14:02+13:00 DEBUG metabase.middleware.log POST /api/dataset 200 [ASYNC: completed] 78.2 ms (9 DB calls) Jetty threads: 2/50 (5 idle, 0 queued) (81 total active threads) Queries in flight: 0

Is this enough of the logs or was there something else specific you were after?

Interestingly, we have just tried out bypassing our CDN (Cloudflare) and no longer have the problem. We are wondering if the size of the body in the POST call to /api/dataset is too large or some header that is required for authentication is being removed when going through Cloudflare? Smaller sized query strings were not showing the problem and it was when making edits that made the query string larger that we would typically see the issue.

Cheers,
April

Intresting. If the 403 response is coming from the CDN I can see why that wouldn’t be showing up in the server logs. Would it be possible to do a screen share? If so, we could coordinate over email; my address is daniel@metabase.com

Thanks!
Daniel

Hi Daniel, I just sent you an email. Cheers, April

@april @nonrecursive Not sure if this is helpful, but just letting you know.
Cloudflare (and similar services) has some pretty aggressive script compacting and WAF (web application firewall) features, which are incompatible with many advanced web-based systems - there has been several reports previously (both in the forum and Github) about strange behaviors (like QB not working) until those were disabled, but it’s the first time I have seen this specific behavior.

@flamber April followed up with me offline and provided this very helpful info:

At about the same time as we started to see this issue with Metabase, we had just turned on the Web Application Firewall (WAF) on Cloudflare. After experimenting with turning that off completely and then back on incrementally, we have discovered that when we saw a 403 to the /api/dataset POST call, this was because we had matched a Cloudflare OWASP rule and so Cloudflare had issued us a challenge. We weren't seeing that on screen though, but if we looked under network in our browser dev tools and viewed the response details of the 403 request, it was the HTML for a challenge page.

If I'm not misunderstanding, it sounds like the issue was in interactions with and configuring of Cloudflare, independent of MetaBase. It sounds like this particular issue is resolved.

I think this issue is probably separate from Permissions errors when running queries or saving anything · Issue #10897 · metabase/metabase · GitHub , as the user johnmastro there isn't using cloudflare. He did report using a proxy so that might be the cause. I'm out for the rest of the week but let him know he could post on this forum if he wanted to do another screen share with someone else while I'm away.

1 Like

For anyone else getting this error, I can confirm that creating a Cloudflare Rule to disable the RocketLoader, and disable the WAF, take care of the issue.
Likewise the above comments were helpful for me to actually look at the console logs and see the CF challenge html in there.