ClassCastException / 500 error when sending test email for a dashboard subscription

Hi there,

I'd like to create a subscription to one of my dashboards. When I send a test email while setting it up, I consistently see the following logs. The final log line is always an HTTP status 500 due to a ClassCastException with no stack trace. I'm wondering if maybe the dashboard is too big (the last log line says it's making 461 DB calls :grimacing:), but the dashboard itself works fine when I load it in the browser.

Any help would be most appreciated!

Logs:

[fde882f3-0ef9-4b4b-9755-d85eae0890d5] 2022-05-04T10:52:53-04:00 DEBUG metabase.server.middleware.log GET /api/pulse 200 7.2 ms (7 DB calls) App DB connections: 0/15 Jetty threads: 3/50 (12 idle, 0 queued) (132 total active threads) Queries in flight: 0 (0 queued)
[fde882f3-0ef9-4b4b-9755-d85eae0890d5] 2022-05-04T10:52:54-04:00 DEBUG metabase.server.middleware.log GET /api/user 200 3.4 ms (4 DB calls) App DB connections: 0/15 Jetty threads: 3/50 (12 idle, 0 queued) (132 total active threads) Queries in flight: 0 (0 queued)
[fde882f3-0ef9-4b4b-9755-d85eae0890d5] 2022-05-04T10:52:54-04:00 DEBUG metabase.server.middleware.log GET /api/pulse/form_input 200 1.4 ms (2 DB calls) App DB connections: 1/15 Jetty threads: 3/50 (12 idle, 0 queued) (132 total active threads) Queries in flight: 0 (0 queued)

...
[fde882f3-0ef9-4b4b-9755-d85eae0890d5] 2022-05-04T10:52:56-04:00 INFO metabase.query-processor.middleware.fetch-source-query Fetched source query from Card 14:

/* This line repeated several times for numerous "Cards" */
...

[fde882f3-0ef9-4b4b-9755-d85eae0890d5] 2022-05-04T10:53:07-04:00 ERROR metabase.server.middleware.log POST /api/pulse/test 500 10.8 s (461 DB calls) 
{:via [{:type java.lang.ClassCastException}], :trace [], :message nil}

Diagnostic info:

{
  "browser-info": {
    "language": "en-US",
    "platform": "MacIntel",
    "userAgent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/15.4 Safari/605.1.15",
    "vendor": "Apple Computer, Inc."
  },
  "system-info": {
    "file.encoding": "UTF-8",
    "java.runtime.name": "OpenJDK Runtime Environment",
    "java.runtime.version": "11.0.13+8",
    "java.vendor": "Eclipse Adoptium",
    "java.vendor.url": "https://adoptium.net/",
    "java.version": "11.0.13",
    "java.vm.name": "OpenJDK 64-Bit Server VM",
    "java.vm.version": "11.0.13+8",
    "os.name": "Linux",
    "os.version": "4.14.256-197.484.amzn2.x86_64",
    "user.language": "en",
    "user.timezone": "GMT"
  },
  "metabase-info": {
    "databases": [
      "postgres",
      "h2"
    ],
    "hosting-env": "unknown",
    "application-database": "postgres",
    "application-database-details": {
      "database": {
        "name": "PostgreSQL",
        "version": "12.8"
      },
      "jdbc-driver": {
        "name": "PostgreSQL JDBC Driver",
        "version": "42.2.23"
      }
    },
    "run-mode": "prod",
    "version": {
      "date": "2021-12-16",
      "tag": "v1.41.5",
      "branch": "release-x.41.x",
      "hash": "fbfffc6"
    },
    "settings": {
      "report-timezone": "America/New_York"
    }
  }
}

Hi @eghs
That's a rather unhelpful "exception". How many cards do you have on the dashboard?

I think you'll need to enable some debug logging to figure out what is going on - unless you create a duplicate dashboard and remove cards one-by-one until you find the suspect.

Docker - example, add this environmental variable to the docker run ... command:

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

Thanks @flamber, I have 10 cards on the dashboard as well as a few headings. I'm honestly a bit confused because the card numbers in the full log go as high as 25.

I'll talk to our engineers about appending that flag to the command. I can definitely try to make a new dashboard to pull the cards in one by one and see if one of them specifically is the culprit.

@sagethan It's because there's a tiny log bug, so when you create nested questions, then it will log the nested question twice, but it's using memorization, so it doesn't cause load.

10 cards is nothing - definitely try to find the culprit within them. It should be able to handle that without a flinch.
Alternatively go to the URL /pulse/create and try inputting each question one-by-one until you find the bad boy.

There has been many fixes since 41-series. Particular to subscriptions. Latest release is 43.0, but otherwise it might be worth looking at 42.4 (at least in a staging environment).

It very much looks like an issue, which we fixed back in 41.0:
https://github.com/metabase/metabase/issues/16888

1 Like

That does seem like the culprit. I'll do some exploration on my end and follow up. Our devs are pretty occupied so not sure we'll be able to do an upgrade any time soon, but that's good to know.

@sagethan But the problem is that you're running 41.5 and we fixed the problem in 41.0, so I'm not entirely sure what is going on.

It would be very helpful to get the question metadata (might contain some sensitive parts) by going to the URL /api/card/123, where 123 is the question ID of the culprit.
Then I can try to reproduce on various versions and figure out if it has been fixed or create an issue.

@flamber Ah true that doesn't quite add up.

I found the suspect card, it's a graph that aggregates by hour of the day (12pm, 1pm, 2pm, etc.) over the past N days, where N is a relative date filter.

Here's the question metadata (I stripped out emails/names of users but everything else is there):

{
    "description": "Average alert claim and resolution times in minutes, broken down by the hour of alert creation",
    "archived": false,
    "collection_position": null,
    "table_id": 7,
    "result_metadata": [
        {
            "semantic_type": "type/CreationTimestamp",
            "coercion_strategy": null,
            "unit": "hour-of-day",
            "name": "createdatetime",
            "field_ref": [
                "field",
                79,
                {
                    "temporal-unit": "hour-of-day"
                }
            ],
            "effective_type": "type/DateTime",
            "id": 79,
            "display_name": "Createdatetime",
            "fingerprint": {
                "global": {
                    "distinct-count": 24,
                    "nil%": 0.0
                },
                "type": {
                    "type/Number": {
                        "min": 0.0,
                        "q1": 5.5,
                        "q3": 17.5,
                        "max": 23.0,
                        "sd": 7.0710678118654755,
                        "avg": 11.5
                    }
                }
            },
            "base_type": "type/DateTime"
        },
        {
            "name": "Average Claim Time",
            "display_name": "Average Claim Time",
            "base_type": "type/Float",
            "effective_type": "type/Float",
            "semantic_type": null,
            "field_ref": [
                "aggregation",
                0
            ],
            "fingerprint": {
                "global": {
                    "distinct-count": 14,
                    "nil%": 0.0
                },
                "type": {
                    "type/Number": {
                        "min": 1.0,
                        "q1": 7.0,
                        "q3": 11.822875655532295,
                        "max": 125.0,
                        "sd": 24.047921661380304,
                        "avg": 13.958333333333334
                    }
                }
            }
        },
        {
            "name": "Average Total Time",
            "display_name": "Average Total Time",
            "base_type": "type/Float",
            "effective_type": "type/Float",
            "semantic_type": null,
            "field_ref": [
                "aggregation",
                1
            ],
            "fingerprint": {
                "global": {
                    "distinct-count": 14,
                    "nil%": 0.0
                },
                "type": {
                    "type/Number": {
                        "min": 2.0,
                        "q1": 8.550510257216821,
                        "q3": 14.0,
                        "max": 126.0,
                        "sd": 23.95103701122445,
                        "avg": 16.0
                    }
                }
            }
        },
        {
            "name": "count",
            "display_name": "Count",
            "base_type": "type/BigInteger",
            "effective_type": "type/BigInteger",
            "semantic_type": "type/Quantity",
            "field_ref": [
                "aggregation",
                2
            ],
            "fingerprint": {
                "global": {
                    "distinct-count": 14,
                    "nil%": 0.0
                },
                "type": {
                    "type/Number": {
                        "min": 2.0,
                        "q1": 4.464101615137754,
                        "q3": 16.0,
                        "max": 23.0,
                        "sd": 6.852482888641929,
                        "avg": 11.0
                    }
                }
            }
        }
    ],
    "creator": {
        "last_login": "2022-02-14T16:39:26.731044Z",
        "is_qbnewb": false,
        "is_superuser": false,
        "id": 2,
        "date_joined": "2022-01-10T21:36:38.39153Z",
    },
    "can_write": true,
    "database_id": 2,
    "enable_embedding": false,
    "collection_id": 10,
    "query_type": "query",
    "name": "Average Alert Claim and Resolution Time in Minutes (By Hour)",
    "last_query_start": "2022-05-04T21:07:08.875153Z",
    "dashboard_count": 2,
    "average_query_time": 4996.1200000000000000,
    "creator_id": 2,
    "moderation_reviews": [],
    "updated_at": "2022-05-04T21:07:13.876324Z",
    "made_public_by_id": null,
    "embedding_params": null,
    "cache_ttl": null,
    "dataset_query": {
        "type": "query",
        "query": {
            "source-table": "card__14",
            "breakout": [
                [
                    "field",
                    79,
                    {
                        "temporal-unit": "hour-of-day"
                    }
                ]
            ],
            "aggregation": [
                [
                    "aggregation-options",
                    [
                        "round",
                        [
                            "avg",
                            [
                                "field",
                                "Claim Time",
                                {
                                    "base-type": "type/Float"
                                }
                            ]
                        ]
                    ],
                    {
                        "name": "Average Claim Time",
                        "display-name": "Average Claim Time"
                    }
                ],
                [
                    "aggregation-options",
                    [
                        "round",
                        [
                            "avg",
                            [
                                "field",
                                "Total Time",
                                {
                                    "base-type": "type/Float"
                                }
                            ]
                        ]
                    ],
                    {
                        "name": "Average Total Time",
                        "display-name": "Average Total Time"
                    }
                ],
                [
                    "count"
                ]
            ]
        },
        "database": 2
    },
    "id": 16,
    "display": "bar",
    "last-edit-info": {
        "id": 4,
        "timestamp": "2022-04-06T14:53:43.377293Z"
    },
    "visualization_settings": {
        "graph.y_axis.title_text": "",
        "graph.show_values": true,
        "graph.x_axis.labels_enabled": true,
        "graph.x_axis.title_text": "Hour of Alert Creation (Eastern)",
        "graph.y_axis.auto_split": false,
        "graph.metrics": [
            "Average Claim Time",
            "Average Total Time",
            "count"
        ],
        "column_settings": {
            "[\"ref\",[\"field\",79,null]]": {
                "time_enabled": "minutes"
            }
        },
        "series_settings": {
            "avg": {
                "title": "Average Claim Time"
            },
            "avg_2": {
                "title": "Average Resolution Time"
            },
            "Average Claim Time": {
                "color": "#A989C5",
                "axis": "left"
            },
            "Average Total Time": {
                "color": "#F2A86F",
                "axis": "left"
            },
            "count": {
                "axis": "right"
            }
        },
        "graph.dimensions": [
            "createdatetime"
        ]
    },
    "collection": {
        "authority_level": null,
        "description": "Components used in the Alerts Dashboard",
        "archived": false,
        "slug": "alerts_dashboard",
        "color": "#271f45",
        "name": "Alerts Dashboard",
        "personal_owner_id": null,
        "id": 10,
        "location": "/4/7/",
        "namespace": null
    },
    "created_at": "2022-01-12T18:10:48.335023Z",
    "public_uuid": null
}

@sagethan Hmmm.... when I create a question similar to yours on 41.5, then I cannot make it fail. See below.

I think the problem might be coming from the nested question, but I have no idea what it could be.
Though, there has been many hundreds of fixes since 41.5.

{
  "description": null,
  "archived": false,
  "collection_position": null,
  "table_id": 10,
  "result_metadata": [
    {
      "description": "The date the product was added to our catalog.",
      "semantic_type": "type/CreationTimestamp",
      "coercion_strategy": null,
      "unit": "hour-of-day",
      "name": "CREATED_AT",
      "field_ref": [
        "field",
        108,
        {
          "temporal-unit": "hour-of-day"
        }
      ],
      "effective_type": "type/Integer",
      "id": 108,
      "display_name": "Created At",
      "fingerprint": {
        "global": {
          "distinct-count": 200,
          "nil%": 0
        },
        "type": {
          "type/DateTime": {
            "earliest": "2016-04-27T01:29:55.147Z",
            "latest": "2019-04-15T19:34:19.931Z"
          }
        }
      },
      "base_type": "type/Integer"
    },
    {
      "name": "count",
      "display_name": "Count",
      "base_type": "type/BigInteger",
      "effective_type": "type/BigInteger",
      "semantic_type": "type/Quantity",
      "field_ref": [
        "aggregation",
        0
      ],
      "fingerprint": {
        "global": {
          "distinct-count": 12,
          "nil%": 0
        },
        "type": {
          "type/Number": {
            "min": 2,
            "q1": 5.656854249492381,
            "q3": 12,
            "max": 15,
            "sd": 3.8410445439236707,
            "avg": 8.333333333333334
          }
        }
      }
    },
    {
      "name": "Avg Price",
      "display_name": "Avg Price",
      "base_type": "type/Float",
      "effective_type": "type/Float",
      "semantic_type": null,
      "field_ref": [
        "aggregation",
        1
      ],
      "fingerprint": {
        "global": {
          "distinct-count": 18,
          "nil%": 0
        },
        "type": {
          "type/Number": {
            "min": 29,
            "q1": 50,
            "q3": 62.5,
            "max": 80,
            "sd": 10.856024174142448,
            "avg": 56.125
          }
        }
      }
    },
    {
      "name": "Avg Rating",
      "display_name": "Avg Rating",
      "base_type": "type/Float",
      "effective_type": "type/Float",
      "semantic_type": "type/Score",
      "field_ref": [
        "aggregation",
        2
      ],
      "fingerprint": {
        "global": {
          "distinct-count": 2,
          "nil%": 0
        },
        "type": {
          "type/Number": {
            "min": 3,
            "q1": 3,
            "q3": 3.901923788646684,
            "max": 4,
            "sd": 0.5036101551853349,
            "avg": 3.4166666666666665
          }
        }
      }
    }
  ],
  "creator": {
    "email": "test@test.test",
    "first_name": "Meta",
    "last_login": "2022-05-03T19:14:49.4",
    "is_qbnewb": false,
    "is_superuser": true,
    "id": 1,
    "last_name": "Base",
    "date_joined": "2019-04-07T23:36:04.697",
    "common_name": "Meta Base"
  },
  "can_write": true,
  "database_id": 4,
  "enable_embedding": false,
  "collection_id": null,
  "query_type": "query",
  "name": "Plain QB - Products, Count, Average of ,Price, and Average of Rating, Grouped by Created At (hour-of-day) - NESTED",
  "last_query_start": "2022-05-05T13:09:24.996417+02:00",
  "dashboard_count": 0,
  "average_query_time": 192,
  "creator_id": 1,
  "moderation_reviews": [],
  "updated_at": "2022-05-05T13:13:24.091",
  "made_public_by_id": null,
  "embedding_params": null,
  "cache_ttl": null,
  "dataset_query": {
    "type": "query",
    "query": {
      "source-table": "card__1114",
      "aggregation": [
        [
          "count"
        ],
        [
          "aggregation-options",
          [
            "round",
            [
              "avg",
              [
                "field",
                "MyPrice",
                {
                  "base-type": "type/Float"
                }
              ]
            ]
          ],
          {
            "name": "Avg Price",
            "display-name": "Avg Price"
          }
        ],
        [
          "aggregation-options",
          [
            "round",
            [
              "avg",
              [
                "field",
                "MyRating",
                {
                  "base-type": "type/Float"
                }
              ]
            ]
          ],
          {
            "name": "Avg Rating",
            "display-name": "Avg Rating"
          }
        ]
      ],
      "breakout": [
        [
          "field",
          108,
          {
            "temporal-unit": "hour-of-day"
          }
        ]
      ]
    },
    "database": 4
  },
  "id": 1113,
  "display": "bar",
  "last-edit-info": {
    "id": 1,
    "email": "test@test.test",
    "first_name": "Meta",
    "last_name": "Base",
    "timestamp": "2022-05-05T13:13:24.099"
  },
  "visualization_settings": {
    "graph.y_axis.title_text": "",
    "graph.show_values": true,
    "graph.x_axis.labels_enabled": true,
    "graph.x_axis.title_text": "Hour of Alert Creation (Eastern)",
    "graph.y_axis.auto_split": false,
    "graph.metrics": [
      "Avg Price",
      "Avg Rating",
      "count"
    ],
    "column_settings": {
      "[\"ref\",[\"field\",108,null]]": {
        "time_enabled": "minutes"
      }
    },
    "series_settings": {
      "avg": {
        "title": "Avg Price"
      },
      "avg_2": {
        "title": "Avg Rating"
      },
      "Avg Price": {
        "color": "#A989C5",
        "axis": "left"
      },
      "Avg Rating": {
        "color": "#F2A86F",
        "axis": "left"
      },
      "count": {
        "axis": "right"
      }
    },
    "graph.dimensions": [
      "CREATED_AT"
    ]
  },
  "collection": null,
  "created_at": "2022-05-05T12:34:56.413",
  "public_uuid": null
}

Hm ok well thanks for looking into it. I'll see about upgrading and follow up if it's still an issue.