search

protojure / lib

A collection of libraries to support Protojure applications at runtime
https://protojure.readthedocs.io
Apache License 2.0
64 stars 14 forks source link

Getting `bad status response` error, but request was not actually sent #80

Closed mvarela closed 2 years ago

mvarela commented 3 years ago

Hi! I'm new to grpc, and trying to use your library to access an in-house grpc service implemented in .NET. I've created the proto file describing the service, and used the clojure protoc plugin to generate the client code, as per the protojure docs.

When doing the following:

(def client @(grpc.http2/connect {:uri "http://127.0.0.1:30420"}))
(try @(client/Name client (com.google.protobuf/new-Empty {}))
     (catch Exception e  e))

I get the following output:

;; => #error {
;;     :cause "bad status response"
;;     :data {:response #function[protojure.internal.grpc.client.providers.http2.core/receive-headers/fn--22275]}
;;     :via
;;     [{:type java.util.concurrent.ExecutionException
;;       :message "clojure.lang.ExceptionInfo: bad status response {:response #function[protojure.internal.grpc.client.providers.http2.core/receive-headers/fn--22275]}"
;;       :at [java.util.concurrent.CompletableFuture reportGet "CompletableFuture.java" 395]}
;;      {:type clojure.lang.ExceptionInfo
;;       :message "bad status response"
;;       :data {:response #function[protojure.internal.grpc.client.providers.http2.core/receive-headers/fn--22275]}
;;       :at [protojure.internal.grpc.client.providers.http2.core$receive_payload invokeStatic "core.clj" 116]}]
;;     :trace
;;     [[protojure.internal.grpc.client.providers.http2.core$receive_payload invokeStatic "core.clj" 116]
;;      [protojure.internal.grpc.client.providers.http2.core$receive_payload invoke "core.clj" 101]
;;      [clojure.lang.AFn applyToHelper "AFn.java" 171]
;;      [clojure.lang.AFn applyTo "AFn.java" 144]
;;      [clojure.core$apply invokeStatic "core.clj" 673]
;;      [clojure.core$partial$fn__5864 doInvoke "core.clj" 2647]
;;      [clojure.lang.RestFn invoke "RestFn.java" 408]
;;      [clojure.core$comp$fn__5826 invoke "core.clj" 2573]
;;      [promesa.util.FunctionWrapper apply "util.cljc" 43]
;;      [java.util.concurrent.CompletableFuture uniComposeStage "CompletableFuture.java" 1106]
;;      [java.util.concurrent.CompletableFuture thenCompose "CompletableFuture.java" 2235]
;;      [java.util.concurrent.CompletableFuture thenCompose "CompletableFuture.java" 143]
;;      [promesa.impl$eval21268$fn__21273 invoke "impl.cljc" 164]
;;      [promesa.protocols$eval20720$fn__20721$G__20703__20734 invoke "protocols.cljc" 28]
;;      [promesa.core$then invokeStatic "core.cljc" 153]
;;      [promesa.core$then invoke "core.cljc" 143]
;;      [protojure.internal.grpc.client.providers.http2.core$client_receive invokeStatic "core.clj" 123]
;;      [protojure.internal.grpc.client.providers.http2.core$client_receive invoke "core.clj" 121]
;;      [protojure.internal.grpc.client.providers.http2.core.Http2Provider$fn__22473 invoke "core.clj" 147]
;;      [clojure.core$comp$fn__5826 invoke "core.clj" 2573]
;;      [promesa.util.FunctionWrapper apply "util.cljc" 43]
;;      [java.util.concurrent.CompletableFuture uniComposeStage "CompletableFuture.java" 1106]
;;      [java.util.concurrent.CompletableFuture thenCompose "CompletableFuture.java" 2235]
;;      [java.util.concurrent.CompletableFuture thenCompose "CompletableFuture.java" 143]
;;      [promesa.impl$eval21268$fn__21273 invoke "impl.cljc" 164]
;;      [promesa.protocols$eval20720$fn__20721$G__20703__20734 invoke "protocols.cljc" 28]
;;      [promesa.core$then invokeStatic "core.cljc" 153]
;;      [promesa.core$then invoke "core.cljc" 143]
;;      [protojure.internal.grpc.client.providers.http2.core.Http2Provider invoke "core.clj" 142]
;;      [protojure.grpc.client.utils$invoke_unary invokeStatic "utils.clj" 56]
;;      [protojure.grpc.client.utils$invoke_unary invoke "utils.clj" 42]
;;      [Profilence.Omicron.IssueTracking.IssueTrackingHostService.client$Name$fn__21599 invoke "client.cljc" 27]
;;      [clojure.core$comp$fn__5826 invoke "core.clj" 2573]
;;      [promesa.util.FunctionWrapper apply "util.cljc" 43]
;;      [java.util.concurrent.CompletableFuture uniComposeStage "CompletableFuture.java" 1106]
;;      [java.util.concurrent.CompletableFuture thenCompose "CompletableFuture.java" 2235]
;;      [java.util.concurrent.CompletableFuture thenCompose "CompletableFuture.java" 143]
;;      [promesa.impl$eval21268$fn__21273 invoke "impl.cljc" 164]
;;      [promesa.protocols$eval20720$fn__20721$G__20703__20734 invoke "protocols.cljc" 28]
;;      [promesa.core$then invokeStatic "core.cljc" 153]
;;      [promesa.core$then invoke "core.cljc" 143]
;;      [Profilence.Omicron.IssueTracking.IssueTrackingHostService.client$Name invokeStatic "client.cljc" 27]
;;      [Profilence.Omicron.IssueTracking.IssueTrackingHostService.client$Name invoke "client.cljc" 18]
;;      [com.profilence.grpctest$eval22781 invokeStatic "NO_SOURCE_FILE" 12]
;;      [com.profilence.grpctest$eval22781 invoke "NO_SOURCE_FILE" 12]
;;      [clojure.lang.Compiler eval "Compiler.java" 7181]
;;      [clojure.lang.Compiler eval "Compiler.java" 7136]
;;      [clojure.core$eval invokeStatic "core.clj" 3202]
;;      [clojure.core$eval invoke "core.clj" 3198]
;;      [nrepl.middleware.interruptible_eval$evaluate$fn__963$fn__964 invoke "interruptible_eval.clj" 87]
;;      [clojure.lang.AFn applyToHelper "AFn.java" 152]
;;      [clojure.lang.AFn applyTo "AFn.java" 144]
;;      [clojure.core$apply invokeStatic "core.clj" 667]
;;      [clojure.core$with_bindings_STAR_ invokeStatic "core.clj" 1977]
;;      [clojure.core$with_bindings_STAR_ doInvoke "core.clj" 1977]
;;      [clojure.lang.RestFn invoke "RestFn.java" 425]
;;      [nrepl.middleware.interruptible_eval$evaluate$fn__963 invoke "interruptible_eval.clj" 87]
;;      [clojure.main$repl$read_eval_print__9112$fn__9115 invoke "main.clj" 437]
;;      [clojure.main$repl$read_eval_print__9112 invoke "main.clj" 437]
;;      [clojure.main$repl$fn__9121 invoke "main.clj" 458]
;;      [clojure.main$repl invokeStatic "main.clj" 458]
;;      [clojure.main$repl doInvoke "main.clj" 368]
;;      [clojure.lang.RestFn applyTo "RestFn.java" 137]
;;      [clojure.core$apply invokeStatic "core.clj" 667]
;;      [clojure.core$apply invoke "core.clj" 662]
;;      [refactor_nrepl.ns.slam.hound.regrow$wrap_clojure_repl$fn__16402 doInvoke "regrow.clj" 20]
;;      [clojure.lang.RestFn invoke "RestFn.java" 1523]
;;      [nrepl.middleware.interruptible_eval$evaluate invokeStatic "interruptible_eval.clj" 84]
;;      [nrepl.middleware.interruptible_eval$evaluate invoke "interruptible_eval.clj" 56]
;;      [nrepl.middleware.interruptible_eval$interruptible_eval$fn__994$fn__998 invoke "interruptible_eval.clj" 152]
;;      [clojure.lang.AFn run "AFn.java" 22]
;;      [nrepl.middleware.session$session_exec$main_loop__1062$fn__1066 invoke "session.clj" 202]
;;      [nrepl.middleware.session$session_exec$main_loop__1062 invoke "session.clj" 201]
;;      [clojure.lang.AFn run "AFn.java" 22]
;;      [java.lang.Thread run "Thread.java" 834]]}

Trace logging shows: 

[nREPL-session-9ad68c63-7bb0-4cf1-be57-eafeacf2266e] DEBUG org.eclipse.jetty.util.log - Logging to org.slf4j.impl.SimpleLogger(org.eclipse.jetty.util.log) via org.eclipse.jetty.util.log.Slf4jLog
[nREPL-session-9ad68c63-7bb0-4cf1-be57-eafeacf2266e] INFO org.eclipse.jetty.util.log - Logging initialized @52939ms to org.eclipse.jetty.util.log.Slf4jLog
[nREPL-session-9ad68c63-7bb0-4cf1-be57-eafeacf2266e] DEBUG protojure.internal.grpc.client.providers.http2.jetty - Connecting with parameters:  {:host 127.0.0.1, :port 30420, :input-buffer-size 16384, :idle-timeout nil, :ssl false}
[nREPL-session-9ad68c63-7bb0-4cf1-be57-eafeacf2266e] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - starting HTTP2Client@5c8f3a15{STOPPED}
[nREPL-session-9ad68c63-7bb0-4cf1-be57-eafeacf2266e] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - HTTP2Client@5c8f3a15{STARTING} added {QueuedThreadPool[qtp1445804310]@562d3916{STOPPED,8<=0<=200,i=0,r=-1,q=0}[NO_TRY],AUTO}
[nREPL-session-9ad68c63-7bb0-4cf1-be57-eafeacf2266e] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - HTTP2Client@5c8f3a15{STARTING} added {ScheduledExecutorScheduler@410ed882{STOPPED},AUTO}
[nREPL-session-9ad68c63-7bb0-4cf1-be57-eafeacf2266e] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - HTTP2Client@5c8f3a15{STARTING} added {org.eclipse.jetty.io.MappedByteBufferPool@2eb6d2d0,POJO}
[nREPL-session-9ad68c63-7bb0-4cf1-be57-eafeacf2266e] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - HTTP2Client@5c8f3a15{STARTING} added {org.eclipse.jetty.http2.client.HTTP2Client$$Lambda$281/0x0000000801d97c40@3adb1cc4,POJO}
[nREPL-session-9ad68c63-7bb0-4cf1-be57-eafeacf2266e] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - HTTP2Client@5c8f3a15{STARTING} added {ClientSelectorManager@2cda4010{STOPPED},AUTO}
[nREPL-session-9ad68c63-7bb0-4cf1-be57-eafeacf2266e] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - starting QueuedThreadPool[qtp1445804310]@562d3916{STOPPED,8<=0<=200,i=0,r=-1,q=0}[NO_TRY]
[nREPL-session-9ad68c63-7bb0-4cf1-be57-eafeacf2266e] DEBUG org.eclipse.jetty.util.thread.ReservedThreadExecutor - ReservedThreadExecutor@7328a76d{s=0/8,p=0}
[nREPL-session-9ad68c63-7bb0-4cf1-be57-eafeacf2266e] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - QueuedThreadPool[qtp1445804310]@562d3916{STARTING,8<=0<=200,i=0,r=-1,q=0}[ReservedThreadExecutor@7328a76d{s=0/8,p=0}] added {ReservedThreadExecutor@7328a76d{s=0/8,p=0},AUTO}
[nREPL-session-9ad68c63-7bb0-4cf1-be57-eafeacf2266e] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - starting ReservedThreadExecutor@7328a76d{s=0/8,p=0}
[nREPL-session-9ad68c63-7bb0-4cf1-be57-eafeacf2266e] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - STARTED @52964ms ReservedThreadExecutor@7328a76d{s=0/8,p=0}
[nREPL-session-9ad68c63-7bb0-4cf1-be57-eafeacf2266e] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - Starting Thread[qtp1445804310-33,5,main]
[nREPL-session-9ad68c63-7bb0-4cf1-be57-eafeacf2266e] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - Starting Thread[qtp1445804310-34,5,main]
[qtp1445804310-33] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - Runner started for QueuedThreadPool[qtp1445804310]@562d3916{STARTING,8<=2<=200,i=2,r=-1,q=0}[ReservedThreadExecutor@7328a76d{s=0/8,p=0}]
[nREPL-session-9ad68c63-7bb0-4cf1-be57-eafeacf2266e] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - Starting Thread[qtp1445804310-35,5,main]
[qtp1445804310-34] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - Runner started for QueuedThreadPool[qtp1445804310]@562d3916{STARTING,8<=3<=200,i=3,r=-1,q=0}[ReservedThreadExecutor@7328a76d{s=0/8,p=0}]
[nREPL-session-9ad68c63-7bb0-4cf1-be57-eafeacf2266e] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - Starting Thread[qtp1445804310-36,5,main]
[qtp1445804310-35] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - Runner started for QueuedThreadPool[qtp1445804310]@562d3916{STARTING,8<=4<=200,i=4,r=-1,q=0}[ReservedThreadExecutor@7328a76d{s=0/8,p=0}]
[nREPL-session-9ad68c63-7bb0-4cf1-be57-eafeacf2266e] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - Starting Thread[qtp1445804310-37,5,main]
[qtp1445804310-36] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - Runner started for QueuedThreadPool[qtp1445804310]@562d3916{STARTING,8<=5<=200,i=5,r=-1,q=0}[ReservedThreadExecutor@7328a76d{s=0/8,p=0}]
[nREPL-session-9ad68c63-7bb0-4cf1-be57-eafeacf2266e] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - Starting Thread[qtp1445804310-38,5,main]
[qtp1445804310-37] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - Runner started for QueuedThreadPool[qtp1445804310]@562d3916{STARTING,8<=6<=200,i=6,r=-1,q=0}[ReservedThreadExecutor@7328a76d{s=0/8,p=0}]
[nREPL-session-9ad68c63-7bb0-4cf1-be57-eafeacf2266e] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - Starting Thread[qtp1445804310-39,5,main]
[qtp1445804310-38] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - Runner started for QueuedThreadPool[qtp1445804310]@562d3916{STARTING,8<=7<=200,i=7,r=-1,q=0}[ReservedThreadExecutor@7328a76d{s=0/8,p=0}]
[nREPL-session-9ad68c63-7bb0-4cf1-be57-eafeacf2266e] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - Starting Thread[qtp1445804310-40,5,main]
[qtp1445804310-39] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - Runner started for QueuedThreadPool[qtp1445804310]@562d3916{STARTING,8<=8<=200,i=8,r=-1,q=0}[ReservedThreadExecutor@7328a76d{s=0/8,p=0}]
[nREPL-session-9ad68c63-7bb0-4cf1-be57-eafeacf2266e] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - STARTED @52969ms QueuedThreadPool[qtp1445804310]@562d3916{STARTED,8<=8<=200,i=8,r=8,q=0}[ReservedThreadExecutor@7328a76d{s=0/8,p=0}]
[qtp1445804310-40] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - Runner started for QueuedThreadPool[qtp1445804310]@562d3916{STARTED,8<=8<=200,i=8,r=8,q=0}[ReservedThreadExecutor@7328a76d{s=0/8,p=0}]
[nREPL-session-9ad68c63-7bb0-4cf1-be57-eafeacf2266e] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - starting ScheduledExecutorScheduler@410ed882{STOPPED}
[nREPL-session-9ad68c63-7bb0-4cf1-be57-eafeacf2266e] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - STARTED @52971ms ScheduledExecutorScheduler@410ed882{STARTED}
[nREPL-session-9ad68c63-7bb0-4cf1-be57-eafeacf2266e] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - starting ClientSelectorManager@2cda4010{STOPPED}
[nREPL-session-9ad68c63-7bb0-4cf1-be57-eafeacf2266e] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - EatWhatYouKill@5268a9a2/SelectorProducer@1f4413b1/IDLE/p=false/QueuedThreadPool[qtp1445804310]@562d3916{STARTED,8<=8<=200,i=8,r=8,q=0}[ReservedThreadExecutor@7328a76d{s=0/8,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-02-04T11:34:58.886049+02:00 added {SelectorProducer@1f4413b1,POJO}
[nREPL-session-9ad68c63-7bb0-4cf1-be57-eafeacf2266e] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - EatWhatYouKill@5268a9a2/SelectorProducer@1f4413b1/IDLE/p=false/QueuedThreadPool[qtp1445804310]@562d3916{STARTED,8<=8<=200,i=8,r=8,q=0}[ReservedThreadExecutor@7328a76d{s=0/8,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-02-04T11:34:58.886985+02:00 added {QueuedThreadPool[qtp1445804310]@562d3916{STARTED,8<=8<=200,i=8,r=8,q=0}[ReservedThreadExecutor@7328a76d{s=0/8,p=0}],UNMANAGED}
[nREPL-session-9ad68c63-7bb0-4cf1-be57-eafeacf2266e] DEBUG org.eclipse.jetty.util.thread.strategy.EatWhatYouKill - EatWhatYouKill@5268a9a2/SelectorProducer@1f4413b1/IDLE/p=false/QueuedThreadPool[qtp1445804310]@562d3916{STARTED,8<=8<=200,i=8,r=8,q=0}[ReservedThreadExecutor@7328a76d{s=0/8,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-02-04T11:34:58.88715+02:00 created
[nREPL-session-9ad68c63-7bb0-4cf1-be57-eafeacf2266e] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - ManagedSelector@30ff2384{STOPPED} id=0 keys=-1 selected=-1 updates=0 added {EatWhatYouKill@5268a9a2/SelectorProducer@1f4413b1/IDLE/p=false/QueuedThreadPool[qtp1445804310]@562d3916{STARTED,8<=8<=200,i=8,r=8,q=0}[ReservedThreadExecutor@7328a76d{s=0/8,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-02-04T11:34:58.887384+02:00,MANAGED}
[nREPL-session-9ad68c63-7bb0-4cf1-be57-eafeacf2266e] DEBUG org.eclipse.jetty.util.component.ContainerLifeCycle - ClientSelectorManager@2cda4010{STARTING} added {ManagedSelector@30ff2384{STOPPED} id=0 keys=-1 selected=-1 updates=0,AUTO}
[nREPL-session-9ad68c63-7bb0-4cf1-be57-eafeacf2266e] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - starting ManagedSelector@30ff2384{STOPPED} id=0 keys=-1 selected=-1 updates=0
[nREPL-session-9ad68c63-7bb0-4cf1-be57-eafeacf2266e] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - starting EatWhatYouKill@5268a9a2/SelectorProducer@1f4413b1/IDLE/p=false/QueuedThreadPool[qtp1445804310]@562d3916{STARTED,8<=8<=200,i=8,r=8,q=0}[ReservedThreadExecutor@7328a76d{s=0/8,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-02-04T11:34:58.887769+02:00
[nREPL-session-9ad68c63-7bb0-4cf1-be57-eafeacf2266e] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - STARTED @52990ms EatWhatYouKill@5268a9a2/SelectorProducer@1f4413b1/IDLE/p=false/QueuedThreadPool[qtp1445804310]@562d3916{STARTED,8<=8<=200,i=8,r=8,q=0}[ReservedThreadExecutor@7328a76d{s=0/8,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-02-04T11:34:58.887995+02:00
[nREPL-session-9ad68c63-7bb0-4cf1-be57-eafeacf2266e] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - queue org.eclipse.jetty.io.ManagedSelector$$Lambda$289/0x0000000801d95440@56d217db startThread=0
[qtp1445804310-33] DEBUG org.eclipse.jetty.util.thread.QueuedThreadPool - run org.eclipse.jetty.io.ManagedSelector$$Lambda$289/0x0000000801d95440@56d217db in QueuedThreadPool[qtp1445804310]@562d3916{STARTED,8<=8<=200,i=7,r=8,q=0}[ReservedThreadExecutor@7328a76d{s=0/8,p=0}]
[nREPL-session-9ad68c63-7bb0-4cf1-be57-eafeacf2266e] DEBUG org.eclipse.jetty.io.ManagedSelector - Queued change org.eclipse.jetty.io.ManagedSelector$Start@551ed0f4 on ManagedSelector@30ff2384{STARTING} id=0 keys=0 selected=0 updates=0
[qtp1445804310-33] DEBUG org.eclipse.jetty.util.thread.strategy.EatWhatYouKill - EatWhatYouKill@5268a9a2/SelectorProducer@1f4413b1/IDLE/p=false/QueuedThreadPool[qtp1445804310]@562d3916{STARTED,8<=8<=200,i=7,r=8,q=0}[ReservedThreadExecutor@7328a76d{s=0/8,p=0}][pc=0,pic=0,pec=0,epc=0]@2021-02-04T11:34:58.890799+02:00 tryProduce false
[qtp1445804310-33] DEBUG org.eclipse.jetty.io.ManagedSelector - updateable 1
[qtp1445804310-33] DEBUG org.eclipse.jetty.io.ManagedSelector - update org.eclipse.jetty.io.ManagedSelector$Start@551ed0f4
[qtp1445804310-33] DEBUG org.eclipse.jetty.io.ManagedSelector - updates 0
[qtp1445804310-33] DEBUG org.eclipse.jetty.io.ManagedSelector - Selector sun.nio.ch.EPollSelectorImpl@13922653 waiting with 0 keys
[nREPL-session-9ad68c63-7bb0-4cf1-be57-eafeacf2266e] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - STARTED @52995ms ManagedSelector@30ff2384{STARTED} id=0 keys=0 selected=0 updates=0
[nREPL-session-9ad68c63-7bb0-4cf1-be57-eafeacf2266e] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - STARTED @52995ms ClientSelectorManager@2cda4010{STARTED}
[nREPL-session-9ad68c63-7bb0-4cf1-be57-eafeacf2266e] DEBUG org.eclipse.jetty.util.component.AbstractLifeCycle - STARTED @52995ms HTTP2Client@5c8f3a15{STARTED}
[nREPL-session-9ad68c63-7bb0-4cf1-be57-eafeacf2266e] DEBUG protojure.internal.grpc.client.providers.http2.jetty - Session established: {:client #object[org.eclipse.jetty.http2.client.HTTP2Client 0x5c8f3a15 HTTP2Client@5c8f3a15{STARTED}], :session #function[protojure.internal.grpc.client.providers.http2.jetty/jetty-promise/fn--22099]}
[nREPL-session-9ad68c63-7bb0-4cf1-be57-eafeacf2266e] TRACE protojure.internal.grpc.client.providers.http2.core - Invoking GRPC "Profilence.Omicron.IssueTracking.IssueTrackingHostService/Name"
[nREPL-session-9ad68c63-7bb0-4cf1-be57-eafeacf2266e] TRACE protojure.internal.grpc.client.providers.http2.jetty - Sending request: {:method POST, :url http://127.0.0.1:30420/Profilence.Omicron.IssueTracking.IssueTrackingHostService/Name, :headers {content-type application/grpc+proto, grpc-encoding identity, grpc-accept-encoding identity,gzip,snappy,deflate}, :input-ch #object[clojure.core.async.impl.channels.ManyToManyChannel 0x4b0029b0 clojure.core.async.impl.channels.ManyToManyChannel@4b0029b0], :meta-ch #object[clojure.core.async.impl.channels.ManyToManyChannel 0x2c951c76 clojure.core.async.impl.channels.ManyToManyChannel@2c951c76], :output-ch #object[clojure.core.async.impl.channels.ManyToManyChannel 0x4440a619 clojure.core.async.impl.channels.ManyToManyChannel@4440a619]} ENDFRAME= false
[nREPL-session-9ad68c63-7bb0-4cf1-be57-eafeacf2266e] ERROR protojure.internal.grpc.client.providers.http2.core - GRPC failed: #error {
 :cause bad status response
 :data {:response #function[protojure.internal.grpc.client.providers.http2.core/receive-headers/fn--22275]}
 :via
 [{:type clojure.lang.ExceptionInfo
   :message bad status response
   :data {:response #function[protojure.internal.grpc.client.providers.http2.core/receive-headers/fn--22275]}
   :at [protojure.internal.grpc.client.providers.http2.core$receive_payload invokeStatic core.clj 116]}]
 :trace
 [[protojure.internal.grpc.client.providers.http2.core$receive_payload invokeStatic core.clj 116]
  [protojure.internal.grpc.client.providers.http2.core$receive_payload invoke core.clj 101]
  [clojure.lang.AFn applyToHelper AFn.java 171]
  [clojure.lang.AFn applyTo AFn.java 144]
  [clojure.core$apply invokeStatic core.clj 673]
  [clojure.core$partial$fn__5864 doInvoke core.clj 2647]
  [clojure.lang.RestFn invoke RestFn.java 408]
  [clojure.core$comp$fn__5826 invoke core.clj 2573]
  [promesa.util.FunctionWrapper apply util.cljc 43]
  [java.util.concurrent.CompletableFuture uniComposeStage CompletableFuture.java 1106]
  [java.util.concurrent.CompletableFuture thenCompose CompletableFuture.java 2235]
  [java.util.concurrent.CompletableFuture thenCompose CompletableFuture.java 143]
  [promesa.impl$eval21268$fn__21273 invoke impl.cljc 164]
  [promesa.protocols$eval20720$fn__20721$G__20703__20734 invoke protocols.cljc 28]
  [promesa.core$then invokeStatic core.cljc 153]
  [promesa.core$then invoke core.cljc 143]
  [protojure.internal.grpc.client.providers.http2.core$client_receive invokeStatic core.clj 123]
  [protojure.internal.grpc.client.providers.http2.core$client_receive invoke core.clj 121]
  [protojure.internal.grpc.client.providers.http2.core.Http2Provider$fn__22473 invoke core.clj 147]
  [clojure.core$comp$fn__5826 invoke core.clj 2573]
  [promesa.util.FunctionWrapper apply util.cljc 43]
  [java.util.concurrent.CompletableFuture uniComposeStage CompletableFuture.java 1106]
  [java.util.concurrent.CompletableFuture thenCompose CompletableFuture.java 2235]
  [java.util.concurrent.CompletableFuture thenCompose CompletableFuture.java 143]
  [promesa.impl$eval21268$fn__21273 invoke impl.cljc 164]
  [promesa.protocols$eval20720$fn__20721$G__20703__20734 invoke protocols.cljc 28]
  [promesa.core$then invokeStatic core.cljc 153]
  [promesa.core$then invoke core.cljc 143]
  [protojure.internal.grpc.client.providers.http2.core.Http2Provider invoke core.clj 142]
  [protojure.grpc.client.utils$invoke_unary invokeStatic utils.clj 56]
  [protojure.grpc.client.utils$invoke_unary invoke utils.clj 42]
  [Profilence.Omicron.IssueTracking.IssueTrackingHostService.client$Name$fn__21599 invoke client.cljc 27]
  [clojure.core$comp$fn__5826 invoke core.clj 2573]
  [promesa.util.FunctionWrapper apply util.cljc 43]
  [java.util.concurrent.CompletableFuture uniComposeStage CompletableFuture.java 1106]
  [java.util.concurrent.CompletableFuture thenCompose CompletableFuture.java 2235]
  [java.util.concurrent.CompletableFuture thenCompose CompletableFuture.java 143]
  [promesa.impl$eval21268$fn__21273 invoke impl.cljc 164]
  [promesa.protocols$eval20720$fn__20721$G__20703__20734 invoke protocols.cljc 28]
  [promesa.core$then invokeStatic core.cljc 153]
  [promesa.core$then invoke core.cljc 143]
  [Profilence.Omicron.IssueTracking.IssueTrackingHostService.client$Name invokeStatic client.cljc 27]
  [Profilence.Omicron.IssueTracking.IssueTrackingHostService.client$Name invoke client.cljc 18]
  [com.profilence.grpctest$eval22777 invokeStatic NO_SOURCE_FILE 12]
  [com.profilence.grpctest$eval22777 invoke NO_SOURCE_FILE 12]
  [clojure.lang.Compiler eval Compiler.java 7181]
  [clojure.lang.Compiler eval Compiler.java 7136]
  [clojure.core$eval invokeStatic core.clj 3202]
  [clojure.core$eval invoke core.clj 3198]
  [nrepl.middleware.interruptible_eval$evaluate$fn__963$fn__964 invoke interruptible_eval.clj 87]
  [clojure.lang.AFn applyToHelper AFn.java 152]
  [clojure.lang.AFn applyTo AFn.java 144]
  [clojure.core$apply invokeStatic core.clj 667]
  [clojure.core$with_bindings_STAR_ invokeStatic core.clj 1977]
  [clojure.core$with_bindings_STAR_ doInvoke core.clj 1977]
  [clojure.lang.RestFn invoke RestFn.java 425]
  [nrepl.middleware.interruptible_eval$evaluate$fn__963 invoke interruptible_eval.clj 87]
  [clojure.main$repl$read_eval_print__9112$fn__9115 invoke main.clj 437]
  [clojure.main$repl$read_eval_print__9112 invoke main.clj 437]
  [clojure.main$repl$fn__9121 invoke main.clj 458]
  [clojure.main$repl invokeStatic main.clj 458]
  [clojure.main$repl doInvoke main.clj 368]
  [clojure.lang.RestFn applyTo RestFn.java 137]
  [clojure.core$apply invokeStatic core.clj 667]
  [clojure.core$apply invoke core.clj 662]
  [refactor_nrepl.ns.slam.hound.regrow$wrap_clojure_repl$fn__16402 doInvoke regrow.clj 20]
  [clojure.lang.RestFn invoke RestFn.java 1523]
  [nrepl.middleware.interruptible_eval$evaluate invokeStatic interruptible_eval.clj 84]
  [nrepl.middleware.interruptible_eval$evaluate invoke interruptible_eval.clj 56]
  [nrepl.middleware.interruptible_eval$interruptible_eval$fn__994$fn__998 invoke interruptible_eval.clj 152]
  [clojure.lang.AFn run AFn.java 22]
  [nrepl.middleware.session$session_exec$main_loop__1062$fn__1066 invoke session.clj 202]
  [nrepl.middleware.session$session_exec$main_loop__1062 invoke session.clj 201]
  [clojure.lang.AFn run AFn.java 22]
  [java.lang.Thread run Thread.java 834]]}
[nREPL-session-9ad68c63-7bb0-4cf1-be57-eafeacf2266e] DEBUG protojure.internal.grpc.client.providers.http2.core - closing output

The interesting thing, however, is that I'm running Wireshark, sniffing for localhost traffic to the service port, and no packets are seen (however, if I run telnet 127.0.0.1 30420, I see traffic, so the capture seems to be well setup).

I run the code in the cider debugger, and it seems that the issue is somewhere in protojure.internal.grpc.client.providers.http2.core/receive-payload 

(defn- receive-payload
  "Handles all remaining response payload, which consists of both response body and trailers.
  We process them in parallel since we can't be sure that the server won't interleave HEADER
  and DATA frames, even though we don't expect this to be a normal ordering.  We _could_
  probably get away with draining the queues serially (data-ch and then meta-ch) but we would
  run the risk of stalling the pipeline if the meta-ch were to fill"
  [codecs meta-ch data-ch output {:keys [status] :as response}]
  (if (-> status (= 200))
    (-> (p/all [(receive-body codecs data-ch output response)
                (receive-trailers meta-ch response)])
        (p/then (fn [[_ {:keys [headers] :as response}]] ;; [body-response trailers-response]
                  (let [{:keys [status] :as resp} (decode-grpc-status headers)]
                    (if (zero? status)
                      resp
                      (p/rejected (ex-info "bad grpc-status response" (assoc resp :meta {:response response}))))))))
    (p/rejected (ex-info "bad status response" {:response response}))))

It seems that receive-payload expects a map in response, but the actual value for it is 

#function[protojure.internal.grpc.client.providers.http2.core/receive-headers/fn--22275]

I've checked whether that function might behave as a map (didn't seem likely, from the name), and it does not (calling it with :status as a parameter throws).

Any ideas of what could be the cause for this error? I'm currently at a loss...

matheusfrancisco commented 3 years ago

@mvarela We have got this problem too, I discover that some lib use [funcool/promesa "6.0.0"] and protojure use [funcool/promesa "3.0.0"] and We're using deps.edn and remove :exclusions [funcool/promesa], but we're trying to fix this problem too, but We don't have some idiomatic solution yet.

ghaskins commented 3 years ago

IIRC, theres just a small amount of work to do to port to promesa 6.0.0, largely in the area of p/promise -> p/create. Is this the only issue, or is something broken too?

mvarela commented 3 years ago

This is the only issue I've noticed. Thanks for having a look!

ghaskins commented 3 years ago

Just an update that I took a look at upgrading from promesa 3.0.0 to 6.0.0, but ran into a snag where the UTs were failing and I havent had a chance to track it down. Will address when I can.

mvarela commented 3 years ago

Thanks, Gregory!

ghaskins commented 2 years ago

FYI v1.7.0 was released with an update to promesa v6.0