Metabse and Google Analytics both stopped working

Get Help
1

Hello, yesterday i.e. Tue 27 Apr, 2021, we've added two connections with Google Analytics. At the time connection, we faced timeout in 5 secs. couple of time, but after few attempt connection was successful.

Later in the evening, one of our colleague used the one of new connection of GA and explored the data set. From then, we'd seen issue in GA real time dashboard. Today i.e. Wed Apr 28, 2021, we noticed our metabase instance was also not reachable along with Google Analytics issue which mentioned earlier.

After restarting the metabase instance and deleting those two new GA connection, we started seeing real time dashboard in GA today.

So need help/clarity for couple of questions below,

  1. As read in one of the topic within this forum, that we need to create OAuth client by selecting Desktop App, after doing that to get the authcode, we've to login with one of the user by allowing few permissions. What is the least permission required for this user ? Can we create a new user with specific roles and permission to get the authcode ?
  2. Is there any proper documentation available for Google Analytics integration ? If yes, then anyone please share the link. Also, which all GA APIs are invoked/accessed by metabase while exploring the data set or periodically while doing background sync or something similar ?
2

Hi @a.omer

Please post "Diagnostic Info" from Admin > Troubleshooting.
If Metabase crashed, then it would be very interesting to get the logs from that.

There's currently a work-in-progress documentation, which eventually should turn into the official docs:
https://github.com/metabase/metabase/blob/5b149e4569ca23752f6d69a7ae091bcc80130dce/docs/administration-guide/databases/google-analytics.md

3

Hi @flamber,

Please find the attached diagnostic info,

{
  "browser-info": {
    "language": "en-US",
    "platform": "MacIntel",
    "userAgent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:87.0) Gecko/20100101 Firefox/87.0",
    "vendor": ""
  },
  "system-info": {
    "file.encoding": "UTF-8",
    "java.runtime.name": "OpenJDK Runtime Environment",
    "java.runtime.version": "1.8.0_282-b08",
    "java.vendor": "AdoptOpenJDK",
    "java.vendor.url": "https://adoptopenjdk.net/",
    "java.version": "1.8.0_282",
    "java.vm.name": "OpenJDK 64-Bit Server VM",
    "java.vm.version": "25.282-b08",
    "os.name": "Linux",
    "os.version": "4.15.0-1113-azure",
    "user.language": "en",
    "user.timezone": "Etc/UTC"
  },
  "metabase-info": {
    "databases": [
      "h2",
      "mysql",
      "mongo",
      "bigquery"
    ],
    "hosting-env": "unknown",
    "application-database": "mysql",
    "application-database-details": {
      "database": {
        "name": "MySQL",
        "version": "5.6.47.0"
      },
      "jdbc-driver": {
        "name": "MariaDB Connector/J",
        "version": "2.6.2"
      }
    },
    "run-mode": "prod",
    "version": {
      "tag": "v0.38.3",
      "date": "2021-04-01",
      "branch": "release-x.38.x",
      "hash": "8332830"
    },
    "settings": {
      "report-timezone": "Asia/Singapore"
    }
  }
}

Also, please note databases info doesn't contain Google Analytics connection, as we've already removed it.

Let me know if any additional details are required from my end.

4

@a.omer Without any logs, then it's hard to tell what the problem could be. Check the logs on Azure.

But you need to upgrade the application database, which is using MySQL 5.6 - the minimum required version is 5.7.7:
https://www.metabase.com/docs/latest/operations-guide/configuring-application-database.html#mysql-or-mariadb

And I would recommend upgrading Java to latest LTS:
https://www.metabase.com/docs/latest/operations-guide/java-versions.html

5

@flamber For MySQL, I'm not sure why it's getting reported as 5.6.x, but we're using MySQL DB on Azure as application database with MySQL version as 8.0.

For JAVA upgrade, can you please suggest which LTS version is most compatible with the installed metabase version 0.38.3 ?

I pulled some metabase logs just before when it went down.

