balena-io-modules / resin-device-logs

Resin.io device logs utilities.
Apache License 2.0
3 stars 2 forks source link

Include multicontainer service ids on log messages, when available #24

Closed pimterry closed 6 years ago

pimterry commented 6 years ago

This is the non-breaking step towards https://github.com/resin-io/resin-sdk/issues/411. We now add a serviceId field to all log message objects, which is the value of c if one exists in the pubnub message, or null otherwise.

This PR also refactors a bunch of the tests to make them easier to change & handle (towards multicontainer log filtering - watch this space). For now this should make them a little more stable and easier to manage, but there's definitely more that could be done here.

resin-io-modules-versionbot[bot] commented 6 years ago

@pimterry, status checks have failed for this PR. Please make appropriate changes and recommit.

resin-io-modules-versionbot[bot] commented 6 years ago

@pimterry, status checks have failed for this PR. Please make appropriate changes and recommit.

resin-io-modules-versionbot[bot] commented 6 years ago

@pimterry, status checks have failed for this PR. Please make appropriate changes and recommit.

pimterry commented 6 years ago

So it turns out the delays aren't the problem, pubnub is just unreliable. Right now in these tests, pubnub accepts a bunch of messages, confirms them all as sent, and then sometimes doesn't return half of them. I'll investigate more on Monday. Very occasionally happens locally, but oddly seems much more frequent on Travis (although maybe that's just because it's running a lot more builds per-push).

Full logs for posterity:

    .history()
<<<<<
[2017-11-11T16:23:51.216Z] 
 https://ps2.pndsn.com/publish/pub-c-02e5848f-c9c5-4e6a-8586-268c44635766/sub-c-4a67af8a-049f-11e7-b09b-0619f8945a4f/0/test-channel-1147187066145954/0/%22Message%201%22 
 { uuid: 'pn-dcd69cc0-d1d4-47c5-a5fa-4e93723c3674',
  pnsdk: 'PubNub-JS-Nodejs/4.15.1' }
-----
>>>>>>
[2017-11-11T16:23:51.238Z / 22] 
 https://ps2.pndsn.com/publish/pub-c-02e5848f-c9c5-4e6a-8586-268c44635766/sub-c-4a67af8a-049f-11e7-b09b-0619f8945a4f/0/test-channel-1147187066145954/0/%22Message%201%22 
 { uuid: 'pn-dcd69cc0-d1d4-47c5-a5fa-4e93723c3674',
  pnsdk: 'PubNub-JS-Nodejs/4.15.1' } 
 [1,"Sent","15104174312085581"]
-----
<<<<<
[2017-11-11T16:23:51.239Z] 
 https://ps2.pndsn.com/publish/pub-c-02e5848f-c9c5-4e6a-8586-268c44635766/sub-c-4a67af8a-049f-11e7-b09b-0619f8945a4f/0/test-channel-1147187066145954/0/%22Message%202%22 
 { uuid: 'pn-dcd69cc0-d1d4-47c5-a5fa-4e93723c3674',
  pnsdk: 'PubNub-JS-Nodejs/4.15.1' }
-----
>>>>>>
[2017-11-11T16:23:51.258Z / 19] 
 https://ps2.pndsn.com/publish/pub-c-02e5848f-c9c5-4e6a-8586-268c44635766/sub-c-4a67af8a-049f-11e7-b09b-0619f8945a4f/0/test-channel-1147187066145954/0/%22Message%202%22 
 { uuid: 'pn-dcd69cc0-d1d4-47c5-a5fa-4e93723c3674',
  pnsdk: 'PubNub-JS-Nodejs/4.15.1' } 
 [1,"Sent","15104174312284539"]
-----
<<<<<
[2017-11-11T16:23:51.258Z] 
 https://ps2.pndsn.com/publish/pub-c-02e5848f-c9c5-4e6a-8586-268c44635766/sub-c-4a67af8a-049f-11e7-b09b-0619f8945a4f/0/test-channel-1147187066145954/0/%22Message%203%22 
 { uuid: 'pn-dcd69cc0-d1d4-47c5-a5fa-4e93723c3674',
  pnsdk: 'PubNub-JS-Nodejs/4.15.1' }
