How to read the Bitbucket Data Center Log Formats

Summary

In this article, we go through the process of how to read Bitbucket Server logs and the formatting for them.

The logs are located in <BITBUCKET_HOME>/log.

Solution

Solution - Bitbucket Data Center

atlassian-bitbucket-access.log

Example log fragment:only available on the end of the request

Logged fields:

1. IP address. If there are multiple addresses, the first address is the 'real' ip address and the remainder the IPs of intermediary proxies

   • This is populated from the "X-Forwarded-For" header provided by the proxies or other external services, and the final IP is the Remote IP (The IP that directly connected to Bitbucket).

   • The order is: X-Forwarded-For,Remote IP | rest of access log line

2. Protocol: http / https / ssh

3. Request id of the format: i*N65BDNx354x326906x2, where:

   • i = start of the request, o = end of the request

   • * or @: '*' if currently clustered or '@' if not.

   • A reasonably (though not necessarily) unique identifier of this Bitbucket Server instance valid until Bitbucket Server terminates. In a Bitbucket Data Center instance it is specific to the node in the cluster that served the request.

   • x = separator

   • 6 = minute in day => 0:00:06

   • x = separator

   • 3112 = request number since last restart

   • x = separator

   • 1 = number of requests being serviced concurrently at the start of the request

4. Username: only available on the end of the request

5. Date / time

6. Action:

   • for HTTP requests: "<http-method> <request-url> <http-version>"

   • for SSH commands: the ssh command-line

7. Request details:

   • for HTTP: "<referrer-url>" "<user-agent>"

   • for SSH: "<remote client's version>"

8. Status code: only available on the end of the request and only on Bitbucket Server 4.0 and later

   • for HTTP: the http response code

   • for SSH: the exit code of the git process

9. Bytes read: only available on the end of the request and only on Bitbucket Server 4.0 and later

10. Bytes written: only available on the end of the request and only on Bitbucket Server 4.0 and later

11. Labels: used in the application to add 'classifications' to requests. Currently supported:

    • type of hosting request: push | fetch | clone | shallow clone | refs | archive

      "Ref advertisement" is the process that allows the git client to determine if it is already up-to-date or what refs it needs to update in relation to the server side. Therefore, this operation will take place in all of the git operations that need to interact with the remote repository - push | fetch | clone | shallow clone - so that the data exchanged between the server and the client is not redundant (i.e. the server doesn't always send the entire repo when the client requests an update but only what's changed or vice-versa).

      If you ran a test in a controlled environment, for every operation performed from a client above you would find a pair like:

      1 2 172.17.0.1 | http | i@OS8A8Sx92x131x0 | - | 2017-04-07 01:32:22,778 | "GET /scm/atest/docker-atlassian-bitbucket-server.git/info/refs HTTP/1.1" | "" "git/2.7.4 (Apple Git-66)" | - | - | - | - | - | - | 172.17.0.1 | http | o@OS8A8Sx92x131x0 | admin | 2017-04-07 01:32:22,958 | "GET /scm/atest/docker-atlassian-bitbucket-server.git/info/refs HTTP/1.1" | "" "git/2.7.4 (Apple Git-66)" | 200 | 0 | 1135 | refs | 179 | - |

      Looking at "Ref advertisment" is important because CI's constantly polling Bitbucket Server to see if there are changes before it builds the source code, could weigh down on the Bitbucket Server's application performance. That is discussed on the Scaling Bitbucket Data Centre for Continuous Integration performance document. By default, we have a "Ref advertisment" caching is disabled but if you use polling you could choose to enable that. cache:hit and cache:miss refer to the "Ref advertisment" caching.That basically means the "Ref advertisment" was successful (200) and it lasted for 179 ms. You always have to look at those as a pair: Input - i@OS8A8Sx92x131x0 vs Output - o@OS8A8Sx92x131x0.

      If you want to go more into the details of how Git uses "Ref advertisment" for cloning a repository, you could check out this blog post: Reimplementing “git clone” in Haskell from the bottom up

    • clone cache: cache:hit | cache:miss | cache:bypass

    • If the request was made using a access-token, a label is added to access log as access-token:id:<access-token-id>

      • e.g. access-token:id:208556733704

12. Response time in milliseconds

13. Session-id

Access Keys

When performing a git operation utilizing an access key, a hexadecimal value will be seen in the username column:

This correlates with the NAME and SLUG column of the STA_SERVICE_USER table. In this case, if we were to query this table for where name=e029569ee85ddc4e:

In addition to the above, the user id (103 in this example ssh:user:id:103) matches the user_id field in the STA_SERVICE_USER table.

