Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix lost panic info and other logs #5174

Merged
merged 17 commits into from Aug 5, 2019

Conversation

@Connor1996
Copy link
Member

commented Aug 1, 2019

What have you changed? (mandatory)

Fix lost panic info and other logs due to the filter of slog doesn't include the modules from components.
The modules' name returned from record.module() are like

mod: tikv::binutil
mod: tikv::server::config
mod: tikv::binutil::server
mod: tikv_util::config::check_kernel
mod: tikv_util::config::check_kernel
mod: tikv_util::config::check_data_dir
mod: tikv::pd::util
mod: grpcio::log_util
mod: tikv::pd::util
mod: tikv::binutil::server
mod: tikv_util::worker
mod: tikv::storage::txn::scheduler
mod: tikv::server::node
mod: tikv::raftstore::store::fsm::peer
mod: raft::raft
mod: tikv::raftstore::store::fsm::store
mod: tikv_util::worker
mod: tikv_util::worker::future
mod: tikv::raftstore::store::fsm::store
mod: tikv_util::worker::future
mod: tikv::storage::gc_worker
mod: tikv_util::worker
mod: tikv::server::server
mod: tikv::server::status_server
mod: tikv::raftstore::store::fsm::peer
mod: tikv_util

This PR filters the log based on blacklist. By default, the blacklist is empty. You can set TIKV_DISABLE_LOG_TARGETS=<module_name1>,<module_name2>... to disable the logs.

What are the type of the changes? (mandatory)

  • Bug fix (change which fixes an issue)

How has this PR been tested? (mandatory)

manual-test, panic info can be printed.

Does this PR affect documentation (docs) or release note? (mandatory)

No

Does this PR affect tidb-ansible update? (mandatory)

No

fix lost panic info
Signed-off-by: Connor1996 <zbk602423539@gmail.com>
@sre-bot

This comment has been minimized.

Copy link
Collaborator

commented Aug 1, 2019

Thanks for your PR.
This PR will be closed by bot because you already had 3 opened PRs, close or merge them before submitting a new one.
#3688 , #3777 , #3792

@sre-bot sre-bot added the S: BotClose label Aug 1, 2019

@sre-bot sre-bot closed this Aug 1, 2019

@Connor1996 Connor1996 reopened this Aug 1, 2019

@Connor1996 Connor1996 requested review from BusyJay, overvenus and siddontang Aug 1, 2019

@Connor1996 Connor1996 force-pushed the Connor1996:panic-info branch from d1e6c02 to ba2ea3d Aug 1, 2019

use hashset instead
Signed-off-by: Connor1996 <zbk602423539@gmail.com>

@Connor1996 Connor1996 force-pushed the Connor1996:panic-info branch from ba2ea3d to 4b23b57 Aug 1, 2019

Makefile Outdated Show resolved Hide resolved
src/binutil/setup.rs Outdated Show resolved Hide resolved

Connor1996 added some commits Aug 1, 2019

fix test logger
Signed-off-by: Connor1996 <zbk602423539@gmail.com>
use blacklist instead
Signed-off-by: Connor1996 <zbk602423539@gmail.com>
change comment
Signed-off-by: Connor1996 <zbk602423539@gmail.com>
add comment
Signed-off-by: Connor1996 <zbk602423539@gmail.com>

@Connor1996 Connor1996 force-pushed the Connor1996:panic-info branch from 0d07ad4 to a1e38e2 Aug 1, 2019

@Connor1996

This comment has been minimized.

Copy link
Member Author

commented Aug 1, 2019

PTAL again @breeswish

Connor1996 added some commits Aug 1, 2019

add comment
Signed-off-by: Connor1996 <zbk602423539@gmail.com>
fix env
Signed-off-by: Connor1996 <zbk602423539@gmail.com>

Connor1996 added some commits Aug 2, 2019

address comment
Signed-off-by: Connor1996 <zbk602423539@gmail.com>
make format
Signed-off-by: Connor1996 <zbk602423539@gmail.com>
fix build
Signed-off-by: Connor1996 <zbk602423539@gmail.com>

@Connor1996 Connor1996 force-pushed the Connor1996:panic-info branch from f38d745 to 5088cc9 Aug 2, 2019

@Connor1996

This comment has been minimized.

Copy link
Member Author

commented Aug 2, 2019

PTAL again @breeswish @overvenus

// ```
// Here get the highest level module name to check.
let module = record.module().splitn(2, "::").nth(0).unwrap();
!disabled_targets.contains(module)

This comment has been minimized.

Copy link
@breeswish

breeswish Aug 2, 2019

Member

Maybe we can simply filter by start_with("tokio_core")

