https://prefect.io logo
Title
d

Daniel Komisar

12/14/2021, 7:51 PM
Hi everyone, I am trying to retrieve logs from prefect server. For a single flow run I am seeing log messages print out of order. They are being printed in timestamp order (and I’ve verified the wrongly ordered lines do not have the exact same timestamp). I am guessing the timestamps are created on the server? Is there any way to embed a sequence number in the log messages or a local timestamp from the agent, or do I have to put something in the log message itself? Thanks.
k

Kevin Kho

12/14/2021, 7:52 PM
It’s actually generated from your Flow compute and uploaded. Could you show me an example so I can get a better picture?
d

Daniel Komisar

12/14/2021, 7:55 PM
I can’t copy all the code, but maybe I can copy some pieces of it. I’ll have to check. But it’s basically a more complicated version of:
logger("Line1")
logger("Line2")
and the log is
Line2
Line1
unfortunately the real log is many thousands of lines long
k

Kevin Kho

12/14/2021, 7:56 PM
What executor are you using?
d

Daniel Komisar

12/14/2021, 7:56 PM
dask
k

Kevin Kho

12/14/2021, 7:57 PM
With an actual cluster?
d

Daniel Komisar

12/14/2021, 7:58 PM
I’m not sure actually, I haven’t set any of that up. I don’t think it’s using a cluster, we’re just using it for local execution so we can gate the flows. But these timestamps are all from a single flow, if it’s all from a local clock shouldn’t that not matter?
k

Kevin Kho

12/14/2021, 8:01 PM
Ah well I’m asking because if you have a Dask cluster, you shouldn’t even get worker logs by default so you would have needed to have some kind of service ship the logs somehow so I was wondering if you had something like this. But also so I can test to try to replicate
d

Daniel Komisar

12/14/2021, 8:01 PM
Hmm maybe we have some logging config I haven’t seen yet. I’ll have to look into it more, thanks.
No cluster, dask running a single instance on the same machine as the agent
k

Kevin Kho

12/14/2021, 8:09 PM
Out timestamp in the backend goes to milliseconds so I can’t think of a reason why they’d be out of order. I don’t really have enough to go off over. Would you be able to DM me some logs?
d

Daniel Komisar

12/14/2021, 8:11 PM
I can probably send you something, thanks
Actually I think it is because of identical timestamps, I must have misinterpreted. At least the one I just found has identical timestamps, and I would expect it to cause this problem. Is there any way to embed extra info in the records, without adding it to the message itself?
k

Kevin Kho

12/14/2021, 8:33 PM
I can’t think of anything because the UI renders the logs separate from what the Flow is sending so you can’t really change the logging format
d

Daniel Komisar

12/14/2021, 8:36 PM
Sorry, this is in our own UI. I’m asking if there is any easy way to include sequence data in the log messages so that I can get the right order through graphql.
I can of course encode it into the log message, I’d rather not do that unless it’s the only way
k

Kevin Kho

12/14/2021, 8:38 PM
I understand. Do you mean you are not using the Prefect UI? Or do you mean Prefect UI but you host it?
d

Daniel Komisar

12/14/2021, 8:39 PM
We don’t use the prefect UI for log viewing, for a number of reasons. Our UI is totally separate from prefect UI, prefect is just a backend service.
k

Kevin Kho

12/14/2021, 8:40 PM
Actually sorry I take that back. The issue is how the logs are stored with Prefect.
{
        "id": "fc715146-435b-4ff3-96f8-cec1dc017a67",
        "message": "Task 'test[1]': Finished task run for task with final state: 'Failed'",
        "timestamp": "2021-12-14T20:16:06.028796+00:00",
        "name": "prefect.CloudTaskRunner"
      },
I don’t see a place you can stick an identifier unless it’s in the message
d

Daniel Komisar

12/14/2021, 8:40 PM
To be more clear, “we” (i.e. the developers of our system) use the prefect UI all the time, but our end users (who need to view logs) do not
k

Kevin Kho

12/14/2021, 8:40 PM
Ah i see
d

Daniel Komisar

12/14/2021, 8:41 PM
Yeah I didn’t think so, but if you look in the api docs there’s lots more fields in the log message type and I don’t know what many of them do. So I figured I’d ask before I hacked my own implementation 🙂
k

Kevin Kho

12/14/2021, 8:41 PM
I did take a look but really not seeing anything to help honestly
d

Daniel Komisar

12/14/2021, 8:42 PM
To clarify further, this is for a build system. We routinely have ~5000 line logs. There is a 2500 line cutoff for your gql, and you can only see a few lines at a time, so the prefect UI isn’t really suitable.
k

Kevin Kho

12/14/2021, 8:42 PM
I’ll leave a message with our engineers to see if we can utilize
info
or
object_id
to hold metadata. Will get back to you when i get a response
d

Daniel Komisar

12/14/2021, 8:43 PM
Ah yes I wanted to ask about
info
. The prefect cli doesn’t use this correctly (or maybe I’m on an old version). prefect cli seems to think
info
is a bool, but in the current api it has a parameter. Whatever that does it may be useful to us. The prodcut I’m working on is a software build system, so logs are very important.
Sorry not a bool, but it didn’t have parameters.
k

Kevin Kho

12/15/2021, 1:33 AM
object_id
 is the object id associated with a log, use for audit log tracking. 
info
 appears to be an arbitrary json blob with some additional information about the log.
So no there is no way to embed some other metadata