When you use access keys it isn't possible to tell which user made this request. The only clue would be the IP address in the first column. You may think it's possible to tell from the Display Name column, but the display name value is populated from the label of the SSH key.

This section also applies to atlassian-bitbucket-audit.log below.

HTTP Access Token

When performing requests using an HTTP access token, the username will be displayed:

However, when using an access token generated at a project/repository level, it won't have a username bound to the token, so you will see the following:

We can see the structure "access-token-user/2/5"; the numbers represent respectively the project number ID and repository ID. In case the token was generated on project level, the structure will be "1/<PROJECT_ID>", for example ""access-token-user/1/2", the number 2 will be the Project ID.

In the column with the value "access-token:id:903951556843", the number correlates with the TOKEN_ID column of the AO_E5A814_ACCESS_TOKEN table. Querying for where token_id=903951556843:

The USER_ID correlated with the USER_ID of the STA_SERVICE_USER table.

atlassian-bitbucket.log

Example log fragment:

Logged fields:

• date

• log level

• [thread]

• logger name (typically a class name)

• log message

audit/atlassian-bitbucket-audit.log

Example log fragment:

Logged fields:

• ip address. If there are multiple addresses, the first address is the 'real' ip address and the remainder the IPs of intermediary proxies

• event name

• user responsible for the event

• timestamp (milliseconds since January 1, 1970 midnight)

• affected entity

• event details

• request id of the format: @8KJQAGx969x538x0, where:

  • * clustering enabled, @ clustering not enabled

  • 8KJQAG = unique identifier of the Bitbucket Server instance that handled the request

  • x = separator

  • 969 = minute in day => 16:09

  • x = separator

  • 538 = request number since last restart

  • x = separator

  • 0 = number of requests being serviced concurrently at the start of the request

• session-id

The request-id and session-id can be used to cross-reference requests and user sessions between the various logs (e.g. access log and audit log)

search/bitbucket_search.log

Example log fragment:

Logged fields:

• Date

• Log level

• Module name

• Cluster name

• Log message

How to change Bitbucket Server logging settings

Have you ever wondered how to automatically gzip bitbucket logs?

Configure Bitbucket Data Center Logging

Logparsers

Over the past years, various log parsers have been created to analyse the Bitbucket Server logs.

They are publicly available, although not officially supported.

• https://bitbucket.org/atlassianlabs/stash-log-parser

• https://bitbucket.org/DTGPS/logp.py

Solution - Bitbucket Mesh

Mesh logs can be found in <mesh-home>/logs for remote Mesh nodes, and <bitbucket-home>/mesh/logs for sidecar nodes

atlassian-mesh-access.log

Example log fragment:only available on the end of the request

Logged fields:

• Ip address

• Protocol: should always be grpc

• Mesh execution id of the format: i@1GGG0Q5Kx420x106x2, where:

  • i = start of the request, o = end of the request

  • An @ separator

  • A reasonably (though not necessarily) unique identifier of this Bitbucket Server instance valid until Bitbucket Server terminates.

  • x = separator

  • 6 = minute in day => 0:00:06

  • x = separator

  • 3112 = request number since last restart

  • x = separator

  • 1 = number of requests being serviced concurrently at the start of the request

• Bitbucket server request ID

• username

• date/time

• request action

• request agent name: Bitbucket node ID or Mesh node name that sent the request.

• RPC status code: only available on the end of the request

• Incoming messages in the request that was processed: only available on the end of the request

• How many messages were sent to Bitbucket server: only available on the end of the request

• bytes read: only available on the end of the request

• bytes written: only available on the end of the request

• labels: used in the application to add 'classifications' to requests

• duration in millis

atlassian-mesh.log

Logged fields:

• Date

• Log level

• [thread]

• User

• Mesh execution ID

• Bitbucket server request ID

  • If there is another ID separated by a comma, it means the request came from another mesh node. This is the remote node mesh execution ID that started this request

• Ip address

• logger name (typically a class name)

• The count of outgoing and incoming messages sent on the connection in relation to the Mesh execution ID (left most)

• Class name

• log message

Mesh Repository markers:

These identify the repository the log line relates to where:

• First number is the partition ID (0030) (in hex)

• Second number is the hierarchy ID (8a2a778e2d97e278f541)

• Third number is the repository ID (5)

Mesh Transaction markers/id:

These identify the transaction number the log line relates to where:

• First number is the pkid of the mesh node which is the leader of the transaction (n/2)

• Second number is the ID of the transaction (tx/131e29470000000000000011)