c - MhagnumDw

/posts/2020-11-19-jboss-eap-docker-image-stacktrace-json-log/banner.png

c

19/11/2020 1642 words 8 minutes

Contents

Ativar o log no formato JSON na imagem docker do JBoss EAP 6.4. Também vamos mudar o formato que o stacktrace aparece no JSON.

Imagem oficial

As imagens docker oficiais podem ser obtidas no registry da RedHat, em registry.redhat.io.

1
2
3
4
5
# login
docker login -u USER registry.redhat.io

# listar as tags disponíveis
skopeo list-tags docker://registry.redhat.io/jboss-eap-6/eap64-openshift

Ativando o log JSON

Para ativar o log do JBoss no formato JSON, basta subir um container setando a variável de ambiente ENABLE_JSON_LOGGING para true.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
# executar
docker run --rm \
  --env ENABLE_JSON_LOGGING=true \
  registry.redhat.io/jboss-eap-6/eap64-openshift:1.9

# ou se você quiser ver o JSON formatado
jq -R '. as $raw | try fromjson catch $raw' <(\
  docker run --rm \
    --env ENABLE_JSON_LOGGING=true \
    registry.redhat.io/jboss-eap-6/eap64-openshift:1.9 \
)

A partir disso cada linha do log da aplicação será parecida com isso:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
{
  "@version": 1,
  "@timestamp": "2020-11-20T14:20:41-03:00",
  "sequence": 7229,
  "loggerClassName": "org.jboss.as.server.ServerLogger_$logger",
  "loggerName": "org.jboss.as",
  "level": "INFO",
  "message": "JBAS015874: JBoss EAP 6.4.20.GA (AS 7.5.20.Final-redhat-1) iniciado em 65151ms - Iniciado 16089 de serviços 16123 (os serviços 121 são lazy, passivos ou em demanda)",
  "threadName": "Controller Boot Thread",
  "threadId": 19,
  "mdc": {},
  "ndc": "",
  "log-handler": "CONSOLE"
}

Se houver exceção, o log será parecido com isso:

