Skip to content

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

@XuHuaiyu

Description

@XuHuaiyu

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]

Metadata

Metadata

Assignees

No one assigned

    Labels

    type/enhancementThe issue or PR belongs to an enhancement.

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions