STDERR logging wraps json at 1024 characters

[gene1wood]

json lines that go beyond 1024 characters wrap to a new line. I suspect these will cause problems for hekad consumption

[pdehaan]

Assigning to @gene1wood to see if this is some downward problem (w/ Circus or whatever)

[gene1wood]

The 1024 issue may be caused by this https://github.com/mozilla-services/circus/blob/master/circus/stream/__init__.py#L137 I'll need to see if @tarekziade has a second to point me in the right direction

[rfk]

Indeed, it's a deployment/configuration bug so probably need to move to wherever @gene1wood is most comfortable managing those. It's pretty definitely causes by circus so also worth opening a github issue on circus repo.

[dannycoates]

I spun the non-json part off into #456

now this issue can just track the 1024 problem

[gene1wood]

I've emailed @tarekziade asking for his help.

[tarekziade]

as far as I see, the buffer size should not be adding extra characters in what your getting.

When you say wrapped, do you mean you're getting extra EOL characters every 1024 characters ? or something else ? Can you provide a file to show me ?

Also, can you give me the exact circus configuration so I can try to reproduce here ?

Thanks!

[gene1wood]

When you say wrapped, do you mean you're getting extra EOL characters every 1024 characters ?

Every line which exceeds 1024 characters in length is having a carriage return added after 1024 characters.

Here's a excerpt of a log line that is being wrapped at 1024 characters

{"name":"fxa-auth-server","hostname":"domU-12-31-39-14-2A-6B","pid":2387,"level":30,"op":"server.response","rid":"1389283439734-2387-33404","path":"/","t":2,"msg":"","time":"2014-01-09
T16:03:59.736Z","v":0}
{"name":"fxa-auth-server","hostname":"i-fd8446d3","pid":31683,"level":30,"env":"stage","log":{"level":"trace"},"publicUrl":"https://api-accounts.stage.mozaws.net","secretKeyFile":"/data/fxa-auth-server/config/secret-key.json","publicKeyFile":"/data/fxa-auth-server/config/public-key.json","db":{"backend":"mysql","available_backends":["memory","mysql"]},"mysql":{"createSchema":true,"master":{"user":"xxxxxxxxxxxxxxx","password":"xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx","database":"fxa","host":"dbwrite.fxa.us-east-1.stage.mozaws.net","port":"3306","connectionLimit":100,"waitForConnections":true},"slave":{"user":"xxxxxxxxxxxxxxx","password":"xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx","database":"fxa","host":"dbwrite.fxa.us-east-1.stage.mozaws.net","port":"3306","connectionLimit":100,"waitForConnections":true}},"listen":{"host":"127.0.0.1","port":8000},"contentServer":{"url":"https://accounts.stage.mozaws.net"},"scryptHelper":{"url":"https://scrypt-accounts.stage.moza
ws.net"},"smtp":{"api":{"host":"127.0.0.1","port":9001},"host":"localhost","port":25,"secure":false,"sender":"Firefox Accounts <no-reply@stage.mozaws.net>","verificationUrl":"https://api-accounts.stage.mozaws.net/v1/verify_email","reportUrl":"#","templatePath":"/data/fxa-auth-server/templates/email"},"redis":{"host":"","port":6379,"database":0,"password":""},"toobusy":{"maxLag":0},"i18n":{"defaultLang":"en","supportedLanguages":["en","en-AU"],"translationDirectory":"resources/i18n/","translationType":"key-value-json"},"domain":"api-accounts.stage.mozaws.net","msg":"starting config","time":"2014-01-09T16:04:10.382Z","v":0}
path.existsSync is now called `fs.existsSync`.
{"name":"fxa-auth-server","hostname":"i-fd8446d3","pid":31683,"level":10,"op":"MySql.createSchema","rid":null,"msg":"","time":"2014-01-09T16:04:11.512Z","v":0}
{"name":"fxa-auth-server","hostname":"i-fd8446d3","pid":31683,"level":10,"op":"MySql.createSchema:CreateDatabase","rid":null,"msg":"","time":"2014-01-09T16:04:11.514Z","v":0}

Line 3 wraps to line 4 at 1024 characters. I believe line 1 is wrapping to line 2 as a side effect of me killing the process that circus is managing in order to get it to display a log line that I know will be over 1024 characters (line 3/4 is displayed when the process starts up). I'm not positive about the wrap on line 1/2 but I've not seen it before. I suspect it's a red herring and can be ignored.

And here's the circus config in play

[watcher:auth_server]
cmd = /usr/bin/node bin/key_server.js
working_dir = /data/fxa-auth-server
uid = app
gid = app
warmup_delay = 0
numprocesses = 1
stdout_stream.class = FileStream
stdout_stream.filename = /media/ephemeral0/fxa-auth-server/auth_out.log
stdout_stream.refresh_time = 0.3
stdout_stream.max_bytes = 1048576
stdout_stream.backup_count = 10
stderr_stream.class = FileStream
stderr_stream.filename = /media/ephemeral0/fxa-auth-server/auth_err.log
stderr_stream.refresh_time = 0.3
stderr_stream.max_bytes = 1048576
stderr_stream.backup_count = 10
check_flapping = true

[env:auth_server]
CONFIG_FILES = /data/fxa-auth-server/config/default.json
PORT = 8000

I've had @dannycoates confirm in a setup without circus in play that those >1024 lines are not wrapped.

[rfk]

@tarekziade I think it's the following block of code that's causing the issue:

https://github.com/mozilla-services/circus/blob/master/circus/stream/file_stream.py#L64

If the input data doesn't end in a newline, this loop will add one.

[tarekziade]

yeah that's what I ended up finding - will fix it now

[tarekziade]

@rfk please look at https://github.com/mozilla-services/circus/pull/712 for r+

@gene1wood once this is commited, please give master a shot to double check you don't have any regression and that the fix works for you. Once you're happy I will make release

[pdehaan]

@rfk and @gene1wood Can you please confirm and close this bug if fixed. Thanks. /cc @jrgm

[gene1wood]

@pdehaan : @rfk needs to review @tarekziade 's PR, then merge, then I'll manually deploy it in an environment to confirm this fixes the issue. Then @tarekziade will create a release with the bugfix. Then I'll update our deploys to use the new circus version.

[rfk]

I merged the upstream fix

[gene1wood]

I still haven't found an opportunity to manually test this fix.

[whd]

I have manually tested this fix (from a git checkout) and it does the trick. @tarekziade can you cut a new release of circus with this fix?

[gene1wood]

@whd has built an RPM of this and merged the puppet change to enable the fix in fxa. We'll see it in future stage builds (see next week)