-----
>>>>>>
[2017-11-11T16:23:51.278Z / 20] 
 https://ps2.pndsn.com/publish/pub-c-02e5848f-c9c5-4e6a-8586-268c44635766/sub-c-4a67af8a-049f-11e7-b09b-0619f8945a4f/0/test-channel-1147187066145954/0/%22Message%203%22 
 { uuid: 'pn-dcd69cc0-d1d4-47c5-a5fa-4e93723c3674',
  pnsdk: 'PubNub-JS-Nodejs/4.15.1' } 
 [1,"Sent","15104174312491333"]
-----
<<<<<
[2017-11-11T16:23:51.279Z] 
 https://ps2.pndsn.com/publish/pub-c-02e5848f-c9c5-4e6a-8586-268c44635766/sub-c-4a67af8a-049f-11e7-b09b-0619f8945a4f/0/test-channel-1147187066145954/0/%22Message%204%22 
 { uuid: 'pn-dcd69cc0-d1d4-47c5-a5fa-4e93723c3674',
  pnsdk: 'PubNub-JS-Nodejs/4.15.1' }
-----
>>>>>>
[2017-11-11T16:23:51.302Z / 23] 
 https://ps2.pndsn.com/publish/pub-c-02e5848f-c9c5-4e6a-8586-268c44635766/sub-c-4a67af8a-049f-11e7-b09b-0619f8945a4f/0/test-channel-1147187066145954/0/%22Message%204%22 
 { uuid: 'pn-dcd69cc0-d1d4-47c5-a5fa-4e93723c3674',
  pnsdk: 'PubNub-JS-Nodejs/4.15.1' } 
 [1,"Sent","15104174312727628"]
-----
<<<<<
[2017-11-11T16:23:51.303Z] 
 https://ps2.pndsn.com/publish/pub-c-02e5848f-c9c5-4e6a-8586-268c44635766/sub-c-4a67af8a-049f-11e7-b09b-0619f8945a4f/0/test-channel-1147187066145954/0/%22Message%205%22 
 { uuid: 'pn-dcd69cc0-d1d4-47c5-a5fa-4e93723c3674',
  pnsdk: 'PubNub-JS-Nodejs/4.15.1' }
-----
>>>>>>
[2017-11-11T16:23:51.332Z / 29] 
 https://ps2.pndsn.com/publish/pub-c-02e5848f-c9c5-4e6a-8586-268c44635766/sub-c-4a67af8a-049f-11e7-b09b-0619f8945a4f/0/test-channel-1147187066145954/0/%22Message%205%22 
 { uuid: 'pn-dcd69cc0-d1d4-47c5-a5fa-4e93723c3674',
  pnsdk: 'PubNub-JS-Nodejs/4.15.1' } 
 [1,"Sent","15104174313017566"]
-----
<<<<<
[2017-11-11T16:24:01.342Z] 
 https://ps2.pndsn.com/v2/history/sub-key/sub-c-4a67af8a-049f-11e7-b09b-0619f8945a4f/channel/test-channel-1147187066145954 
 { include_token: 'true',
  count: 100,
  uuid: 'pn-dcd69cc0-d1d4-47c5-a5fa-4e93723c3674',
  pnsdk: 'PubNub-JS-Nodejs/4.15.1' }
-----
>>>>>>
[2017-11-11T16:24:01.398Z / 56] 
 https://ps2.pndsn.com/v2/history/sub-key/sub-c-4a67af8a-049f-11e7-b09b-0619f8945a4f/channel/test-channel-1147187066145954 
 { include_token: 'true',
  count: 100,
  uuid: 'pn-dcd69cc0-d1d4-47c5-a5fa-4e93723c3674',
  pnsdk: 'PubNub-JS-Nodejs/4.15.1' } 
 [[{"message":"Message 1","timetoken":15104174312085581},{"message":"Message 3","timetoken":15104174312491333},{"message":"Message 5","timetoken":15104174313017566}],15104174312085581,15104174313017566]
-----
      2) should retrieve the history messages
      AssertionError: expected [ Array(3) ] to deeply equal [ Array(5) ]
      + expected - actual
       [
         "Message 1"
      +  "Message 2"
         "Message 3"
      +  "Message 4"
         "Message 5"
       ]
pimterry commented 6 years ago

Ok, I'm not going to try and delve into whatever the hell pubnub think they're doing here, since we're dropping them soon anyway. I've added automatic test retrying, which should make the end result pretty stable here at least, and squashed all my test tweaking commits back down.

Assuming this passes, I'll merge and ship shortly, which should immediately make logMessage.serviceId available in the UI (although it'll only be non-null if you have a supervisor that sets it).