[C++] grpc logging levels

[Arpit Baldeva]

Hi,

Tested on 1.4.2.

Currently, grpc has 3 logging levels. 

  GPR_LOG_SEVERITY_DEBUG,

  GPR_LOG_SEVERITY_INFO,

  GPR_LOG_SEVERITY_ERROR

IMHO, currently GPR_LOG_SEVERITY_INFO logs too much and is unsuitable for use in prod scenario. INFO to me means that something interesting happened which is not an error but an important event to be noticed. So for example, if a client logs in, login/logout may be INFO log but if the client executes 5 rpcs, rpc handling generates DEBUG logs and not INFO log.

Currently, for a single rpc call , it spews 20 lines when nothing out of ordinary happened.  

2017/10/04-15:42:54.247 INFO   RETURN_EVENT[000001DCD6DBA130]: OP_COMPLETE: tag:000001E6B6B60870 OK

2017/10/04-15:42:54.247 INFO   grpc_call_start_batch(call=000001DCD713FBE8, ops=0000003515AFF510, nops=1, tag=000001E6B6B45180, reserved=0000000000000000)

2017/10/04-15:42:54.247 INFO   ops[0]: RECV_CLOSE_ON_SERVER cancelled=000001E6B6B451F0

2017/10/04-15:42:54.247 INFO   grpc_completion_queue_next(cc=000001DCD6DBA130, deadline=gpr_timespec { tv_sec: 9223372036854775807, tv_nsec: 0, clock_type: 1 }, reserved=0000000000000000)

2017/10/04-15:42:54.247 INFO   grpc_server_request_registered_call(server=000001DCD6CE1AA0, rmp=000001DCD7064460, call=000001E6B6B60A28, deadline=000001DDBA92F558, initial_metadata=000001DDBA92F590, optional_payload=000001E6B6B60A30, cq_bound_to_call=000001DCD6DBA130, cq_for_notification=000001DCD6DBA130, tag=000001E6B6B609F0)

2017/10/04-15:42:54.247 INFO   grpc_call_get_peer(000001DCD713FBE8)

2017/10/04-15:42:54.247 INFO   grpc_call_get_peer(000001DCD713FBE8)

2017/10/04-15:42:54.263 INFO   grpc_call_start_batch(call=000001DCD713FBE8, ops=000000351C4FE5E0, nops=3, tag=000001DDB9ADCCC8, reserved=0000000000000000)

2017/10/04-15:42:54.263 INFO   ops[0]: SEND_INITIAL_METADATA(nil)

2017/10/04-15:42:54.263 INFO   ops[1]: SEND_MESSAGE ptr=000001DCD6C06700

2017/10/04-15:42:54.263 INFO   ops[2]: SEND_STATUS_FROM_SERVER status=0 details=(null)(nil)

2017/10/04-15:42:54.263 INFO   cq_end_op_for_next(exec_ctx=000000351C4FE528, cc=000001DCD6DBA130, tag=000001DDB9ADCCC8, error="No Error", done=00007FF6349AFA90, done_arg=000001DCD71413E8, storage=000001DCD71413F0)

2017/10/04-15:42:54.263 INFO   cq_end_op_for_next(exec_ctx=000000351C4FE528, cc=000001DCD6DBA130, tag=000001E6B6B45180, error="No Error", done=00007FF6349AFA90, done_arg=000001DCD7141308, storage=000001DCD7141310)

2017/10/04-15:42:54.263 INFO   RETURN_EVENT[000001DCD6DBA130]: OP_COMPLETE: tag:000001DDB9ADCCC8 OK

2017/10/04-15:42:54.263 INFO   grpc_completion_queue_next(cc=000001DCD6DBA130, deadline=gpr_timespec { tv_sec: 9223372036854775807, tv_nsec: 0, clock_type: 1 }, reserved=0000000000000000)

2017/10/04-15:42:54.263 INFO   RETURN_EVENT[000001DCD6DBA130]: OP_COMPLETE: tag:000001E6B6B45180 OK

2017/10/04-15:42:54.263 INFO   grpc_completion_queue_next(cc=000001DCD6DBA130, deadline=gpr_timespec { tv_sec: 9223372036854775807, tv_nsec: 0, clock_type: 1 }, reserved=0000000000000000)

2017/10/04-15:42:54.264 INFO   grpc_call_unref(c=000001DCD713FBE8)

2017/10/04-15:42:54.264 INFO   grpc_metadata_array_destroy(array=000001DCD71403D8)

2017/10/04-15:42:54.264 INFO   grpc_metadata_array_destroy(array=000001DDB9ADCB40)

Does this seem like reasonable for INFO log level? 

How about increasing the granularity of log levels? For example, SPAM, TRACE, INFO, WARN, ERROR so that different logs are handled appropriately? 

Thanks. 

[Vijay Pai]

The amount of logging you're describing suggests that you have GRPC_TRACE=api environment variable set; is that correct? I don't think that the combination of api tracing and INFO level logging is intended for production use. If you don't have the GRPC_TRACE environment variable set, that much won't come out on INFO.

- Vijay

--
You received this message because you are subscribed to the Google Groups "grpc.io" group.
To unsubscribe from this group and stop receiving emails from it, send an email to grpc-io+u...@googlegroups.com.
To post to this group, send email to grp...@googlegroups.com.
Visit this group at https://groups.google.com/group/grpc-io.
To view this discussion on the web visit https://groups.google.com/d/msgid/grpc-io/3475a2c9-c3fd-4321-84a7-a04df7707970%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Arpit Baldeva]

Yes, I do turn on the trace for api (and some other categories) and set the verbosity level to INFO. 

I thought of the various GRPC_TRACE variables as simply the categories I can enable for logging. Are you suggesting if I don't turn anything on, I'll still get INFO/ERR logging at a much reduced level or you mean that "api" category itself is too verbose for production usage?

What would be a typical logging configuration for prod in your opinion?

Thanks.  

[Vijay Pai]

I don't think that any value of GRPC_TRACE is valid for production; those are all way too spammy since their whole purpose is to allow detailed inspection. They are really meant for tracing individual steps in the operation of gRPC for development and debugging purposes.

As for logs, our default value is ERROR but I think that INFO or ERROR would be ok. DEBUG might be too spammy, though most uses of DEBUG are gated behind other tracers anyway.

[Arpit Baldeva]

Thanks for the info!