Do not print `write to tunnel which is already closed` log if query is canceled expectedly before
Nobody has claimed this yet.
- 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
- Read the whole issue, then the project's contributing guide.
- Comment on the issue to say you are picking it up — it saves two people doing the same work.
- Fork the repository and make your change on a branch.
- 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