How to read the Bitbucket Server Log Formats

お困りですか?

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

コミュニティに質問

この記事はアトラシアンのサーバー製品にのみ適用されます。クラウドとサーバー製品の違いについてはこちらをご確認ください。

目的

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

ソリューション

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:

  • ip address. If there are multiple addresses, the first address is the 'real' ip address and the remainder the IPs of intermediary proxies
  • protocol: http/https/ssh
  • 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 Stash instance valid until Stash 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
  • username: only available on the end of the request
  • date/time
  • action: 
    • for HTTP requests: "<http-method> <request-url> <http-version>"
    • for SSH commands: the ssh command-line
  • request details:
    • for HTTP: "<referrer-url>" "<user-agent>"
    • for SSH: "<remote client's version>"
  • 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
  • bytes read: only available on the end of the request and only on Bitbucket Server 4.0 and later
  • bytes written: only available on the end of the request and only on Bitbucket Server 4.0 and later
  • 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 Server 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
    • 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 
  • response time in millis
  • 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 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.


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)
  • 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:

  • 日付
  • 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 Server 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.



説明

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

製品 Bitbucket
プラットフォーム サーバー
最終更新日 2019 年 4 月 1 日

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

はい
いいえ
この記事についてのフィードバックを送信する
Powered by Confluence and Scroll Viewport.