Telemetry data feedback

Camunda 7 Topics Discussion & Questions
1

I’m using latest Camunda 7.14.0-alpha1 together with Wildfly 20 in my test environment and enabled sending of telemetry data.
A few hours ago this appeared in wildfly’s server.log:

08.07. 12:13:12,560 FINE  [camundajar.impl.org.apache.http.client.protocol.RequestAddCookies#process] CookieSpec selected: default
08.07. 12:13:12,617 FINE  [camundajar.impl.org.apache.http.client.protocol.RequestAuthCache#process] Auth cache not set in the context
08.07. 12:13:12,629 FINE  [camundajar.impl.org.apache.http.impl.conn.PoolingHttpClientConnectionManager#requestConnection] Connection request: [route: {s}->https://api.telemetry.camunda.cloud:443][total kept alive: 0; route allocated: 0 of 5; total allocated: 0 of 10]
08.07. 12:13:12,737 FINE  [camundajar.impl.org.apache.http.impl.conn.PoolingHttpClientConnectionManager#leaseConnection] Connection leased: [id: 0][route: {s}->https://api.telemetry.camunda.cloud:443][total kept alive: 0; route allocated: 1 of 5; total allocated: 1 of 10]
08.07. 12:13:12,761 FINE  [camundajar.impl.org.apache.http.impl.execchain.MainClientExec#execute] Opening connection {s}->https://api.telemetry.camunda.cloud:443
08.07. 12:13:12,814 FINE  [camundajar.impl.org.apache.http.impl.conn.DefaultHttpClientConnectionOperator#connect] Connecting to api.telemetry.camunda.cloud/35.233.40.222:443
08.07. 12:13:12,815 FINE  [camundajar.impl.org.apache.http.conn.ssl.SSLConnectionSocketFactory#connectSocket] Connecting socket to api.telemetry.camunda.cloud/35.233.40.222:443 with timeout 0
08.07. 12:13:13,016 FINE  [camundajar.impl.org.apache.http.conn.ssl.SSLConnectionSocketFactory#createLayeredSocket] Enabled protocols: [TLSv1, TLSv1.1, TLSv1.2]
08.07. 12:13:13,018 FINE  [camundajar.impl.org.apache.http.conn.ssl.SSLConnectionSocketFactory#createLayeredSocket] Enabled cipher suites:[TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA384, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384, TLS_RSA_WITH_AES_256_CBC_SHA256, TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA384, TLS_ECDH_RSA_WITH_AES_256_CBC_SHA384, TLS_DHE_RSA_WITH_AES_256_CBC_SHA256, TLS_DHE_DSS_WITH_AES_256_CBC_SHA256, TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA, TLS_RSA_WITH_AES_256_CBC_SHA, TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA, TLS_ECDH_RSA_WITH_AES_256_CBC_SHA, TLS_DHE_RSA_WITH_AES_256_CBC_SHA, TLS_DHE_DSS_WITH_AES_256_CBC_SHA, TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA256, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256, TLS_RSA_WITH_AES_128_CBC_SHA256, TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA256, TLS_ECDH_RSA_WITH_AES_128_CBC_SHA256, TLS_DHE_RSA_WITH_AES_128_CBC_SHA256, TLS_DHE_DSS_WITH_AES_128_CBC_SHA256, TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA, TLS_RSA_WITH_AES_128_CBC_SHA, TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA, TLS_ECDH_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_DSS_WITH_AES_128_CBC_SHA, TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384, TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384, TLS_RSA_WITH_AES_256_GCM_SHA384, TLS_ECDH_ECDSA_WITH_AES_256_GCM_SHA384, TLS_ECDH_RSA_WITH_AES_256_GCM_SHA384, TLS_DHE_RSA_WITH_AES_256_GCM_SHA384, TLS_DHE_DSS_WITH_AES_256_GCM_SHA384, TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256, TLS_RSA_WITH_AES_128_GCM_SHA256, TLS_ECDH_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDH_RSA_WITH_AES_128_GCM_SHA256, TLS_DHE_RSA_WITH_AES_128_GCM_SHA256, TLS_DHE_DSS_WITH_AES_128_GCM_SHA256, TLS_EMPTY_RENEGOTIATION_INFO_SCSV]
08.07. 12:13:13,018 FINE  [camundajar.impl.org.apache.http.conn.ssl.SSLConnectionSocketFactory#createLayeredSocket] Starting handshake
08.07. 12:13:14,383 FINE  [camundajar.impl.org.apache.http.conn.ssl.SSLConnectionSocketFactory#verifyHostname] Secure session established
08.07. 12:13:14,384 FINE  [camundajar.impl.org.apache.http.conn.ssl.SSLConnectionSocketFactory#verifyHostname]  negotiated protocol: TLSv1.2
08.07. 12:13:14,385 FINE  [camundajar.impl.org.apache.http.conn.ssl.SSLConnectionSocketFactory#verifyHostname]  negotiated cipher suite: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
08.07. 12:13:14,387 FINE  [camundajar.impl.org.apache.http.conn.ssl.SSLConnectionSocketFactory#verifyHostname]  peer principal: CN=api.prod.telemetry.camunda.cloud
08.07. 12:13:14,389 FINE  [camundajar.impl.org.apache.http.conn.ssl.SSLConnectionSocketFactory#verifyHostname]  peer alternative names: [api.prod.telemetry.camunda.cloud, api.telemetry.camunda.cloud, ui.prod.telemetry.camunda.cloud, ui.telemetry.camunda.cloud]
08.07. 12:13:14,390 FINE  [camundajar.impl.org.apache.http.conn.ssl.SSLConnectionSocketFactory#verifyHostname]  issuer principal: CN=Let's Encrypt Authority X3, O=Let's Encrypt, C=US
08.07. 12:13:14,432 FINE  [camundajar.impl.org.apache.http.impl.conn.DefaultHttpClientConnectionOperator#connect] Connection established 192.168.178.2:61698<->35.233.40.222:443
08.07. 12:13:14,434 FINE  [camundajar.impl.org.apache.http.impl.execchain.MainClientExec#execute] Executing request POST /pings HTTP/1.1
08.07. 12:13:14,435 FINE  [camundajar.impl.org.apache.http.impl.execchain.MainClientExec#execute] Target auth state: UNCHALLENGED
08.07. 12:13:14,442 FINE  [camundajar.impl.org.apache.http.impl.execchain.MainClientExec#execute] Proxy auth state: UNCHALLENGED
08.07. 12:13:14,464 FINE  [camundajar.impl.org.apache.http.headers#onRequestSubmitted] http-outgoing-0 >> POST /pings HTTP/1.1
08.07. 12:13:14,465 FINE  [camundajar.impl.org.apache.http.headers#onRequestSubmitted] http-outgoing-0 >> Content-Type: application/json
08.07. 12:13:14,465 FINE  [camundajar.impl.org.apache.http.headers#onRequestSubmitted] http-outgoing-0 >> Content-Length: 233
08.07. 12:13:14,466 FINE  [camundajar.impl.org.apache.http.headers#onRequestSubmitted] http-outgoing-0 >> Host: api.telemetry.camunda.cloud
08.07. 12:13:14,466 FINE  [camundajar.impl.org.apache.http.headers#onRequestSubmitted] http-outgoing-0 >> Connection: Keep-Alive
08.07. 12:13:14,467 FINE  [camundajar.impl.org.apache.http.headers#onRequestSubmitted] http-outgoing-0 >> User-Agent: Apache-HttpClient/4.5.9 (Java/1.8.0_252)
08.07. 12:13:14,468 FINE  [camundajar.impl.org.apache.http.headers#onRequestSubmitted] http-outgoing-0 >> Accept-Encoding: gzip,deflate
08.07. 12:13:14,470 FINE  [camundajar.impl.org.apache.http.wire#wire] http-outgoing-0 >> "POST /pings HTTP/1.1[\r][\n]"
08.07. 12:13:14,471 FINE  [camundajar.impl.org.apache.http.wire#wire] http-outgoing-0 >> "Content-Type: application/json[\r][\n]"
08.07. 12:13:14,472 FINE  [camundajar.impl.org.apache.http.wire#wire] http-outgoing-0 >> "Content-Length: 233[\r][\n]"
08.07. 12:13:14,473 FINE  [camundajar.impl.org.apache.http.wire#wire] http-outgoing-0 >> "Host: api.telemetry.camunda.cloud[\r][\n]"
08.07. 12:13:14,473 FINE  [camundajar.impl.org.apache.http.wire#wire] http-outgoing-0 >> "Connection: Keep-Alive[\r][\n]"
08.07. 12:13:14,474 FINE  [camundajar.impl.org.apache.http.wire#wire] http-outgoing-0 >> "User-Agent: Apache-HttpClient/4.5.9 (Java/1.8.0_252)[\r][\n]"
08.07. 12:13:14,474 FINE  [camundajar.impl.org.apache.http.wire#wire] http-outgoing-0 >> "Accept-Encoding: gzip,deflate[\r][\n]"
08.07. 12:13:14,475 FINE  [camundajar.impl.org.apache.http.wire#wire] http-outgoing-0 >> "[\r][\n]"
08.07. 12:13:14,478 FINE  [camundajar.impl.org.apache.http.wire#wire] http-outgoing-0 >> "{"installation":"e4018c03-5df4-41c5-85a9-0354bcdfdba8","product":{"name":"Camunda BPM Runtime","version":"7.14.0-SNAPSHOT","edition":"community","internals":{"database":{"vendor":"Informix Dynamic Server","version":"12.10.FC12WE"}}}}"
08.07. 12:13:14,565 FINE  [camundajar.impl.org.apache.http.wire#wire] http-outgoing-0 << "HTTP/1.1 202 Accepted[\r][\n]"
08.07. 12:13:14,566 FINE  [camundajar.impl.org.apache.http.wire#wire] http-outgoing-0 << "Server: nginx/1.17.7[\r][\n]"
08.07. 12:13:14,567 FINE  [camundajar.impl.org.apache.http.wire#wire] http-outgoing-0 << "Date: Wed, 08 Jul 2020 10:13:14 GMT[\r][\n]"
08.07. 12:13:14,567 FINE  [camundajar.impl.org.apache.http.wire#wire] http-outgoing-0 << "Content-Type: text/plain; charset=utf-8[\r][\n]"
08.07. 12:13:14,568 FINE  [camundajar.impl.org.apache.http.wire#wire] http-outgoing-0 << "Content-Length: 8[\r][\n]"
08.07. 12:13:14,569 FINE  [camundajar.impl.org.apache.http.wire#wire] http-outgoing-0 << "Connection: keep-alive[\r][\n]"
08.07. 12:13:14,569 FINE  [camundajar.impl.org.apache.http.wire#wire] http-outgoing-0 << "Strict-Transport-Security: max-age=15724800; includeSubDomains[\r][\n]"
08.07. 12:13:14,570 FINE  [camundajar.impl.org.apache.http.wire#wire] http-outgoing-0 << "Access-Control-Allow-Origin: *[\r][\n]"
08.07. 12:13:14,571 FINE  [camundajar.impl.org.apache.http.wire#wire] http-outgoing-0 << "Access-Control-Allow-Credentials: true[\r][\n]"
08.07. 12:13:14,571 FINE  [camundajar.impl.org.apache.http.wire#wire] http-outgoing-0 << "Access-Control-Allow-Methods: POST[\r][\n]"
08.07. 12:13:14,572 FINE  [camundajar.impl.org.apache.http.wire#wire] http-outgoing-0 << "Access-Control-Allow-Headers: DNT,X-CustomHeader,Keep-Alive,User-Agent,X-Requested-With,If-Modified-Since,Cache-Control,Content-Type,Authorization[\r][\n]"
08.07. 12:13:14,573 FINE  [camundajar.impl.org.apache.http.wire#wire] http-outgoing-0 << "[\r][\n]"
08.07. 12:13:14,573 FINE  [camundajar.impl.org.apache.http.wire#wire] http-outgoing-0 << "Accepted"
08.07. 12:13:14,608 FINE  [camundajar.impl.org.apache.http.headers#onResponseReceived] http-outgoing-0 << HTTP/1.1 202 Accepted
08.07. 12:13:14,609 FINE  [camundajar.impl.org.apache.http.headers#onResponseReceived] http-outgoing-0 << Server: nginx/1.17.7
08.07. 12:13:14,610 FINE  [camundajar.impl.org.apache.http.headers#onResponseReceived] http-outgoing-0 << Date: Wed, 08 Jul 2020 10:13:14 GMT
08.07. 12:13:14,611 FINE  [camundajar.impl.org.apache.http.headers#onResponseReceived] http-outgoing-0 << Content-Type: text/plain; charset=utf-8
08.07. 12:13:14,611 FINE  [camundajar.impl.org.apache.http.headers#onResponseReceived] http-outgoing-0 << Content-Length: 8
08.07. 12:13:14,612 FINE  [camundajar.impl.org.apache.http.headers#onResponseReceived] http-outgoing-0 << Connection: keep-alive
08.07. 12:13:14,657 FINE  [camundajar.impl.org.apache.http.headers#onResponseReceived] http-outgoing-0 << Strict-Transport-Security: max-age=15724800; includeSubDomains
08.07. 12:13:14,659 FINE  [camundajar.impl.org.apache.http.headers#onResponseReceived] http-outgoing-0 << Access-Control-Allow-Origin: *
08.07. 12:13:14,659 FINE  [camundajar.impl.org.apache.http.headers#onResponseReceived] http-outgoing-0 << Access-Control-Allow-Credentials: true
08.07. 12:13:14,660 FINE  [camundajar.impl.org.apache.http.headers#onResponseReceived] http-outgoing-0 << Access-Control-Allow-Methods: POST
08.07. 12:13:14,660 FINE  [camundajar.impl.org.apache.http.headers#onResponseReceived] http-outgoing-0 << Access-Control-Allow-Headers: DNT,X-CustomHeader,Keep-Alive,User-Agent,X-Requested-With,If-Modified-Since,Cache-Control,Content-Type,Authorization
08.07. 12:13:14,692 FINE  [camundajar.impl.org.apache.http.impl.execchain.MainClientExec#execute] Connection can be kept alive indefinitely

Is this to be shine up here with log level fine and with this strange package name?
Log-Level is set to DEBUG for CONSOLE and FILE.
Shouldn’t LogLevel FINE be lower than DEBUG and therefore be eliminated with my config?

            <console-handler name="CONSOLE">
                <level name="DEBUG"/>
                <formatter>
                    <named-formatter name="COLOR-PATTERN"/>
                </formatter>
            </console-handler>
            <size-rotating-file-handler name="FILE" autoflush="true">
                <level name="DEBUG"/>
                <formatter>
                    <named-formatter name="PATTERN"/>
                </formatter>
                <file relative-to="jboss.server.log.dir" path="server.log"/>
                <rotate-size value="1g"/>
                <append value="true"/>
            </size-rotating-file-handler>

The connection stays in CLOSE_WAIT state since then:

sb2000.[sla2e]/mbi/mbi2e_all. netstat -f inet

TCP: IPv4
   Local Address        Remote Address    Swind Send-Q Rwind Recv-Q    State
-------------------- -------------------- ----- ------ ----- ------ -----------
.....
sb2000.61698         222.40.233.35.bc.googleusercontent.com.443 42368      0 49700      0 CLOSE_WAIT
2

Thanks a lot for the feedback Frank.
I’ll pass this along to the Dev team.

3

Hi Frank,

Thank you for reporting this, I will have a look and create a ticket for it.
I will keep you posted.

Best regards,
Yana

4

Hi Frank, is it possible to sent us the complete configuration of
<subsystem xmlns="urn:jboss:domain:logging:8.0">
I want to make sure that I reproduce the issue correctly
Also it will be helpful if you send the complete standalone.xml file

5

Hi Yana, here’s my wildfly config file standlone-langfr.xml based on standalone-full.xml of WildFly 20.0.1 !

standalone-langfr.xml (36.6 KB)

6

Thank you, Frank.
I will have a look and get back to you with my findings.

7

Hi Frank,

Sorry for my late reply.
The strange name of the package is due to the shading which we did in the engine to prevent having the httpclient dependency. In some case we decide to do libraries shading and relocate the classes so the users are not tied to specific version of the dependency that we are using.

We are going to make adjustments in the engine dependencies (and use the connect - CAM-12158) so those logs will be with org.apache.http package in the next releases.

And back to your question:

Shouldn’t LogLevel FINE be lower than DEBUG and therefore be eliminated with my config?

It is not eliminated as it seems that you have missing the level of the root-logger.

            <root-logger>
                <level name="INFO"/> <!-- This seems to be missing-->
                <handlers>
                    <handler name="CONSOLE"/>
                    <handler name="FILE"/>
                </handlers>
            </root-logger>

Without it the default level of the loggers is ALL as per Wildfly documentation.

Does this help you? Please let me know if you have any further questions or concerns.
Edit: Keep in mind that I am not a WildFly expert, I tried to find the root case with the help of the documentation and some adjustments that I made with the provided standalone.xml file.

Best regards,
Yana

8

Hi Yana,

regarding the logging:
Camunda uses java.util.logging whereas WildFly uses org.apache.log4j.
Both have different names for their log levels which get mapped to each other.
So LogLevel.FINE becomes Priority.DEBUG.

Setting the level on root-logger does not change anything as I’ve already set the log level to DEBUG on the defined handlers.

But as my minimum log-level is DEBUG messages with LogLevel.FINE comes through.
To avoid this, I have logger category for camundajar like already done for cockpit and others

            <logger category="cockpit">
                <level name="INFO"/>
            </logger>

as long as this is still the package name for logging.

9