This comment has been minimized.

Copy link
@Connor1996

Connor1996 Aug 2, 2019

Author Member

for tikv and tikv_util, using start_with would be wrong.

This comment has been minimized.

Copy link
@breeswish

breeswish Aug 2, 2019

Member

Looks like you can always filter by starts_with() something. For example, if you really want to filter away tikv but not tikv_util, you can write tikv::. Additionally I would like to leave the role of writing :: to the user, instead of hardcoded, so that filtering away tokio* can be easily achieved.

This comment has been minimized.

Copy link
@Connor1996

Connor1996 Aug 2, 2019

Author Member

The returned value of record.module() maybe tikv without ::, so tikv:: is also wrong.

This comment has been minimized.

Copy link
@breeswish

breeswish Aug 3, 2019

Member

So when will you have a record.module() to be tikv and when you want to filter away logs from tikv? If this is not a scenario that is going to be happen, then I think it don't need to be considered.

This comment has been minimized.

Copy link
@Connor1996

Connor1996 Aug 3, 2019

Author Member

tikv is just an example, maybe other modules.

address comment
Signed-off-by: Connor1996 <zbk602423539@gmail.com>
components/tikv_util/src/logger/mod.rs Outdated Show resolved Hide resolved
.any(|target| record.module().starts_with(target))
});
// Default disabled log targets for test.
let disabled_targets = vec!["tokio_core".to_owned(), "tokio_reactor".to_owned()];

This comment has been minimized.

Copy link
@breeswish

breeswish Aug 3, 2019

Member

we may need to disable these targets by default, no matter in test or in production.

This comment has been minimized.

Copy link
@Connor1996

Connor1996 Aug 3, 2019

Author Member

there are only debug logs for these mods, seems it's okay for production?

This comment has been minimized.

Copy link
@breeswish

breeswish Aug 5, 2019

Member

I think it's still better to disable them by default, because sometimes we will need debug level logs in production to trace some problems and then these modules will mess up our logs.

This comment has been minimized.

Copy link
@breeswish

breeswish Aug 5, 2019

Member

BTW a kindly reminder: if we add these default disabled targets, then the empty check shall be removed.

This comment has been minimized.

Copy link
@Connor1996

Connor1996 Aug 5, 2019

Author Member

If that you can set env variable. And I want to avoid string comparing in production for performance issue.

This comment has been minimized.

Copy link
@breeswish

breeswish Aug 5, 2019

Member

Ok this is a good reason for not enabling them by default. However our DBAs may not be happy with this XD. I will give my approval after testing this PR personally.

This comment has been minimized.

Copy link
@Connor1996

Connor1996 Aug 5, 2019

Author Member

thx!

components/tikv_util/src/logger/mod.rs Outdated Show resolved Hide resolved
fix empty
Signed-off-by: Connor1996 <zbk602423539@gmail.com>

@Connor1996 Connor1996 force-pushed the Connor1996:panic-info branch from 26bf6f1 to 79f8b7b Aug 3, 2019

@breeswish

This comment has been minimized.

Copy link
Member

commented Aug 5, 2019

Looks like you should flip the return value:

