ERROR: push.pushToDevices logged error object is empty

[vladikoff]

Seeing some error reports from pushToDevices when running functional tests locally:

fxa-auth-server.ERROR: push.pushToDevices {"op":"push.pushToDevices","deviceId":"af3852996ac4bcb63f518633a066974d","err":{}}
fxa-auth-server.INFO: push.pushToDevices {"op":"push.pushToDevices","name":"push.device_connected.no_push_callback"}
{"Timestamp":1464361019183000000,"Logger":"fxa-auth-db-server","Type":"bin.server.summary","Severity":6,"Pid":38945,"EnvVersion":"2.0","Fields":{"code":200,"route":"getsessiontokenid","method":"GET","path":"/sessionToken/3337e1d2225e988320e8653c8d0e31405e007ea1d415d14a1ded613495fda443","t":1}}
{"Timestamp":1464361019185000000,"Logger":"fxa-auth-db-server","Type":"bin.server.summary","Severity":6,"Pid":38945,"EnvVersion":"2.0","Fields":{"code":200,"route":"getaccountiddevices","method":"GET","path":"/account/2752333d9d8148658b2c684486970947/devices","t":0}}
fxa-auth-server.INFO: request.summary {"op":"request.summary","code":200,"errno":0,"rid":"1464361019182:vladikoff-2:38946:iopupbu9:10021","path":"/v1/account/devices","lang":"en-US,en;q=0.5","agent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10.10; rv:40.0) Gecko/20100101 Firefox/40.0 FxATester/1.0","remoteAddressChain":["127.0.0.1"],"t":5,"uid":"2752333d9d8148658b2c684486970947"}
{"Timestamp":1464361019257000000,"Logger":"fxa-auth-db-server","Type":"bin.server.summary","Severity":6,"Pid":38945,"EnvVersion":"2.0","Fields":{"code":200,"route":"getsessiontokeniddevice","method":"GET","path":"/sessionToken/bc0f1e95e776d4ef36a6af167b4651649c5b740f13e9f6aa4b1e6784b96d0bb2/device","t":1}}
{"Timestamp":1464361019263000000,"Logger":"fxa-auth-db-server","Type":"bin.server.summary","Severity":6,"Pid":38945,"EnvVersion":"2.0","Fields":{"code":200,"route":"postaccountuiddevicedeviceidupdate","method":"POST","path":"/account/2752333d9d8148658b2c684486970947/device/af3852996ac4bcb63f518633a066974d/update","t":2}}
fxa-auth-server.INFO: request.summary {"op":"request.summary","code":200,"errno":0,"rid":"1464361019256:vladikoff-2:38946:iopupbu9:10022","path":"/v1/account/device","agent":"node-XMLHttpRequest","remoteAddressChain":["127.0.0.1"],"t":9,"uid":"2752333d9d8148658b2c684486970947"}
{"Timestamp":1464361019265000000,"Logger":"fxa-auth-db-server","Type":"bin.server.summary","Severity":6,"Pid":38945,"EnvVersion":"2.0","Fields":{"code":200,"route":"getaccountiddevices","method":"GET","path":"/account/2752333d9d8148658b2c684486970947/devices","t":1}}
fxa-auth-server.ERROR: push.pushToDevices {"op":"push.pushToDevices","deviceId":"c9efde3a8835939ad2d3aa47321c324e","err":{}}

We need to see what the error actually is but it just "err":{}. @eoger @rfk thoughts?

[vladikoff]

Okay the error itself is fxa-auth-server.WARN: console {"op":"console","message":"[Error: No Push Callback]"} fxa-auth-server.ERROR: push.pushToDevices {"op":"push.pushToDevices","deviceId":"4c991ea3f56572fdbd0d0bdec3321988","err":{}}

That error is 'expected', but we should probably fix mozlog to show it.

[vladikoff]

cc @jrgm

[rfk]

So is this basically an issue with serialization in mozlog, discarding the data from the error object? Does it also happen if using the heka formatter rather than default pretty-printer?

[eoger]

The pretty printer discards the error, see heka formatted:
{"Timestamp":1464734661129000000,"Logger":"fxa-auth-server","Type":"push.pushToDevices","Severity":2,"Pid":12067,"EnvVersion":"2.0","Fields":{"op":"push.pushToDevices","deviceId":"foo","err":"Error: No Push Callback"}}

[eoger]

I was thinking of pulling the error message and adding it as an errMessage prop here, is this the right way?

[vladikoff]

Hm my first thought on this is that if the Heka formatter works correctly then we should fix pretty print in mozlog.