How to read the Stash Log Formats
atlassian-stash-access.log
Example log fragment:
63.246.22.199,172.16.1.187 | https | i@9K7Z3NNx6x3112x1 | - | 2012-10-29 00:06:26,723 | "GET /git/STASH/mina-sshd-fork.git/info/refs HTTP/1.1" | "" "git/1.7.4.1" | - | - | - |
63.246.22.199,172.16.1.187 | https | o@9K7Z3NNx6x3112x1 | - | 2012-10-29 00:06:26,736 | "GET /git/STASH/mina-sshd-fork.git/info/refs HTTP/1.1" | "" "git/1.7.4.1" | - | 13 | - |
63.246.22.199,172.16.1.187 | https | i@9K7Z3NNx6x3113x1 | - | 2012-10-29 00:06:26,737 | "GET /git/STASH/mina-sshd-fork.git/info/refs HTTP/1.1" | "" "git/1.7.4.1" | - | - | - |
63.246.22.199,172.16.1.187 | https | o@9K7Z3NNx6x3113x1 | eaccru | 2012-10-29 00:06:26,838 | "GET /git/STASH/mina-sshd-fork.git/info/refs HTTP/1.1" | "" "git/1.7.4.1" | refs, cache:hit | 101 | tmpqqw |
63.246.22.199,172.16.1.187 | https | i@9K7Z3NNx6x3114x1 | - | 2012-10-29 00:06:26,875 | "GET /git/STASH/mina-sshd-fork.git/info/refs HTTP/1.1" | "" "git/1.7.4.1" | - | - | - |
63.246.22.199,172.16.1.187 | https | o@9K7Z3NNx6x3114x1 | - | 2012-10-29 00:06:26,889 | "GET /git/STASH/mina-sshd-fork.git/info/refs HTTP/1.1" | "" "git/1.7.4.1" | - | 14 | - |
63.246.22.199,172.16.1.187 | https | i@9K7Z3NNx6x3115x1 | - | 2012-10-29 00:06:26,890 | "GET /git/STASH/mina-sshd-fork.git/info/refs HTTP/1.1" | "" "git/1.7.4.1" | - | - | - |
63.246.22.199,172.16.1.187 | https | o@9K7Z3NNx6x3115x1 | eaccru | 2012-10-29 00:06:27,009 | "GET /git/STASH/mina-sshd-fork.git/info/refs HTTP/1.1" | "" "git/1.7.4.1" | refs, cache:hit | 119 | 7t4voq |
59.167.133.100,172.16.1.187 | https | i@9K7Z3NNx6x3116x1 | - | 2012-10-29 00:06:28,118 | "GET /projects/STASH/repos/stash/diff/func-test/soke/src/main/resources/load.conf HTTP/1.1" | "https://stash-dev.atlassian.com/projects/STASH/repos/stash/diff/func-test/soke/src/main/resources/load.conf?until=3acf5116812ab79981f6e48974b82139098c0355&since=3d710cbf5de2774641827ba0c2b0256b331dfdf8&at=3acf5116812ab79981f6e48974b82139098c0355" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_6_8) AppleWebKit/537.4 (KHTML, like Gecko) Chrome/22.0.1229.79 Safari/537.4" | - | - | 1zdnfi |
59.167.133.100,172.16.1.187 | https | o@9K7Z3NNx6x3116x1 | jwesleysmith | 2012-10-29 00:06:28,176 | "GET /projects/STASH/repos/stash/diff/func-test/soke/src/main/resources/load.conf HTTP/1.1" | "https://stash-dev.atlassian.com/projects/STASH/repos/stash/diff/func-test/soke/src/main/resources/load.conf?until=3acf5116812ab79981f6e48974b82139098c0355&since=3d710cbf5de2774641827ba0c2b0256b331dfdf8&at=3acf5116812ab79981f6e48974b82139098c0355" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_6_8) AppleWebKit/537.4 (KHTML, like Gecko) Chrome/22.0.1229.79 Safari/537.4" | - | 58 | 1zdnfi |
59.167.133.100,172.16.1.187 | https | i@9K7Z3NNx6x3117x1 | - | 2012-10-29 00:06:28,400 | "GET /s/en_US-1988229788/dc2edb4/1/1.0/_/download/resources/com.atlassian.stash.stash-web-plugin:diff-view/diff-torn-edge.png HTTP/1.1" | "https://stash-dev.atlassian.com/projects/STASH/repos/stash/diff/func-test/soke/src/main/resources/load.conf?until=3acf5116812ab79981f6e48974b82139098c0355&since=3d710cbf5de2774641827ba0c2b0256b331dfdf8&at=3acf5116812ab79981f6e48974b82139098c0355" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_6_8) AppleWebKit/537.4 (KHTML, like Gecko) Chrome/22.0.1229.79 Safari/537.4" | - | - | 1zdnfi |
59.167.133.100,172.16.1.187 | https | o@9K7Z3NNx6x3117x1 | jwesleysmith | 2012-10-29 00:06:28,409 | "GET /s/en_US-1988229788/dc2edb4/1/1.0/_/download/resources/com.atlassian.stash.stash-web-plugin:diff-view/diff-torn-edge.png HTTP/1.1" | "https://stash-dev.atlassian.com/projects/STASH/repos/stash/diff/func-test/soke/src/main/resources/load.conf?until=3acf5116812ab79981f6e48974b82139098c0355&since=3d710cbf5de2774641827ba0c2b0256b331dfdf8&at=3acf5116812ab79981f6e48974b82139098c0355" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_6_8) AppleWebKit/537.4 (KHTML, like Gecko) Chrome/22.0.1229.79 Safari/537.4" | - | 9 | 1zdnfi |
63.246.22.199,172.16.1.187 | https | i@9K7Z3NNx6x3118x1 | - | 2012-10-29 00:06:31,093 | "GET /scm/STASH/stash-mirror-plugin.git/info/refs HTTP/1.1" | "" "git/1.7.4.1" | - | - | - |
63.246.22.199,172.16.1.187 | https | o@9K7Z3NNx6x3118x1 | - | 2012-10-29 00:06:31,107 | "GET /scm/STASH/stash-mirror-plugin.git/info/refs HTTP/1.1" | "" "git/1.7.4.1" | - | 14 | - |
63.246.22.199,172.16.1.187 | https | i@9K7Z3NNx6x3119x1 | - | 2012-10-29 00:06:31,111 | "GET /scm/STASH/stash-mirror-plugin.git/info/refs HTTP/1.1" | "" "git/1.7.4.1" | - | - | - |
63.246.22.199,172.16.1.187 | https | o@9K7Z3NNx6x3119x1 | eaccru | 2012-10-29 00:06:31,216 | "GET /scm/STASH/stash-mirror-plugin.git/info/refs HTTP/1.1" | "" "git/1.7.4.1" | refs, cache:hit | 105 | 1svh6v7 |
172.16.1.187 | ssh | i@9K7Z3NNx6x3134x1 | jhinch | 2012-10-29 00:06:56,364 | git-receive-pack '/STASH/stash.git' | - | - | - | 1g301pk |
172.16.1.187 | ssh | o@9K7Z3NNx6x3134x1 | jhinch | 2012-10-29 00:06:57,612 | git-receive-pack '/STASH/stash.git' | - | - | 1248 | 1g301pk |
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@9K7Z3NNx6x3112x1
, where:- i = start of the request, o = end of the request
- * clustering enabled, @ clustering not enabled
9K7Z3NN
= unique identifier of the Stash instance that handled the request- x = separator
- 6 = minute in day => 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: -
- labels: used in the application to add 'classifications' to requests. Currently supported:
- type of hosting request: push | fetch | clone | clone | shallow clone | refs
- git-receive-pack is always a push, but for old versions of Stash it was missing
- older versions of Stash reported "shallow clone" for shallow clone operations. Since 2.10, this is reported as a two separate labels: the 'shallow' qualifier and the 'clone' request type.
- hosting request qualifier: shallow | rejected
- the 'shallow' qualifier is returned for clone and fetch operations for which a
--depth
parameter is specified (since 2.10) - the 'rejected' qualifier is returned for push operations that are rejected because of repository hooks (since 3.6)
- the 'shallow' qualifier is returned for clone and fetch operations for which a
- clone cache: cache:hit | cache:miss
- type of hosting request: push | fetch | clone | clone | shallow clone | refs
- 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:3 | 52 | mvbea5 |
In this case e029569ee85ddc4e
.
This correlates with the NAME and SLUG column of the STA_SERVICE_USER
table.
USER_ID | DISPLAY_NAME | ACTIVE | NAME | SLUG | EMAIL_ADDRESS | LABEL |
---|---|---|---|---|---|---|
103 | Access key user (example@atlassian.com) | true | e029569ee85ddc4e | e029569ee85ddc4e | (null) | access-key |
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-stash.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/stash/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:
- date
- log level
- [thread]
- logger name (typically a class name)
- log message
audit/atlassian-stash-audit.log
Example log fragment:
0:0:0:0:0:0:0:1 | RestrictedRefAddedEvent | admin | 1400681361906 | STASH/stash | {"id":1,"value":"refs/heads/random-cleanups","users":["user"]} | @8KJQAGx969x538x0 | 6ywzi6
0:0:0:0:0:0:0:1 | RestrictedRefRemovedEvent | admin | 1400681365418 | STASH/stash | {"id":1,"value":"refs/heads/random-cleanups"} | @8KJQAGx969x540x0 | 6ywzi6
0:0:0:0:0:0:0:1 | RestrictedRefAddedEvent | admin | 1400681373433 | STASH/stash | {"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 Stash 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)