CC ignores log_level for DB log

[poligraph]

I am trying to reduce logs from CF and I have found that CC ignores settings for DB operations

I use CF V230

-1. go to api machine
-2. open /var/vcap/jobs/cloud_controller_ng/config/cloud_controller_ng.yml and change loglevel

db: &db
  database: postgres://ccadmin:password@192.168.111.16:5524/ccdb
  max_connections: 25
  pool_timeout: 10
  log_level: fatal

-3. check logfile /var/vcap/sys/log/cloud_controller_ng/cloud_controller_ng.log
There is a lot of messages with log level fatal
Even if I change to error or info nothing happened and I still can see a lot of messages like this:

{"timestamp":1460121236.5210814,"message":"(0.000533s) SELECT * FROM "delayed_jobs" WHERE (((("run_at" <= '2016-04-08 13:13:56.519899+0000') AND ("locked_at" IS NULL)) OR ("locked_by" = 'cc_api_worker.api_z2.0.1')) AND ("failed_at" IS NULL) AND ("queue" IN ('cc-api_z2-0'))) ORDER BY "priority" ASC, "run_at" ASC LIMIT 5","log_level":"fatal","source":"cc.background","data":{},"thread_id":47458667846040,"fiber_id":47458708540280,"process_id":24480,"file":"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sequel-4.29.0/lib/sequel/database/logging.rb","lineno":70,"method":"block in log_each"}

{"timestamp":1460120984.43897,"message":"(0.000553s) SELECT * FROM "delayed_jobs" WHERE (((("run_at" <= '2016-04-08 13:09:44.437743+0000') AND ("locked_at" IS NULL)) OR ("locked_by" = 'cc_api_worker.api_z2.0.1')) AND ("failed_at" IS NULL) AND ("queue" IN ('cc-api_z2-0'))) ORDER BY "priority" ASC, "run_at" ASC LIMIT 5","log_level":"error","source":"cc.background","data":{},"thread_id":46939921660300,"fiber_id":46939962348880,"process_id":23233,"file":"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sequel-4.29.0/lib/sequel/database/logging.rb","lineno":70,"method":"block in log_each"}

I think this messages shoud be only in debug or trace, not in info/error and sure not in fatal

[cf-gitbot]

We have created an issue in Pivotal Tracker to manage this. You can view the current status of your issue at: https://www.pivotaltracker.com/story/show/117228039.

[ameowlia]

Hi @poligraph,

Thanks for alerting us to this. We were able to recreate this issue. It seems like there are two problems.

1: The SQL delayed_job logs, seem to have their log_levels set to whichever log_level is in cloud_controller_ng.yml. So when we set the log level to debug, they were at the debug level, when we set the debug level to fatal, they were at the fatal level. We don't see this problem with any other SQL query.

{"timestamp":1460484720.7848167,"message":"(0.000613s) SELECT * FROM "delayed_jobs" WHERE (((("run_at" <= '2016-04-12 18:12:00.783649+0000') AND ("locked_at" IS NULL)) OR ("locked_by" = 'cc_api_worker.api_z1.0.2')) AND ("failed_at" IS NULL) AND ("queue" IN ('cc-api_z1-0'))) ORDER BY "priority" ASC, "run_at" ASC LIMIT 5","log_level":"error","source":"cc.background","data":{},"thread_id":47009275599240,"fiber_id":47009323625100,"process_id":9045,"file":"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/sequel-4.29.0/lib/sequel/database/logging.rb","lineno":70,"method":"block in log_each"}

2: We are not respecting the log_level for logs from gems. This doesn't seem to be causing as much noise as the SQL issue though.

{"timestamp":1460484851.5304098,"message":"Statsd: cc.requests.outstanding:-1|c\ncc.requests.completed:1|c\ncc.http_status.2XX:1|c","log_level":"debug","source":"statsd.client","data":{},"thread_id":47066535341360,"fiber_id":47066554352980,"process_id":8930,"file":"/var/vcap/packages/cloud_controller_ng/cloud_controller_ng/vendor/bundle/ruby/2.2.0/gems/statsd-ruby-1.2.1/lib/statsd.rb","lineno":254,"method":"send_to_socket"}

We are looking into these issues.
@adowns01 & @simonleung8, CAPI team members

[ameowlia]

Hello again @poligraph,

This has been fixed in this commit. Now all SQL logs will be set at debug2 except for errors, which will be logged as errors.

If you think this fixes the issue, please close this issue.

Thanks,
@adowns01 && @simonleung8

[poligraph]

Hi @adowns01,
Looks like commit should fix this issue, closing it.

Thanks,
Konstantin.

[dcarley]

I'm not clear how the referenced commit fixes the described problem of the logs being too noisy. It seems that hardcoding the DB log level to debug2 will always make them noisy. Would you be able to explain?

Has there been some confusion about how cc.logging_level (of the outer Steno logger passed to Sequel) and cc.db_logging_level (of the Sequel option log_level) interact with each other?

I've created issue #617 to tidy up after cc.db_logging_level, if it's being removed.

[ameowlia]

Hi @dcarley,

I can't speak to why debug2 is the default. I see you asked that question here.

Getting rid of db.sql_log_level = opts[:log_level] removes sql log lines from the logs when the user requests logs higher than debug2. Before, if you asked to see only errors, ops[:log_level] would equal errors and then sql would log everything at the error level. So no matter what level you asked to see, sequel was logging at that level.

Hope that clears it up.
@adowns01

[thausler786]

Hi @poligraph ,

After some further investigation, we believe we have resolved the confusion around db.logging_level. db.logging_level is being populated from the cc.db_logging_level parameter from the deployment manifest, and is controlling what logging level the database queries are labeled as.

It sounds like what you were originally looking for was the ability to set the logging filter level, which is configured by a different variable with an unfortunately similar name. This variable is cc.logging_level in the deployment manifest and populates the logging.level field in the yml template on the bosh job.

We are rolling back the commit that we made to fix this issue and instead will be using @dcarley's suggestion in pull request #618 to set the default for cc.logging_level to default to info. This makes the default cloud controller logs less verbose but still configurable, while allowing you to configure what level your database logs are labeled as. These two features allow you to see as many or as few database logs as you want.

Special thanks to @dcarley to pointing us in the right direction on this one.

@thausler786 && @simonleung8, CAPI team members