refine error message in mpptask (#5304)

ref #5095
pingcap · Jul 7, 2022 · 3e8df4b · 3e8df4b
1 parent 0aec04a
commit 3e8df4b
Show file tree

Hide file tree

Showing 8 changed files with 28 additions and 58 deletions.
diff --git a/dbms/src/Flash/EstablishCall.cpp b/dbms/src/Flash/EstablishCall.cpp
@@ -143,7 +143,7 @@ void EstablishCallData::finishTunnelAndResponder()
     state = FINISH;
     if (mpp_tunnel)
     {
-        mpp_tunnel->consumerFinish("grpc writes failed.", true); //trigger mpp tunnel finish work
+        mpp_tunnel->consumerFinish(fmt::format("{}: finishTunnelAndResponder called.", mpp_tunnel->id()), true); //trigger mpp tunnel finish work
     }
     grpc::Status status(static_cast<grpc::StatusCode>(GRPC_STATUS_UNKNOWN), "Consumer exits unexpected, grpc writes failed.");
     responder.Finish(status, this);

diff --git a/dbms/src/Flash/Mpp/MPPTask.cpp b/dbms/src/Flash/Mpp/MPPTask.cpp
@@ -379,7 +379,7 @@ void MPPTask::runImpl()
     }
     catch (...)
     {
-        err_msg = getCurrentExceptionMessage(true);
+        err_msg = getCurrentExceptionMessage(true, true);
     }
 
     if (err_msg.empty())
@@ -405,6 +405,8 @@ void MPPTask::runImpl()
         if (status == RUNNING)
         {
             LOG_FMT_ERROR(log, "task running meets error: {}", err_msg);
+            /// trim the stack trace to avoid too many useless information in log
+            trimStackTrace(err_msg);
             try
             {
                 handleError(err_msg);

diff --git a/dbms/src/Flash/Mpp/MPPTunnel.cpp b/dbms/src/Flash/Mpp/MPPTunnel.cpp
@@ -220,7 +220,11 @@ void MPPTunnelBase<Writer>::sendJob(bool need_lock)
         err_msg = "fatal error in sendJob()";
     }
     if (!err_msg.empty())
+    {
+        /// append tunnel id to error message
+        err_msg = fmt::format("{} meet error: {}", tunnel_id, err_msg);
         LOG_ERROR(log, err_msg);
+    }
     consumerFinish(err_msg, need_lock);
     if (is_async)
         writer->writeDone(grpc::Status::OK);

diff --git a/dbms/src/Flash/Mpp/Utils.cpp b/dbms/src/Flash/Mpp/Utils.cpp
@@ -13,6 +13,7 @@
 // limitations under the License.
 
 #include <Flash/Mpp/Utils.h>
+#include <Poco/String.h>
 
 #include <memory>
 
@@ -27,4 +28,14 @@ mpp::MPPDataPacket getPacketWithError(String reason)
     return data;
 }
 
+void trimStackTrace(String & message)
+{
+    auto stack_trace_pos = message.find("Stack trace");
+    if (stack_trace_pos != String::npos)
+    {
+        message.resize(stack_trace_pos);
+        Poco::trimRightInPlace(message);
+    }
+}
+
 } // namespace DB
diff --git a/dbms/src/Flash/Mpp/Utils.h b/dbms/src/Flash/Mpp/Utils.h
@@ -23,5 +23,6 @@
 namespace DB
 {
 mpp::MPPDataPacket getPacketWithError(String reason);
+void trimStackTrace(String & message);
 
 } // namespace DB
diff --git a/dbms/src/Flash/Mpp/tests/gtest_mpptunnel.cpp b/dbms/src/Flash/Mpp/tests/gtest_mpptunnel.cpp
@@ -382,7 +382,7 @@ TEST_F(TestMPPTunnelBase, WriteError)
     }
     catch (Exception & e)
     {
-        GTEST_ASSERT_EQ(e.message(), "Consumer exits unexpected, grpc writes failed.");
+        GTEST_ASSERT_EQ(e.message(), "Consumer exits unexpected, 0000_0001 meet error: grpc writes failed.");
     }
 }
 
