Fork me on GitHub
#pathom
<
2021-06-25
>
dehli16:06:35

Hi, I’ve got some strange behavior that I’m trying to trace down in pathom2. I’ve got a resolver that calls out to the parser from within it. To narrow down the issue I’ve started removing keys that are in the subquery to figure out what’s causing the misbehavior. I was able to reduce the query all the way to the following and it still returns unexpectedly. To me it seems like this should be impossible. Is there any ideas for how I can further debug?

;; Subquery within the resolver
(parser env [{[:curriculum/uuid "my-uuid"] [:curriculum/uuid]}])

;; Response from above subquery
{[:curriculum/uuid "my-uuid"] {:curriculum/uuid ::p.core/not-found}}

wilkerlucio17:06:21

looks strange indeed, any chance a plugin may be doing something?

dehli17:06:35

Unfortunately not. I’ve removed all plugins (other than pc/connect-plugin)and I’m still seeing that behavior.

dehli17:06:08

I’m going to try to remove references to placeholders in my test and then remove the placeholder reader to see if that’s related

wilkerlucio13:06:56

I tried to replicate the issue in a small setup, but the results looks as expected:

(pc/defresolver inner-call [{:keys [parser] :as env} _]
  {::pc/output [:inner-result]}
  {:inner-result (parser env [{[:foo 1] [:foo]}])})

;; define a list will our resolvers
(def my-resolvers [inner-call])