Apr 27 10:42:09 prod-metabase-01 metabase[1419]: 2021-04-27 10:42:09,230 DEBUG middleware.log :: #033[32mPOST /api/card/26/query 202 [ASYNC: completed] 3.4 s (10 DB calls) App DB connections: 7/15 Jetty threads: 3/50 (17 idle, 0 queued) (162 total active threads) Queries in flight: 5 (0 queued)#033[0m
Apr 27 10:42:09 prod-metabase-01 metabase[1419]: 2021-04-27 10:42:09,230 DEBUG middleware.log :: #033[32mPOST /api/card/7/query 202 [ASYNC: completed] 3.7 s (13 DB calls) App DB connections: 7/15 Jetty threads: 2/50 (18 idle, 0 queued) (162 total active threads) Queries in flight: 5 (0 queued)#033[0m
Apr 27 10:42:09 prod-metabase-01 metabase[1419]: 2021-04-27 10:42:09,392 DEBUG middleware.log :: #033[32mPOST /api/card/29/query 202 [ASYNC: completed] 3.8 s (14 DB calls) App DB connections: 7/15 Jetty threads: 2/50 (18 idle, 0 queued) (162 total active threads) Queries in flight: 4 (0 queued)#033[0m
Apr 27 10:42:09 prod-metabase-01 metabase[1419]: 2021-04-27 10:42:09,395 DEBUG middleware.log :: #033[32mPOST /api/card/21/query 202 [ASYNC: completed] 3.7 s (10 DB calls) App DB connections: 6/15 Jetty threads: 5/50 (16 idle, 0 queued) (162 total active threads) Queries in flight: 3 (0 queued)#033[0m
Apr 27 10:42:09 prod-metabase-01 metabase[1419]: 2021-04-27 10:42:09,558 DEBUG middleware.log :: #033[32mPOST /api/card/6/query 202 [ASYNC: completed] 4.0 s (12 DB calls) App DB connections: 6/15 Jetty threads: 2/50 (18 idle, 0 queued) (162 total active threads) Queries in flight: 2 (0 queued)#033[0m
Apr 27 10:42:09 prod-metabase-01 metabase[1419]: 2021-04-27 10:42:09,587 DEBUG middleware.log :: #033[32mPOST /api/card/9/query 202 [ASYNC: completed] 3.8 s (15 DB calls) App DB connections: 6/15 Jetty threads: 6/50 (15 idle, 0 queued) (162 total active threads) Queries in flight: 1 (0 queued)#033[0m
Apr 27 10:42:09 prod-metabase-01 metabase[1419]: 2021-04-27 10:42:09,743 DEBUG middleware.log :: #033[32mPOST /api/card/19/query 202 [ASYNC: completed] 4.2 s (18 DB calls) App DB connections: 5/15 Jetty threads: 2/50 (18 idle, 0 queued) (162 total active threads) Queries in flight: 0 (0 queued)#033[0m
Apr 27 10:42:34 prod-metabase-01 metabase[1419]: 2021-04-27 10:42:34,241 DEBUG middleware.log :: #033[32mGET /api/database/12/metadata 200 549.9 ms (13 DB calls) App DB connections: 1/15 Jetty threads: 3/50 (17 idle, 0 queued) (162 total active threads) Queries in flight: 0 (0 queued)#033[0m
Apr 27 10:52:10 prod-metabase-01 metabase[1419]: 2021-04-27 10:52:10,837 INFO sync.util :: #033[35mFINISHED: step 'sync-metabase-metadata' for googleanalytics Database 11 'GA - ONE' (22.3 mins)#033[0m
Apr 27 10:52:11 prod-metabase-01 metabase[1419]: 2021-04-27 10:52:11,941 INFO sync.util :: #033[35mFINISHED: Sync metadata for googleanalytics Database 11 'GA - ONE' (42.8 mins)#033[0m
Apr 27 10:52:11 prod-metabase-01 metabase[1419]: 2021-04-27 10:52:11,946 INFO sync.util :: #033[35mSTARTING: Analyze data for googleanalytics Database 11 'GA - ONE'#033[0m
Apr 27 10:52:11 prod-metabase-01 metabase[1419]: 2021-04-27 10:52:11,999 INFO sync.util :: #033[35mSTARTING: step 'fingerprint-fields' for googleanalytics Database 11 'GA - ONE'#033[0m
Apr 27 10:52:12 prod-metabase-01 metabase[1419]: 2021-04-27 10:52:12,000 INFO sync.analyze :: #033[34mfingerprint-fields Analyzed [*****·················?
····························]    10% Table 175 '199474617'#033[0m
Apr 27 10:52:12 prod-metabase-01 metabase[1419]: 2021-04-27 10:52:12,003 INFO sync.analyze :: #033[34mfingerprint-fields Analyzed [**********··············??
?·························]    20% Table 183 '216304428'#033[0m
Apr 27 10:52:12 prod-metabase-01 metabase[1419]: 2021-04-27 10:52:12,004 INFO sync.analyze :: #033[34mfingerprint-fields Analyzed [***************············?
·······················]    30% Table 172 '236937490'#033[0m
Apr 27 10:52:12 prod-metabase-01 metabase[1419]: 2021-04-27 10:52:12,004 INFO sync.util :: #033[35mFINISHED: step 'fingerprint-fields' for googleanalytics Database 11 'GA - ONE' (5.6 ms)#033[0m
Apr 27 10:52:12 prod-metabase-01 metabase[1419]: 2021-04-27 10:52:12,005 INFO sync.util :: #033[35mSTARTING: step 'classify-fields' for googleanalytics Database 11 'GA - ONE'#033[0m
Apr 27 10:52:12 prod-metabase-01 metabase[1419]: 2021-04-27 10:52:12,022 INFO sync.analyze :: #033[34mclassify-fields Analyzed [********************···········?
···················]    40% Table 173 '199448438'#033[0m
Apr 27 10:52:12 prod-metabase-01 metabase[1419]: 2021-04-27 10:52:12,034 INFO sync.analyze :: #033[34mclassify-fields Analyzed [*************************········??
?················]    50% Table 174 '213375181'#033[0m
Apr 27 10:52:12 prod-metabase-01 metabase[1419]: 2021-04-27 10:52:12,046 INFO sync.analyze :: #033[34mclassify-fields Analyzed [******************************······?
··············]    60% Table 180 '236936896'#033[0m
Apr 27 10:52:12 prod-metabase-01 metabase[1419]: 2021-04-27 10:52:12,052 INFO sync.util :: #033[35mFINISHED: step 'classify-fields' for googleanalytics Database 11 'GA - ONE' (46.7 ms)#033[0m
Apr 27 10:52:12 prod-metabase-01 metabase[1419]: 2021-04-27 10:52:12,053 INFO sync.util :: #033[35mSTARTING: step 'classify-tables' for googleanalytics Database 11 'GA - ONE'#033[0m
Apr 27 10:52:12 prod-metabase-01 metabase[1419]: 2021-04-27 10:52:12,460 INFO sync.analyze :: #033[34mclassify-tables Analyzed [**********************************····?   
············]    70% Table 182 '199442343'#033[0m
Apr 27 10:52:13 prod-metabase-01 metabase[1419]: 2021-04-27 10:52:13,240 INFO sync.analyze :: #033[34mclassify-tables Analyzed [****************************************·?
·········]    80% Table 178 '199483900'#033[0m
Apr 27 10:52:13 prod-metabase-01 metabase[1419]: 2021-04-27 10:52:13,989 INFO sync.analyze :: #033[34mclassify-tables Analyzed [********************************************······]    90% Table 176 '228770067'#033[0m
Apr 27 10:52:14 prod-metabase-01 metabase[1419]: 2021-04-27 10:52:14,569 INFO sync.util :: #033[35mFINISHED: step 'classify-tables' for googleanalytics Database 11 'GA - ONE' (2.5 s)#033[0m
Apr 27 10:52:15 prod-metabase-01 metabase[1419]: 2021-04-27 10:52:15,302 INFO sync.util :: #033[35mFINISHED: Analyze data for googleanalytics Database 11 'GA - ONE' (3.4 s)#033[0m
Apr 27 10:52:15 prod-metabase-01 metabase[1419]: 2021-04-27 10:52:15,304 INFO sync.util :: #033[35mSTARTING: Cache field values in googleanalytics Database 11 'GA - ONE'#033[0m
Apr 27 10:52:15 prod-metabase-01 metabase[1419]: 2021-04-27 10:52:15,305 INFO sync.util :: #033[35mSTARTING: step 'update-field-values' for googleanalytics Database 11 'GA - ONE'#033[0m
Apr 27 10:52:31 prod-metabase-01 metabase[1419]: 2021-04-27 10:52:31,262 INFO sync.util :: #033[35mFINISHED: step 'update-field-values' for googleanalytics Database 11 'GA - ONE' (16.0 s)#033[0m
Apr 27 10:52:31 prod-metabase-01 metabase[1419]: 2021-04-27 10:52:31,633 INFO sync.util :: #033[35mFINISHED: Cache field values in googleanalytics Database 11 'GA - ONE' (16.3 s)#033[0m
Apr 27 10:52:31 prod-metabase-01 metabase[1419]: 2021-04-27 10:52:31,633 INFO sync.util :: #033[35mFINISHED: Sync googleanalytics Database 11 'GA - ONE' (43.1 mins)#033[0m
Apr 27 11:00:00 prod-metabase-01 metabase[1419]: 2021-04-27 11:00:00,262 INFO task.send-pulses :: Sending scheduled pulses...
Apr 27 11:10:40 prod-metabase-01 metabase[1419]: 2021-04-27 11:10:40,147 WARN middleware.log :: #033[31mPOST /api/jsonws/invoke 404 111.1 µs (0 DB calls)
Apr 27 11:10:40 prod-metabase-01 metabase[1419]: "API endpoint does not exist."
Apr 27 11:10:40 prod-metabase-01 metabase[1419]: #033[0m
Apr 27 12:00:00 prod-metabase-01 metabase[1419]: 2021-04-27 12:00:00,197 INFO task.send-pulses :: Sending scheduled pulses...
Apr 27 13:00:00 prod-metabase-01 metabase[1419]: 2021-04-27 13:00:00,319 INFO task.send-pulses :: Sending scheduled pulses...
Apr 27 14:00:00 prod-metabase-01 metabase[1419]: 2021-04-27 14:00:00,212 INFO task.send-pulses :: Sending scheduled pulses...
Apr 27 15:00:00 prod-metabase-01 metabase[1419]: 2021-04-27 15:00:00,186 INFO task.send-pulses :: Sending scheduled pulses...
Apr 27 15:00:01 prod-metabase-01 metabase[1419]: 2021-04-27 15:00:01,121 INFO task.sync-databases :: Update Field values task triggered for Database 1.
Apr 27 15:00:01 prod-metabase-01 metabase[1419]: 2021-04-27 15:00:01,126 INFO sync.util :: #033[35mSTARTING: Cache field values in h2 Database 1 'Sample Dataset'#033[0m
Apr 27 15:00:01 prod-metabase-01 metabase[1419]: 2021-04-27 15:00:01,126 INFO sync.util :: #033[35mSTARTING: step 'update-field-values' for h2 Database 1 'Sample Dataset'#033[0m
Apr 27 15:00:03 prod-metabase-01 metabase[1419]: 2021-04-27 15:00:03,225 INFO sync.util :: #033[35mFINISHED: step 'update-field-values' for h2 Database 1 'Sample Dataset' (2.1 s)#033[0m
Apr 27 15:00:03 prod-metabase-01 metabase[1419]: 2021-04-27 15:00:03,460 INFO sync.util :: #033[35mFINISHED: Cache field values in h2 Database 1 'Sample Dataset' (2.3 s)#033[0m
Apr 27 16:00:00 prod-metabase-01 metabase[1419]: 2021-04-27 16:00:00,204 INFO task.send-pulses :: Sending scheduled pulses...
Apr 27 17:00:00 prod-metabase-01 metabase[1419]: 2021-04-27 17:00:00,195 INFO task.send-pulses :: Sending scheduled pulses...
Apr 27 18:00:00 prod-metabase-01 metabase[1419]: 2021-04-27 18:00:00,151 INFO task.send-pulses :: Sending scheduled pulses...
Apr 27 19:00:00 prod-metabase-01 metabase[1419]: 2021-04-27 19:00:00,267 INFO task.send-pulses :: Sending scheduled pulses...
Apr 27 20:00:00 prod-metabase-01 metabase[1419]: 2021-04-27 20:00:00,069 INFO task.send-pulses :: Sending scheduled pulses...
Apr 27 20:00:00 prod-metabase-01 metabase[1419]: 2021-04-27 20:00:00,786 INFO task.sync-databases :: Update Field values task triggered for Database 10.
Apr 27 20:00:00 prod-metabase-01 metabase[1419]: 2021-04-27 20:00:00,790 INFO sync.util :: #033[35mSTARTING: Cache field values in bigquery Database 10 'KPI Dashboard - BigQuery'#033[0m
Apr 27 20:00:00 prod-metabase-01 metabase[1419]: 2021-04-27 20:00:00,790 INFO sync.util :: #033[35mSTARTING: step 'update-field-values' for bigquery Database 10 'KPI Dashboard - BigQuery'#033[0m
Apr 27 20:03:57 prod-metabase-01 metabase[1419]: 2021-04-27 20:03:57,980 INFO sync.util :: #033[35mFINISHED: step 'update-field-values' for bigquery Database 10 'KPI Dashboard - BigQuery' (4.0 mins)#033[0m
Apr 27 20:03:58 prod-metabase-01 metabase[1419]: 2021-04-27 20:03:58,222 INFO sync.util :: #033[35mFINISHED: Cache field values in bigquery Database 10 'KPI Dashboard - BigQuery' (4.0 mins)#033[0m
Apr 27 21:00:00 prod-metabase-01 metabase[1419]: 2021-04-27 21:00:00,180 INFO task.send-pulses :: Sending scheduled pulses...
Apr 27 22:00:00 prod-metabase-01 metabase[1419]: 2021-04-27 22:00:00,090 INFO task.send-pulses :: Sending scheduled pulses...

Based on these logs, it looks like after last entry of timestamp Apr 27 10:52:31, it went down as scheduled pulses didn't get any response back. You can clarify it better. If my understanding is correct, then please help me in understanding what happens just before that. I'm sensing some background sync of metabase caused the issue, but you can confirm for that.

6

@a.omer Metabase is getting the version number from the database. I don't know if Azure is announcing itself as something else, just like most browsers announces as Mozilla.
For reference: https://github.com/metabase/metabase/blob/master/src/metabase/driver/mysql.clj#L45-L47
But try running this on the application database: SELECT @@VERSION;

The latest LTS is 11: https://adoptopenjdk.net/releases.html

I don't see anything in the logs that indicates that Metabase crashed, since there would then be a possible crash log, and definitely a startup log of several hundred lines.
It says on 10:52:31 that it finished doing analysis of a GA database, which took 43 minutes.