How to read the Bitbucket Server Log Formats

関連コンテンツ

  • 関連コンテンツがありません

お困りですか?

アトラシアン コミュニティをご利用ください。

コミュニティに質問

プラットフォームについて: Server および Data Center のみ。この記事は、Server および Data Center プラットフォームのアトラシアン製品にのみ適用されます。

Support for Server* products ended on February 15th 2024. If you are running a Server product, you can visit the Atlassian Server end of support announcement to review your migration options.

*Fisheye および Crucible は除く

目的

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 - Bitbucket Server

atlassian-bitbucket-access.log

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

172.24.12.153 | https | i@PZQFBCx921x19253x0 | - | 2015-09-09 15:21:08,431 | "GET /status HTTP/1.1" | "" "" | - | - | - | - | - | 1irez8i |
172.24.12.153 | https | o@PZQFBCx921x19253x0 | - | 2015-09-09 15:21:08,437 | "GET /status HTTP/1.1" | "" "" | 200 | 0 | 19 | - | 6 | 1irez8i |
172.24.12.146 | https | i*1Y8NA7Ox764x406x0 | - | 2015-09-10 12:44:32,515 | "GET /status HTTP/1.1" | "" "" | - | - | - | - | - | 1hpn738 |
172.24.12.146 | https | o*1Y8NA7Ox764x406x0 | - | 2015-09-10 12:44:32,523 | "GET /status HTTP/1.1" | "" "" | 200 | 0 | 19 | - | 7 | 1hpn738 |
172.24.36.105 | ssh | o*N65BDNx354x326903x0 | username | 2015-03-02 05:54:25,425 | SSH - git-upload-pack '/foo/bar.git' | - | 0 | 123 | 1024 | cache:miss, refs, ssh:id:610, ssh:label:'sshek@atlassian.com' | 1cl58rd |
172.24.36.105 | ssh | i*N65BDNx354x326907x0 | bamboo_user | 2015-03-02 05:54:25,733 | SSH - git-upload-pack '/bar/support-tools-base.git' | "SSH-2.0-OpenSSH_7.2p2 Ubuntu-4ubuntu2.1" | - | - | y3r3kf |
172.24.36.105 | ssh | o*N65BDNx354x326907x0 | bamboo_user | 2015-03-02 05:54:25,802 | SSH - git-upload-pack '/bar/support-tools-base.git' | "SSH-2.0-OpenSSH_6.6.1p1 Ubuntu-2ubuntu2.3" | 0 | 101 | 4398 | cache:miss, refs, ssh:id:2754, ssh:label:'https://ecosystem-bamboo.internal.atlassian.com' | 69 | y3r3kf |

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:

      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:

0:0:0:0:0:0:0:1 | ssh | o@I2Q0UQx718x241x0 | e029569ee85ddc4e | 2015-10-06 11:58:12,880 | SSH - git-upload-pack '/mob/eyeql.git' | - | 0 | 1740 | 3547 | fetch, ssh:user:id:103 | 52 | mvbea5 |

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:

USER_ID | DISPLAY_NAME | ACTIVE | NAME | SLUG | EMAIL_ADDRESS | LABEL
103 | Access key user (example@atlassian.com) | true | e029569ee85ddc4e | e029569ee85ddc4e | (null) | access-key

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:

ips | https | o@1749XX8x952x97182x0 | <USERNAME> | 2024-05-02 15:52:07,836 | "POST /scm/tb/testing-token.git/git-upload-pack HTTP/1.1" | "" "git/2.44.0" | 200 | 175 | 52 | access-token:id:263466287238, async, protocol:2, refs | 43 | eyoqcd |

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:

ips | https | o@1749XX8x909x95538x0 | access-token-user/2/5 | 2024-05-02 15:09:35,724 | "POST /scm/tb/testing-token.git/git-upload-pack HTTP/1.1" | "" "git/2.44.0" | 200 | 175 | 52 | access-token:id:903951556843, async, protocol:2, refs | 47 | rz9ncj |

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:

CREATED_DATE | EXPIRY_DAYS | HASHED_TOKEN | LAST_AUTHENTICATED | NAME | TOKEN_ID | USER_ID 
2024-05-02 10:52:32.507 | NULL | {PKCS5S2}qmbTibSy0Oa4sZ155jbjT4uUEJrO3f/LX4tfYEq0VwRx9FgyOGf26kR0/viQaXq+ | 2024-08-19 11:58:08.144 | Test | 903951556843 |252

The USER_ID correlated with the USER_ID of the STA_SERVICE_USER table.


atlassian-bitbucket.log