Clique AQUI para visualizar o log em JSON

  1
  2
  3
  4
  5
  6
  7
  8
  9
 10
 11
 12
 13
 14
 15
 16
 17
 18
 19
 20
 21
 22
 23
 24
 25
 26
 27
 28
 29
 30
 31
 32
 33
 34
 35
 36
 37
 38
 39
 40
 41
 42
 43
 44
 45
 46
 47
 48
 49
 50
 51
 52
 53
 54
 55
 56
 57
 58
 59
 60
 61
 62
 63
 64
 65
 66
 67
 68
 69
 70
 71
 72
 73
 74
 75
 76
 77
 78
 79
 80
 81
 82
 83
 84
 85
 86
 87
 88
 89
 90
 91
 92
 93
 94
 95
 96
 97
 98
 99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
{
  "@version": 1,
  "@timestamp": "2020-11-20T16:24:35-03:00",
  "sequence": 4998,
  "loggerClassName": "org.jboss.jca.core.CoreLogger_$logger",
  "loggerName": "org.jboss.jca.core.connectionmanager.pool.strategy.OnePool",
  "level": "WARN",
  "message": "IJ000604: Throwable while attempting to get a new connection: null",
  "threadName": "ServerService Thread Pool -- 62",
  "threadId": 126,
  "mdc": {},
  "ndc": "",
  "exception": {
    "refId": 1,
    "exceptionType": "javax.resource.ResourceException",
    "message": "Could not create connection",
    "frames": [
      {
        "class": "org.jboss.jca.adapters.jdbc.local.LocalManagedConnectionFactory",
        "method": "getLocalManagedConnection",
        "line": 351
      },
      {
        "class": "org.jboss.jca.adapters.jdbc.local.LocalManagedConnectionFactory",
        "method": "createManagedConnection",
        "line": 299
      },
      {
        "class": "org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreArrayListManagedConnectionPool",
        "method": "createConnectionEventListener",
        "line": 874
      },
      {
        "class": "org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreArrayListManagedConnectionPool",
        "method": "getConnection",
        "line": 416
      },
      {
        "class": "org.jboss.jca.core.connectionmanager.pool.AbstractPool",
        "method": "getSimpleConnection",
        "line": 479
      },
      {
        "class": "org.jboss.jca.core.connectionmanager.pool.AbstractPool",
        "method": "getConnection",
        "line": 451
      },
      {
        "class": "org.jboss.jca.core.connectionmanager.AbstractConnectionManager",
        "method": "getManagedConnection",
        "line": 344
      },
      {
        "class": "org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl",
        "method": "getManagedConnection",
        "line": 367
      },
      {
        "class": "org.jboss.jca.core.connectionmanager.AbstractConnectionManager",
        "method": "allocateConnection",
        "line": 499
      },
      {
        "class": "org.jboss.jca.adapters.jdbc.WrapperDataSource",
        "method": "getConnection",
        "line": 143
      },
      {
        "class": "org.jboss.as.connector.subsystems.datasources.WildFlyDataSource",
        "method": "getConnection",
        "line": 69
      },
      {
        "class": "org.hibernate.ejb.connection.InjectedDataSourceConnectionProvider",
        "method": "getConnection",
        "line": 71
      },
      {
        "class": "org.hibernate.cfg.SettingsFactory",
        "method": "buildSettings",
        "line": 113
      },
      {
        "class": "org.hibernate.cfg.Configuration",
        "method": "buildSettingsInternal",
        "line": 2863
      },
      {
        "class": "org.hibernate.cfg.Configuration",
        "method": "buildSettings",
        "line": 2859
      },
      {
        "class": "org.hibernate.cfg.Configuration",
        "method": "buildSessionFactory",
        "line": 1870
      },
      {
        "class": "org.hibernate.ejb.Ejb3Configuration",
        "method": "buildEntityManagerFactory",
        "line": 906
      },
      {
        "class": "org.hibernate.ejb.HibernatePersistence",
        "method": "createContainerEntityManagerFactory",
        "line": 74
      },
      {
        "class": "org.jboss.as.jpa.service.PersistenceUnitServiceImpl",
        "method": "createContainerEntityManagerFactory",
        "line": 226
      },
      {
        "class": "org.jboss.as.jpa.service.PersistenceUnitServiceImpl",
        "method": "access$700",
        "line": 59
      },
      {
        "class": "org.jboss.as.jpa.service.PersistenceUnitServiceImpl$1",
        "method": "run",
        "line": 107
      },
      {
        "class": "java.util.concurrent.ThreadPoolExecutor",
        "method": "runWorker",
        "line": 1149
      },
      {
        "class": "java.util.concurrent.ThreadPoolExecutor$Worker",
        "method": "run",
        "line": 624
      },
      {
        "class": "java.lang.Thread",
        "method": "run",
        "line": 748
      },
      {
        "class": "org.jboss.threads.JBossThread",
        "method": "run",
        "line": 122
      }
    ],
    "causedBy": {
      "exception": {
        "refId": 2,
        "exceptionType": "java.sql.SQLException",
        "message": "ORA-01017: invalid username/password; logon denied\n",
        "frames": [
          {
            "class": "oracle.jdbc.driver.T4CTTIoer11",
            "method": "processError",
            "line": 494
          },
          {
            "class": "oracle.jdbc.driver.T4CTTIoer11",
            "method": "processError",
            "line": 441
          },
          {
            "class": "oracle.jdbc.driver.T4CTTIoer11",
            "method": "processError",
            "line": 436
          },
          {
            "class": "oracle.jdbc.driver.T4CTTIfun",
            "method": "processError",
            "line": 1061
          },
          {
            "class": "oracle.jdbc.driver.T4CTTIoauthenticate",
            "method": "processError",
            "line": 550
          },
          {
            "class": "oracle.jdbc.driver.T4CTTIfun",
            "method": "receive",
            "line": 623
          },
          {
            "class": "oracle.jdbc.driver.T4CTTIfun",
            "method": "doRPC",
            "line": 252
          },
          {
            "class": "oracle.jdbc.driver.T4CTTIoauthenticate",
            "method": "doOAUTH",
            "line": 499
          },
          {
            "class": "oracle.jdbc.driver.T4CTTIoauthenticate",
            "method": "doOAUTH",
            "line": 1279
          },
          {
            "class": "oracle.jdbc.driver.T4CConnection",
            "method": "logon",
            "line": 663
          },
          {
            "class": "oracle.jdbc.driver.PhysicalConnection",
            "method": "connect",
            "line": 688
          },
          {
            "class": "oracle.jdbc.driver.T4CDriverExtension",
            "method": "getConnection",
            "line": 39
          },
          {
            "class": "oracle.jdbc.driver.OracleDriver",
            "method": "connect",
            "line": 691
          },
          {
            "class": "org.jboss.jca.adapters.jdbc.local.LocalManagedConnectionFactory",
            "method": "getLocalManagedConnection",
            "line": 323
          },
          {
            "class": "org.jboss.jca.adapters.jdbc.local.LocalManagedConnectionFactory",
            "method": "createManagedConnection",
            "line": 299
          },
          {
            "class": "org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreArrayListManagedConnectionPool",
            "method": "createConnectionEventListener",
            "line": 874
          },
          {
            "class": "org.jboss.jca.core.connectionmanager.pool.mcp.SemaphoreArrayListManagedConnectionPool",
            "method": "getConnection",
            "line": 416
          },
          {
            "class": "org.jboss.jca.core.connectionmanager.pool.AbstractPool",
            "method": "getSimpleConnection",
            "line": 479
          },
          {
            "class": "org.jboss.jca.core.connectionmanager.pool.AbstractPool",
            "method": "getConnection",
            "line": 451
          },
          {
            "class": "org.jboss.jca.core.connectionmanager.AbstractConnectionManager",
            "method": "getManagedConnection",
            "line": 344
          },
          {
            "class": "org.jboss.jca.core.connectionmanager.tx.TxConnectionManagerImpl",
            "method": "getManagedConnection",
            "line": 367
          },
          {
            "class": "org.jboss.jca.core.connectionmanager.AbstractConnectionManager",
            "method": "allocateConnection",
            "line": 499
          },
          {
            "class": "org.jboss.jca.adapters.jdbc.WrapperDataSource",
            "method": "getConnection",
            "line": 143
          },
          {
            "class": "org.jboss.as.connector.subsystems.datasources.WildFlyDataSource",
            "method": "getConnection",
            "line": 69
          },
          {
            "class": "org.hibernate.ejb.connection.InjectedDataSourceConnectionProvider",
            "method": "getConnection",
            "line": 71
          },
          {
            "class": "org.hibernate.cfg.SettingsFactory",
            "method": "buildSettings",
            "line": 113
          },
          {
            "class": "org.hibernate.cfg.Configuration",
            "method": "buildSettingsInternal",
            "line": 2863
          },
          {
            "class": "org.hibernate.cfg.Configuration",
            "method": "buildSettings",
            "line": 2859
          },
          {
            "class": "org.hibernate.cfg.Configuration",
            "method": "buildSessionFactory",
            "line": 1870
          },
          {
            "class": "org.hibernate.ejb.Ejb3Configuration",
            "method": "buildEntityManagerFactory",
            "line": 906
          },
          {
            "class": "org.hibernate.ejb.HibernatePersistence",
            "method": "createContainerEntityManagerFactory",
            "line": 74
          },
          {
            "class": "org.jboss.as.jpa.service.PersistenceUnitServiceImpl",
            "method": "createContainerEntityManagerFactory",
            "line": 226
          },
          {
            "class": "org.jboss.as.jpa.service.PersistenceUnitServiceImpl",
            "method": "access$700",
            "line": 59
          },
          {
            "class": "org.jboss.as.jpa.service.PersistenceUnitServiceImpl$1",
            "method": "run",
            "line": 107
          },
          {
            "class": "java.util.concurrent.ThreadPoolExecutor",
            "method": "runWorker",
            "line": 1149
          },
          {
            "class": "java.util.concurrent.ThreadPoolExecutor$Worker",
            "method": "run",
            "line": 624
          },
          {
            "class": "java.lang.Thread",
            "method": "run",
            "line": 748
          },
          {
            "class": "org.jboss.threads.JBossThread",
            "method": "run",
            "line": 122
          }
        ]
      }
    }
  },
  "log-handler": "CONSOLE"
}

