What happened to the logging configuration

1

Since upgrading to version 1.3.2 from version 1.2.1 of the java-protobuf SDK it seems that the logback.xml that I provide with the service is ignored.

By default the following levels are configured:

<logger name="akka" level="INFO"/>
<logger name="kalix" level="INFO"/>
<logger name="akka.http" level="INFO"/>
<logger name="io.grpc" level="INFO"/>

What I now see in the logs on Kalix Console is:

16:58:52.462 [main] DEBUG kalix.javasdk.impl.AnySupport -- Attempting to load class com.google.protobuf.StringValue
16:58:53.497 [kalix-akka.actor.default-dispatcher-6] DEBUG akka.actor.ActorSystemImpl -- Binding server using HTTP/2
16:59:04.918 [kalix-akka.actor.default-dispatcher-6] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Changing state from Idle to WaitingForNetworkToSendControlFrames

Especially the Http2ServerDemux logs a lot of messages.

I even tried to add

<logger name="akka.http.impl.engine.http2.Http2ServerDemux" level="INFO"/>

It does not silence the debug output.

There is fix: load logback-dev-mode.xml using Configurator by octonato · Pull Request #1719 · lightbend/kalix-jvm-sdk · GitHub which seems related, but does not mention a change on how the logback.xml is read.

I have the logback.xml in src/main/resources.

I hope someone is able to push me in the right direction on how to fix this logging issue.

Kind regards,
Richard

2

Hi Richard,

I tried some different configs but I’m not being able to replicate the issue. Would you be able to provide some more details:

  • upon start, there should be some logs from ch.qos.logback.*, could you show what they say?
  • which logback files do you have on the project and what are their locations?
  • I assume you’re seeing this behaviour when running locally, is this correct? if so, running with the IDE or by command line? With which command?

Thanks

3

I see this behavior running locally and when deployed. And I just tried version 1.3.0, thats when I get logback output, but when I run with versions 1.3.1 I get the output I posted.

With version 1.3.0

