pingcap / pingcap/tiflash

Do not print `write to tunnel which is already closed` log if query is canceled expectedly before

Open
#4,208 0 comments 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

type/enhancement
Dominant language
C++
Stars
1k
Forks
423
Avg merge
1d 15h
Merged PRs (30d)
24

Description

Enhancement

We can see from the log that the query is canceled, and all tunnels are closed.
If MPPTask.runImpl tries to write to the tunnel later, an exception write to tunnel which is already closed will be thrown.
The error logs will be printed in this case, which will make the users confused. The exception is actually expected.
Thus we should avoid print the error log for this case.

102869:[2022/03/08 20:08:42.330 +08:00] [WARN] [<unknown>] ["TaskManager:Begin cancel query: 431683357167058946"] [thread_id=512]
102870:[2022/03/08 20:08:42.330 +08:00] [WARN] [<unknown>] ["TaskManager:Remaining task in query 431683357167058946 are: <query:431683357167058946,task:3> "] [thread_id=512]
102871:[2022/03/08 20:08:42.330 +08:00] [WARN] [MPPTask.cpp:396] ["MPPTask:<query:431683357167058946,task:3> Begin cancel task: <query:431683357167058946,task:3>"] [thread_id=27115]
102872:[2022/03/08 20:08:42.330 +08:00] [ERROR] [<unknown>] ["MPPTask:<query:431683357167058946,task:3> tunnel3+-1 grpc writes failed."] [thread_id=450]
102873:[2022/03/08 20:08:42.331 +08:00] [WARN] [<unknown>] ["MPPTask:<query:431683357167058946,task:3> Finish cancel task from running"] [thread_id=27115]
102874:[2022/03/08 20:08:42.331 +08:00] [WARN] [<unknown>] ["TaskManager:Finish cancel query: 431683357167058946"] [thread_id=512]
102875-[2022/03/08 20:08:42.335 +08:00] [WARN] [CoprocessorHandler.cpp:112] ["CoprocessorHandler:grpc::Status DB::CoprocessorHandler::execute(): LockException: region 705, message: "] [thread_id=344]
102876-[2022/03/08 20:08:42.335 +08:00] [WARN] [CoprocessorHandler.cpp:112] ["CoprocessorHandler:grpc::Status DB::CoprocessorHandler::execute(): LockException: region 2153, message: "] [thread_id=308]
102877-[2022/03/08 20:08:42.335 +08:00] [WARN] [CoprocessorHandler.cpp:112] ["CoprocessorHandler:grpc::Status DB::CoprocessorHandler::execute(): LockException: region 698, message: "] [thread_id=294]
102878-[2022/03/08 20:08:42.335 +08:00] [WARN] [CoprocessorHandler.cpp:112] ["CoprocessorHandler:grpc::Status DB::CoprocessorHandler::execute(): LockException: region 565, message: "] [thread_id=337]
102879:[2022/03/08 20:08:42.387 +08:00] [ERROR] [MPPTask.cpp:332] ["MPPTask:<query:431683357167058946,task:3> task running meets error: DB::Exception: write to tunnel which is already closed,grpc writes failed. Stack Trace : 0. /tiflash/tiflash(StackTrace::StackTrace()+0x13) [0x4d34443]
102880-1. /tiflash/tiflash(DB::Exception::Exception(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, int)+0x26) [0x4d31a46]
102881-2. /tiflash/tiflash(DB::MPPTunnelBase<grpc_impl::ServerWriter<mpp::MPPDataPacket> >::write(mpp::MPPDataPacket const&, bool)+0x56f) [0xa8912bf]
102882-3. /tiflash/tiflash(DB::MPPTunnelSetBase<DB::MPPTunnel>::write(tipb::SelectResponse&)+0x34) [0xa893a54]
102883-4. /tiflash/tiflash(void DB::StreamingDAGResponseWriter<std::__1::shared_ptr<DB::MPPTunnelSet> >::batchWrite<true>()+0x77) [0xa854ff7]
102884-5. /tiflash/tiflash(DB::UnionBlockInputStream<(DB::StreamUnionMode)0, true>::readSuffix()+0x4a) [0xa84eeda]
102885-6. /tiflash/tiflash(DB::MPPTask::runImpl()+0x986) [0xa87ee16]
102886-7. /tiflash/tiflash(std::__1::__packaged_task_func<auto DB::wrapInvocable<std::__1::function<void ()>&>(bool, std::__1::function<void ()>&)::'lambda'(), std::__1::allocator<auto DB::wrapInvocable<std::__1::function<void ()>&>(bool, std::__1::function<void ()>&)::'lambda'()>, void ()>::operator()()+0x6e) [0x4dfe16e]
102887-8. /tiflash/tiflash(std::__1::packaged_task<void ()>::operator()()+0x45) [0x4dfe2d5]
102888-9. /tiflash/tiflash(DB::executeTask(std::__1::unique_ptr<DB::IExecutableTask, std::__1::default_delete<DB::IExecutableTask> > const&)+0x78) [0x4d92128]
102889-10. /tiflash/tiflash(DB::DynamicThreadPool::fixedWork(unsigned long)+0xb5) [0x4d91ae5]
102890-11. /tiflash/tiflash(auto std::__1::thread DB::ThreadFactory::newThread<void (DB::DynamicThreadPool::*)(unsigned long), DB::DynamicThreadPool*, unsigned long&>(bool, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, void (DB::DynamicThreadPool::*&&)(unsigned long), DB::DynamicThreadPool*&&, unsigned long&)::'lambda'(auto&&...)::operator()<DB::DynamicThreadPool*, unsigned long>(auto&&...) const+0x121) [0x4d93151]
102891-12. /tiflash/tiflash() [0x4d92f79]
102892-13. /lib64/libpthread.so.0(+0x7ea5) [0x7f3ab86c8ea5]
102893-14. /lib64/libc.so.6(clone+0x6d) [0x7f3ab81db96d]
102894-"] [thread_id=135]
102895-[2022/03/08 20:08:42.422 +08:00] [ERROR] [Exception.cpp:64] ["MPPTask:Failed to write error DB::Exception: write to tunnel which is already closed,grpc writes failed. to tunnel: tunnel3+-1: Code: 0, e.displayText() = DB::Exception: write to tunnel which is already closed,grpc writes failed., e.what() = DB::Exception, Stack trace:
102896-
102897-0. /tiflash/tiflash(StackTrace::StackTrace()+0x13) [0x4d34443]
102898-1. /tiflash/tiflash(DB::Exception::Exception(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, int)+0x26) [0x4d31a46]
102899-2. /tiflash/tiflash(DB::MPPTunnelBase<grpc_impl::ServerWriter<mpp::MPPDataPacket> >::write(mpp::MPPDataPacket const&, bool)+0x56f) [0xa8912bf]
102900-3. /tiflash/tiflash(DB::MPPTask::writeErrToAllTunnels(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&)+0x76) [0xa8801e6]
102901-4. /tiflash/tiflash(DB::MPPTask::runImpl()+0xb49) [0xa87efd9]
102902-5. /tiflash/tiflash(std::__1::__packaged_task_func<auto DB::wrapInvocable<std::__1::function<void ()>&>(bool, std::__1::function<void ()>&)::'lambda'(), std::__1::allocator<auto DB::wrapInvocable<std::__1::function<void ()>&>(bool, std::__1::function<void ()>&)::'lambda'()>, void ()>::operator()()+0x6e) [0x4dfe16e]
102903-6. /tiflash/tiflash(std::__1::packaged_task<void ()>::operator()()+0x45) [0x4dfe2d5]
102904-7. /tiflash/tiflash(DB::executeTask(std::__1::unique_ptr<DB::IExecutableTask, std::__1::default_delete<DB::IExecutableTask> > const&)+0x78) [0x4d92128]
102905-8. /tiflash/tiflash(DB::DynamicThreadPool::fixedWork(unsigned long)+0xb5) [0x4d91ae5]
102906-9. /tiflash/tiflash(auto std::__1::thread DB::ThreadFactory::newThread<void (DB::DynamicThreadPool::*)(unsigned long), DB::DynamicThreadPool*, unsigned long&>(bool, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, void (DB::DynamicThreadPool::*&&)(unsigned long), DB::DynamicThreadPool*&&, unsigned long&)::'lambda'(auto&&...)::operator()<DB::DynamicThreadPool*, unsigned long>(auto&&...) const+0x121) [0x4d93151]
102907-10. /tiflash/tiflash() [0x4d92f79]
102908-11. /lib64/libpthread.so.0(+0x7ea5) [0x7f3ab86c8ea5]
102909-12. /lib64/libc.so.6(clone+0x6d) [0x7f3ab81db96d]
102910-"] [thread_id=135]
102911:[2022/03/08 20:08:42.422 +08:00] [ERROR] [<unknown>] ["TaskManager:The task <query:431683357167058946,task:3> cannot be found and fail to unregister"] [thread_id=135]
102912:[2022/03/08 20:08:42.422 +08:00] [WARN] [<unknown>] ["MPPTask:<query:431683357167058946,task:3> finish task which was cancelled before"] [thread_id=135]

Contributor guide

No contributing guide indexed for this repository

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start in MPPTask.cpp around the reported runImpl and cancellation paths, including the error at line 332 and cancellation handling near line 396. Trace writeErrToAllTunnels and the tunnel write failure after cancellation, using the supplied log sequence as the behavior reference. Done means an expected write after query cancellation no longer emits an error log.

Written by the indexing model from the issue text.

Assessment

Tech stack
cpp
Domain
distributed-systems
Issue type
Bug
Difficulty
3/5
Estimated time
1-2 days
Activity status
Stale
Clarity
Mostly clear
Newbie friendliness
45/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.