📋 Observar que cada linha do stacktrace ficou em um fragmento de JSON, o que pode deixar um pouco chato a visualização.

Podemos configurar para que o stacktrace da exception fique no formato padrão, de quando visualizamos no console.

Formato do stacktrace da exception no log

Vamos mudar para o formato tradicional, algo parecido com:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
org.jboss.msc.service.StartException in service jboss.web.deployment.default-host./xxx: org.jboss.msc.service.StartException in anonymous service: JBAS018040: Falha ao iniciar o contexto
    at org.jboss.as.web.deployment.WebDeploymentService$1.run(WebDeploymentService.java:99)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)
    at org.jboss.threads.JBossThread.run(JBossThread.java:122)
Caused by: org.jboss.msc.service.StartException in anonymous service: JBAS018040: Falha ao iniciar o contexto
    at org.jboss.as.web.deployment.WebDeploymentService.doStart(WebDeploymentService.java:168)
    at org.jboss.as.web.deployment.WebDeploymentService.access$000(WebDeploymentService.java:61)
    at org.jboss.as.web.deployment.WebDeploymentService$1.run(WebDeploymentService.java:96)
    ... 6 more

Não é possível simplesmente por meio de um parâmetro da imagem. Precisamos alterar o arquivo /opt/eap/standalone/configuration/logging.properties para configurar o formatter OPENSHIFT do log4j.