2023-08-03T15:20:11.185898813Z 15:20:11,092 |-INFO in ch.qos.logback.classic.LoggerContext[default] - This is logback-classic version ?
2023-08-03T15:20:11.185952668Z 15:20:11,108 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
2023-08-03T15:20:11.186018747Z 15:20:11,114 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [jar:file:/maven/mercury-1.8.10-SNAPSHOT.jar!/logback.xml]
2023-08-03T15:20:11.186050102Z 15:20:11,117 |-INFO in ch.qos.logback.core.joran.spi.ConfigurationWatchList@13a5fe33 - URL [jar:file:/maven/mercury-1.8.10-SNAPSHOT.jar!/logback.xml] is not of type file
2023-08-03T15:20:11.187211392Z 15:20:11,187 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - Processing appender named [JSON-STDOUT]
2023-08-03T15:20:11.187338453Z 15:20:11,187 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
2023-08-03T15:20:11.265137151Z 15:20:11,264 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - Processing appender named [ASYNC-JSON-STDOUT]
2023-08-03T15:20:11.265177896Z 15:20:11,265 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - About to instantiate appender of type [ch.qos.logback.classic.AsyncAppender]
2023-08-03T15:20:11.266953760Z 15:20:11,266 |-INFO in ch.qos.logback.core.model.processor.AppenderRefModelHandler - Attaching appender named [JSON-STDOUT] to ch.qos.logback.classic.AsyncAppender[ASYNC-JSON-STDOUT]
2023-08-03T15:20:11.267392623Z 15:20:11,267 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNC-JSON-STDOUT] - Attaching appender named [JSON-STDOUT] to AsyncAppender.
2023-08-03T15:20:11.269495810Z 15:20:11,269 |-INFO in ch.qos.logback.classic.AsyncAppender[ASYNC-JSON-STDOUT] - Setting discardingThreshold to 1638
2023-08-03T15:20:11.269686061Z 15:20:11,269 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - Processing appender named [SLACK]
2023-08-03T15:20:11.269692936Z 15:20:11,269 |-INFO in ch.qos.logback.core.model.processor.AppenderModelHandler - About to instantiate appender of type [nl.thriven.logging.SlackAppender]
2023-08-03T15:20:11.397031600Z 15:20:11,396 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [akka] to INFO
2023-08-03T15:20:11.397086836Z 15:20:11,397 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [kalix] to INFO
2023-08-03T15:20:11.397110892Z 15:20:11,397 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [akka.http] to INFO
2023-08-03T15:20:11.397173882Z 15:20:11,397 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [io.grpc] to INFO
2023-08-03T15:20:11.397244073Z 15:20:11,397 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [akka.http.impl.engine.http2.Http2ServerDemux] to INFO
2023-08-03T15:20:11.397250151Z 15:20:11,397 |-INFO in ch.qos.logback.classic.model.processor.LoggerModelHandler - Setting level of logger [nl.thriven] to DEBUG
2023-08-03T15:20:11.397397539Z 15:20:11,397 |-INFO in ch.qos.logback.classic.model.processor.RootLoggerModelHandler - Setting level of ROOT logger to INFO
2023-08-03T15:20:11.397468333Z 15:20:11,397 |-INFO in ch.qos.logback.core.model.processor.AppenderRefModelHandler - Attaching appender named [ASYNC-JSON-STDOUT] to Logger[ROOT]
2023-08-03T15:20:11.397490969Z 15:20:11,397 |-INFO in ch.qos.logback.core.model.processor.AppenderRefModelHandler - Attaching appender named [SLACK] to Logger[ROOT]
2023-08-03T15:20:11.397656594Z 15:20:11,397 |-INFO in ch.qos.logback.core.model.processor.DefaultProcessor@6f53b8a - End of configuration.
2023-08-03T15:20:11.397941917Z 15:20:11,397 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@4007f65e - Registering current configuration as safe fallback point
2023-08-03T15:20:11.405850031Z {"timestamp":"2023-08-03T15:20:11.398Z","thread":"main","logger":"nl.thriven.Main","message":"starting the Akka Serverless service","context":"default","severity":"INFO"}
2023-08-03T15:20:11.768253007Z {"timestamp":"2023-08-03T15:20:11.767Z","thread":"kalix-akka.actor.default-dispatcher-3","logger":"akka.event.slf4j.Slf4jLogger","message":"Slf4jLogger started","context":"default","severity":"INFO"}
2023-08-03T15:20:18.315714712Z {"timestamp":"2023-08-03T15:20:18.314Z","thread":"kalix-akka.actor.default-dispatcher-6","logger":"kalix.javasdk.impl.DiscoveryImpl","message":"Received discovery call from [kalix-proxy-core 1.1.16] at [localhost]:[9000] supporting Kalix protocol 1.1","context":"default","severity":"INFO"}
2023-08-03T15:20:19.394659788Z {"timestamp":"2023-08-03T15:20:19.394Z","thread":"kalix-akka.actor.default-dispatcher-3","logger":"kalix.javasdk.impl.DiscoveryImpl","message":"Info reported from Kalix system:  Service started and reachable at 0.0.0.0:9000","context":"default","severity":"INFO"}

After changing the SDK versions to 1.3.1

