Frequent "Request canceled before finishing" message in log file. This is potentially causing pulse to work randomly

Get Help
1 
{
  "browser-info": {
    "language": "en-US",
    "platform": "MacIntel",
    "userAgent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/94.0.4606.81 Safari/537.36",
    "vendor": "Google Inc."
  },
  "system-info": {
    "file.encoding": "UTF-8",
    "java.runtime.name": "OpenJDK Runtime Environment",
    "java.runtime.version": "11.0.11+9",
    "java.vendor": "AdoptOpenJDK",
    "java.vendor.url": "https://adoptopenjdk.net/",
    "java.version": "11.0.11",
    "java.vm.name": "OpenJDK 64-Bit Server VM",
    "java.vm.version": "11.0.11+9",
    "os.name": "Linux",
    "os.version": "4.14.225-169.362.amzn2.x86_64",
    "user.language": "en",
    "user.timezone": "UTC"
  },
  "metabase-info": {
    "databases": [
      "postgres"
    ],
    "hosting-env": "unknown",
    "application-database": "postgres",
    "application-database-details": {
      "database": {
        "name": "PostgreSQL",
        "version": "12.7"
      },
      "jdbc-driver": {
        "name": "PostgreSQL JDBC Driver",
        "version": "42.2.18"
      }
    },
    "run-mode": "prod",
    "version": {
      "date": "2021-05-27",
      "tag": "v0.39.3",
      "branch": "release-x.39.x",
      "hash": "598a112"
    },
    "settings": {
      "report-timezone": "US/Eastern"
    }
  }
}

We have multiple pulse setup for different questions. It does not always send email at the schedule day/time, looking at the log we see these messages and we're suspecting it is issues with pulse. Any thoughts?

2021-10-29T14:09:20-04:00 INFO metabase.server.middleware.exceptions Request canceled before finishing.
2021-10-29T14:09:35-04:00 INFO metabase.server.middleware.exceptions Request canceled before finishing.
2021-10-29T14:09:45-04:00 INFO metabase.server.middleware.exceptions Request canceled before finishing.
2021-10-29T14:10:30-04:00 INFO metabase.server.middleware.exceptions Request canceled before finishing.
2021-10-29T14:10:30-04:00 INFO metabase.server.middleware.exceptions Request canceled before finishing.
2

Hi @hmahatma
I doubt it has anything to do with pulses, since pulses run hourly - on the hour.
This error comes from the middleware, where the Jetty webserver lives:
https://github.com/metabase/metabase/blob/master/src/metabase/server/middleware/exceptions.clj#L76-L79
It's usually caused by the browser client closing a tab/window before the response could be delivered.
You can safely ignore that.

It sounds more like something similar to https://github.com/metabase/metabase/issues/14613 or https://github.com/metabase/metabase/issues/10088

But I would recommend that you upgrade to a newer release. There has been many performance fixes since.
https://github.com/metabase/metabase/releases

3

Thanks for the quick response. Confusing part is, previously when Pulse successfully triggered and sent email, we were able to see /alert action in log but other times, there is no /alert action shown in log - even though we have pulse setup to run hourly. This was the reason I was suspecting middleware exceptions as the culprit.

We have plan to upgrade in couple of weeks but if you have any other thoughts to fix this in a meantime, please let me know.
Thanks!

4

@hmahatma Not sure which "/alert action" you're referring to, but Pulses and Alerts are two different things, though, they share a lot of code, so you should see something like this:
INFO metabase.task.send-pulses Sending scheduled pulses...

You can enable more debug logging to see more information:
https://www.metabase.com/docs/latest/operations-guide/log-configuration.html
Docker - example, add this environmental variable to the docker run ... command:

... -e JAVA_OPTS="-Dlog4j.configurationFile=https://log4j.us/v2/templates/metabase?trace=metabase.task,metabase.pulse,metabase.email" ...
5

Sorry for the confusion. Here's the log where there was no "Sending scheduled pulses..." entry for time 2PM eastern - ignore table names.