@@ -631,7 +631,7 @@ TEST_F(TestMPPTunnelBase, AsyncWriteError)
     }
     catch (Exception & e)
     {
-        GTEST_ASSERT_EQ(e.message(), "Consumer exits unexpected, grpc writes failed.");
+        GTEST_ASSERT_EQ(e.message(), "Consumer exits unexpected, 0000_0001 meet error: grpc writes failed.");
     }
 }
 

diff --git a/tests/fullstack-test/mpp/issue_2471.test b/tests/fullstack-test/mpp/issue_2471.test
@@ -35,15 +35,7 @@ mysql> use test; set @@tidb_isolation_read_engines='tiflash'; set @@tidb_opt_bro
 => DBGInvoke __enable_fail_point(exception_in_creating_set_input_stream)
 
 mysql> use test; set @@tidb_isolation_read_engines='tiflash'; set @@tidb_opt_broadcast_cartesian_join=2; select * from a as t1 left join a as t2 on t1.id = t2.id;
-ERROR 1105 (HY000) at line 1: other error for mpp stream: Code: 10007, e.displayText() = DB::Exception: Fail point FailPoints::exception_in_creating_set_input_stream is triggered., e.what() = DB::Exception, Stack trace:
-{#LINE}
-{#LINE}
-{#LINE}
-{#LINE}
-{#LINE}
-{#LINE}
-{#LINE}
-{#LINE}
+ERROR 1105 (HY000) at line 1: other error for mpp stream: Code: 10007, e.displayText() = DB::Exception: Fail point FailPoints::exception_in_creating_set_input_stream is triggered., e.what() = DB::Exception,
 
 => DBGInvoke __disable_fail_point(exception_in_creating_set_input_stream)
 

diff --git a/tests/fullstack-test/mpp/mpp_fail.test b/tests/fullstack-test/mpp/mpp_fail.test
@@ -71,59 +71,28 @@ ERROR 1105 (HY000) at line 1: DB::Exception: Fail point FailPoints::exception_be
 ## exception during mpp run non root task
 => DBGInvoke __enable_fail_point(exception_during_mpp_non_root_task_run)
 mysql> use test; set @@tidb_isolation_read_engines='tiflash'; set @@tidb_allow_mpp=1; select count(value), id from t group by id;
-ERROR 1105 (HY000) at line 1: other error for mpp stream: Code: 0, e.displayText() = DB::Exception: Exchange receiver meet error : Code: 10007, e.displayText() = DB::Exception: Fail point FailPoints::exception_during_mpp_non_root_task_run is triggered., e.what() = DB::Exception, Stack trace:
-{#LINE}
-{#LINE}
-{#LINE}
-{#LINE}
-{#LINE}
-{#LINE}
-{#LINE}
+ERROR 1105 (HY000) at line 1: other error for mpp stream: Code: 0, e.displayText() = DB::Exception: Exchange receiver meet error : Code: 10007, e.displayText() = DB::Exception: Fail point FailPoints::exception_during_mpp_non_root_task_run is triggered., e.what() = DB::Exception,, e.what() = DB::Exception,
 => DBGInvoke __disable_fail_point(exception_during_mpp_non_root_task_run)
 
 ## exception during mpp run root task
 => DBGInvoke __enable_fail_point(exception_during_mpp_root_task_run)
 mysql> use test; set @@tidb_isolation_read_engines='tiflash'; set @@tidb_allow_mpp=1; select count(value), id from t group by id;
-ERROR 1105 (HY000) at line 1: other error for mpp stream: Code: 10007, e.displayText() = DB::Exception: Fail point FailPoints::exception_during_mpp_root_task_run is triggered., e.what() = DB::Exception, Stack trace:
-{#LINE}
-{#LINE}
-{#LINE}
-{#LINE}
-{#LINE}
-{#LINE}
-{#LINE}
-{#LINE}
+ERROR 1105 (HY000) at line 1: other error for mpp stream: Code: 10007, e.displayText() = DB::Exception: Fail point FailPoints::exception_during_mpp_root_task_run is triggered., e.what() = DB::Exception,
 => DBGInvoke __disable_fail_point(exception_during_mpp_root_task_run)
 
 ## exception during mpp write err to tunnel
 => DBGInvoke __enable_fail_point(exception_during_mpp_non_root_task_run)
 => DBGInvoke __enable_fail_point(exception_during_mpp_write_err_to_tunnel)
 mysql> use test; set @@tidb_isolation_read_engines='tiflash'; set @@tidb_allow_mpp=1; select count(value), id from t group by id;
-ERROR 1105 (HY000) at line 1: other error for mpp stream: Code: 0, e.displayText() = DB::Exception: Exchange receiver meet error : Failed to write error msg to tunnel, e.what() = DB::Exception, Stack trace:
-{#LINE}
-{#LINE}
-{#LINE}
-{#LINE}
-{#LINE}
-{#LINE}
-{#LINE}
-{#LINE}
-{#LINE}
+ERROR 1105 (HY000) at line 1: other error for mpp stream: Code: 0, e.displayText() = DB::Exception: Exchange receiver meet error : Failed to write error msg to tunnel, e.what() = DB::Exception,
 => DBGInvoke __disable_fail_point(exception_during_mpp_non_root_task_run)
 => DBGInvoke __disable_fail_point(exception_during_mpp_write_err_to_tunnel)
 
 ## exception during mpp write close tunnel
 => DBGInvoke __enable_fail_point(exception_during_mpp_non_root_task_run)
 => DBGInvoke __enable_fail_point(exception_during_mpp_close_tunnel)
 mysql> use test; set @@tidb_isolation_read_engines='tiflash'; set @@tidb_allow_mpp=1; select count(value), id from t group by id;
-ERROR 1105 (HY000) at line 1: other error for mpp stream: Code: 0, e.displayText() = DB::Exception: Exchange receiver meet error : Code: 10007, e.displayText() = DB::Exception: Fail point FailPoints::exception_during_mpp_non_root_task_run is triggered., e.what() = DB::Exception, Stack trace:
-{#LINE}
-{#LINE}
-{#LINE}
-{#LINE}
-{#LINE}
-{#LINE}
-{#LINE}
+ERROR 1105 (HY000) at line 1: other error for mpp stream: Code: 0, e.displayText() = DB::Exception: Exchange receiver meet error : Code: 10007, e.displayText() = DB::Exception: Fail point FailPoints::exception_during_mpp_non_root_task_run is triggered., e.what() = DB::Exception,, e.what() = DB::Exception,
 => DBGInvoke __disable_fail_point(exception_during_mpp_non_root_task_run)
 => DBGInvoke __disable_fail_point(exception_during_mpp_close_tunnel)
 
@@ -156,16 +125,7 @@ ERROR 1105 (HY000) at line 1: other error for mpp stream: Code: 0, e.displayText
 ## ensure build1, build2-probe1, probe2 in the CreatingSets, test the bug where build1 throw exception but not change the build state, thus block the build2-probe1, at last this query hangs.
 => DBGInvoke __enable_fail_point(exception_mpp_hash_build)
 mysql> use test; set @@tidb_isolation_read_engines='tiflash'; set @@tidb_allow_mpp=1; set @@tidb_broadcast_join_threshold_count=0; set @@tidb_broadcast_join_threshold_size=0; select t1.id from test.t t1 join test.t t2 on t1.id = t2.id and t1.id <2 join (select id from test.t group by id) t3 on t2.id=t3.id;
-ERROR 1105 (HY000) at line 1: other error for mpp stream: Code: 10007, e.displayText() = DB::Exception: Fail point FailPoints::exception_mpp_hash_build is triggered., e.what() = DB::Exception, Stack trace:
-{#LINE}
-{#LINE}
-{#LINE}
-{#LINE}
-{#LINE}
-{#LINE}
-{#LINE}
-{#LINE}
-{#LINE}
+ERROR 1105 (HY000) at line 1: other error for mpp stream: Code: 10007, e.displayText() = DB::Exception: Fail point FailPoints::exception_mpp_hash_build is triggered., e.what() = DB::Exception,
 => DBGInvoke __disable_fail_point(exception_mpp_hash_build)
 
 # Clean up.