Best Heroic Cloud logging practices

We’re seeing some issues when running our game on Heroic Cloud that do not show up when running a server locally. It’s likely something that our code doesn’t account for when the latency is a bit higher. In order to track that down it seems that logging much more stuff is our best way forward. However, viewing logs on the Heroic Cloud console is awkward at best. It’s not particularly developer friendly especially when there are a bit more debug logging going on.

So, what are good practices for better knowing what the server is doing and why? I would like to get the real log files for better checking out what’s going on, but that doesn’t seem to be possible. Another way would be to install an own logger that just streams the messages to my own server somewhere so that I can filter and store them. Installing custom log handler doesn’t seem to be supported either? Of course I could log to a totally own log handler, but then I would not get everything that Nakama itself logs its own logger. One could of course hack Nakama’s sources to inject an own log handler, but then we could not run that version on Heroic Cloud.

Any good solutions to this?

I’ll answer this here, but please contact us directly for questions/issues regarding Heroic Cloud (HC) as the forum is not the best place for this (as usually questions are specific to projects on HC).

The typical workflow that we had in mind for debug-level logging is that the project running in Heroic Cloud should be using the ‘dev’ instance as the amount log produced is less because it’s not running in a Production setting. However there are times when you can’t reproduce the issue in development, and we can enable debug logging for production instances for a short period of time to help with debugging.

In addition, all logging must be done with Nakama’s logger to be picked up by Heroic Cloud logging framework (as opposed to fmt.println or else).

I’d not recommend hijacking Nakama’s logger, however we can accommodate for the logs to be stored in a storage bucket and for you to stream the logs from there into an existing system (again for a specified amount of time). If this is of interest, please email me/us directly and we can help you.

Lastly, would be good to jump on a call together at some point and understand what the UI/UX/changes need to be to make the logging view more useful for you and other developers. Again, ping me and we can setup a time to chat.

I didn’t know of any other way to reach anyone, so the forum it was.

The workflow I use right now is a local Nakama on my own system. It’s a perfect setup for developing the server side component of our game. However this setup works too well and I don’t see the issue I’m now trying to track down. Here I can pipe the logs to my scripts and de-JSON:ify it and easily search for interesting things, highlight strings etc.

We also use the development side of Heroic Cloud. Nothing has been deployed into production yet. On HC I see an issue when our game clients join matches. I’m pretty sure something in our server module is sensitive to latency and it ends up causing some of our clients to get in a wrong state. The bug is not in Nakama’s code as an older version of the server module works ok. Logs here are annoying to browse as I can only see a few lines of logging at one time and the whole process means clicking around on a web page instead of reading a text file.

What I personally would like to do is just insert a thing into Nakama’s logger that would give me a duplicate of everything that gets logged and which I could stream to some random socket somewhere for handling.

If this is an issue that you are noticing only in our Heroic Cloud environment, please send an email to support@heroiclabs.com and one of the team members can help you with it.

It’s an issue that we’ve seen only on HC, but it’s likely not related to Nakama at all. Clients get matched and a match is created, but a bit later when doing some own communication to set up the game we get some weirdness.

Meh, trying to use the console log system is really not fun at all. Our game ticks at 10 Hz and clients send some state data for each tick so my log fills up with internal Nakama logging:

... "msg":"Received *rtapi.Envelope_MatchDataSend message" ...

Slowly loading logs from a couple minutes back is slow and cumbersome. Not looking forward to debugging something when there is more than one game going on at the same time.

Ah, now I see that the log messages are all in the wrong order. See the screenshot and note the tick which is logged from our MatchLoop function:

It seems all messages have no millisecond part of their timestamps, so perhaps the messages go through something which sorts them somehow? Or if the millisecond data will not be included, perhaps it should be removed entirely as now it’s extremely misleading. When I look at the logging on my locally running server I see milliseconds just fine and all messages seem to be in correct order.

/cc @mofirouz

Yes excessive logging is both throttled (some log lines will be missed) and could be out of order. We’ll look into fixing it by adding the ms timestamp to the log lines but won’t help with reconciliation of log lines across different nodes.

You really are not making it easy to debug things on HC. Any technical reason why you chose to have log lines be out of order?

My only insight into what our code does is the logger as we can’t write to any files or do anything else that stores data. So what am I to do if I want to log a lot while debugging? What are the best practices here? Right now I don’t care about having multiple nodes if I can’t even debug one single game.

You really are not making it easy to debug things on HC. Any technical reason why you chose to have log lines be out of order?

Firstly, what you are observing in regards to out of order log lines is caused by missing millisecond timestamps. We’ve not chosen to make this more difficult. These are technical limitations that we are working through to improve logging generally and it’s non-trivial work.

Secondly, we’ve not had any other projects have issues with our logging and specifically out-of-order logging. You are logging excessively and I’m not sure how logging every tick can help with your debugging without knowing more about what you are trying to achieve.

My only insight into what our code does is the logger as we can’t write to any files or do anything else that stores data. So what am I to do if I want to log a lot while debugging? What are the best practices here? Right now I don’t care about having multiple nodes if I can’t even debug one single game.

I did previously offer for us to stream the logs to a file that you can download. I also did ask previously to email us so we can discuss your specific issue and find out what the root cause of your issue is. Beyond this, without specifics, I cannot help further with your debugging.