;; setup for a given connect system
(def parser
  (p/parser
    {::p/env     {::p/reader               [p/map-reader
                                            pc/reader2
                                            pc/open-ident-reader
                                            p/env-placeholder-reader]
                  ::p/placeholder-prefixes #{">"}}
     ::p/mutate  pc/mutate
     ::p/plugins [(pc/connect-plugin {::pc/register my-resolvers})
                  p/error-handler-plugin
                  p/request-cache-plugin
                  p/trace-plugin]}))

(comment
  (parser {} [:inner-result]))

dehli12:06:22

thanks! it normally works as expected. it’s just when i have many resolvers nested that I get this strange behavior

dehli12:06:38

if I can’t trace it down, i’ll try to come up with a reproducible example

dehli15:06:32

Looks like I was able to reproduce the bug in a smaller project. I think it has to do with parallel-parser or parallel-reader b/c when I switch to using the regular reader / parser the bug goes away. Here’s the example project I setup. https://github.com/dehli/pathom2-bug/blob/main/src/dev/dehli/pathom_bug.cljs

wilkerlucio16:06:07

ok, I did some investigation, and I think I got it

wilkerlucio16:06:30

the problem is that in the parallel case the entity gets modified upon each request

dehli16:06:35

Awesome! That’s great news 🙂 Thanks!

wilkerlucio16:06:32

just replied on the issue with details, please let me know if the solution proposed there works for you

dehli16:06:52

Thanks! I think that would work. I was initially using placeholders, and the bug only started to surface as I moved to idents. Is this intended behavior for the parallel-parser?

wilkerlucio16:06:32

using parser inside parser has some of this repercusions, its kinda expected

👍 3
wilkerlucio16:06:50

if you are using it too much, would be nice to see why, ,and if it could be avoied

wilkerlucio16:06:25

but there cases (specially on pathom 2) that its just the only way (a hack way for optional and/or nested inputs)

dehli16:06:25

cool! we don’t use them too often (almost always it’s due to nested inputs). pathom3 will fix that, so we are excited to make the switch 🙂

👍 3
dehli18:06:54

Hello again! I’m still seeing similar behavior (even when using the (with-entity) function you had suggested. I’ve also tried clearing out ::p/request-cache and I’m still getting a subset of my query returned in my nested parser call. Is there some other key in env that I could look at to debug? If not, I can try to find another reproducible example.

dehli17:06:12

I’ve got another example showing the bug I’m seeing. For this one, I am using the with-entity function. I’ll keep playing around with it to try to better figure out what’s going on.

(ns dev.dehli.pathom-bug
  (:require [clojure.core.async :refer [go <! <!!]]
            [com.wsscode.pathom.core :as p]
            [com.wsscode.pathom.connect :as pc]
            [com.wsscode.pathom.parser :as pp]))

(defn with-entity [env ent]
  (assoc env ::p/entity (atom ent)))

(pc/defresolver one
  [{id :id}]
  {:one (str "one " id)})

(pc/defresolver state
  [{:keys [parser] :as env} {id :id}]
  {::pc/output [:state]}
  (go
    {:state (<! (parser (with-entity env {:id id}) [:one]))}))

(def parser
  (p/parallel-parser
    {::p/env     {::p/reader               [p/map-reader
                                            pc/parallel-reader
                                            pc/open-ident-reader
                                            p/env-placeholder-reader]
                  ::p/placeholder-prefixes #{">"}
                  ::pp/external-wait-ignore-timeout 100}
     ::p/plugins [(pc/connect-plugin {::pc/register [state
                                                     one]})
                  p/error-handler-plugin
                  p/trace-plugin]}))

(comment
  (<!! (parser {} [{[:id "foo"] [:one :state]}]))

  ;; Returns
  ;; {[:id "foo"] {:one "one foo" :state {}}}
  )

👀 2
dehli19:06:29

It seems to be returning empty state b/c it’s reaching the ::pp/external-wait-ignore-timeout

dehli20:06:48

I think I was able to fix the bug by adding ::pp/processing-recheck-timer

dehli20:06:59

although it does seem like a bandaid rather than a full solution

wilkerlucio20:06:26

yeah, I'm taking a deeper look, it doesn't look very good

wilkerlucio20:06:50

the issue is that the parallel processor has all these "tricks" add for performance tuning over time

wilkerlucio20:06:17

and these examples are exposing their sensitivity for recursive calls

dehli20:06:24

I see. That lines up with what I’m seeing on my end as well. Our recently added resolvers utilize recursion which must be why we’re starting to see some unexpected behavior.

wilkerlucio20:06:47

did you recently changed to parallel parser? or recently add recursive calls like this?

dehli20:06:06

we’ve been using parallel parser but recently added recursive calls like this

wilkerlucio20:06:55

and the reason you use the parallel parser is related to long attribute dependencies? or because of processing many entities in parallel? ou maybe both?

dehli20:06:32

we’re using the parallel parser for the second reason (needing to execute many entities in parallel)

dehli20:06:44

i guess the first as well

dehli20:06:14

we saw pretty good performance improvements when we switched to parallel

wilkerlucio20:06:54

gotcha, we can try to hack a bit on the parallel and "reset" the things that need reset on the recursive call, we may be able to make this work for now

dehli21:06:53

ya, i was looking through the env map to try and figure out what could be reset to give it a “fresh” view

dehli21:06:52

additionally the bandaid might be enough as well until we make the switch to pathom3. it seems that the parallel parser can be implemented much simpler with the new architecture

wilkerlucio21:06:08

yes, parallel processing in pathom 3 should be much simpler

2
wilkerlucio21:06:25

I'm thinking of doing something in pathom 2 that I did for pathom 3 regarding env

wilkerlucio21:06:44

there I just save a "backup" version of the env on entry, so you can restore to it

wilkerlucio21:06:56

but may not be enough, because of some mutable state things, like active-paths

wilkerlucio21:06:58

ok, I find something that works with your example:

wilkerlucio21:06:59

(defn with-entity [env ent]
  (assoc env ::p/entity (atom ent)))

(pc/defresolver one
  [{id :id}]
  {:one (str "one " id)})

(defn reset-env [env]
  (assoc env
    :com.wsscode.pathom.parser/active-paths (atom #{})
    :com.wsscode.pathom.parser/waiting #{}
    :com.wsscode.pathom.parser/key-watchers (atom {})
    :com.wsscode.pathom.core/entity-path-cache (atom {})))

(pc/defresolver state
  [{:keys [parser] :as env} {id :id}]
  {::pc/output [:state]}
  (go
    {:state (<! (parser (-> env
                            (reset-env)
                            (with-entity {:id id})) [:one]))}))

(def parser
  (p/parallel-parser
    {::p/env     {::p/reader                        [p/map-reader
                                                     pc/parallel-reader
                                                     pc/open-ident-reader
                                                     p/env-placeholder-reader]
                  ::p/placeholder-prefixes          #{">"}
                  ::pp/external-wait-ignore-timeout 100}
     ::p/plugins [(pc/connect-plugin {::pc/register [state
                                                     one]})
                  p/error-handler-plugin
                  p/trace-plugin]}))

wilkerlucio21:06:25

I can make reset-env part of the Pathom API, so we can move it with the library (and if we find more things to reset, an update will fix)

dehli21:06:58

awesome! ya, i’ll give that a go. I have a quick question about the processing-recheck-timer how does it know it’s “stuck”? does that just mean the resolver is still executing? Trying to determine what’s a good value so that I don’t retry database calls, etc.

wilkerlucio21:06:33

Im reading again on the code to remember what thats about

wilkerlucio21:06:48

for reasons I don't remember now, the parser may get stuck in some part of the process, this is probably due to the channel madness going on in the orchestration there, looking at the code, its a kinda of "timeout" case, the parallel parser will walk all children of the AST, and try to make sure every attribute is "started" (not every single attribute will trigger a process, for each process pathom knows all "expected" attributes, and will skip those during the scan in case a previous attribute ended up hitting it in the process)

wilkerlucio21:06:07

so after start everything, it waits for some response, to merge as they come

wilkerlucio21:06:54

but if it is stuck, that will not finish, this is where the process-recheck-timer enters, it its like a timeout case for this step, and if the code reaches it, it will re-trigger the process for the attributes that still pending

dehli21:06:52

ya, that makes sense! thanks so much! i’ve also gotten your reset-env function added to our subquery function so i think that will fix the issues we’ve run into. will test it out and let you know!

wilkerlucio21:06:43

a little polishing on the api:

wilkerlucio21:06:44

(defn with-entity [env ent]
  (assoc env ::p/entity (atom ent)))

(pc/defresolver one
  [{id :id}]
  {:one (str "one " id)})

(defn reset-env [env]
  (assoc env
    :com.wsscode.pathom.parser/active-paths (atom #{})
    :com.wsscode.pathom.parser/waiting #{}
    :com.wsscode.pathom.parser/key-watchers (atom {})
    :com.wsscode.pathom.core/entity-path-cache (atom {})))

(defn call-parser [{:keys [parser] :as env} entity tx]
  (parser
    (-> (reset-env env) (with-entity entity))
    tx))

(pc/defresolver state
  [env {id :id}]
  {::pc/output [:state]}
  (go
    {:state (<! (call-parser env {:id id} [:one]))}))

💯 2
dehli14:07:01

Thanks again for all your help! Have deployed with the changes and the unexpected behavior is now gone 🙂

🎉 2
wilkerlucio14:07:49

great to hear! 🙂 later I'll put the reset-env at the library, so you can use from it

🎉 6