2023-08-03T15:21:54.205862474Z 15:21:54.204 [main] INFO nl.thriven.Main -- starting the Akka Serverless service
2023-08-03T15:21:54.337661517Z 15:21:54.337 [main] DEBUG kalix.javasdk.impl.AnySupport -- Attempting to load class com.google.protobuf.Empty
... More classes loading...
2023-08-03T15:21:54.583436313Z 15:21:54.583 [kalix-akka.actor.default-dispatcher-3] INFO akka.event.slf4j.Slf4jLogger -- Slf4jLogger started
2023-08-03T15:21:54.585726065Z 15:21:54.585 [kalix-akka.actor.default-dispatcher-3] DEBUG akka.event.EventStream -- logger log1-Slf4jLogger started
2023-08-03T15:21:54.585747101Z 15:21:54.585 [kalix-akka.actor.default-dispatcher-3] DEBUG akka.event.EventStream -- Default Loggers started
2023-08-03T15:21:54.602951520Z 15:21:54.602 [kalix-akka.actor.default-dispatcher-3] DEBUG akka.serialization.Serialization(akka://kalix) -- Replacing JavaSerializer with DisabledJavaSerializer, due to `akka.actor.allow-java-serialization = off`.
2023-08-03T15:21:54.620880840Z 15:21:54.620 [main] DEBUG kalix.javasdk.KalixRunner -- JVM [OpenJDK Runtime Environment 17.0.7+7], max heap [8004 MB], processors [32]
2023-08-03T15:21:54.738637631Z 15:21:54.738 [kalix-akka.actor.default-dispatcher-3] DEBUG akka.actor.ActorSystemImpl -- Binding server using HTTP/2
2023-08-03T15:21:54.815661206Z 15:21:54.815 [kalix-akka.actor.default-dispatcher-3] DEBUG akka.io.TcpListener -- Successfully bound to /0.0.0.0:8080
2023-08-03T15:21:54.819003614Z 15:21:54.818 [kalix-akka.actor.default-dispatcher-2] DEBUG akka.actor.ActorSystemImpl -- gRPC server started 0.0.0.0:8080
2023-08-03T15:21:54.966007052Z 15:21:54.965 [kalix-akka.actor.default-dispatcher-3] DEBUG akka.io.TcpListener -- New connection accepted
2023-08-03T15:21:55.000972186Z 15:21:55.000 [kalix-akka.actor.default-dispatcher-3] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Changing state from Idle to WaitingForNetworkToSendControlFrames
2023-08-03T15:21:55.001236863Z 15:21:55.001 [kalix-akka.actor.default-dispatcher-3] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Changing state from WaitingForNetworkToSendControlFrames to Idle
2023-08-03T15:21:55.006792048Z 15:21:55.006 [kalix-akka.actor.default-dispatcher-3] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Got 4 settings!
2023-08-03T15:21:55.006809247Z 15:21:55.006 [kalix-akka.actor.default-dispatcher-3] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Ignoring setting SETTINGS_ENABLE_PUSH -> 0 (in Demux)
2023-08-03T15:21:55.006919218Z 15:21:55.006 [kalix-akka.actor.default-dispatcher-3] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Setting initial window to 1048576
2023-08-03T15:21:55.008436512Z 15:21:55.008 [kalix-akka.actor.default-dispatcher-3] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Ignoring setting SETTINGS_MAX_HEADER_LIST_SIZE -> 8192 (in Demux)
2023-08-03T15:21:55.008472867Z 15:21:55.008 [kalix-akka.actor.default-dispatcher-3] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Changing state from Idle to WaitingForNetworkToSendControlFrames
2023-08-03T15:21:55.008481465Z 15:21:55.008 [kalix-akka.actor.default-dispatcher-3] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Updating outgoing connection window by 983041 to 1048576
2023-08-03T15:21:55.008837327Z 15:21:55.008 [kalix-akka.actor.default-dispatcher-3] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Changing state from WaitingForNetworkToSendControlFrames to Idle
2023-08-03T15:21:55.009746047Z 15:21:55.009 [kalix-akka.actor.default-dispatcher-3] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Changing state from Idle to WaitingForData
2023-08-03T15:21:55.036323261Z 15:21:55.036 [kalix-akka.actor.default-dispatcher-2] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Incoming side of stream [3] changed state: Idle -> CollectingIncomingData after handling [handleStreamEvent(ParsedHeadersFrame)]
2023-08-03T15:21:55.036761992Z 15:21:55.036 [kalix-akka.actor.default-dispatcher-2] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Changing state from WaitingForData to Idle
2023-08-03T15:21:55.036779765Z 15:21:55.036 [kalix-akka.actor.default-dispatcher-2] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Incoming side of stream [3] changed state: CollectingIncomingData -> HalfClosedRemoteWaitingForOutgoingStream after handling [handleStreamEvent(DataFrame)]
2023-08-03T15:21:55.038278602Z 15:21:55.037 [kalix-akka.actor.default-dispatcher-4] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Changing state from Idle to WaitingForData
2023-08-03T15:21:55.050101110Z 15:21:55.049 [kalix-akka.actor.default-dispatcher-2] INFO kalix.javasdk.impl.DiscoveryImpl -- Received discovery call from [kalix-proxy-core 1.1.16] at [localhost]:[9000] supporting Kalix protocol 1.1
2023-08-03T15:21:55.050431114Z 15:21:55.050 [kalix-akka.actor.default-dispatcher-2] DEBUG kalix.javasdk.impl.ProxyInfoHolder -- Proxy hostname: [localhost]
2023-08-03T15:21:55.050447346Z 15:21:55.050 [kalix-akka.actor.default-dispatcher-2] DEBUG kalix.javasdk.impl.ProxyInfoHolder -- Proxy port to: [9000]
2023-08-03T15:21:55.050575919Z 15:21:55.050 [kalix-akka.actor.default-dispatcher-2] DEBUG kalix.javasdk.impl.ProxyInfoHolder -- Identification name: [Some(IdentificationInfo(impersonate-kalix-service,self,impersonate-kalix-service,self,UnknownFieldSet(Map())))]
2023-08-03T15:21:55.056286177Z 15:21:55.056 [kalix-akka.actor.default-dispatcher-2] DEBUG kalix.javasdk.impl.DiscoveryImpl -- Supported sidecar entity types: [kalix.component.valueentity.ValueEntities,kalix.component.eventsourcedentity.EventSourcedEntities,kalix.component.view.Views,kalix.component.workflow.WorkflowEntities,kalix.component.replicatedentity.ReplicatedEntities,kalix.component.action.Actions]
2023-08-03T15:21:55.083020698Z 15:21:55.082 [kalix-akka.actor.default-dispatcher-3] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Changing state from WaitingForData to Idle
2023-08-03T15:21:55.084332836Z 15:21:55.084 [kalix-akka.actor.default-dispatcher-3] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Changing state from Idle to WaitingForNetworkToSendData
2023-08-03T15:21:55.084346605Z 15:21:55.084 [kalix-akka.actor.default-dispatcher-3] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Updating window for 3 by 0 to 1048576 buffered bytes: 78716
2023-08-03T15:21:55.084569447Z 15:21:55.084 [kalix-akka.actor.default-dispatcher-3] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Incoming side of stream [3] changed state: HalfClosedRemoteWaitingForOutgoingStream -> HalfClosedRemoteSendingData after handling [handleOutgoingCreated]
2023-08-03T15:21:55.085698889Z 15:21:55.085 [kalix-akka.actor.default-dispatcher-3] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- [3] sending 16384 bytes, endStream = false, remaining buffer [62332], remaining stream-level WINDOW [1032192]
2023-08-03T15:21:55.085965332Z 15:21:55.085 [kalix-akka.actor.default-dispatcher-3] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Incoming side of stream [3] changed state: HalfClosedRemoteSendingData -> HalfClosedRemoteSendingData after handling [pullNextFrame]
2023-08-03T15:21:55.086341304Z 15:21:55.086 [kalix-akka.actor.default-dispatcher-2] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- [3] sending 16384 bytes, endStream = false, remaining buffer [45948], remaining stream-level WINDOW [1015808]
2023-08-03T15:21:55.086533628Z 15:21:55.086 [kalix-akka.actor.default-dispatcher-2] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Incoming side of stream [3] changed state: HalfClosedRemoteSendingData -> HalfClosedRemoteSendingData after handling [pullNextFrame]
2023-08-03T15:21:55.086676733Z 15:21:55.086 [kalix-akka.actor.default-dispatcher-2] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- [3] sending 16384 bytes, endStream = false, remaining buffer [29564], remaining stream-level WINDOW [999424]
2023-08-03T15:21:55.086691099Z 15:21:55.086 [kalix-akka.actor.default-dispatcher-2] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Incoming side of stream [3] changed state: HalfClosedRemoteSendingData -> HalfClosedRemoteSendingData after handling [pullNextFrame]
2023-08-03T15:21:55.087042746Z 15:21:55.086 [kalix-akka.actor.default-dispatcher-2] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- [3] sending 16384 bytes, endStream = false, remaining buffer [13180], remaining stream-level WINDOW [983040]
2023-08-03T15:21:55.087097265Z 15:21:55.087 [kalix-akka.actor.default-dispatcher-2] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Incoming side of stream [3] changed state: HalfClosedRemoteSendingData -> HalfClosedRemoteSendingData after handling [pullNextFrame]
2023-08-03T15:21:55.087670155Z 15:21:55.087 [kalix-akka.actor.default-dispatcher-3] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- [3] sending 13180 bytes, endStream = false, remaining buffer [0], remaining stream-level WINDOW [969860]
2023-08-03T15:21:55.087700499Z 15:21:55.087 [kalix-akka.actor.default-dispatcher-3] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Incoming side of stream [3] changed state: HalfClosedRemoteSendingData -> Closed after handling [pullNextFrame]
2023-08-03T15:21:55.087776912Z 15:21:55.087 [kalix-akka.actor.default-dispatcher-3] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Changing state from WaitingForNetworkToSendData to WaitingForNetworkToSendControlFrames
2023-08-03T15:21:55.088127986Z 15:21:55.087 [kalix-akka.actor.default-dispatcher-3] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Changing state from WaitingForNetworkToSendControlFrames to Idle
2023-08-03T15:21:55.088156603Z 15:21:55.088 [kalix-akka.actor.default-dispatcher-3] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Changing state from Idle to WaitingForData
2023-08-03T15:21:55.259421376Z 15:21:55.259 [kalix-akka.actor.default-dispatcher-6] DEBUG akka.io.TcpListener -- New connection accepted
2023-08-03T15:21:55.263588585Z 15:21:55.263 [kalix-akka.actor.default-dispatcher-6] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Changing state from Idle to WaitingForNetworkToSendControlFrames
2023-08-03T15:21:55.263646504Z 15:21:55.263 [kalix-akka.actor.default-dispatcher-6] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Changing state from WaitingForNetworkToSendControlFrames to Idle
2023-08-03T15:21:55.263946221Z 15:21:55.263 [kalix-akka.actor.default-dispatcher-7] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Got 4 settings!
2023-08-03T15:21:55.264005755Z 15:21:55.263 [kalix-akka.actor.default-dispatcher-7] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Ignoring setting SETTINGS_ENABLE_PUSH -> 0 (in Demux)
2023-08-03T15:21:55.264036414Z 15:21:55.263 [kalix-akka.actor.default-dispatcher-7] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Setting initial window to 1048576
2023-08-03T15:21:55.265037673Z 15:21:55.264 [kalix-akka.actor.default-dispatcher-7] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Ignoring setting SETTINGS_MAX_HEADER_LIST_SIZE -> 8192 (in Demux)
2023-08-03T15:21:55.265077889Z 15:21:55.264 [kalix-akka.actor.default-dispatcher-7] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Changing state from Idle to WaitingForNetworkToSendControlFrames
2023-08-03T15:21:55.265084329Z 15:21:55.264 [kalix-akka.actor.default-dispatcher-7] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Updating outgoing connection window by 983041 to 1048576
2023-08-03T15:21:55.265087646Z 15:21:55.264 [kalix-akka.actor.default-dispatcher-7] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Changing state from WaitingForNetworkToSendControlFrames to Idle
2023-08-03T15:21:55.265304390Z 15:21:55.265 [kalix-akka.actor.default-dispatcher-7] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Changing state from Idle to WaitingForData
2023-08-03T15:21:55.268249921Z 15:21:55.268 [kalix-akka.actor.default-dispatcher-6] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Incoming side of stream [3] changed state: Idle -> CollectingIncomingData after handling [handleStreamEvent(ParsedHeadersFrame)]
2023-08-03T15:21:55.268294356Z 15:21:55.268 [kalix-akka.actor.default-dispatcher-6] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Changing state from WaitingForData to Idle
2023-08-03T15:21:55.268325445Z 15:21:55.268 [kalix-akka.actor.default-dispatcher-6] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Incoming side of stream [3] changed state: CollectingIncomingData -> HalfClosedRemoteWaitingForOutgoingStream after handling [handleStreamEvent(DataFrame)]
2023-08-03T15:21:55.268356383Z 15:21:55.268 [kalix-akka.actor.default-dispatcher-6] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Changing state from Idle to WaitingForData
2023-08-03T15:21:55.271224745Z 15:21:55.271 [kalix-akka.actor.default-dispatcher-7] WARN kalix.javasdk.impl.DiscoveryImpl -- Warning reported from Kalix system: KLX-00011 A newer version of the kalix-java-protobuf-sdk [1.3.2] is available. Your current version is [1.3.1].
2023-08-03T15:21:55.271248875Z
2023-08-03T15:21:55.271250358Z To fix this issue, update the version of kalix-java-protobuf-sdk in your Kalix service. Then build and deploy a new version of it.
2023-08-03T15:21:55.271723912Z 15:21:55.271 [kalix-akka.actor.default-dispatcher-7] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Changing state from WaitingForData to Idle
2023-08-03T15:21:55.271733238Z 15:21:55.271 [kalix-akka.actor.default-dispatcher-7] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Changing state from Idle to WaitingForNetworkToSendData
2023-08-03T15:21:55.271740540Z 15:21:55.271 [kalix-akka.actor.default-dispatcher-7] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Updating window for 3 by 0 to 1048576 buffered bytes: 5
2023-08-03T15:21:55.271765019Z 15:21:55.271 [kalix-akka.actor.default-dispatcher-7] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Incoming side of stream [3] changed state: HalfClosedRemoteWaitingForOutgoingStream -> HalfClosedRemoteSendingData after handling [handleOutgoingCreated]
2023-08-03T15:21:55.272776170Z 15:21:55.272 [kalix-akka.actor.default-dispatcher-7] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- [3] sending 5 bytes, endStream = false, remaining buffer [0], remaining stream-level WINDOW [1048571]
2023-08-03T15:21:55.272808967Z 15:21:55.272 [kalix-akka.actor.default-dispatcher-7] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Incoming side of stream [3] changed state: HalfClosedRemoteSendingData -> Closed after handling [pullNextFrame]
2023-08-03T15:21:55.272815525Z 15:21:55.272 [kalix-akka.actor.default-dispatcher-7] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Changing state from WaitingForNetworkToSendData to WaitingForNetworkToSendControlFrames
2023-08-03T15:21:55.272988302Z 15:21:55.272 [kalix-akka.actor.default-dispatcher-7] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Changing state from WaitingForNetworkToSendControlFrames to Idle
2023-08-03T15:21:55.273354649Z 15:21:55.273 [kalix-akka.actor.default-dispatcher-7] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Changing state from Idle to WaitingForData
2023-08-03T15:21:56.540701754Z 15:21:56.540 [kalix-akka.actor.default-dispatcher-3] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Incoming side of stream [5] changed state: Idle -> CollectingIncomingData after handling [handleStreamEvent(ParsedHeadersFrame)]
2023-08-03T15:21:56.540737222Z 15:21:56.540 [kalix-akka.actor.default-dispatcher-3] DEBUG akka.http.impl.engine.http2.Http2ServerDemux -- Incoming side of stream [5] changed state: CollectingIncomingData -> HalfClosedRemoteWaitingForOutgoingStream after handling [handleStreamEvent(DataFrame)]
2023-08-03T15:21:56.540850212Z 15:21:56.540 [kalix-akka.actor.default-dispatcher-7] INFO kalix.javasdk.impl.DiscoveryImpl -- Info reported from Kalix system:  Service started and reachable at 0.0.0.0:9000

I launch it using the docker-compose, I’ve added the image as service.
To me it seems that something changed in the SDK, because the only thing I change is the version number, clean and package it, and then start the application.

I’ve observed this behaviour when running locally and when deployed on Kalix.

I have 2 logback files:

  • src/main/resources/logback.xml
  • src/test/resources/logback-test.xml
4

Oh, I definitely think it’s related with the PR you mentioned in the initial message as well. I just wasn’t able to reproduce it and that makes it a bit harder to know how to fix it, of course.

On some of the latest releases we have made some changes (some related to logs) which we believe provide for much better developer experience. One of those is that, by default, we try to have logs in plain-text other than JSON (much easier to read and follow).

My suspicion is that in your case, since you’re moving from an older version there might be some old config left that shouldn’t be there anymore and might be causing you these troubles.

To fix it, my first suggestion would be for you to add a file called logback-dev-mode.xml with the following contents, along side the existing logback.xml:

<?xml version="1.0" encoding="utf-8"?>
<!-- Non json config for Kalix user dev modes, note that for actual deploy
     the default sample JSON logging output must be used or else production
     does not work -->
<configuration>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} %-5level %logger{36} - %msg%n</pattern>
        </encoder>
    </appender>

    <!-- Silence some details from Akka, should not be important to user/SDK dev mode -->
    <logger name="akka" level="WARN"/>

    <root level="INFO">
        <appender-ref ref="STDOUT"/>
    </root>