Example log fragment:

2013-01-18 16:53:49,516 INFO  [scheduler_Worker-7]  c.a.m.client.MarketplaceClient GET https://marketplace.atlassian.com/rest/1.0/
2013-01-18 16:53:49,517 INFO  [scheduler_Worker-7]  c.a.m.client.MarketplaceClient GET https://marketplace.atlassian.com/rest/1.0/applications/bitbucket/2000000
2013-01-18 17:53:43,924 DEBUG [scheduler_Worker-2]  c.a.s.i.crowd.HibernateDirectoryDao Updating object: com.atlassian.crowd.model.directory.DirectoryImpl@5929c0d[lowerName=ldap server,description=<null>,type=CONNECTOR,implementationClass=com.atlassian.crowd.directory.OpenLDAP,allowedOperations=[UPDATE_GROUP_ATTRIBUTE, UPDATE_USER_ATTRIBUTE],attributes={directory.cache.synchronise.interval=3600, ldap.read.timeout=240000, ldap.user.displayname=displayName, ldap.usermembership.use=false, ldap.search.timelimit=120000, ldap.user.objectclass=inetorgperson, ldap.group.objectclass=groupOfUniqueNames, ldap.user.firstname=givenName, ldap.pagedresults=false, ldap.group.description=description, ldap.pool.timeout=0, crowd.sync.incremental.enabled=true, ldap.group.usernames=uniqueMember, ldap.user.group=memberOf, ldap.user.filter=(objectclass=inetorgperson), ldap.user.username.rdn=cn, ldap.secure=false, ldap.password=********, ldap.relaxed.dn.standardisation=true, ldap.user.encryption=sha, com.atlassian.crowd.directory.sync.lastdurationms=19, ldap.group.filter=(objectclass=groupOfUniqueNames), com.atlassian.crowd.directory.sync.laststartsynctime=1358524423921, ldap.nestedgroups.disabled=true, ldap.user.username=cn, ldap.group.dn=, ldap.user.email=mail, autoAddGroups=, ldap.basedn=ou=users,ou=system, ldap.propogate.changes=false, ldap.roles.disabled=true, com.atlassian.crowd.directory.sync.currentstartsynctime=1358528023923, ldap.connection.timeout=30000, ldap.url=ldap://localhost:10389, ldap.usermembership.use.for.groups=false, ldap.referral=true, ldap.userdn=uid=admin,ou=system, ldap.user.lastname=sn, ldap.pagedresults.size=1000, ldap.group.name=cn, ldap.local.groups=false, ldap.user.dn=, com.atlassian.crowd.directory.sync.issynchronising=true, ldap.user.password=userPassword}]
2013-01-18 17:53:43,955 INFO  [scheduler_Worker-2]  c.a.c.d.DbCachingRemoteDirectory synchronisation for directory [ 524289 ] starting
2013-01-18 17:53:43,958 INFO  [scheduler_Worker-2]  c.a.c.d.DbCachingRemoteDirectory failed synchronisation complete in [ 3ms ]
2013-01-18 17:53:43,962 DEBUG [scheduler_Worker-2]  c.a.s.i.crowd.HibernateDirectoryDao Updating object: com.atlassian.crowd.model.directory.DirectoryImpl@285cc379[lowerName=ldap server,description=<null>,type=CONNECTOR,implementationClass=com.atlassian.crowd.directory.OpenLDAP,allowedOperations=[UPDATE_GROUP_ATTRIBUTE, UPDATE_USER_ATTRIBUTE],attributes={ldap.read.timeout=240000, directory.cache.synchronise.interval=3600, ldap.user.displayname=displayName, ldap.search.timelimit=120000, ldap.usermembership.use=false, ldap.group.objectclass=groupOfUniqueNames, ldap.user.objectclass=inetorgperson, ldap.pagedresults=false, ldap.group.description=description, ldap.user.firstname=givenName, ldap.pool.timeout=0, crowd.sync.incremental.enabled=true, ldap.group.usernames=uniqueMember, ldap.user.group=memberOf, ldap.user.filter=(objectclass=inetorgperson), ldap.relaxed.dn.standardisation=true, ldap.password=********, ldap.secure=false, ldap.user.username.rdn=cn, ldap.user.encryption=sha, com.atlassian.crowd.directory.sync.lastdurationms=38, ldap.group.filter=(objectclass=groupOfUniqueNames), com.atlassian.crowd.directory.sync.laststartsynctime=1358528023923, ldap.nestedgroups.disabled=true, ldap.user.username=cn, ldap.group.dn=, ldap.user.email=mail, autoAddGroups=, ldap.propogate.changes=false, ldap.basedn=ou=users,ou=system, ldap.roles.disabled=true, ldap.connection.timeout=30000, com.atlassian.crowd.directory.sync.currentstartsynctime=null, ldap.url=ldap://localhost:10389, ldap.usermembership.use.for.groups=false, ldap.referral=true, ldap.user.lastname=sn, ldap.userdn=uid=admin,ou=system, ldap.pagedresults.size=1000, ldap.group.name=cn, ldap.local.groups=false, ldap.user.dn=, com.atlassian.crowd.directory.sync.issynchronising=false, ldap.user.password=userPassword}]
2013-01-18 17:53:43,988 ERROR [scheduler_Worker-2]  c.a.c.d.DbCachingDirectoryPoller Error occurred while refreshing the cache for directory [ 524289 ].

Logged fields:

  • 日付
  • log level
  • [thread]
  • logger name (typically a class name)
  • log message  

audit/atlassian-bitbucket-audit.log

Example log fragment:

0:0:0:0:0:0:0:1 | RestrictedRefAddedEvent | admin | 1400681361906 | BITBUCKET/bitbucket | {"id":1,"value":"refs/heads/random-cleanups","users":["user"]} | @8KJQAGx969x538x0 | 6ywzi6
0:0:0:0:0:0:0:1 | RestrictedRefRemovedEvent | admin | 1400681365418 | BITBUCKET/bitbucket | {"id":1,"value":"refs/heads/random-cleanups"} | @8KJQAGx969x540x0 | 6ywzi6
0:0:0:0:0:0:0:1 | RestrictedRefAddedEvent | admin | 1400681373433 | BITBUCKET/bitbucket | {"id":2,"value":"refs/heads/random-cleanups","users":["user"]} | @8KJQAGx969x543x0 | 6ywzi6

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:

[2016-07-01 15:50:35,691][INFO ][gateway                  ] [bitbucket_bundled] recovered [0] indices into cluster_state
[2016-07-01 15:50:35,711][INFO ][http                     ] [bitbucket_bundled] publish_address {127.0.0.1:7992}, bound_addresses {[::1]:7992}, {127.0.0.1:7992}
[2016-07-01 15:50:35,711][INFO ][node                     ] [bitbucket_bundled] started
[2016-07-01 15:51:07,804][INFO ][com.atlassian.elasticsearch.buckler.config.BucklerConfig] Basic authentication for HTTP transport enabled (auth.basic.http.enabled): true

Logged fields:

  • 日付
  • ログ レベル
  • 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.


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

10.229.31.65 | grpc | i@1GGG0Q5Kx420x106x2 | @5XDWX5x420x2768x0 | admin | 2022-04-12 07:00:50,059 | "HostingService/HttpBackend" | - | - | - | - | - | - | - | -
10.229.31.65 | grpc | o@1GGG0Q5Kx420x106x2 | @5XDWX5x420x2768x0 | admin | 2022-04-12 07:09:18,086 | "HostingService/HttpBackend" | - | 0 | 2 | 141583 | 18951 | 3826461940 | - | 508028

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

2022-04-12 05:39:57,408 INFO  [tx:thread-2] admin 2CM38K4Fx339x113x2 @5XDWX5x339x568x0,4SJOMSOBx339x40x2 10.229.31.195 "TransactionService/Transact" (>2 <1) c.a.b.m.r.DefaultRepositoryManager Repository 0030-8a2a778e2d97e278f541-5 has been created and configured successfully
2022-04-12 05:39:57,766 INFO  [grpc-server:thread-16] admin 2CM38K4Fx339x114x2 @5XDWX5x339x568x0 10.229.31.65 "ManagementService/RepairRepository" (>1 <0) c.a.b.m.repair.DefaultRepairManager [p/0030/h/8a2a778e2d97e278f541/r/5] Repair from mesh2@2 completed in 238 ms

Logged fields:

  • 日付
  • ログ レベル
  • [thread]
  • ユーザー
  • 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)
  • クラス名
  • log message  

Mesh Repository markers:

[p/0030/h/8a2a778e2d97e278f541/r/5]

0030-8a2a778e2d97e278f541-5

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:

transaction n/2/tx/131e29470000000000000011

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)





説明

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

製品Bitbucket
プラットフォームServer
最終更新日 2024 年 11 月 7 日

この内容はお役に立ちましたか?

はい
いいえ
この記事についてのフィードバックを送信する

関連コンテンツ

  • 関連コンテンツがありません
Powered by Confluence and Scroll Viewport.