$ TIKV_DISABLE_LOG_TARGETS=tokio_core ./2_start_tikv.sh 
[2019/08/05 10:47:58.096 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:315] ["consuming notification queue"]
[2019/08/05 10:47:58.096 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:305] ["loop poll - 43.925µs"]
[2019/08/05 10:47:58.096 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:306] ["loop time - Instant { t: 32231777459426 }"]
[2019/08/05 10:47:58.097 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:308] ["loop process, 16.479µs"]
[2019/08/05 10:47:58.097 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:315] ["consuming notification queue"]
[2019/08/05 10:47:58.097 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:305] ["loop poll - 33.249µs"]
[2019/08/05 10:47:58.097 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:306] ["loop time - Instant { t: 32231777862460 }"]
[2019/08/05 10:47:58.097 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:308] ["loop process, 14.712µs"]
[2019/08/05 10:47:58.097 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:315] ["consuming notification queue"]
[2019/08/05 10:47:58.098 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:305] ["loop poll - 32.889µs"]
[2019/08/05 10:47:58.098 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:306] ["loop time - Instant { t: 32231778077439 }"]
[2019/08/05 10:47:58.098 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:308] ["loop process, 16.039µs"]
[2019/08/05 10:48:00.097 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:305] ["loop poll - 2.001235285s"]
[2019/08/05 10:48:00.098 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:306] ["loop time - Instant { t: 32233778722413 }"]
[2019/08/05 10:48:00.098 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:308] ["loop process, 33.571µs"]
[2019/08/05 10:48:00.098 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:305] ["loop poll - 435.067µs"]
[2019/08/05 10:48:00.099 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:306] ["loop time - Instant { t: 32233779768045 }"]
[2019/08/05 10:48:00.099 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:308] ["loop process, 22.534µs"]
[2019/08/05 10:48:00.099 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:305] ["loop poll - 26.03µs"]
[2019/08/05 10:48:00.099 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:306] ["loop time - Instant { t: 32233779831792 }"]
[2019/08/05 10:48:00.099 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:308] ["loop process, 20.118µs"]
[2019/08/05 10:48:03.095 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:305] ["loop poll - 2.996900365s"]
[2019/08/05 10:48:03.096 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:306] ["loop time - Instant { t: 32236776767114 }"]
[2019/08/05 10:48:03.096 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:308] ["loop process, 33.743µs"]
[2019/08/05 10:48:03.096 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:305] ["loop poll - 124.603µs"]
[2019/08/05 10:48:03.096 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:306] ["loop time - Instant { t: 32236777254594 }"]
[2019/08/05 10:48:03.096 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:308] ["loop process, 17.565µs"]
[2019/08/05 10:48:03.097 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:305] ["loop poll - 175.665µs"]
[2019/08/05 10:48:03.097 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:306] ["loop time - Instant { t: 32236777459660 }"]
[2019/08/05 10:48:03.097 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:308] ["loop process, 22.997µs"]
[2019/08/05 10:48:03.097 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:305] ["loop poll - 28.175µs"]
[2019/08/05 10:48:03.097 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:306] ["loop time - Instant { t: 32236777526876 }"]
[2019/08/05 10:48:03.097 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:308] ["loop process, 22.518µs"]
[2019/08/05 10:48:08.096 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:305] ["loop poll - 5.000147203s"]
[2019/08/05 10:48:08.097 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:306] ["loop time - Instant { t: 32241777712184 }"]
[2019/08/05 10:48:08.097 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:308] ["loop process, 29.86µs"]
[2019/08/05 10:48:08.097 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:305] ["loop poll - 104.322µs"]
[2019/08/05 10:48:08.097 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:306] ["loop time - Instant { t: 32241778015497 }"]
[2019/08/05 10:48:08.097 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:308] ["loop process, 17.989µs"]
[2019/08/05 10:48:08.097 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:305] ["loop poll - 160.247µs"]
[2019/08/05 10:48:08.097 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:306] ["loop time - Instant { t: 32241778206378 }"]
[2019/08/05 10:48:08.098 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:308] ["loop process, 18.619µs"]
[2019/08/05 10:48:08.098 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:305] ["loop poll - 21.57µs"]
[2019/08/05 10:48:08.098 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:306] ["loop time - Instant { t: 32241778259263 }"]
[2019/08/05 10:48:08.098 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:308] ["loop process, 16.214µs"]
[2019/08/05 10:48:08.105 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:305] ["loop poll - 7.64361ms"]
[2019/08/05 10:48:08.105 +08:00] [DEBUG] [tokio_core::reactor] [mod.rs:306] ["loop time - Instant { t: 32241785930160 }"]
fix disable targets
Signed-off-by: Connor1996 <zbk602423539@gmail.com>
@breeswish

This comment has been minimized.

Copy link
Member

commented Aug 5, 2019

/run-all-tests

@Connor1996

This comment has been minimized.

Copy link
Member Author

commented Aug 5, 2019

@breeswish Thanks for your test. How careless I am!🤣

@sre-bot

This comment has been minimized.

Copy link
Collaborator

commented Aug 5, 2019

/run-all-tests

@sre-bot sre-bot merged commit 3f3a32d into tikv:master Aug 5, 2019

5 checks passed

DCO All commits are signed off!
Details
idc-jenkins-ci-tikv/integration-common-test Jenkins job succeeded.
Details
idc-jenkins-ci-tikv/integration-compatibility-test Jenkins job succeeded.
Details
idc-jenkins-ci-tikv/integration-ddl-test Jenkins job succeeded.
Details
idc-jenkins-ci/test Jenkins job succeeded.
Details
@sre-bot

This comment has been minimized.

Copy link
Collaborator

commented Aug 5, 2019

cherry pick to release-3.0 in PR #5198

Connor1996 added a commit that referenced this pull request Aug 5, 2019

Fix lost panic info and other logs (#5174) (#5198)
* fix lost panic info

Signed-off-by: Connor1996 <zbk602423539@gmail.com>

fredchenbj added a commit to fredchenbj/tikv that referenced this pull request Aug 5, 2019

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
4 participants
You can’t perform that action at this time.