</configuration>

You can also add this option -Dlogback.configurationFile=logback-dev-mode.xml on your JAVA_TOOL_OPTIONS in docker-compose.yml so the proxy logs are also in plain text.

Additionally, what command are you using to run the service locally? mvn exec:exec? Can you try mvn kalix:run if that’s not the one you’re using currently?

If neither of these work as expected, if you can send a minimal reproducer that I can run locally, that can make it easier to spot the problem.

5

Unfortunately adding the logback-dev-mode.xml did not change the output of the service.

I do not use a maven command/plugin to run the service locally, I have added the container image to the docker-compose.yml in order to start all service using docker-compose.

I’m unable to use kalix:run as I can not add environment variables to the command, which I use to provide the values of secrets, which I am able to do using exec:exec command.
When using exec:exec the output is as expected.
Only when I run the service using docker-compose I see the same output as I’ve seen when the service is deployed on Kalix.

To reproduce this, take the java-protobuf-customer-registry-quickstart, mvn install, adjust the docker-compose.yml to (You need to adjust the customer-registry image to your local build timestamp)

# If you're looking to use eventing with Google PubSub, to get an emulator running:
# - add property "-Dkalix.proxy.eventing.support=google-pubsub-emulator" to the JAVA_TOOL_OPTIONS environment map under the kalix-proxy service
# - uncomment the env var PUBSUB_EMULATOR_HOST and the section below for gcloud-pubsub-emulator service
version: "3"
services:
  kalix-proxy:
    image: gcr.io/kalix-public/kalix-proxy:1.1.16
    ports:
      - "9000:9000"
    extra_hosts:
      - "host.docker.internal:host-gateway"
    environment:
      JAVA_TOOL_OPTIONS: >
        -Dconfig.resource=dev-mode.conf
        -Dlogback.configurationFile=logback-dev-mode.xml
      USER_FUNCTION_HOST: ${USER_FUNCTION_HOST:-my-first-service}
      USER_FUNCTION_PORT: ${USER_FUNCTION_PORT:-8080}
      #PUBSUB_EMULATOR_HOST: gcloud-pubsub-emulator
  #gcloud-pubsub-emulator:
  #  image: gcr.io/google.com/cloudsdktool/cloud-sdk:341.0.0
  #  command: gcloud beta emulators pubsub start --project=test --host-port=0.0.0.0:8085
  #  ports:
  #    - 8085:8085
  customer-registry:
    image: my-docker-repo/customer-registry:1.0-SNAPSHOT-20230806115623
    ports:
      - '8080:8080'
    environment:
      HOST: 0.0.0.0

And after docker-compose up, I see the same logging of the Http2ServerDemux as I posted.
I hope this helps in reproducing.

Richard

6

Thanks for the reproducer. I missed the bit that you were running it inside docker compose previously, my bad.

I raised this issue so we can have a look at it.

7

Not a problem, I see it is already fixed, thank you for the quick response!

8

The fix for this is now released with JVM SDKs v1.3.3. Thanks.