2021-10-29T13:53:07-04:00 INFO metabase.sync.util STARTING: step 'fingerprint-fields' for postgres Database 6 'DB (Test)'
2021-10-29T13:53:08-04:00 INFO metabase.sync.analyze fingerprint-fields Analyzed [*****·············································] 😢   11% Table 156 'table1'
2021-10-29T13:53:12-04:00 INFO metabase.sync.analyze fingerprint-fields Analyzed [**********········································] 😒   21% Table 158 'table2'
2021-10-29T13:53:12-04:00 INFO metabase.sync.analyze fingerprint-fields Analyzed [****************··································] 😕   32% Table 168 'table3'
2021-10-29T13:53:12-04:00 INFO metabase.sync.util FINISHED: step 'fingerprint-fields' for postgres Database 6 'DB (Test)' (5.1 s)
2021-10-29T13:53:12-04:00 INFO metabase.sync.util STARTING: step 'classify-fields' for postgres Database 6 'DB (Test)'
2021-10-29T13:53:13-04:00 INFO metabase.sync.analyze classify-fields Analyzed [*********************·····························] 😐   43% Table 156 'table1'
2021-10-29T13:53:13-04:00 INFO metabase.sync.analyze classify-fields Analyzed [**************************························] 😬   54% Table 158 'table2'
2021-10-29T13:53:13-04:00 INFO metabase.sync.analyze classify-fields Analyzed [********************************··················] 😏   64% Table 168 'table3'
2021-10-29T13:53:13-04:00 INFO metabase.sync.util FINISHED: step 'classify-fields' for postgres Database 6 'DB (Test)' (235.3 ms)
2021-10-29T13:53:13-04:00 INFO metabase.sync.util STARTING: step 'classify-tables' for postgres Database 6 'DB (Test)'
2021-10-29T13:53:13-04:00 INFO metabase.sync.analyze classify-tables Analyzed [*************************************·············] 😋   75% Table 156 'table4'
2021-10-29T13:53:13-04:00 INFO metabase.sync.analyze classify-tables Analyzed [******************************************········] 😊   86% Table 158 'table3'
2021-10-29T13:53:13-04:00 INFO metabase.sync.analyze classify-tables Analyzed [************************************************··] 😎   96% Table 168 'table2'
2021-10-29T13:53:13-04:00 INFO metabase.sync.util FINISHED: step 'classify-tables' for postgres Database 6 'DB (Test)' (555.1 ms)
2021-10-29T13:53:13-04:00 INFO metabase.sync.util FINISHED: Analyze data for postgres Database 6 'DB (Test)' (6.0 s)
2021-10-29T14:09:20-04:00 INFO metabase.server.middleware.exceptions Request canceled before finishing.
2021-10-29T14:09:35-04:00 INFO metabase.server.middleware.exceptions Request canceled before finishing.
2021-10-29T14:09:45-04:00 INFO metabase.server.middleware.exceptions Request canceled before finishing.
2021-10-29T14:10:30-04:00 INFO metabase.server.middleware.exceptions Request canceled before finishing.
2021-10-29T14:10:30-04:00 INFO metabase.server.middleware.exceptions Request canceled before finishing.

and here's the log entry when pulse did run and I received email (3PM eastern),

2021-10-29T15:00:00-04:00 INFO metabase.task.send-pulses Sending scheduled pulses...

I'll enable debug logging and will get back here with more information.

6

@hmahatma Yeah, I've been investigating that the entire week. I have absolutely no idea how it can occur, but my guess is that it's race-condition, where the scheduler task doesn't run.
Basically something similar to issue 10088, but even more frustrating, since it starts working again.

7

Ah I see. Let me know if you end up figuring this out. Thank you so much!

8

@hmahatma Posted the wrong debug log config, since most people are having problems with sync.

... -e JAVA_OPTS="-Dlog4j.configurationFile=https://log4j.us/v2/templates/metabase?trace=metabase.task,metabase.pulse,metabase.email" ...