Visualizar o /opt/eap/standalone/configuration/logging.properties e observar a configuração do formatter.OPENSHIFT:

1
2
3
docker run --rm \
  registry.redhat.io/jboss-eap-6/eap64-openshift:1.9 \
  cat -n /opt/eap/standalone/configuration/logging.properties

Agora vamos criar um Dockerfile conforme abaixo, que vai configurar o formatter.OPENSHIFT para printar o stacktrace no formato que desejamos:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
FROM registry.redhat.io/jboss-eap-6/eap64-openshift:1.9

# backup do arquivo original
RUN cp -a /opt/eap/standalone/configuration/logging.properties \
          /opt/eap/standalone/configuration/logging.properties.original

# adiciona a propriedade exceptionOutputType
RUN sed -i -E \
      's|^formatter.OPENSHIFT.properties=metaData$|formatter.OPENSHIFT.properties=metaData,exceptionOutputType|' \
      /opt/eap/standalone/configuration/logging.properties

# define exceptionOutputType=FORMATTED (default: DETAILED)
RUN echo -e \
      '\nformatter.OPENSHIFT.exceptionOutputType=FORMATTED' >> \
      /opt/eap/standalone/configuration/logging.properties

📋 As três linhas de RUN podem ficar em um único RUN. Estão separadas para melhorar a visualização.

Com o Dockerfile já criado, vamos construir a imagem:

`1`	`docker build -t jboss:json .`

Agora é só executar como já vimos anteriormente:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
# executar
docker run --rm \
  --env ENABLE_JSON_LOGGING=true \
  jboss:json

# ou se você quiser ver o JSON formatado
jq -R '. as $raw | try fromjson catch $raw' <(\
  docker run --rm \
    --env ENABLE_JSON_LOGGING=true \
    jboss:json \
)

E se houver uma exceção, o log com o stacktrace será algo parecido com:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
{
  "@version": 1,
  "@timestamp": "2020-11-21T11:18:28-03:00",
  "sequence": 7086,
  "loggerClassName": "org.jboss.msc.service.ServiceLogger_$logger",
  "loggerName": "org.jboss.msc.service.fail",
  "level": "ERROR",
  "message": "MSC000001: Failed to start service jboss.web.deployment.default-host./xxx",
  "threadName": "ServerService Thread Pool -- 107",
  "threadId": 237,
  "mdc": {},
  "ndc": "",
  "stackTrace": "org.jboss.msc.service.StartException in service jboss.web.deployment.default-host./xxx: org.jboss.msc.service.StartException in anonymous service: JBAS018040: Falha ao iniciar o contexto\n\tat org.jboss.as.web.deployment.WebDeploymentService$1.run(WebDeploymentService.java:99)\n\tat java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)\n\tat java.util.concurrent.FutureTask.run(FutureTask.java:266)\n\tat java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)\n\tat java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)\n\tat java.lang.Thread.run(Thread.java:748)\n\tat org.jboss.threads.JBossThread.run(JBossThread.java:122)\nCaused by: org.jboss.msc.service.StartException in anonymous service: JBAS018040: Falha ao iniciar o contexto\n\tat org.jboss.as.web.deployment.WebDeploymentService.doStart(WebDeploymentService.java:168)\n\tat org.jboss.as.web.deployment.WebDeploymentService.access$000(WebDeploymentService.java:61)\n\tat org.jboss.as.web.deployment.WebDeploymentService$1.run(WebDeploymentService.java:96)\n\t... 6 more\n",
  "log-handler": "CONSOLE"
}

📋 Agora todo o stacktrace é um único atributo no json.

Uma ferramenta como o Kibana vai mostrar o log acima formatado, algo parecido com:

Ou você pode salvar o log acima para um arquivo e ver formatado, assim:

1
while read -r line; do echo -e $line; done <log.json

Contents

c

Imagem oficial

Ativando o log JSON

Formato do stacktrace da exception no log

Referências

See Also